darkfi/util/
logger.rs

1/* This file is part of DarkFi (https://dark.fi)
2 *
3 * Copyright (C) 2020-2026 Dyne.org foundation
4 *
5 * This program is free software: you can redistribute it and/or modify
6 * it under the terms of the GNU Affero General Public License as
7 * published by the Free Software Foundation, either version 3 of the
8 * License, or (at your option) any later version.
9 *
10 * This program is distributed in the hope that it will be useful,
11 * but WITHOUT ANY WARRANTY; without even the implied warranty of
12 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
13 * GNU Affero General Public License for more details.
14 *
15 * You should have received a copy of the GNU Affero General Public License
16 * along with this program.  If not, see <https://www.gnu.org/licenses/>.
17 */
18
19use std::{
20    env, fmt,
21    io::{Result as IOResult, Write},
22    marker::{Send, Sync},
23    sync::OnceLock,
24    time::UNIX_EPOCH,
25};
26
27use nu_ansi_term::{Color, Style};
28use smol::channel::Sender;
29use tracing::{field::Field, Event, Level as TracingLevel, Metadata, Subscriber};
30use tracing_appender::non_blocking::NonBlocking;
31use tracing_subscriber::{
32    fmt::{
33        format, format::FmtSpan, time::FormatTime, FmtContext, FormatEvent, FormatFields,
34        FormattedFields, Layer as FmtLayer, MakeWriter,
35    },
36    layer::{Context, Filter, SubscriberExt},
37    registry::LookupSpan,
38    reload::{Handle, Layer as ReloadLayer},
39    util::SubscriberInitExt,
40    Layer, Registry,
41};
42
43use crate::{util::time::DateTime, Error, Result};
44
45// Creates a `verbose` log level by wrapping an info! macro and
46// adding a `verbose` field.
47// This allows us to extract the field name in the event metadata and
48// identify the event as a `verbose` event log.
49// Currently, it only supports a subset of argument forms; additional arms
50// can be added as needed to handle more use cases.
51#[macro_export]
52macro_rules! verbose {
53    (target: $target:expr, $($arg:tt)*) => {
54        tracing::info!(target: $target, verbose=true, $($arg)*);
55    };
56    ($($arg:tt)*) => {
57        tracing::info!(verbose=true, $($arg)*);
58    };
59}
60
61pub use verbose;
62
63/// A custom log level type.
64///
65/// This extends the standard [`tracing::Level`] by introducing
66/// additional log levels.
67///
68/// This type is intended for use in custom filtering, formatting,
69/// and logging layers that need to distinguish custom logging levels.
70#[derive(PartialEq, Eq, PartialOrd, Ord, Copy, Clone, Debug)]
71pub enum Level {
72    Trace = 0,
73    Debug = 1,
74    Verbose = 2,
75    Info = 3,
76    Warn = 4,
77    Error = 5,
78}
79
80impl Level {
81    /// Creates a custom [`Level`] from a [`Metadata`] instance.
82    ///
83    /// This method inspects the metadata's fields for a custom level
84    /// (e.g., a `verbose` field). If a custom level is present, it is returned.
85    /// Otherwise, the standard `tracing::Level` is converted to this type.
86    fn new(metadata: &Metadata) -> Self {
87        if metadata.fields().field("verbose").is_some() {
88            Level::Verbose
89        } else {
90            (*metadata.level()).into()
91        }
92    }
93}
94
95impl From<TracingLevel> for Level {
96    fn from(value: TracingLevel) -> Self {
97        match value {
98            TracingLevel::TRACE => Level::Trace,
99            TracingLevel::DEBUG => Level::Debug,
100            TracingLevel::INFO => Level::Info,
101            TracingLevel::WARN => Level::Warn,
102            TracingLevel::ERROR => Level::Error,
103        }
104    }
105}
106
107impl fmt::Display for Level {
108    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
109        match self {
110            Level::Trace => write!(f, "TRACE"),
111            Level::Debug => write!(f, "DEBUG"),
112            Level::Verbose => write!(f, "VERBOSE"),
113            Level::Info => write!(f, "INFO"),
114            Level::Warn => write!(f, "WARN"),
115            Level::Error => write!(f, "ERROR"),
116        }
117    }
118}
119
120/// A formatter for the custom [`Level`]
121///
122/// It implements [`fmt::Display`] and can produce a colored output
123/// when writing to terminal and plain otherwise.
124struct LevelFormatter<'a> {
125    level: &'a Level,
126    ansi: bool,
127}
128
129impl<'a> LevelFormatter<'a> {
130    fn new(level: &'a Level, ansi: bool) -> Self {
131        Self { level, ansi }
132    }
133}
134
135impl fmt::Display for LevelFormatter<'_> {
136    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
137        if self.ansi {
138            match self.level {
139                Level::Trace => write!(f, "{}", Color::Purple.paint(format!("[{}]", self.level))),
140                Level::Debug => write!(f, "{}", Color::Blue.paint(format!("[{}]", self.level))),
141                Level::Verbose => write!(f, "{}", Color::Cyan.paint(format!("[{}]", self.level))),
142                Level::Info => write!(f, "{}", Color::Green.paint(format!("[{}]", self.level))),
143                Level::Warn => write!(f, "{}", Color::Yellow.paint(format!("[{}]", self.level))),
144                Level::Error => write!(f, "{}", Color::Red.paint(format!("[{}]", self.level))),
145            }
146        } else {
147            write!(f, "[{}]", self.level)
148        }
149    }
150}
151
152/// Formats event timestamps as `HH:MM:SS` for `tracing` output.
153pub struct EventTimeFormatter;
154
155impl FormatTime for EventTimeFormatter {
156    fn format_time(&self, w: &mut format::Writer<'_>) -> fmt::Result {
157        let now = DateTime::from_timestamp(UNIX_EPOCH.elapsed().unwrap().as_secs(), 0);
158        write!(w, "{:02}:{:02}:{:02}", now.hour, now.min, now.sec)
159    }
160}
161
162/// Formats `tracing` events for output, with support for custom log levels.
163///
164/// `EventFormatter` behaves like the default event formatter from
165/// tracing-subscriber except for extracting custom levels from
166/// event metadata fields and formatting them accordingly.
167pub struct EventFormatter {
168    ansi: bool,
169    display_target: bool,
170    timer: EventTimeFormatter,
171}
172
173impl EventFormatter {
174    pub fn new(ansi: bool, display_target: bool) -> Self {
175        Self { ansi, display_target, timer: EventTimeFormatter {} }
176    }
177}
178
179impl<S, N> FormatEvent<S, N> for EventFormatter
180where
181    S: Subscriber + for<'a> LookupSpan<'a>,
182    N: for<'a> FormatFields<'a> + 'static,
183{
184    fn format_event(
185        &self,
186        ctx: &FmtContext<'_, S, N>,
187        mut writer: format::Writer<'_>,
188        event: &Event<'_>,
189    ) -> fmt::Result {
190        let meta = event.metadata();
191        // creates a custom level
192        let level = Level::new(meta);
193
194        // format timestamp
195        if self.ansi {
196            let style = Style::new().dimmed();
197            write!(writer, "{}", style.prefix())?;
198            self.timer.format_time(&mut writer)?;
199            write!(writer, "{} ", style.suffix())?
200        } else {
201            self.timer.format_time(&mut writer)?;
202            write!(writer, " ")?;
203        }
204
205        // format custom level
206        write!(writer, "{} ", LevelFormatter::new(&level, self.ansi))?;
207
208        // format span
209        let dimmed = if self.ansi { Style::new().dimmed() } else { Style::new() };
210
211        if let Some(scope) = ctx.event_scope() {
212            let bold = if self.ansi { Style::new().bold() } else { Style::new() };
213
214            let mut seen = false;
215
216            let spans: Vec<_> = scope.from_root().collect();
217            let last_span_idx = spans.len() - 1;
218
219            // Displays the full span tree
220            for (span_idx, span) in spans.into_iter().enumerate() {
221                let span_name = bold.paint(span.metadata().name());
222                // Crop span_id to 6 chars
223                let span_id = span.id().into_u64().to_string();
224                let span_id = &span_id[..span_id.len().min(6)];
225                write!(writer, "{span_name}[{span_id}]")?;
226
227                seen = true;
228
229                // Only show the fields of the last span
230                if meta.is_span() && span_idx == last_span_idx {
231                    let ext = span.extensions();
232                    if let Some(fields) = &ext.get::<FormattedFields<N>>() {
233                        if !fields.is_empty() {
234                            write!(writer, "{}{} {}", bold.paint("{"), fields, bold.paint("}"))?;
235                        }
236                    }
237                }
238                write!(writer, "{}", dimmed.paint(":"))?;
239            }
240
241            if seen {
242                writer.write_char(' ')?;
243            }
244        };
245
246        // format target
247        if self.display_target {
248            write!(writer, "{}{} ", dimmed.paint(meta.target()), dimmed.paint(":"))?;
249        }
250
251        // format event fields
252        ctx.format_fields(writer.by_ref(), event)?;
253        writeln!(writer)
254    }
255}
256
257/// Formats event fields for terminal output, hiding level fields like `verbose`.
258pub fn terminal_field_formatter(
259    writer: &mut format::Writer<'_>,
260    field: &Field,
261    value: &dyn fmt::Debug,
262) -> fmt::Result {
263    match field.name() {
264        // skip showing verbose field
265        "verbose" => Ok(()),
266        "message" => write!(writer, "{value:?}"),
267        name if name.starts_with("log.") => Ok(()),
268        name if name.starts_with("r#") => write!(
269            writer,
270            " {}{}{:?}",
271            Style::new().italic().paint(&name[2..]),
272            Style::new().dimmed().paint("="),
273            value
274        ),
275        name => write!(
276            writer,
277            " {}{}{:?}",
278            Style::new().italic().paint(name),
279            Style::new().dimmed().paint("="),
280            value
281        ),
282    }
283}
284
285/// Formats event fields for file logging, hiding level fields like `verbose`.
286pub fn file_field_formatter(
287    writer: &mut format::Writer<'_>,
288    field: &Field,
289    value: &dyn fmt::Debug,
290) -> fmt::Result {
291    match field.name() {
292        // skip showing verbose field
293        "verbose" => Ok(()),
294        name if name.starts_with("log.") => Ok(()),
295        name if name.starts_with("r#") => write!(writer, " {}={value:?}", &name[2..],),
296        "message" => write!(writer, "{value:?}"),
297        name => write!(writer, " {name}={value:?}"),
298    }
299}
300/// A `tracing-subscriber` layer that filters events based on their target.
301pub struct TargetFilter {
302    /// Targets where logs should always be ignored.
303    ignored_targets: Vec<String>,
304    /// If non-empty, only these targets are allowed.
305    allowed_targets: Vec<String>,
306    /// Per-target minimum level that must be met for an event to be logged.
307    target_levels: Vec<(String, Level)>,
308    /// Default minimum level if no override is found
309    default_level: Level,
310}
311
312impl TargetFilter {
313    /// Create a `TargetFilter` by parsing `allowed_targets` and
314    /// `ignored_targets` from a string in the format `target1,target2`
315    /// or `!target1,!target2`
316    pub fn parse_targets(mut self, log_targets: String) -> Self {
317        let targets: Vec<String> = log_targets.split(',').map(|s| s.to_string()).collect();
318
319        for target in targets {
320            if target.starts_with('!') {
321                self.ignored_targets.push(target.trim_start_matches('!').to_string());
322                continue
323            }
324
325            self.allowed_targets.push(target.to_string());
326        }
327
328        self
329    }
330
331    /// Overrides default level with verbosity level.
332    pub fn with_verbosity(mut self, verbosity_level: u8) -> Self {
333        let level = match verbosity_level {
334            0 => Level::Info,
335            1 => Level::Verbose,
336            2 => Level::Debug,
337            _ => Level::Trace,
338        };
339
340        self.default_level = level;
341        self
342    }
343
344    /// Adds multiple allowed targets.
345    pub fn allow_targets<I, S>(mut self, targets: I) -> Self
346    where
347        I: IntoIterator<Item = S>,
348        S: AsRef<str>,
349    {
350        self.allowed_targets.extend(targets.into_iter().map(|s| s.as_ref().to_string()));
351        self
352    }
353
354    /// Adds multiple ignored targets.
355    pub fn ignore_targets<I, S>(mut self, targets: I) -> Self
356    where
357        I: IntoIterator<Item = S>,
358        S: AsRef<str>,
359    {
360        self.ignored_targets.extend(targets.into_iter().map(|s| s.as_ref().to_string()));
361        self
362    }
363
364    /// Assign a log level filter for multiple targets.
365    pub fn targets_level<I, S>(mut self, targets: I, level: Level) -> Self
366    where
367        I: IntoIterator<Item = S>,
368        S: AsRef<str>,
369    {
370        self.target_levels.extend(targets.into_iter().map(|s| (s.as_ref().to_string(), level)));
371        self
372    }
373
374    /// Override default level filter.
375    pub fn default_level(mut self, level: Level) -> Self {
376        self.default_level = level;
377        self
378    }
379
380    /// Helper method to implement the filtering logic.
381    fn filter<S: Subscriber>(&self, metadata: &Metadata<'_>, _ctx: &Context<'_, S>) -> bool {
382        let target = metadata.target();
383
384        // Explicit ignore is given priority.
385        if self.ignored_targets.iter().any(|s| target.starts_with(s)) {
386            return false;
387        }
388
389        // If allowed list exists, only allow those.
390        if !self.allowed_targets.is_empty() {
391            return self.allowed_targets.iter().any(|s| target.starts_with(s));
392        }
393
394        let level = Level::new(metadata);
395        // check level filter overrides.
396        if let Some(min_level) = self
397            .target_levels
398            .iter()
399            .filter(|(s, _)| target.starts_with(s))
400            .max_by_key(|(s, _)| s.len()) // select the most specific target
401            .map(|(_, lvl)| *lvl)
402        {
403            return level >= min_level;
404        }
405
406        // Otherwise default to level check.
407        level >= self.default_level
408    }
409}
410
411impl Default for TargetFilter {
412    fn default() -> Self {
413        Self {
414            allowed_targets: Vec::new(),
415            ignored_targets: Vec::new(),
416            target_levels: Vec::new(),
417            default_level: Level::Info,
418        }
419    }
420}
421
422/// Implement [`Filter`] to be able to filter inside a specific Layer.
423impl<S: Subscriber> Filter<S> for TargetFilter {
424    fn enabled(&self, metadata: &Metadata<'_>, ctx: &Context<'_, S>) -> bool {
425        self.filter(metadata, ctx)
426    }
427}
428
429/// Implement [`Filter`] to be able to add the filter as a Layer thus
430/// filtering for multiple layers.
431impl<S: Subscriber> Layer<S> for TargetFilter {
432    fn enabled(&self, metadata: &Metadata<'_>, ctx: Context<'_, S>) -> bool {
433        self.filter(metadata, &ctx)
434    }
435}
436
437/// Global singleton holding the tracing terminal layer handle.
438static TERMINAL_LAYER_HANDLE: OnceLock<Handle<Box<dyn Layer<Registry> + Send + Sync>, Registry>> =
439    OnceLock::new();
440
441/// Wrapper structure over a smol channel sender to use as a logs
442/// writer for the interactive shell.
443pub struct ChannelWriter {
444    pub sender: Sender<Vec<String>>,
445}
446
447impl Write for ChannelWriter {
448    fn write(&mut self, buf: &[u8]) -> IOResult<usize> {
449        let string = String::from_utf8_lossy(buf).to_string();
450        let mut message = vec![];
451        for line in string.lines() {
452            message.push(line.to_string());
453        }
454        let _ = self.sender.send_blocking(message);
455        Ok(buf.len())
456    }
457
458    fn flush(&mut self) -> IOResult<()> {
459        Ok(())
460    }
461}
462
463/// Trait definitions for cleaner code.
464pub trait TerminalWriter: for<'writer> MakeWriter<'writer> + 'static + Sized + Send + Sync {}
465impl<W: for<'writer> MakeWriter<'writer> + 'static + Sized + Send + Sync> TerminalWriter for W {}
466
467/// Auxiliary function to set the tracing terminal layer writer.
468pub fn set_terminal_writer(verbosity_level: u8, writer: impl TerminalWriter) -> Result<()> {
469    // Grab the singleton
470    let Some(reload_handle) = TERMINAL_LAYER_HANDLE.get() else {
471        return Err(Error::Custom(String::from("Tracing terminal layer reload handle is not set")))
472    };
473
474    // Generate the terminal layer again using provided writer
475    let terminal_layer = FmtLayer::new()
476        .with_span_events(FmtSpan::NEW | FmtSpan::CLOSE)
477        .event_format(EventFormatter::new(true, verbosity_level != 0))
478        .fmt_fields(format::debug_fn(terminal_field_formatter))
479        .with_writer(writer)
480        .boxed();
481
482    // Reload the layer in the handler
483    if let Err(e) = reload_handle.reload(terminal_layer) {
484        return Err(Error::Custom(format!("Unable to reload terminal layer: {e}")))
485    }
486    Ok(())
487}
488
489/// Helper for setting up logging for bins.
490pub fn setup_logging(verbosity_level: u8, log_file: Option<NonBlocking>) -> Result<()> {
491    let terminal_field_format = format::debug_fn(terminal_field_formatter);
492    let file_field_format = format::debug_fn(file_field_formatter);
493
494    let terminal_layer = FmtLayer::new()
495        .with_span_events(FmtSpan::NEW | FmtSpan::CLOSE)
496        .event_format(EventFormatter::new(true, verbosity_level != 0))
497        .fmt_fields(terminal_field_format)
498        .with_writer(std::io::stdout)
499        .boxed();
500    let (terminal_layer, reload_handle) = ReloadLayer::new(terminal_layer);
501    if TERMINAL_LAYER_HANDLE.set(reload_handle).is_err() {
502        return Err(Error::Custom(String::from(
503            "Could not set tracing terminal layer reload handle",
504        )))
505    }
506
507    let mut target_filter = TargetFilter::default().with_verbosity(verbosity_level);
508    if let Ok(log_targets) = env::var("LOG_TARGETS") {
509        target_filter = target_filter.parse_targets(log_targets);
510    }
511
512    let file_layer = log_file.map(|log_file| {
513        FmtLayer::new()
514            .with_span_events(FmtSpan::NEW | FmtSpan::CLOSE)
515            .event_format(EventFormatter::new(false, true))
516            .fmt_fields(file_field_format)
517            .with_writer(log_file)
518    });
519
520    Ok(Registry::default().with(terminal_layer).with(file_layer).with(target_filter).try_init()?)
521}
522
523/// Helper for setting up terminal logging for tests.
524pub fn setup_test_logger(ignored_targets: &[&str], show_target: bool, level: Level) -> Result<()> {
525    let terminal_field_format = format::debug_fn(terminal_field_formatter);
526    let terminal_layer = FmtLayer::new()
527        .event_format(EventFormatter::new(true, show_target))
528        .fmt_fields(terminal_field_format)
529        .with_writer(std::io::stdout);
530
531    let target_filter =
532        TargetFilter::default().ignore_targets(ignored_targets).default_level(level);
533
534    Ok(Registry::default().with(terminal_layer).with(target_filter).try_init()?)
535}
darkfi/util/logger.rs

darkfi/util/
logger.rs
