ant_logging/
lib.rs

1// Copyright 2024 MaidSafe.net limited.
2//
3// This SAFE Network Software is licensed to you under The General Public License (GPL), version 3.
4// Unless required by applicable law or agreed to in writing, the SAFE Network Software distributed
5// under the GPL Licence is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
6// KIND, either express or implied. Please review the Licences for the specific language governing
7// permissions and limitations relating to use of the SAFE Network Software.
8
9// Allow expect usage in logging initialization
10#![allow(clippy::expect_used)]
11// Allow enum variant names that end with Error as they come from external derives
12#![allow(clippy::enum_variant_names)]
13
14mod appender;
15mod error;
16mod layers;
17#[cfg(feature = "process-metrics")]
18pub mod metrics;
19
20use crate::error::Result;
21use layers::TracingLayers;
22use serde::{Deserialize, Serialize};
23use std::path::PathBuf;
24use tracing::info;
25use tracing_core::dispatcher::DefaultGuard;
26use tracing_subscriber::{prelude::__tracing_subscriber_SubscriberExt, util::SubscriberInitExt};
27
28pub use error::Error;
29pub use layers::ReloadHandle;
30pub use tracing_appender::non_blocking::WorkerGuard;
31
32// re-exporting the tracing crate's Level as it is used in our public API
33pub use tracing_core::Level;
34
35#[derive(Debug, Clone)]
36pub enum LogOutputDest {
37    /// Log to standard error
38    Stderr,
39    /// Log to standard output
40    Stdout,
41    /// If a path with .log extension is provided, log to that file.
42    ///
43    /// If a directory path is provided, log with file rotation enabled in that directory.
44    ///
45    /// If the directory does not exist, it will be created.
46    Path(PathBuf),
47}
48
49impl LogOutputDest {
50    pub fn parse_from_str(val: &str) -> Result<Self> {
51        match val {
52            "stdout" => Ok(LogOutputDest::Stdout),
53            "data-dir" => {
54                // Get the current timestamp and format it to be human readable
55                let timestamp = chrono::Local::now().format("%Y-%m-%d_%H-%M-%S").to_string();
56
57                // Get the data directory path and append the timestamp to the log file name
58                let dir = match dirs_next::data_dir() {
59                    Some(dir) => dir
60                        .join("autonomi")
61                        .join("client")
62                        .join("logs")
63                        .join(format!("log_{timestamp}")),
64                    None => {
65                        return Err(Error::LoggingConfiguration(
66                            "could not obtain data directory path".to_string(),
67                        ));
68                    }
69                };
70                Ok(LogOutputDest::Path(dir))
71            }
72            // The path should be a directory, but we can't use something like `is_dir` to check
73            // because the path doesn't need to exist. We can create it for the user.
74            value => Ok(LogOutputDest::Path(PathBuf::from(value))),
75        }
76    }
77}
78
79impl std::fmt::Display for LogOutputDest {
80    fn fmt(&self, f: &mut std::fmt::Formatter) -> std::fmt::Result {
81        match self {
82            LogOutputDest::Stderr => write!(f, "stderr"),
83            LogOutputDest::Stdout => write!(f, "stdout"),
84            LogOutputDest::Path(p) => write!(f, "{}", p.to_string_lossy()),
85        }
86    }
87}
88
89#[derive(Debug, Clone, Copy, Serialize, Deserialize, PartialEq, Eq)]
90pub enum LogFormat {
91    Default,
92    Json,
93}
94
95impl LogFormat {
96    pub fn parse_from_str(val: &str) -> Result<Self> {
97        match val {
98            "default" => Ok(LogFormat::Default),
99            "json" => Ok(LogFormat::Json),
100            _ => Err(Error::LoggingConfiguration(
101                "The only valid values for this argument are \"default\" or \"json\"".to_string(),
102            )),
103        }
104    }
105
106    pub fn as_str(&self) -> &'static str {
107        match self {
108            LogFormat::Default => "default",
109            LogFormat::Json => "json",
110        }
111    }
112}
113
114pub struct LogBuilder {
115    default_logging_targets: Vec<(String, Level)>,
116    output_dest: LogOutputDest,
117    format: LogFormat,
118    max_log_files: Option<usize>,
119    max_archived_log_files: Option<usize>,
120    /// Setting this would print the ant_logging related updates to stdout.
121    print_updates_to_stdout: bool,
122}
123
124impl LogBuilder {
125    /// Create a new builder
126    /// Provide the default_logging_targets that are used if the `ANT_LOG` env variable is not set.
127    ///
128    /// By default, we use log to the StdOut with the default format.
129    pub fn new(default_logging_targets: Vec<(String, Level)>) -> Self {
130        Self {
131            default_logging_targets,
132            output_dest: LogOutputDest::Stderr,
133            format: LogFormat::Default,
134            max_log_files: None,
135            max_archived_log_files: None,
136            print_updates_to_stdout: true,
137        }
138    }
139
140    /// Set the logging output destination
141    pub fn output_dest(&mut self, output_dest: LogOutputDest) {
142        self.output_dest = output_dest;
143    }
144
145    /// Set the logging format
146    pub fn format(&mut self, format: LogFormat) {
147        self.format = format
148    }
149
150    /// The max number of uncompressed log files to store
151    pub fn max_log_files(&mut self, files: usize) {
152        self.max_log_files = Some(files);
153    }
154
155    /// The max number of compressed files to store
156    pub fn max_archived_log_files(&mut self, files: usize) {
157        self.max_archived_log_files = Some(files);
158    }
159
160    /// Setting this to false would prevent ant_logging from printing things to stdout.
161    pub fn print_updates_to_stdout(&mut self, print: bool) {
162        self.print_updates_to_stdout = print;
163    }
164
165    /// Inits node logging, returning the NonBlocking guard if present.
166    /// This guard should be held for the life of the program.
167    ///
168    /// Logging should be instantiated only once.
169    pub fn initialize(self) -> Result<(ReloadHandle, Option<WorkerGuard>)> {
170        let mut layers = TracingLayers::default();
171
172        let reload_handle = layers.fmt_layer(
173            self.default_logging_targets.clone(),
174            &self.output_dest,
175            self.format,
176            self.max_log_files,
177            self.max_archived_log_files,
178            self.print_updates_to_stdout,
179        )?;
180
181        #[cfg(feature = "otlp")]
182        {
183            match std::env::var("OTEL_EXPORTER_OTLP_ENDPOINT") {
184                Ok(_) => layers.otlp_layer(self.default_logging_targets)?,
185                Err(_) => println!(
186                    "The OTLP feature is enabled but the OTEL_EXPORTER_OTLP_ENDPOINT variable is not \
187                set, so traces will not be submitted."
188                ),
189            }
190        }
191
192        if tracing_subscriber::registry()
193            .with(layers.layers)
194            .try_init()
195            .is_err()
196        {
197            eprintln!("Tried to initialize and set global default subscriber more than once");
198        }
199
200        Ok((reload_handle, layers.log_appender_guard))
201    }
202
203    /// Logs to the data_dir with per-test log files. Should be called from a single threaded tokio/non-tokio context.
204    /// Each test gets its own log file based on the test name.
205    ///
206    /// This function creates separate log files for each test to avoid mixing logs from different tests.
207    /// The test file name is automatically detected from the test module path.
208    /// subscriber.set_default() should be used if under a single threaded tokio / single threaded non-tokio context.
209    /// Refer here for more details: <https://github.com/tokio-rs/tracing/discussions/1626>
210    pub fn init_single_threaded_tokio_test() -> (Option<WorkerGuard>, DefaultGuard) {
211        let test_name = std::thread::current()
212            .name()
213            .unwrap_or("unknown_test")
214            .to_string();
215
216        // Auto-detect test file name from the test name
217        let test_file_name = Self::extract_test_file_name(&test_name);
218
219        let layers = Self::get_test_layers(&test_name, &test_file_name);
220        let log_guard = tracing_subscriber::registry()
221            .with(layers.layers)
222            .set_default();
223
224        info!("Running test: {test_name}");
225        (layers.log_appender_guard, log_guard)
226    }
227
228    /// Logs to the data_dir. Should be called from a multi threaded tokio context.
229    /// The test file name is automatically detected from the test module path.
230    ///
231    /// subscriber.init() should be used under multi threaded tokio context. If you have 1+ multithreaded tokio tests under
232    /// the same integration test, this might result in loss of logs. Hence use .init() (instead of .try_init()) to panic
233    /// if called more than once.
234    pub fn init_multi_threaded_tokio_test() -> Option<WorkerGuard> {
235        let test_name = std::thread::current()
236            .name()
237            .unwrap_or("unknown_test")
238            .to_string();
239
240        // Auto-detect test file name from the test name
241        let test_file_name = Self::extract_test_file_name(&test_name);
242
243        let layers = Self::get_test_layers(&test_name, &test_file_name);
244        tracing_subscriber::registry()
245        .with(layers.layers)
246        .try_init()
247        .expect("You have tried to init multi_threaded tokio logging twice\nRefer ant_logging::get_test_layers docs for more.");
248
249        layers.log_appender_guard
250    }
251
252    /// Extract the test file name from the test name.
253    /// Test names typically follow the pattern: module::path::test_name
254    /// We extract the module path and use it as the test file name.
255    fn extract_test_file_name(test_name: &str) -> String {
256        let (module_prefix, executable_name, _) = Self::test_name_sources(test_name);
257
258        module_prefix
259            .or(executable_name)
260            .unwrap_or_else(|| test_name.to_string())
261    }
262
263    /// Determine the crate name associated with the test, if possible.
264    fn extract_crate_name(test_name: &str) -> Option<String> {
265        let (module_prefix, executable_name, package_name) = Self::test_name_sources(test_name);
266
267        let module_normalized = module_prefix.as_deref().map(Self::normalized_crate_name);
268        let executable_normalized = executable_name.as_deref().map(Self::normalized_crate_name);
269        let package_normalized = package_name.as_deref().map(Self::normalized_crate_name);
270
271        if let (Some(pkg), Some(module)) = (&package_normalized, &module_normalized)
272            && pkg == module
273        {
274            return Some(pkg.clone());
275        }
276
277        if let (Some(pkg), Some(exe)) = (&package_normalized, &executable_normalized)
278            && pkg == exe
279        {
280            return Some(pkg.clone());
281        }
282
283        if let (Some(module), Some(exe)) = (&module_normalized, &executable_normalized)
284            && module == exe
285        {
286            return Some(module.clone());
287        }
288
289        executable_normalized
290            .or(package_normalized)
291            .or(module_normalized)
292    }
293
294    fn test_name_sources(test_name: &str) -> (Option<String>, Option<String>, Option<String>) {
295        let module_prefix = test_name
296            .split_once("::")
297            .map(|(segment, _)| segment)
298            .filter(|segment| !segment.is_empty())
299            .map(|segment| segment.to_string());
300
301        let executable_name = std::env::current_exe().ok().and_then(|path| {
302            path.file_name().map(|name| {
303                let name = name.to_string_lossy().into_owned();
304                name.split_once('-')
305                    .map(|(prefix, _)| prefix.to_string())
306                    .unwrap_or(name)
307            })
308        });
309
310        let package_name = std::env::var("CARGO_PKG_NAME").ok();
311
312        (module_prefix, executable_name, package_name)
313    }
314
315    fn normalized_crate_name(name: &str) -> String {
316        name.replace('-', "_").to_ascii_lowercase()
317    }
318
319    /// Initialize just the fmt_layer for testing purposes with per-test log files.
320    ///
321    /// Each test gets its own log file based on the test name to avoid mixing logs.
322    /// Also overwrites the ANT_LOG variable to log everything including the test_file_name
323    fn get_test_layers(test_name: &str, test_file_name: &str) -> TracingLayers {
324        let log_pattern = format!("{test_file_name}=TRACE,{test_file_name}::tests=TRACE,all");
325
326        println!("Setting ANT_LOG to: {log_pattern}");
327
328        // SAFETY: This is called during test initialization before any other threads
329        // are spawned, so there's no risk of data races. Setting ANT_LOG is necessary
330        // to configure logging levels for test execution.
331        #[allow(unsafe_code)]
332        unsafe {
333            std::env::set_var("ANT_LOG", log_pattern);
334        }
335
336        let crate_name = std::env::var("CARGO_PKG_NAME")
337            .ok()
338            .or_else(|| Self::extract_crate_name(test_name))
339            .unwrap_or_else(|| "unknown_crate".to_string());
340        let sanitized_crate_name = crate_name.replace("::", "-").replace(" ", "-");
341        let sanitized_test_name = test_name.replace("::", "-").replace(" ", "-");
342
343        let override_dest = std::env::var("ANT_LOG_DEST")
344            .ok()
345            .and_then(|raw| {
346                let value = raw.trim();
347                if value.is_empty() {
348                    return None;
349                }
350                match LogOutputDest::parse_from_str(value) {
351                    Ok(dest) => Some(dest),
352                    Err(err) => {
353                        eprintln!(
354                            "ANT_LOG_DEST='{value}' is invalid ({err}). Falling back to default test log destination."
355                        );
356                        None
357                    }
358                }
359            });
360
361        let output_dest = override_dest.unwrap_or_else(|| {
362            match dirs_next::data_dir() {
363                Some(dir) => {
364                    // Get the current timestamp and format it to be human readable
365                    let timestamp = chrono::Local::now().format("%Y-%m-%d_%H-%M-%S").to_string();
366                    // Create unique filename using test name and timestamp
367                    let path = dir
368                        .join("autonomi")
369                        .join("client")
370                        .join("logs")
371                        .join(format!(
372                            "log-{timestamp}-{sanitized_crate_name}-{sanitized_test_name}.log"
373                        ));
374                    LogOutputDest::Path(path)
375                }
376                None => LogOutputDest::Stdout,
377            }
378        });
379
380        println!(
381            "Logging test {test_name:?} from {test_file_name:?} (crate {crate_name:?}) to {output_dest:?}"
382        );
383
384        let mut layers = TracingLayers::default();
385
386        let _reload_handle = layers
387            .fmt_layer(vec![], &output_dest, LogFormat::Default, None, None, false)
388            .expect("Failed to get TracingLayers");
389        layers
390    }
391}
392
393#[cfg(test)]
394mod tests {
395    use crate::{LogBuilder, ReloadHandle, layers::LogFormatter};
396    use color_eyre::Result;
397    use std::sync::{Mutex, OnceLock};
398    use tracing::{Level, trace, warn};
399    use tracing_subscriber::{
400        Layer, Registry,
401        filter::Targets,
402        fmt as tracing_fmt,
403        layer::{Filter, SubscriberExt},
404        reload,
405        util::SubscriberInitExt,
406    };
407    use tracing_test::internal::global_buf;
408
409    static ENV_LOCK: OnceLock<Mutex<()>> = OnceLock::new();
410
411    struct EnvVarGuard {
412        key: String,
413        previous: Option<String>,
414    }
415
416    impl EnvVarGuard {
417        fn set(key: &str, value: &str) -> Self {
418            let previous = std::env::var(key).ok();
419            #[allow(unsafe_code)]
420            unsafe {
421                std::env::set_var(key, value);
422            }
423            Self {
424                key: key.to_owned(),
425                previous,
426            }
427        }
428    }
429
430    impl Drop for EnvVarGuard {
431        fn drop(&mut self) {
432            if let Some(previous) = &self.previous {
433                #[allow(unsafe_code)]
434                unsafe {
435                    std::env::set_var(&self.key, previous);
436                }
437            } else {
438                #[allow(unsafe_code)]
439                unsafe {
440                    std::env::remove_var(&self.key);
441                }
442            }
443        }
444    }
445
446    fn lock_env() -> std::sync::MutexGuard<'static, ()> {
447        ENV_LOCK
448            .get_or_init(|| Mutex::new(()))
449            .lock()
450            .expect("env mutex poisoned")
451    }
452
453    fn current_executable_base() -> String {
454        let exe = std::env::current_exe().expect("executable path available");
455        let file_name = exe.file_name().expect("executable name available");
456        let name = file_name.to_string_lossy().into_owned();
457        name.split_once('-')
458            .map(|(prefix, _)| prefix.to_string())
459            .unwrap_or(name)
460    }
461
462    #[test]
463    fn extract_crate_name_prefers_executable_for_unit_like_tests() {
464        let expected = LogBuilder::normalized_crate_name(&current_executable_base());
465
466        let detected = LogBuilder::extract_crate_name("client::tests::some_unit_test")
467            .expect("crate name should be detected");
468
469        assert_eq!(detected, expected);
470    }
471
472    #[test]
473    fn extract_crate_name_handles_structured_paths() {
474        let detected =
475            LogBuilder::extract_crate_name("ant_logging::tests::structured_test").unwrap();
476
477        assert_eq!(detected, "ant_logging");
478    }
479
480    #[test]
481    fn extract_test_file_name_prefers_module_prefix() {
482        let file_name = LogBuilder::extract_test_file_name("mock_crate::tests::takes_module");
483        assert_eq!(file_name, "mock_crate");
484    }
485
486    #[test]
487    fn extract_test_file_name_falls_back_to_executable() {
488        let expected = current_executable_base();
489        let file_name = LogBuilder::extract_test_file_name("no_module_name");
490        assert_eq!(file_name, expected);
491    }
492
493    #[test]
494    fn extract_crate_name_prefers_package_when_matching_module() {
495        let _lock = lock_env();
496        let _env_guard = EnvVarGuard::set("CARGO_PKG_NAME", "mock-crate");
497
498        let detected =
499            LogBuilder::extract_crate_name("mock_crate::tests::unit").expect("crate name");
500
501        assert_eq!(detected, "mock_crate");
502    }
503
504    #[test]
505    fn extract_crate_name_prefers_package_when_matching_executable() {
506        let expected = LogBuilder::normalized_crate_name(&current_executable_base());
507        let _lock = lock_env();
508        let _env_guard = EnvVarGuard::set("CARGO_PKG_NAME", &expected);
509
510        let detected = LogBuilder::extract_crate_name("other_module::tests::unit").unwrap();
511
512        assert_eq!(detected, expected);
513    }
514
515    #[test]
516    fn extract_crate_name_prefers_module_when_exe_matches_but_package_differs() {
517        let expected = LogBuilder::normalized_crate_name(&current_executable_base());
518        let _lock = lock_env();
519        let _env_guard = EnvVarGuard::set("CARGO_PKG_NAME", "different-package");
520
521        let mut owned_name = expected.clone();
522        owned_name.push_str("::tests::unit");
523        let detected = LogBuilder::extract_crate_name(&owned_name).unwrap();
524
525        assert_eq!(detected, expected);
526    }
527
528    #[test]
529    // todo: break down the TracingLayers so that we can plug in the writer without having to rewrite the whole function
530    // here.
531    fn reload_handle_should_change_log_levels() -> Result<()> {
532        // A mock write that writes to stdout + collects events to a global buffer. We can later read from this buffer.
533        let mock_writer = tracing_test::internal::MockWriter::new(global_buf());
534
535        // Constructing the fmt layer manually.
536        let layer = tracing_fmt::layer()
537            .with_ansi(false)
538            .with_target(false)
539            .event_format(LogFormatter)
540            .with_writer(mock_writer)
541            .boxed();
542
543        let test_target = "ant_logging::tests".to_string();
544        // to enable logs just for the test.
545        let target_filters: Box<dyn Filter<Registry> + Send + Sync> =
546            Box::new(Targets::new().with_targets(vec![(test_target.clone(), Level::TRACE)]));
547
548        // add the reload layer
549        let (filter, handle) = reload::Layer::new(target_filters);
550        let reload_handle = ReloadHandle(handle);
551        let layer = layer.with_filter(filter);
552        tracing_subscriber::registry().with(layer).try_init()?;
553
554        // Span is not controlled by the ReloadHandle. So we can set any span here.
555        let _span = tracing::info_span!("info span");
556
557        trace!("First trace event");
558
559        {
560            let buf = global_buf().lock().unwrap();
561
562            let events: Vec<&str> = std::str::from_utf8(&buf)
563                .expect("Logs contain invalid UTF8")
564                .lines()
565                .collect();
566            assert_eq!(events.len(), 1);
567            assert!(events[0].contains("First trace event"));
568        }
569
570        reload_handle.modify_log_level("ant_logging::tests=WARN")?;
571
572        // trace should not be logged now.
573        trace!("Second trace event");
574        warn!("First warn event");
575
576        {
577            let buf = global_buf().lock().unwrap();
578
579            let events: Vec<&str> = std::str::from_utf8(&buf)
580                .expect("Logs contain invalid UTF8")
581                .lines()
582                .collect();
583
584            assert_eq!(events.len(), 2);
585            assert!(events[0].contains("First trace event"));
586            assert!(events[1].contains("First warn event"));
587        }
588
589        Ok(())
590    }
591}
ant_logging/lib.rs

ant_logging/
lib.rs
