casper_node/
logging.rs

1//! Logging via the tracing crate.
2
3use std::{env, fmt, io, string::ToString};
4
5use ansi_term::{Color, Style};
6use anyhow::anyhow;
7use datasize::DataSize;
8use once_cell::sync::OnceCell;
9use serde::{Deserialize, Serialize};
10use smallvec::SmallVec;
11use tracing::{
12    field::{Field, Visit},
13    Event, Level, Subscriber,
14};
15use tracing_subscriber::{
16    fmt::{
17        format::{self, FieldFn, Format, Json, JsonFields, Writer},
18        time::{FormatTime, SystemTime},
19        FmtContext, FormatEvent, FormatFields, FormattedFields, Layer,
20    },
21    layer::Layered,
22    registry::LookupSpan,
23    reload::{self, Handle},
24    EnvFilter, Registry,
25};
26
27const LOG_VERBOSITY_LEVEL_ENVVAR: &str = "RUST_LOG";
28
29const LOG_FIELD_MESSAGE: &str = "message";
30const LOG_FIELD_TARGET: &str = "log.target";
31const LOG_FIELD_MODULE: &str = "log.module_path";
32const LOG_FIELD_FILE: &str = "log.file";
33const LOG_FIELD_LINE: &str = "log.line";
34
35/// Global reload handle.
36///
37/// We use a static variable for the reload handle since our logger instance is also global.
38static RELOAD_HANDLE: OnceCell<ReloadHandle> = OnceCell::new();
39
40/// Logging configuration.
41#[derive(Clone, DataSize, Debug, Default, Deserialize, Serialize)]
42#[serde(deny_unknown_fields)]
43pub struct LoggingConfig {
44    /// Output format for log.
45    pub format: LoggingFormat,
46
47    /// Colored output (has no effect if JSON format is enabled).
48    ///
49    /// If set, the logger will inject ANSI color codes into log messages.  This is useful if
50    /// writing out to stdout or stderr on an ANSI terminal, but not so if writing to a logfile.
51    pub color: bool,
52
53    /// Abbreviate module names (has no effect if JSON format is enabled).
54    ///
55    /// If set, human-readable formats will abbreviate module names, `foo::bar::baz::bizz` will
56    /// turn into `f:b:b:bizz`.
57    pub abbreviate_modules: bool,
58}
59
60impl LoggingConfig {
61    /// Creates a new instance of LoggingConfig.
62    #[cfg(test)]
63    pub fn new(format: LoggingFormat, color: bool, abbreviate_modules: bool) -> Self {
64        LoggingConfig {
65            format,
66            color,
67            abbreviate_modules,
68        }
69    }
70}
71
72/// Logging output format.
73///
74/// Defaults to "text"".
75#[derive(Clone, DataSize, Debug, Deserialize, Serialize, Default)]
76#[serde(rename_all = "lowercase")]
77pub enum LoggingFormat {
78    /// Text format.
79    #[default]
80    Text,
81    /// JSON format.
82    Json,
83}
84
85/// This is used to implement tracing's `FormatEvent` so that we can customize the way tracing
86/// events are formatted.
87pub struct FmtEvent {
88    /// Whether to use ANSI color formatting or not.
89    ansi_color: bool,
90    /// Whether module segments should be shortened to first letter only.
91    abbreviate_modules: bool,
92}
93
94impl FmtEvent {
95    fn new(ansi_color: bool, abbreviate_modules: bool) -> Self {
96        FmtEvent {
97            ansi_color,
98            abbreviate_modules,
99        }
100    }
101
102    fn enable_dimmed_if_ansi(&self, writer: &mut dyn fmt::Write) -> fmt::Result {
103        if self.ansi_color {
104            write!(writer, "{}", Style::new().dimmed().prefix())
105        } else {
106            Ok(())
107        }
108    }
109
110    fn disable_dimmed_if_ansi(&self, writer: &mut dyn fmt::Write) -> fmt::Result {
111        if self.ansi_color {
112            write!(writer, "{}", Style::new().dimmed().suffix())
113        } else {
114            Ok(())
115        }
116    }
117}
118
119// Used to gather the relevant details from the fields applied by the `tracing_log::LogTracer`,
120// which is used by logging macros when dependent crates use `log` rather than `tracing`.
121#[derive(Default)]
122struct FieldVisitor {
123    module: Option<String>,
124    file: Option<String>,
125    line: Option<u32>,
126}
127
128impl Visit for FieldVisitor {
129    fn record_str(&mut self, field: &Field, value: &str) {
130        if field.name() == LOG_FIELD_MODULE {
131            self.module = Some(value.to_string())
132        } else if field.name() == LOG_FIELD_FILE {
133            self.file = Some(value.to_string())
134        }
135    }
136
137    fn record_u64(&mut self, field: &Field, value: u64) {
138        if field.name() == LOG_FIELD_LINE {
139            self.line = Some(value as u32)
140        }
141    }
142
143    fn record_debug(&mut self, _field: &Field, _value: &dyn fmt::Debug) {}
144}
145
146impl<S, N> FormatEvent<S, N> for FmtEvent
147where
148    S: Subscriber + for<'a> LookupSpan<'a>,
149    N: for<'a> FormatFields<'a> + 'static,
150{
151    fn format_event(
152        &self,
153        ctx: &FmtContext<'_, S, N>,
154        mut writer: Writer<'_>,
155        event: &Event<'_>,
156    ) -> fmt::Result {
157        // print the date/time with dimmed style if `ansi_color` is true
158        self.enable_dimmed_if_ansi(&mut writer)?;
159        SystemTime.format_time(&mut writer)?;
160        self.disable_dimmed_if_ansi(&mut writer)?;
161
162        // print the log level
163        let meta = event.metadata();
164        if self.ansi_color {
165            let color = match *meta.level() {
166                Level::TRACE => Color::Purple,
167                Level::DEBUG => Color::Blue,
168                Level::INFO => Color::Green,
169                Level::WARN => Color::Yellow,
170                Level::ERROR => Color::Red,
171            };
172
173            write!(
174                writer,
175                " {}{:<6}{}",
176                color.prefix(),
177                meta.level(),
178                color.suffix()
179            )?;
180        } else {
181            write!(writer, " {:<6}", meta.level().to_string())?;
182        }
183
184        // print the span information as per
185        // https://github.com/tokio-rs/tracing/blob/21f28f74/tracing-subscriber/src/fmt/format/mod.rs#L667-L695
186        let mut span_seen = false;
187
188        ctx.visit_spans(|span| {
189            write!(writer, "{}", span.metadata().name())?;
190            span_seen = true;
191
192            let ext = span.extensions();
193            let fields = &ext
194                .get::<FormattedFields<N>>()
195                .expect("Unable to find FormattedFields in extensions; this is a bug");
196            if !fields.is_empty() {
197                write!(writer, "{{{}}}", fields)?;
198            }
199            writer.write_char(':')
200        })?;
201
202        if span_seen {
203            writer.write_char(' ')?;
204        }
205
206        // print the module path, filename and line number with dimmed style if `ansi_color` is true
207        let mut field_visitor = FieldVisitor::default();
208        event.record(&mut field_visitor);
209        let module = {
210            let full_module_path = meta
211                .module_path()
212                .or(field_visitor.module.as_deref())
213                .unwrap_or_default();
214            if self.abbreviate_modules {
215                // Use a smallvec for going up to six levels deep.
216                let mut parts: SmallVec<[&str; 6]> = full_module_path.split("::").collect();
217
218                let count = parts.len();
219                // Abbreviate all but last segment.
220                if count > 1 {
221                    for part in parts.iter_mut().take(count - 1) {
222                        assert!(part.is_ascii());
223                        *part = &part[0..1];
224                    }
225                }
226                // Use a single `:` to join the abbreviated modules to make the output even shorter.
227                parts.join(":")
228            } else {
229                full_module_path.to_owned()
230            }
231        };
232
233        let file = if !self.abbreviate_modules {
234            meta.file()
235                .or(field_visitor.file.as_deref())
236                .unwrap_or_default()
237                .rsplit_once('/')
238                .map(|parts| parts.1)
239                .unwrap_or_default()
240        } else {
241            ""
242        };
243
244        let line = meta.line().or(field_visitor.line).unwrap_or_default();
245
246        if !module.is_empty() && (!file.is_empty() || self.abbreviate_modules) {
247            self.enable_dimmed_if_ansi(&mut writer)?;
248            write!(writer, "[{} {}:{}] ", module, file, line,)?;
249            self.disable_dimmed_if_ansi(&mut writer)?;
250        }
251
252        // print the log message and other fields
253        ctx.format_fields(writer.by_ref(), event)?;
254        writeln!(writer)
255    }
256}
257
258/// Initializes the logging system with the default parameters.
259///
260/// See `init_params` for details.
261#[cfg(test)]
262pub fn init() -> anyhow::Result<()> {
263    init_with_config(&Default::default())
264}
265
266/// A handle for reloading the logger.
267#[allow(clippy::type_complexity)] // Cannot be helped, unfortunately.
268pub enum ReloadHandle {
269    /// Text-logger reload handle.
270    Text(Handle<EnvFilter, Layered<Layer<Registry, FieldFn<FormatDebugFn>, FmtEvent>, Registry>>),
271    /// JSON-logger reload handle.
272    Json(Handle<EnvFilter, Layered<Layer<Registry, JsonFields, Format<Json>>, Registry>>),
273}
274
275impl ReloadHandle {
276    /// Swaps out the [`EnvFilter`] used to filter log events.
277    fn reload_env_filter(&self, new_filter: EnvFilter) -> Result<(), reload::Error> {
278        match self {
279            ReloadHandle::Text(handle) => handle.reload(new_filter),
280            ReloadHandle::Json(handle) => handle.reload(new_filter),
281        }
282    }
283
284    /// Returns a string representation of the current [`EnvFilter`], if set.
285    fn display_log_filter(&self) -> Result<String, reload::Error> {
286        match self {
287            ReloadHandle::Text(handle) => handle.with_current(ToString::to_string),
288            ReloadHandle::Json(handle) => handle.with_current(ToString::to_string),
289        }
290    }
291}
292
293/// Swaps out the global [`EnvFilter`].
294pub fn reload_global_env_filter(new_filter: EnvFilter) -> anyhow::Result<()> {
295    let handle = RELOAD_HANDLE
296        .get()
297        .ok_or_else(|| anyhow!("could not fetch reload handle - logger not initialized?"))?;
298    handle.reload_env_filter(new_filter)?;
299
300    Ok(())
301}
302
303/// Returns a string representation of the current global [`EnvFilter`], if set.
304pub fn display_global_env_filter() -> anyhow::Result<String> {
305    let handle = RELOAD_HANDLE
306        .get()
307        .ok_or_else(|| anyhow!("could not fetch reload handle - logger not initialized?"))?;
308    let formatted = handle.display_log_filter()?;
309
310    Ok(formatted)
311}
312
313/// Type alias for the formatting function used.
314pub type FormatDebugFn = fn(&mut Writer, &Field, &dyn fmt::Debug) -> fmt::Result;
315
316fn format_into_debug_writer(
317    writer: &mut Writer,
318    field: &Field,
319    value: &dyn fmt::Debug,
320) -> fmt::Result {
321    match field.name() {
322        LOG_FIELD_MESSAGE => write!(writer, "{:?}", value),
323        LOG_FIELD_TARGET | LOG_FIELD_MODULE | LOG_FIELD_FILE | LOG_FIELD_LINE => Ok(()),
324        _ => write!(writer, "; {}={:?}", field, value),
325    }
326}
327
328/// Initializes the logging system.
329///
330/// This function should only be called once during the lifetime of the application. Do not call
331/// this outside of the application or testing code, the installed logger is global.
332///
333/// See the `README.md` for hints on how to configure logging at runtime.
334// The `io::stdout as fn()...` casts are necessary, as is the `FormatDebugFn` cast.
335#[allow(trivial_casts)]
336pub fn init_with_config(config: &LoggingConfig) -> anyhow::Result<()> {
337    let formatter = format::debug_fn(format_into_debug_writer as FormatDebugFn);
338
339    let filter = EnvFilter::new(
340        env::var(LOG_VERBOSITY_LEVEL_ENVVAR)
341            .as_deref()
342            .unwrap_or("warn,casper_node=info"),
343    );
344
345    match config.format {
346        // Setup a new tracing-subscriber writing to `stdout` for logging.
347        LoggingFormat::Text => {
348            let builder = tracing_subscriber::fmt()
349                .with_writer(io::stdout as fn() -> io::Stdout)
350                .with_env_filter(filter)
351                .fmt_fields(formatter)
352                .event_format(FmtEvent::new(config.color, config.abbreviate_modules))
353                .with_filter_reloading();
354            let handle = ReloadHandle::Text(builder.reload_handle());
355            builder.try_init().map_err(|error| anyhow!(error))?;
356            drop(RELOAD_HANDLE.set(handle));
357            Ok(())
358        }
359
360        // JSON logging writes to `stdout` as well but uses the JSON format.
361        LoggingFormat::Json => {
362            let builder = tracing_subscriber::fmt()
363                .with_writer(io::stdout as fn() -> io::Stdout)
364                .with_env_filter(filter)
365                .json()
366                .with_filter_reloading();
367            let handle = ReloadHandle::Json(builder.reload_handle());
368            builder.try_init().map_err(|error| anyhow!(error))?;
369            drop(RELOAD_HANDLE.set(handle));
370            Ok(())
371        }
372    }
373}
casper_node/logging.rs

casper_node/
logging.rs
