breez_sdk_spark/
logger.rs

1use std::{fmt::Debug, fs::OpenOptions};
2use tracing::{
3    Event, Span, Subscriber,
4    field::{Field, Visit},
5    span::{Attributes, Id},
6};
7use tracing_subscriber::{
8    Layer,
9    filter::{LevelFilter, Targets},
10    fmt::{FormatFields, format::Writer},
11    layer::{Context, SubscriberExt},
12    registry::LookupSpan,
13    util::SubscriberInitExt,
14};
15
16use crate::{LogEntry, Logger, SdkError};
17
18/// Default tracing filter: `info` globally, `debug` for first-party crates,
19/// and noisy third-party crates silenced below `warn`. Shared with the WASM
20/// bindings so both default to the same behaviour.
21pub const DEFAULT_FILTER: &str = concat!(
22    "info",
23    // First-party crates: keep debug logging.
24    ",breez_sdk_spark=debug",
25    ",breez_sdk_common=debug",
26    ",breez_sdk_spark_wasm=debug",
27    ",breez_sdk_spark_bindings=debug",
28    ",spark=debug",
29    ",spark_wallet=debug",
30    ",spark_postgres=debug",
31    ",spark_mysql=debug",
32    ",flashnet=debug",
33    ",platform_utils=debug",
34    // Noisy third-party crates: silence below warn.
35    ",h2=warn",
36    ",rustls=warn",
37    ",rustyline=warn",
38    ",hyper=warn",
39    ",hyper_util=warn",
40    ",tower=warn",
41    ",Connection=warn",
42    ",tonic=warn",
43);
44
45/// Target of the spans that carry an SDK instance's identifier in their
46/// `instance` field. It must match the target `macros::instance_span` emits.
47const INSTANCE_SPAN_TARGET: &str = "breez_sdk_spark_instance";
48const INSTANCE_FIELD: &str = "instance";
49
50/// The filter of the layers that forward log entries to the app: `filter` in
51/// `RUST_LOG` syntax, or [`DEFAULT_FILTER`], with instance spans always enabled
52/// so that every entry that passes it can be attributed to its instance.
53#[doc(hidden)]
54pub fn sdk_log_filter(filter: Option<&str>) -> Targets {
55    parse_log_filter(filter.unwrap_or(DEFAULT_FILTER))
56        .with_target(INSTANCE_SPAN_TARGET, LevelFilter::TRACE)
57}
58
59/// The filter of the log file. Instance spans are left out: the file prints the
60/// spans each line was emitted in, and every line would carry the identity key.
61fn file_log_filter(filter: Option<&str>) -> Targets {
62    parse_log_filter(filter.unwrap_or(DEFAULT_FILTER))
63        .with_target(INSTANCE_SPAN_TARGET, LevelFilter::OFF)
64}
65
66/// A span attributing what runs in it to the SDK instance `instance_id`.
67pub(crate) fn instance_span(instance_id: &str) -> Span {
68    tracing::error_span!(target: INSTANCE_SPAN_TARGET, "sdk", instance = instance_id)
69}
70
71/// Parses a log filter in `RUST_LOG` syntax: comma-separated `target=level`
72/// directives and bare levels, where the most specific target wins. Directives
73/// that filter on spans or fields (`target[span{field=value}]=level`) are not
74/// supported and are ignored, like any other directive that does not parse.
75fn parse_log_filter(filter: &str) -> Targets {
76    let directives: Vec<_> = filter
77        .split(',')
78        .map(str::trim)
79        .filter(|d| !d.is_empty())
80        .filter_map(parse_directive)
81        .collect();
82    // Like `EnvFilter`, a filter with no usable directive shows errors only.
83    if directives.is_empty() {
84        return Targets::new().with_default(LevelFilter::ERROR);
85    }
86    directives
87        .into_iter()
88        .fold(Targets::new(), |targets, (target, level)| match target {
89            Some(target) => targets.with_target(target, level),
90            None => targets.with_default(level),
91        })
92}
93
94/// A target (`None` for a bare level) and its level. A target without a level,
95/// or with an empty one, enables every level.
96fn parse_directive(directive: &str) -> Option<(Option<&str>, LevelFilter)> {
97    let first = directive.chars().next()?;
98    let valid_start = first.is_alphanumeric() || matches!(first, '-' | ':' | '_');
99    if !valid_start || directive.contains(['[', '{']) {
100        return None;
101    }
102    match directive.split_once('=') {
103        Some((target, level)) => {
104            let level = match level.trim() {
105                "" => LevelFilter::TRACE,
106                level => level.parse().ok()?,
107            };
108            Some((Some(target.trim()), level))
109        }
110        None => Some(match directive.parse() {
111            Ok(level) => (None, level),
112            Err(_) => (Some(directive), LevelFilter::TRACE),
113        }),
114    }
115}
116
117/// An instance identifier, stored in the extensions of the span that carries it.
118struct InstanceId(String);
119
120#[derive(Default)]
121struct InstanceVisitor(Option<String>);
122
123impl Visit for InstanceVisitor {
124    fn record_str(&mut self, field: &Field, value: &str) {
125        if field.name() == INSTANCE_FIELD {
126            self.0 = Some(value.to_string());
127        }
128    }
129
130    fn record_debug(&mut self, field: &Field, value: &dyn Debug) {
131        if field.name() == INSTANCE_FIELD {
132            self.0 = Some(format!("{value:?}"));
133        }
134    }
135}
136
137/// Stores the instance identifier of a new instance span, for
138/// [`event_instance_id`] to find. Call from `Layer::on_new_span`.
139#[doc(hidden)]
140pub fn record_instance_id<S>(attrs: &Attributes<'_>, id: &Id, ctx: &Context<'_, S>)
141where
142    S: Subscriber + for<'a> LookupSpan<'a>,
143{
144    if attrs.metadata().target() != INSTANCE_SPAN_TARGET {
145        return;
146    }
147    let mut visitor = InstanceVisitor::default();
148    attrs.record(&mut visitor);
149    if let (Some(instance_id), Some(span)) = (visitor.0, ctx.span(id)) {
150        span.extensions_mut().replace(InstanceId(instance_id));
151    }
152}
153
154/// The identifier of the SDK instance an event was emitted in: the one carried
155/// by its closest instance span.
156#[doc(hidden)]
157pub fn event_instance_id<S>(event: &Event<'_>, ctx: &Context<'_, S>) -> Option<String>
158where
159    S: Subscriber + for<'a> LookupSpan<'a>,
160{
161    ctx.event_scope(event)?.find_map(|span| {
162        span.extensions()
163            .get::<InstanceId>()
164            .map(|instance| instance.0.clone())
165    })
166}
167
168pub(crate) struct GlobalSdkLogger {
169    /// Optional external log listener, that can receive a stream of log statements
170    pub(crate) log_listener: Option<Box<dyn Logger>>,
171}
172
173impl<S> Layer<S> for GlobalSdkLogger
174where
175    S: Subscriber + for<'a> LookupSpan<'a>,
176{
177    fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) {
178        record_instance_id(attrs, id, &ctx);
179    }
180
181    fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) {
182        if let Some(s) = self.log_listener.as_ref() {
183            let mut buf = String::new();
184            let writer = Writer::new(&mut buf);
185
186            if tracing_subscriber::fmt::format::DefaultFields::new()
187                .format_fields(writer, event)
188                .is_ok()
189            {
190                s.log(LogEntry {
191                    line: buf,
192                    level: event.metadata().level().to_string(),
193                    instance_id: event_instance_id(event, &ctx),
194                });
195            }
196        }
197    }
198}
199
200pub(super) fn init_logging(
201    log_dir: Option<&str>,
202    app_logger: Option<Box<dyn Logger>>,
203    log_filter: Option<&str>,
204) -> Result<(), SdkError> {
205    let registry = tracing_subscriber::registry().with(
206        GlobalSdkLogger {
207            log_listener: app_logger,
208        }
209        .with_filter(sdk_log_filter(log_filter)),
210    );
211
212    if let Some(log_dir) = log_dir {
213        let log_file = OpenOptions::new()
214            .create(true)
215            .append(true)
216            .open(format!("{log_dir}/sdk.log"))
217            .map_err(|e| SdkError::Generic(e.to_string()))?;
218        let fmt_layer = tracing_subscriber::fmt::layer()
219            .with_ansi(false)
220            .with_line_number(true)
221            .with_writer(log_file);
222        // Bench-only: render span CLOSE lines (`time.busy` / `time.idle`)
223        // so the breez-bench aggregator can attribute per-RPC latency.
224        // The user's filter (`spark::operator_rpc=info`, etc.) controls
225        // which spans actually emit.
226        #[cfg(feature = "span-trace")]
227        let fmt_layer = fmt_layer.with_span_events(tracing_subscriber::fmt::format::FmtSpan::CLOSE);
228        let fmt_layer = fmt_layer.with_filter(file_log_filter(log_filter));
229        registry.with(fmt_layer).try_init()?;
230    } else {
231        registry.try_init()?;
232    }
233
234    Ok(())
235}
236
237#[cfg(test)]
238mod tests {
239    use std::sync::{Arc, Mutex};
240
241    use tracing::{debug, error, info, trace, warn};
242    use tracing_subscriber::{EnvFilter, Registry, layer::Filter};
243
244    use super::{
245        Context, DEFAULT_FILTER, Event, GlobalSdkLogger, Layer, SubscriberExt, file_log_filter,
246        instance_span, parse_log_filter, sdk_log_filter,
247    };
248    use crate::{LogEntry, Logger};
249
250    /// External logger that records the level of every entry it receives.
251    struct CapturingLogger {
252        levels: Arc<Mutex<Vec<String>>>,
253    }
254
255    impl Logger for CapturingLogger {
256        fn log(&self, l: LogEntry) {
257            self.levels.lock().unwrap().push(l.level);
258        }
259    }
260
261    /// Runs `emit` with a [`GlobalSdkLogger`] filtered by `filter` installed as
262    /// the thread-local default, returning the levels that reached the external
263    /// logger. `emit` must use a literal `target:` (the macros bake it into a
264    /// `static` callsite) matching a directive in `filter`.
265    fn forwarded_levels(filter: &str, emit: impl FnOnce()) -> Vec<String> {
266        let levels = Arc::new(Mutex::new(Vec::new()));
267        let subscriber = tracing_subscriber::registry().with(
268            GlobalSdkLogger {
269                log_listener: Some(Box::new(CapturingLogger {
270                    levels: levels.clone(),
271                })),
272            }
273            .with_filter(parse_log_filter(filter)),
274        );
275
276        tracing::subscriber::with_default(subscriber, emit);
277
278        levels.lock().unwrap().clone()
279    }
280
281    #[test]
282    fn external_logger_respects_filter_level() {
283        // A `debug` filter forwards debug (and above) but not trace — this is
284        // the behaviour that regressed when the layer hard-capped at INFO.
285        let levels = forwarded_levels("brz_logtest_debug=debug", || {
286            info!(target: "brz_logtest_debug", "info");
287            debug!(target: "brz_logtest_debug", "debug");
288            trace!(target: "brz_logtest_debug", "trace");
289        });
290        assert!(levels.contains(&"INFO".to_string()), "got {levels:?}");
291        assert!(levels.contains(&"DEBUG".to_string()), "got {levels:?}");
292        assert!(!levels.contains(&"TRACE".to_string()), "got {levels:?}");
293
294        // A `trace` filter forwards trace too.
295        let levels = forwarded_levels("brz_logtest_trace=trace", || {
296            debug!(target: "brz_logtest_trace", "debug");
297            trace!(target: "brz_logtest_trace", "trace");
298        });
299        assert!(levels.contains(&"DEBUG".to_string()), "got {levels:?}");
300        assert!(levels.contains(&"TRACE".to_string()), "got {levels:?}");
301    }
302
303    /// Records the target and level of every event that passes the filter.
304    struct EventRecorder(Arc<Mutex<Vec<String>>>);
305
306    impl<S: tracing::Subscriber> Layer<S> for EventRecorder {
307        fn on_event(&self, event: &Event<'_>, _ctx: Context<'_, S>) {
308            let meta = event.metadata();
309            self.0
310                .lock()
311                .unwrap()
312                .push(format!("{}:{}", meta.target(), meta.level()));
313        }
314    }
315
316    /// Emits an event at every level for a fixed set of targets and returns
317    /// the ones `filter` lets through.
318    fn enabled_events(filter: impl Filter<Registry> + Send + Sync + 'static) -> Vec<String> {
319        let events = Arc::new(Mutex::new(Vec::new()));
320        let subscriber =
321            tracing_subscriber::registry().with(EventRecorder(events.clone()).with_filter(filter));
322        tracing::subscriber::with_default(subscriber, || {
323            macro_rules! at_all_levels {
324                ($($target:literal),*) => {$(
325                    trace!(target: $target, "");
326                    debug!(target: $target, "");
327                    info!(target: $target, "");
328                    warn!(target: $target, "");
329                    error!(target: $target, "");
330                )*};
331            }
332            at_all_levels!(
333                "breez_sdk_spark",
334                "breez_sdk_spark::sdk",
335                "spark",
336                "spark::tree",
337                "sparkle",
338                "h2::codec",
339                "Connection",
340                "other"
341            );
342        });
343        events.lock().unwrap().clone()
344    }
345
346    #[test]
347    fn log_filter_matches_env_filter() {
348        let filters = [
349            DEFAULT_FILTER,
350            "",
351            "info",
352            "debug",
353            "TRACE",
354            "5",
355            "off",
356            "warn,spark=trace",
357            "spark",
358            "spark=",
359            "spark::=debug",
360            "spark=debug,spark=warn",
361            "debug,info",
362            "info,debug",
363            "info,,debug",
364            "spark=debug,",
365            "debug,spark=off",
366            "error,breez_sdk_spark::sdk=trace,breez_sdk_spark=info",
367            "garbage!!,debug",
368            "=debug",
369            "spark=verbose",
370            "info;spark=debug",
371            "Spark=debug",
372        ];
373        for filter in filters {
374            assert_eq!(
375                enabled_events(parse_log_filter(filter)),
376                enabled_events(EnvFilter::new(filter)),
377                "filter `{filter}`"
378            );
379        }
380    }
381
382    #[test]
383    fn log_filter_ignores_span_and_field_directives() {
384        assert_eq!(
385            enabled_events(parse_log_filter("warn,spark[sync]=debug,[{id=1}]=trace")),
386            enabled_events(parse_log_filter("warn"))
387        );
388    }
389
390    #[test]
391    fn log_filter_tolerates_whitespace() {
392        assert_eq!(
393            enabled_events(parse_log_filter("info, spark = debug ")),
394            enabled_events(parse_log_filter("info,spark=debug"))
395        );
396    }
397
398    /// External logger that records the message and instance of every entry.
399    #[derive(Clone, Default)]
400    struct EntryRecorder(Arc<Mutex<Vec<LogEntry>>>);
401
402    impl Logger for EntryRecorder {
403        fn log(&self, l: LogEntry) {
404            self.0.lock().unwrap().push(l);
405        }
406    }
407
408    impl EntryRecorder {
409        /// A subscriber forwarding to this recorder through `sdk_log_filter(filter)`.
410        fn subscriber(&self, filter: &str) -> impl tracing::Subscriber + Send + Sync {
411            tracing_subscriber::registry().with(
412                GlobalSdkLogger {
413                    log_listener: Some(Box::new(self.clone())),
414                }
415                .with_filter(sdk_log_filter(Some(filter))),
416            )
417        }
418
419        fn instance_of(&self, line: &str) -> Option<String> {
420            let entries = self.0.lock().unwrap();
421            let entry = entries
422                .iter()
423                .find(|entry| entry.line == line)
424                .unwrap_or_else(|| panic!("`{line}` not logged, got {entries:?}"));
425            entry.instance_id.clone()
426        }
427    }
428
429    #[test]
430    fn external_logger_receives_closest_instance() {
431        let recorder = EntryRecorder::default();
432        tracing::subscriber::with_default(recorder.subscriber("brz_logtest_instance=info"), || {
433            info!(target: "brz_logtest_instance", "outside");
434            instance_span("alice").in_scope(|| {
435                // Spans between the instance span and the event don't hide it.
436                tracing::info_span!(target: "brz_logtest_instance", "inner").in_scope(|| {
437                    info!(target: "brz_logtest_instance", "in alice");
438                });
439                instance_span("bob").in_scope(|| {
440                    info!(target: "brz_logtest_instance", "in bob");
441                });
442            });
443        });
444        assert_eq!(recorder.instance_of("outside"), None);
445        assert_eq!(recorder.instance_of("in alice").as_deref(), Some("alice"));
446        assert_eq!(recorder.instance_of("in bob").as_deref(), Some("bob"));
447    }
448
449    #[test]
450    fn instance_survives_filters_that_exclude_its_span() {
451        let recorder = EntryRecorder::default();
452        // `off` disables every target the filter doesn't name, the instance
453        // span's included.
454        let filter = "off,brz_logtest_filtered=warn";
455        tracing::subscriber::with_default(recorder.subscriber(filter), || {
456            instance_span("alice").in_scope(|| {
457                warn!(target: "brz_logtest_filtered", "warned");
458            });
459        });
460        assert_eq!(recorder.instance_of("warned").as_deref(), Some("alice"));
461    }
462
463    /// Collects what a formatting layer writes.
464    #[derive(Clone, Default)]
465    struct Buffer(Arc<Mutex<Vec<u8>>>);
466
467    impl std::io::Write for Buffer {
468        fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
469            self.0.lock().unwrap().extend_from_slice(buf);
470            Ok(buf.len())
471        }
472
473        fn flush(&mut self) -> std::io::Result<()> {
474            Ok(())
475        }
476    }
477
478    impl Buffer {
479        /// A subscriber formatting what passes `filter` into this buffer, spans
480        /// included, the way the log file does.
481        fn subscriber(
482            &self,
483            filter: tracing_subscriber::filter::Targets,
484        ) -> impl tracing::Subscriber + Send + Sync {
485            let writer = self.clone();
486            tracing_subscriber::registry().with(
487                tracing_subscriber::fmt::layer()
488                    .with_ansi(false)
489                    .with_writer(move || writer.clone())
490                    .with_filter(filter),
491            )
492        }
493
494        fn contents(&self) -> String {
495            String::from_utf8(self.0.lock().unwrap().clone()).unwrap()
496        }
497    }
498
499    #[test]
500    fn log_file_leaves_out_instance_spans() {
501        let buffer = Buffer::default();
502        tracing::subscriber::with_default(buffer.subscriber(file_log_filter(None)), || {
503            instance_span("alice").in_scope(|| {
504                tracing::info_span!(target: "brz_logtest_file", "inner").in_scope(|| {
505                    info!(target: "brz_logtest_file", "logged");
506                });
507            });
508        });
509
510        let output = buffer.contents();
511        assert!(
512            output.contains("inner: brz_logtest_file: logged"),
513            "got {output}"
514        );
515        assert!(!output.contains("alice"), "got {output}");
516    }
517
518    struct Instance {
519        instance_id: String,
520    }
521
522    #[macros::instance_span]
523    impl Instance {
524        pub async fn log_here_and_in_task(&self) {
525            info!(target: "brz_logtest_macro", "in method");
526            platform_utils::spawn(async { info!(target: "brz_logtest_macro", "in task") })
527                .await
528                .unwrap();
529        }
530
531        #[tracing::instrument(
532            target = "brz_logtest_record",
533            skip_all,
534            fields(payment_id = tracing::field::Empty),
535        )]
536        pub fn record_in_own_span(&self) {
537            tracing::Span::current().record("payment_id", "abc");
538            info!(target: "brz_logtest_record", "recorded");
539        }
540    }
541
542    #[test]
543    fn instance_span_macro_leaves_method_span_current() {
544        let buffer = Buffer::default();
545        let subscriber = buffer.subscriber(sdk_log_filter(Some("brz_logtest_record=info")));
546        tracing::subscriber::with_default(subscriber, || {
547            Instance {
548                instance_id: "alice".to_string(),
549            }
550            .record_in_own_span();
551        });
552        let output = buffer.contents();
553        assert!(
554            output.contains("record_in_own_span{payment_id=\"abc\"}"),
555            "got {output}"
556        );
557    }
558
559    #[macros::async_test_all]
560    async fn instance_span_macro_attributes_method_and_spawned_tasks() {
561        let recorder = EntryRecorder::default();
562        let _guard =
563            tracing::subscriber::set_default(recorder.subscriber("brz_logtest_macro=info"));
564        Instance {
565            instance_id: "alice".to_string(),
566        }
567        .log_here_and_in_task()
568        .await;
569        assert_eq!(recorder.instance_of("in method").as_deref(), Some("alice"));
570        assert_eq!(recorder.instance_of("in task").as_deref(), Some("alice"));
571    }
572}
breez_sdk_spark/logger.rs

breez_sdk_spark/
logger.rs
