zebrad/components/tracing/
component.rs

1//! The Abscissa component for Zebra's `tracing` implementation.
2
3use std::{
4    fs::{self, File},
5    io::Write,
6};
7
8use abscissa_core::{Component, FrameworkError, Shutdown};
9
10use tokio::sync::watch;
11use tracing::{field::Visit, Level};
12use tracing_appender::non_blocking::{NonBlocking, NonBlockingBuilder, WorkerGuard};
13use tracing_error::ErrorLayer;
14use tracing_subscriber::{
15    fmt::{format, Formatter},
16    layer::SubscriberExt,
17    reload::Handle,
18    util::SubscriberInitExt,
19    EnvFilter, Layer,
20};
21use zebra_chain::parameters::Network;
22
23use crate::{application::build_version, components::tracing::Config};
24
25#[cfg(feature = "flamegraph")]
26use super::flame;
27
28// Art generated with these two images.
29// Zebra logo: book/theme/favicon.png
30// License: MIT or Apache 2.0
31//
32// Heart image: https://commons.wikimedia.org/wiki/File:Love_Heart_SVG.svg
33// Author: Bubinator
34// License: Public Domain or Unconditional Use
35//
36// How to render
37//
38// Convert heart image to PNG (2000px):
39// curl -o heart.svg https://upload.wikimedia.org/wikipedia/commons/4/42/Love_Heart_SVG.svg
40// cargo install resvg
41// resvg --width 2000 --height 2000 heart.svg heart.png
42//
43// Then to text (40x20):
44// img2txt -W 40 -H 20 -f utf8 -d none heart.png > heart.utf8
45// img2txt -W 40 -H 20 -f utf8 -d none favicon.png > logo.utf8
46// paste -d "\0" logo.utf8 heart.utf8 > zebra.utf8
47static ZEBRA_ART: [u8; include_bytes!("zebra.utf8").len()] = *include_bytes!("zebra.utf8");
48
49/// A type-erased boxed writer that can be sent between threads safely.
50pub type BoxWrite = Box<dyn Write + Send + Sync + 'static>;
51
52/// Abscissa component for initializing the `tracing` subsystem
53pub struct Tracing {
54    /// The installed filter reloading handle, if enabled.
55    //
56    // TODO: when fmt::Subscriber supports per-layer filtering, remove the Option
57    filter_handle: Option<
58        Handle<
59            EnvFilter,
60            Formatter<format::DefaultFields, format::Format<format::Full>, NonBlocking>,
61        >,
62    >,
63
64    /// The originally configured filter.
65    initial_filter: String,
66
67    /// The installed flame graph collector, if enabled.
68    #[cfg(feature = "flamegraph")]
69    flamegrapher: Option<flame::Grapher>,
70
71    /// Drop guard for worker thread of non-blocking logger,
72    /// responsible for flushing any remaining logs when the program terminates.
73    //
74    // Correctness: must be listed last in the struct, so it drops after other drops have logged.
75    _guard: Option<WorkerGuard>,
76}
77
78impl Tracing {
79    /// Try to create a new [`Tracing`] component with the given `config`.
80    ///
81    /// If `uses_intro` is true, show a welcome message, the `network`,
82    /// and the Zebra logo on startup. (If the terminal supports it.)
83    //
84    // This method should only print to stderr, because stdout is for tracing logs.
85    #[allow(clippy::print_stdout, clippy::print_stderr, clippy::unwrap_in_result)]
86    pub fn new(
87        network: &Network,
88        config: Config,
89        uses_intro: bool,
90    ) -> Result<Self, FrameworkError> {
91        // Only use color if tracing output is being sent to a terminal or if it was explicitly
92        // forced to.
93        let use_color = config.use_color_stdout();
94        let use_color_stderr = config.use_color_stderr();
95
96        let filter = config.filter.clone().unwrap_or_default();
97        let flame_root = &config.flamegraph;
98
99        // Only show the intro for user-focused node server commands like `start`
100        if uses_intro {
101            // If it's a terminal and color escaping is enabled: clear screen and
102            // print Zebra logo (here `use_color` is being interpreted as
103            // "use escape codes")
104            if use_color_stderr {
105                // Clear screen
106                eprint!("\x1B[2J");
107                eprintln!(
108                    "{}",
109                    std::str::from_utf8(&ZEBRA_ART)
110                        .expect("should always work on a UTF-8 encoded constant")
111                );
112            }
113
114            eprintln!(
115                "Thank you for running a {} zebrad {} node!",
116                network.lowercase_name(),
117                build_version()
118            );
119            eprintln!(
120                "You're helping to strengthen the network and contributing to a social good :)"
121            );
122        }
123
124        let writer = if let Some(log_file) = config.log_file.as_ref() {
125            // Make sure the directory for the log file exists.
126            // If the log is configured in the current directory, it won't have a parent directory.
127            //
128            // # Security
129            //
130            // If the user is running Zebra with elevated permissions ("root"), they should
131            // create the log file directory before running Zebra, and make sure the Zebra user
132            // account has exclusive access to that directory, and other users can't modify
133            // its parent directories.
134            //
135            // This avoids a TOCTOU security issue in the Rust filesystem API.
136            let log_file_dir = log_file.parent();
137            if let Some(log_file_dir) = log_file_dir {
138                if !log_file_dir.exists() {
139                    eprintln!("Directory for log file {log_file:?} does not exist, trying to create it...");
140
141                    if let Err(create_dir_error) = fs::create_dir_all(log_file_dir) {
142                        eprintln!("Failed to create directory for log file: {create_dir_error}");
143                        eprintln!("Trying log file anyway...");
144                    }
145                }
146            }
147
148            if uses_intro {
149                // We want this to appear on stdout instead of the usual log messages.
150                println!("Sending logs to {log_file:?}...");
151            }
152            let log_file = File::options().append(true).create(true).open(log_file)?;
153            Box::new(log_file) as BoxWrite
154        } else {
155            let stdout = std::io::stdout();
156            Box::new(stdout) as BoxWrite
157        };
158
159        // Builds a lossy NonBlocking logger with a default line limit of 128_000 or an explicit buffer_limit.
160        // The write method queues lines down a bounded channel with this capacity to a worker thread that writes to stdout.
161        // Increments error_counter and drops lines when the buffer is full.
162        let (non_blocking, worker_guard) = NonBlockingBuilder::default()
163            .buffered_lines_limit(config.buffer_limit.max(100))
164            .finish(writer);
165
166        // Construct a format subscriber with the supplied global logging filter,
167        // and optionally enable reloading.
168        //
169        // TODO: when fmt::Subscriber supports per-layer filtering, always enable this code
170        #[cfg(not(all(feature = "tokio-console", tokio_unstable)))]
171        let (subscriber, filter_handle) = {
172            use tracing_subscriber::FmtSubscriber;
173
174            let logger = FmtSubscriber::builder()
175                .with_ansi(use_color)
176                .with_writer(non_blocking)
177                .with_env_filter(&filter);
178
179            // Enable reloading if that feature is selected.
180            #[cfg(feature = "filter-reload")]
181            let (filter_handle, logger) = {
182                let logger = logger.with_filter_reloading();
183
184                (Some(logger.reload_handle()), logger)
185            };
186
187            #[cfg(not(feature = "filter-reload"))]
188            let filter_handle = None;
189
190            let warn_error_layer = LastWarnErrorLayer {
191                last_warn_error_sender: crate::application::LAST_WARN_ERROR_LOG_SENDER.clone(),
192            };
193            let subscriber = logger
194                .finish()
195                .with(warn_error_layer)
196                .with(ErrorLayer::default());
197
198            (subscriber, filter_handle)
199        };
200
201        // Construct a tracing registry with the supplied per-layer logging filter,
202        // and disable filter reloading.
203        //
204        // TODO: when fmt::Subscriber supports per-layer filtering,
205        //       remove this registry code, and layer tokio-console on top of fmt::Subscriber
206        #[cfg(all(feature = "tokio-console", tokio_unstable))]
207        let (subscriber, filter_handle) = {
208            use tracing_subscriber::{fmt, Layer};
209
210            let subscriber = tracing_subscriber::registry();
211            // TODO: find out why crawl_and_dial and try_to_sync evade this filter,
212            //       and why they also don't get the global net/commit span.
213            // Note: this might have been fixed by tracing 0.3.15, or by recent Zebra refactors.
214            //
215            // Using `registry` as the base subscriber, the logs from most other functions get filtered.
216            // Using `FmtSubscriber` as the base subscriber, all the logs get filtered.
217            let logger = fmt::Layer::new()
218                .with_ansi(use_color)
219                .with_writer(non_blocking)
220                .with_filter(EnvFilter::from(&filter));
221
222            let subscriber = subscriber.with(logger);
223
224            let span_logger = ErrorLayer::default().with_filter(EnvFilter::from(&filter));
225            let subscriber = subscriber.with(span_logger);
226
227            (subscriber, None)
228        };
229
230        // Add optional layers based on dynamic and compile-time configs
231
232        // Add a flamegraph
233        #[cfg(feature = "flamegraph")]
234        let (flamelayer, flamegrapher) = if let Some(path) = flame_root {
235            let (flamelayer, flamegrapher) = flame::layer(path);
236
237            (Some(flamelayer), Some(flamegrapher))
238        } else {
239            (None, None)
240        };
241        #[cfg(feature = "flamegraph")]
242        let subscriber = subscriber.with(flamelayer);
243
244        #[cfg(feature = "journald")]
245        let journaldlayer = if config.use_journald {
246            use abscissa_core::FrameworkErrorKind;
247
248            let layer = tracing_journald::layer()
249                .map_err(|e| FrameworkErrorKind::ComponentError.context(e))?;
250
251            // If the global filter can't be used, add a per-layer filter instead.
252            // TODO: when fmt::Subscriber supports per-layer filtering, always enable this code
253            #[cfg(all(feature = "tokio-console", tokio_unstable))]
254            let layer = {
255                use tracing_subscriber::Layer;
256                layer.with_filter(EnvFilter::from(&filter))
257            };
258
259            Some(layer)
260        } else {
261            None
262        };
263        #[cfg(feature = "journald")]
264        let subscriber = subscriber.with(journaldlayer);
265
266        #[cfg(feature = "sentry")]
267        let subscriber = subscriber.with(sentry::integrations::tracing::layer());
268
269        // spawn the console server in the background, and apply the console layer
270        // TODO: set Builder::poll_duration_histogram_max() if needed
271        #[cfg(all(feature = "tokio-console", tokio_unstable))]
272        let subscriber = subscriber.with(console_subscriber::spawn());
273
274        // Initialise the global tracing subscriber
275        subscriber.init();
276
277        // Log the tracing stack we just created
278        tracing::info!(
279            ?filter,
280            TRACING_STATIC_MAX_LEVEL = ?tracing::level_filters::STATIC_MAX_LEVEL,
281            LOG_STATIC_MAX_LEVEL = ?log::STATIC_MAX_LEVEL,
282            "started tracing component",
283        );
284
285        if flame_root.is_some() {
286            if cfg!(feature = "flamegraph") {
287                info!(flamegraph = ?flame_root, "installed flamegraph tracing layer");
288            } else {
289                warn!(
290                    flamegraph = ?flame_root,
291                    "unable to activate configured flamegraph: \
292                     enable the 'flamegraph' feature when compiling zebrad",
293                );
294            }
295        }
296
297        if config.use_journald {
298            if cfg!(feature = "journald") {
299                info!("installed journald tracing layer");
300            } else {
301                warn!(
302                    "unable to activate configured journald tracing: \
303                     enable the 'journald' feature when compiling zebrad",
304                );
305            }
306        }
307
308        #[cfg(feature = "sentry")]
309        info!("installed sentry tracing layer");
310
311        #[cfg(all(feature = "tokio-console", tokio_unstable))]
312        info!(
313            TRACING_STATIC_MAX_LEVEL = ?tracing::level_filters::STATIC_MAX_LEVEL,
314            LOG_STATIC_MAX_LEVEL = ?log::STATIC_MAX_LEVEL,
315            "installed tokio-console tracing layer",
316        );
317
318        // Write any progress reports sent by other tasks to the terminal
319        //
320        // TODO: move this to its own module?
321        #[cfg(feature = "progress-bar")]
322        if let Some(progress_bar_config) = config.progress_bar.as_ref() {
323            use howudoin::consumers::TermLine;
324            use std::time::Duration;
325
326            // Stops flickering during the initial sync.
327            const PROGRESS_BAR_DEBOUNCE: Duration = Duration::from_secs(2);
328
329            let terminal_consumer = TermLine::with_debounce(PROGRESS_BAR_DEBOUNCE);
330            howudoin::init(terminal_consumer);
331
332            info!(?progress_bar_config, "activated progress bars");
333        } else {
334            info!(
335                "set 'tracing.progress_bar =\"summary\"' in zebrad.toml to activate progress bars"
336            );
337        }
338
339        Ok(Self {
340            filter_handle,
341            initial_filter: filter,
342            #[cfg(feature = "flamegraph")]
343            flamegrapher,
344            _guard: Some(worker_guard),
345        })
346    }
347
348    /// Drops guard for worker thread of non-blocking logger,
349    /// to flush any remaining logs when the program terminates.
350    pub fn shutdown(&mut self) {
351        self.filter_handle.take();
352
353        #[cfg(feature = "flamegraph")]
354        self.flamegrapher.take();
355
356        self._guard.take();
357    }
358
359    /// Return the currently-active tracing filter.
360    pub fn filter(&self) -> String {
361        if let Some(filter_handle) = self.filter_handle.as_ref() {
362            filter_handle
363                .with_current(|filter| filter.to_string())
364                .expect("the subscriber is not dropped before the component is")
365        } else {
366            self.initial_filter.clone()
367        }
368    }
369
370    /// Reload the currently-active filter with the supplied value.
371    ///
372    /// This can be used to provide a dynamic tracing filter endpoint.
373    pub fn reload_filter(&self, filter: impl Into<EnvFilter>) {
374        let filter = filter.into();
375
376        if let Some(filter_handle) = self.filter_handle.as_ref() {
377            tracing::info!(
378                ?filter,
379                TRACING_STATIC_MAX_LEVEL = ?tracing::level_filters::STATIC_MAX_LEVEL,
380                LOG_STATIC_MAX_LEVEL = ?log::STATIC_MAX_LEVEL,
381                "reloading tracing filter",
382            );
383
384            filter_handle
385                .reload(filter)
386                .expect("the subscriber is not dropped before the component is");
387        } else {
388            tracing::warn!(
389                ?filter,
390                TRACING_STATIC_MAX_LEVEL = ?tracing::level_filters::STATIC_MAX_LEVEL,
391                LOG_STATIC_MAX_LEVEL = ?log::STATIC_MAX_LEVEL,
392                "attempted to reload tracing filter, but filter reloading is disabled",
393            );
394        }
395    }
396}
397
398impl std::fmt::Debug for Tracing {
399    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
400        f.debug_struct("Tracing").finish()
401    }
402}
403
404impl<A: abscissa_core::Application> Component<A> for Tracing {
405    fn id(&self) -> abscissa_core::component::Id {
406        abscissa_core::component::Id::new("zebrad::components::tracing::component::Tracing")
407    }
408
409    fn version(&self) -> abscissa_core::Version {
410        build_version()
411    }
412
413    fn before_shutdown(&self, _kind: Shutdown) -> Result<(), FrameworkError> {
414        #[cfg(feature = "flamegraph")]
415        if let Some(ref grapher) = self.flamegrapher {
416            use abscissa_core::FrameworkErrorKind;
417
418            info!("writing flamegraph");
419
420            grapher
421                .write_flamegraph()
422                .map_err(|e| FrameworkErrorKind::ComponentError.context(e))?
423        }
424
425        #[cfg(feature = "progress-bar")]
426        howudoin::disable();
427
428        Ok(())
429    }
430}
431
432impl Drop for Tracing {
433    fn drop(&mut self) {
434        #[cfg(feature = "progress-bar")]
435        howudoin::disable();
436    }
437}
438
439// Visitor to extract only the "message" field from a log event.
440struct MessageVisitor {
441    message: Option<String>,
442}
443
444impl Visit for MessageVisitor {
445    fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) {
446        if field.name() == "message" {
447            self.message = Some(format!("{value:?}"));
448        }
449    }
450}
451
452// Layer to store the last WARN or ERROR log event.
453#[derive(Debug, Clone)]
454struct LastWarnErrorLayer {
455    last_warn_error_sender: watch::Sender<Option<(String, Level, chrono::DateTime<chrono::Utc>)>>,
456}
457
458impl<S> Layer<S> for LastWarnErrorLayer
459where
460    S: tracing::Subscriber + for<'lookup> tracing_subscriber::registry::LookupSpan<'lookup>,
461{
462    fn on_event(
463        &self,
464        event: &tracing::Event<'_>,
465        _ctx: tracing_subscriber::layer::Context<'_, S>,
466    ) {
467        let level = *event.metadata().level();
468        let timestamp = chrono::Utc::now();
469
470        if level == Level::WARN || level == Level::ERROR {
471            let mut visitor = MessageVisitor { message: None };
472            event.record(&mut visitor);
473
474            if let Some(message) = visitor.message {
475                let _ = self
476                    .last_warn_error_sender
477                    .send(Some((message, level, timestamp)));
478            }
479        }
480    }
481}