1  /* This file is part of DarkFi (https://dark.fi)
  2   *
  3   * Copyright (C) 2020-2025 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  
 19  use std::{env, fmt, time::UNIX_EPOCH};
 20  
 21  use nu_ansi_term::{Color, Style};
 22  use tracing::{field::Field, Event, Level as TracingLevel, Metadata, Subscriber};
 23  use tracing_appender::non_blocking::NonBlocking;
 24  use tracing_subscriber::{
 25      fmt::{
 26          format, format::FmtSpan, time::FormatTime, FmtContext, FormatEvent, FormatFields,
 27          FormattedFields, Layer as FmtLayer,
 28      },
 29      layer::{Context, Filter, SubscriberExt},
 30      registry::LookupSpan,
 31      util::SubscriberInitExt,
 32      Layer, Registry,
 33  };
 34  
 35  use crate::{util::time::DateTime, Result};
 36  
 37  // Creates a `verbose` log level by wrapping an info! macro and
 38  // adding a `verbose` field.
 39  // This allows us to extract the field name in the event metadata and
 40  // identify the event as a `verbose` event log.
 41  // Currently, it only supports a subset of argument forms; additional arms
 42  // can be added as needed to handle more use cases.
 43  #[macro_export]
 44  macro_rules! verbose {
 45      (target: $target:expr, $($arg:tt)*) => {
 46          tracing::info!(target: $target, verbose=true, $($arg)*);
 47      };
 48      ($($arg:tt)*) => {
 49          tracing::info!(verbose=true, $($arg)*);
 50      };
 51  }
 52  
 53  pub use verbose;
 54  
 55  /// A custom log level type.
 56  ///
 57  /// This extends the standard [`tracing::Level`] by introducing
 58  /// additional log levels.
 59  ///
 60  /// This type is intended for use in custom filtering, formatting,
 61  /// and logging layers that need to distinguish custom logging levels.
 62  #[derive(PartialEq, Eq, PartialOrd, Ord, Copy, Clone, Debug)]
 63  pub enum Level {
 64      Trace = 0,
 65      Debug = 1,
 66      Verbose = 2,
 67      Info = 3,
 68      Warn = 4,
 69      Error = 5,
 70  }
 71  
 72  impl Level {
 73      /// Creates a custom [`Level`] from a [`Metadata`] instance.
 74      ///
 75      /// This method inspects the metadata's fields for a custom level
 76      /// (e.g., a `verbose` field). If a custom level is present, it is returned.
 77      /// Otherwise, the standard `tracing::Level` is converted to this type.
 78      fn new(metadata: &Metadata) -> Self {
 79          if metadata.fields().field("verbose").is_some() {
 80              Level::Verbose
 81          } else {
 82              (*metadata.level()).into()
 83          }
 84      }
 85  }
 86  
 87  impl From<TracingLevel> for Level {
 88      fn from(value: TracingLevel) -> Self {
 89          match value {
 90              TracingLevel::TRACE => Level::Trace,
 91              TracingLevel::DEBUG => Level::Debug,
 92              TracingLevel::INFO => Level::Info,
 93              TracingLevel::WARN => Level::Warn,
 94              TracingLevel::ERROR => Level::Error,
 95          }
 96      }
 97  }
 98  
 99  impl fmt::Display for Level {
100      fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
101          match self {
102              Level::Trace => write!(f, "TRACE"),
103              Level::Debug => write!(f, "DEBUG"),
104              Level::Verbose => write!(f, "VERBOSE"),
105              Level::Info => write!(f, "INFO"),
106              Level::Warn => write!(f, "WARN"),
107              Level::Error => write!(f, "ERROR"),
108          }
109      }
110  }
111  
112  /// A formatter for the custom [`Level`]
113  ///
114  /// It implements [`fmt::Display`] and can produce a colored output
115  /// when writing to terminal and plain otherwise.
116  struct LevelFormatter<'a> {
117      level: &'a Level,
118      ansi: bool,
119  }
120  
121  impl<'a> LevelFormatter<'a> {
122      fn new(level: &'a Level, ansi: bool) -> Self {
123          Self { level, ansi }
124      }
125  }
126  
127  impl fmt::Display for LevelFormatter<'_> {
128      fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
129          if self.ansi {
130              match self.level {
131                  Level::Trace => write!(f, "{}", Color::Purple.paint(format!("[{}]", self.level))),
132                  Level::Debug => write!(f, "{}", Color::Blue.paint(format!("[{}]", self.level))),
133                  Level::Verbose => write!(f, "{}", Color::Cyan.paint(format!("[{}]", self.level))),
134                  Level::Info => write!(f, "{}", Color::Green.paint(format!("[{}]", self.level))),
135                  Level::Warn => write!(f, "{}", Color::Yellow.paint(format!("[{}]", self.level))),
136                  Level::Error => write!(f, "{}", Color::Red.paint(format!("[{}]", self.level))),
137              }
138          } else {
139              write!(f, "[{}]", self.level)
140          }
141      }
142  }
143  
144  /// Formats event timestamps as `HH:MM:SS` for `tracing` output.
145  pub struct EventTimeFormatter;
146  
147  impl FormatTime for EventTimeFormatter {
148      fn format_time(&self, w: &mut format::Writer<'_>) -> fmt::Result {
149          let now = DateTime::from_timestamp(UNIX_EPOCH.elapsed().unwrap().as_secs(), 0);
150          write!(w, "{:02}:{:02}:{:02}", now.hour, now.min, now.sec)
151      }
152  }
153  
154  /// Formats `tracing` events for output, with support for custom log levels.
155  ///
156  /// `EventFormatter` behaves like the default event formatter from
157  /// tracing-subscriber except for extracting custom levels from
158  /// event metadata fields and formatting them accordingly.
159  pub struct EventFormatter {
160      ansi: bool,
161      display_target: bool,
162      timer: EventTimeFormatter,
163  }
164  
165  impl EventFormatter {
166      pub fn new(ansi: bool, display_target: bool) -> Self {
167          Self { ansi, display_target, timer: EventTimeFormatter {} }
168      }
169  }
170  
171  impl<S, N> FormatEvent<S, N> for EventFormatter
172  where
173      S: Subscriber + for<'a> LookupSpan<'a>,
174      N: for<'a> FormatFields<'a> + 'static,
175  {
176      fn format_event(
177          &self,
178          ctx: &FmtContext<'_, S, N>,
179          mut writer: format::Writer<'_>,
180          event: &Event<'_>,
181      ) -> fmt::Result {
182          let meta = event.metadata();
183          // creates a custom level
184          let level = Level::new(meta);
185  
186          // format timestamp
187          if self.ansi {
188              let style = Style::new().dimmed();
189              write!(writer, "{}", style.prefix())?;
190              self.timer.format_time(&mut writer)?;
191              write!(writer, "{} ", style.suffix())?
192          } else {
193              self.timer.format_time(&mut writer)?;
194              write!(writer, " ")?;
195          }
196  
197          // format custom level
198          write!(writer, "{} ", LevelFormatter::new(&level, self.ansi))?;
199  
200          // format span
201          let dimmed = if self.ansi { Style::new().dimmed() } else { Style::new() };
202  
203          if let Some(scope) = ctx.event_scope() {
204              let bold = if self.ansi { Style::new().bold() } else { Style::new() };
205  
206              let mut seen = false;
207  
208              for span in scope.from_root() {
209                  write!(writer, "{}", bold.paint(span.metadata().name()))?;
210                  seen = true;
211  
212                  let ext = span.extensions();
213                  if let Some(fields) = &ext.get::<FormattedFields<N>>() {
214                      if !fields.is_empty() {
215                          write!(writer, "{}{}{}", bold.paint("{"), fields, bold.paint("}"))?;
216                      }
217                  }
218                  write!(writer, "{}", dimmed.paint(":"))?;
219              }
220  
221              if seen {
222                  writer.write_char(' ')?;
223              }
224          };
225  
226          // format target
227          if self.display_target {
228              write!(writer, "{}{} ", dimmed.paint(meta.target()), dimmed.paint(":"))?;
229          }
230  
231          // format event fields
232          ctx.format_fields(writer.by_ref(), event)?;
233          writeln!(writer)
234      }
235  }
236  
237  /// Formats event fields for terminal output, hiding level fields like `verbose`.
238  pub fn terminal_field_formatter(
239      writer: &mut format::Writer<'_>,
240      field: &Field,
241      value: &dyn fmt::Debug,
242  ) -> fmt::Result {
243      match field.name() {
244          // skip showing verbose field
245          "verbose" => Ok(()),
246          "message" => write!(writer, "{value:?}"),
247          name if name.starts_with("log.") => Ok(()),
248          name if name.starts_with("r#") => write!(
249              writer,
250              " {}{}{:?}",
251              Style::new().italic().paint(&name[2..]),
252              Style::new().dimmed().paint("="),
253              value
254          ),
255          name => write!(
256              writer,
257              " {}{}{:?}",
258              Style::new().italic().paint(name),
259              Style::new().dimmed().paint("="),
260              value
261          ),
262      }
263  }
264  
265  /// Formats event fields for file logging, hiding level fields like `verbose`.
266  pub fn file_field_formatter(
267      writer: &mut format::Writer<'_>,
268      field: &Field,
269      value: &dyn fmt::Debug,
270  ) -> fmt::Result {
271      match field.name() {
272          // skip showing verbose field
273          "verbose" => Ok(()),
274          name if name.starts_with("log.") => Ok(()),
275          name if name.starts_with("r#") => write!(writer, " {}={value:?}", &name[2..],),
276          "message" => write!(writer, "{value:?}"),
277          name => write!(writer, " {name}={value:?}"),
278      }
279  }
280  /// A `tracing-subscriber` layer that filters events based on their target.
281  pub struct TargetFilter {
282      /// Targets where logs should always be ignored.
283      ignored_targets: Vec<String>,
284      /// If non-empty, only these targets are allowed.
285      allowed_targets: Vec<String>,
286      /// Per-target minimum level that must be met for an event to be logged.
287      target_levels: Vec<(String, Level)>,
288      /// Default minimum level if no override is found
289      default_level: Level,
290  }
291  
292  impl TargetFilter {
293      /// Create a `TargetFilter` by parsing `allowed_targets` and
294      /// `ignored_targets` from a string in the format `target1,target2`
295      /// or `!target1,!target2`
296      pub fn parse_targets(mut self, log_targets: String) -> Self {
297          let targets: Vec<String> = log_targets.split(',').map(|s| s.to_string()).collect();
298  
299          for target in targets {
300              if target.starts_with('!') {
301                  self.ignored_targets.push(target.trim_start_matches('!').to_string());
302                  continue
303              }
304  
305              self.allowed_targets.push(target.to_string());
306          }
307  
308          self
309      }
310  
311      /// Overrides default level with verbosity level.
312      pub fn with_verbosity(mut self, verbosity_level: u8) -> Self {
313          let level = match verbosity_level {
314              0 => Level::Info,
315              1 => Level::Verbose,
316              2 => Level::Debug,
317              _ => Level::Trace,
318          };
319  
320          self.default_level = level;
321          self
322      }
323  
324      /// Adds multiple allowed targets.
325      pub fn allow_targets<I, S>(mut self, targets: I) -> Self
326      where
327          I: IntoIterator<Item = S>,
328          S: AsRef<str>,
329      {
330          self.allowed_targets.extend(targets.into_iter().map(|s| s.as_ref().to_string()));
331          self
332      }
333  
334      /// Adds multiple ignored targets.
335      pub fn ignore_targets<I, S>(mut self, targets: I) -> Self
336      where
337          I: IntoIterator<Item = S>,
338          S: AsRef<str>,
339      {
340          self.ignored_targets.extend(targets.into_iter().map(|s| s.as_ref().to_string()));
341          self
342      }
343  
344      /// Assign a log level filter for multiple targets.
345      pub fn targets_level<I, S>(mut self, targets: I, level: Level) -> Self
346      where
347          I: IntoIterator<Item = S>,
348          S: AsRef<str>,
349      {
350          self.target_levels.extend(targets.into_iter().map(|s| (s.as_ref().to_string(), level)));
351          self
352      }
353  
354      /// Override default level filter.
355      pub fn default_level(mut self, level: Level) -> Self {
356          self.default_level = level;
357          self
358      }
359  
360      /// Helper method to implement the filtering logic.
361      fn filter<S: Subscriber>(&self, metadata: &Metadata<'_>, _ctx: &Context<'_, S>) -> bool {
362          let target = metadata.target();
363  
364          // Explicit ignore is given priority.
365          if self.ignored_targets.iter().any(|s| target.starts_with(s)) {
366              return false;
367          }
368  
369          // If allowed list exists, only allow those.
370          if !self.allowed_targets.is_empty() {
371              return self.allowed_targets.iter().any(|s| target.starts_with(s));
372          }
373  
374          let level = Level::new(metadata);
375          // check level filter overrides.
376          if let Some(min_level) = self
377              .target_levels
378              .iter()
379              .filter(|(s, _)| target.starts_with(s))
380              .max_by_key(|(s, _)| s.len()) // select the most specific target
381              .map(|(_, lvl)| *lvl)
382          {
383              return level >= min_level;
384          }
385  
386          // Otherwise default to level check.
387          level >= self.default_level
388      }
389  }
390  
391  impl Default for TargetFilter {
392      fn default() -> Self {
393          Self {
394              allowed_targets: Vec::new(),
395              ignored_targets: Vec::new(),
396              target_levels: Vec::new(),
397              default_level: Level::Info,
398          }
399      }
400  }
401  
402  /// Implement [`Filter`] to be able to filter inside a specific Layer.
403  impl<S: Subscriber> Filter<S> for TargetFilter {
404      fn enabled(&self, metadata: &Metadata<'_>, ctx: &Context<'_, S>) -> bool {
405          self.filter(metadata, ctx)
406      }
407  }
408  
409  /// Implement [`Filter`] to be able to add the filter as a Layer thus
410  /// filtering for multiple layers.
411  impl<S: Subscriber> Layer<S> for TargetFilter {
412      fn enabled(&self, metadata: &Metadata<'_>, ctx: Context<'_, S>) -> bool {
413          self.filter(metadata, &ctx)
414      }
415  }
416  
417  /// Helper for setting up logging for bins.
418  pub fn setup_logging(verbosity_level: u8, log_file: Option<NonBlocking>) -> Result<()> {
419      let terminal_field_format = format::debug_fn(terminal_field_formatter);
420      let file_field_format = format::debug_fn(file_field_formatter);
421  
422      let terminal_layer = FmtLayer::new()
423          .with_span_events(FmtSpan::NEW | FmtSpan::CLOSE)
424          .event_format(EventFormatter::new(true, verbosity_level != 0))
425          .fmt_fields(terminal_field_format)
426          .with_writer(std::io::stdout);
427  
428      let mut target_filter = TargetFilter::default().with_verbosity(verbosity_level);
429      if let Ok(log_targets) = env::var("LOG_TARGETS") {
430          target_filter = target_filter.parse_targets(log_targets);
431      }
432  
433      let file_layer = log_file.map(|log_file| {
434          FmtLayer::new()
435              .with_span_events(FmtSpan::NEW | FmtSpan::CLOSE)
436              .event_format(EventFormatter::new(true, true))
437              .fmt_fields(file_field_format)
438              .with_writer(log_file)
439      });
440  
441      Ok(Registry::default().with(terminal_layer).with(file_layer).with(target_filter).try_init()?)
442  }
443  
444  /// Helper for setting up terminal logging for tests.
445  pub fn setup_test_logger(ignored_targets: &[&str], show_target: bool, level: Level) -> Result<()> {
446      let terminal_field_format = format::debug_fn(terminal_field_formatter);
447      let terminal_layer = FmtLayer::new()
448          .event_format(EventFormatter::new(true, show_target))
449          .fmt_fields(terminal_field_format)
450          .with_writer(std::io::stdout);
451  
452      let target_filter =
453          TargetFilter::default().ignore_targets(ignored_targets).default_level(level);
454  
455      Ok(Registry::default().with(terminal_layer).with(target_filter).try_init()?)
456  }