1
//! Configure tracing subscribers for Arti
2

            
3
use anyhow::{Context, Result, anyhow};
4
use derive_deftly::Deftly;
5
use fs_mistrust::Mistrust;
6
use serde::{Deserialize, Serialize};
7
use std::io::IsTerminal as _;
8
use std::path::Path;
9
use std::str::FromStr;
10
use tor_basic_utils::PathExt as _;
11
use tor_config::ConfigBuildError;
12
use tor_config_shared::opentelemetry::{OpentelemetryConfig, OpentelemetryConfigBuilder};
13
use tor_config::derive::prelude::*;
14
use tor_config_path::{CfgPath, CfgPathResolver};
15
use tor_error::warn_report;
16
use tracing::{Subscriber, error};
17
use tracing_appender::non_blocking::WorkerGuard;
18
use tracing_subscriber::layer::SubscriberExt;
19
use tracing_subscriber::prelude::*;
20
use tracing_subscriber::{Layer, filter::Targets, fmt, registry};
21

            
22
mod fields;
23
mod time;
24

            
25
/// Structure to hold our logging configuration options
26
#[derive(Debug, Clone, Deftly, Eq, PartialEq)]
27
#[derive_deftly(TorConfig)]
28
#[cfg_attr(feature = "experimental-api", visibility::make(pub))]
29
#[cfg_attr(feature = "experimental-api", deftly(tor_config(vis = "pub")))]
30
pub(crate) struct LoggingConfig {
31
    /// Filtering directives that determine tracing levels as described at
32
    /// <https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/targets/struct.Targets.html#impl-FromStr>
33
    ///
34
    /// You can override this setting with the -l, --log-level command line parameter.
35
    ///
36
    /// Example: "info,tor_proto::channel=trace"
37
    #[deftly(tor_config(default = "default_console_filter()"))]
38
    console: Option<String>,
39

            
40
    /// Filtering directives for the journald logger.
41
    ///
42
    /// Only takes effect if Arti is built with the `journald` filter.
43
    #[deftly(tor_config(
44
        build = r#"|this: &Self| tor_config::resolve_option(&this.journald, || None)"#
45
    ))]
46
    journald: Option<String>,
47

            
48
    /// Filtering directives for the syslog logger.
49
    ///
50
    /// Only takes effect if Arti is built with the `syslog` feature.
51
    #[deftly(tor_config(
52
        cfg = r#"all(feature = "syslog", unix)"#,
53
        cfg_desc = "with syslog support",
54
        default = r#"Some("".into())"#,
55
    ))]
56
    syslog: Option<String>,
57

            
58
    /// Configuration for logging spans with OpenTelemetry.
59
    #[deftly(tor_config(
60
        sub_builder,
61
        cfg = r#" feature = "opentelemetry" "#,
62
        cfg_desc = "with opentelemetry support"
63
    ))]
64
    opentelemetry: OpentelemetryConfig,
65

            
66
    /// Configuration for passing information to tokio-console.
67
    #[deftly(tor_config(
68
        sub_builder,
69
        cfg = r#" feature = "tokio-console" "#,
70
        cfg_desc = "with tokio-console support"
71
    ))]
72
    tokio_console: TokioConsoleConfig,
73

            
74
    /// Configuration for one or more logfiles.
75
    ///
76
    /// The default is not to log to any files.
77
    #[deftly(tor_config(list(element(build), listtype = "LogfileList"), default = "vec![]"))]
78
    files: Vec<LogfileConfig>,
79

            
80
    /// If set to true, we disable safe logging on _all logs_, and store
81
    /// potentially sensitive information at level `info` or higher.
82
    ///
83
    /// This can be useful for debugging, but it increases the value of your
84
    /// logs to an attacker.  Do not turn this on in production unless you have
85
    /// a good log rotation mechanism.
86
    //
87
    // TODO: Eventually we might want to make this more complex, and add a
88
    // per-log mechanism to turn off unsafe logging. Alternatively, we might do
89
    // that by extending the filter syntax implemented by `tracing` to have an
90
    // "unsafe" flag on particular lines.
91
    #[deftly(tor_config(default))]
92
    log_sensitive_information: bool,
93

            
94
    /// If set to true, promote Tor protocol-violation reports to warning level.
95
    #[deftly(tor_config(default))]
96
    protocol_warnings: bool,
97

            
98
    /// An approximate granularity with which log times should be displayed.
99
    ///
100
    /// This value controls every log time that arti outputs; it doesn't have any
101
    /// effect on times written by other logging programs like `journald`.
102
    ///
103
    /// We may round this value up for convenience: For example, if you say
104
    /// "2.5s", we may treat it as if you had said "3s."
105
    ///
106
    /// The default is "1s", or one second.
107
    #[deftly(tor_config(default = "std::time::Duration::new(1,0)"))]
108
    time_granularity: std::time::Duration,
109
}
110

            
111
/// Return a default tracing filter value for `logging.console`.
112
#[allow(clippy::unnecessary_wraps)]
113
76
fn default_console_filter() -> Option<String> {
114
76
    Some("info".to_owned())
115
76
}
116

            
117
/// Configuration information for an (optionally rotating) logfile.
118
#[derive(Debug, Deftly, Clone, Eq, PartialEq)]
119
#[derive_deftly(TorConfig)]
120
#[deftly(tor_config(no_default_trait))]
121
#[cfg_attr(feature = "experimental-api", visibility::make(pub))]
122
#[cfg_attr(feature = "experimental-api", deftly(tor_config(vis = "pub")))]
123
pub(crate) struct LogfileConfig {
124
    /// How often to rotate the file?
125
    #[deftly(tor_config(default))]
126
    rotate: LogRotation,
127
    /// Where to write the files?
128
    #[deftly(tor_config(no_default))]
129
    path: CfgPath,
130
    /// Filter to apply before writing
131
    #[deftly(tor_config(no_default))]
132
    filter: String,
133
}
134

            
135
/// How often to rotate a log file
136
#[derive(Debug, Default, Clone, Serialize, Deserialize, Copy, Eq, PartialEq)]
137
#[non_exhaustive]
138
#[serde(rename_all = "lowercase")]
139
#[cfg_attr(feature = "experimental-api", visibility::make(pub))]
140
pub(crate) enum LogRotation {
141
    /// Rotate logs daily
142
    Daily,
143
    /// Rotate logs hourly
144
    Hourly,
145
    /// Never rotate the log
146
    #[default]
147
    Never,
148
}
149

            
150
/// Configuration for logging to the tokio console.
151
#[derive(Debug, Deftly, Copy, Clone, Eq, PartialEq, Serialize, Deserialize)]
152
#[derive_deftly(TorConfig)]
153
#[cfg(feature = "tokio-console")]
154
#[cfg_attr(feature = "experimental-api", visibility::make(pub))]
155
#[cfg_attr(feature = "experimental-api", deftly(tor_config(vis = "pub")))]
156
pub(crate) struct TokioConsoleConfig {
157
    /// If true, the tokio console subscriber should be enabled.
158
    ///
159
    /// This requires that tokio (and hence arti) is built with `--cfg tokio_unstable`
160
    /// in RUSTFLAGS.
161
    #[deftly(tor_config(default))]
162
    enabled: bool,
163
}
164

            
165
/// Placeholder for unused tokio console config.
166
#[cfg(not(feature = "tokio-console"))]
167
type TokioConsoleConfig = ();
168

            
169
/// As [`Targets::from_str`], but wrapped in an [`anyhow::Result`].
170
//
171
// (Note that we have to use `Targets`, not `EnvFilter`: see comment in
172
// `setup_logging()`.)
173
276
fn filt_from_str_verbose(s: &str, source: &str) -> Result<Targets> {
174
276
    Targets::from_str(s).with_context(|| format!("in {}", source))
175
276
}
176

            
177
/// As filt_from_str_verbose, but treat an absent filter (or an empty string) as
178
/// None.
179
828
fn filt_from_opt_str(s: &Option<String>, source: &str) -> Result<Option<Targets>> {
180
552
    Ok(match s {
181
552
        Some(s) if !s.is_empty() => Some(filt_from_str_verbose(s, source)?),
182
552
        _ => None,
183
    })
184
828
}
185

            
186
/// Try to construct a tracing [`Layer`] for logging to stderr.
187
276
fn console_layer<S>(config: &LoggingConfig, cli: Option<&str>) -> Result<impl Layer<S> + use<S>>
188
276
where
189
276
    S: Subscriber + for<'span> tracing_subscriber::registry::LookupSpan<'span>,
190
{
191
276
    let timer = time::new_formatter(config.time_granularity);
192
276
    let filter = cli
193
276
        .map(|s| filt_from_str_verbose(s, "--log-level command line parameter"))
194
276
        .or_else(|| filt_from_opt_str(&config.console, "logging.console").transpose())
195
276
        .unwrap_or_else(|| Ok(Targets::from_str("debug").expect("bad default")))?;
196
276
    let use_color = std::io::stderr().is_terminal();
197
    // We used to suppress safe-logging on the console, but we removed that
198
    // feature: we cannot be certain that the console really is volatile. Even
199
    // if isatty() returns true on the console, we can't be sure that the
200
    // terminal isn't saving backlog to disk or something like that.
201
276
    Ok(fmt::Layer::default()
202
276
        // we apply custom field formatting so that error fields are listed last
203
276
        .fmt_fields(fields::ErrorsLastFieldFormatter)
204
276
        .with_ansi(use_color)
205
276
        .with_timer(timer)
206
276
        .with_writer(std::io::stderr) // we make this explicit, to match with use_color.
207
276
        .with_filter(filter))
208
276
}
209

            
210
/// Try to construct a tracing [`Layer`] for logging to journald, if one is
211
/// configured.
212
#[cfg(feature = "journald")]
213
276
fn journald_layer<S>(config: &LoggingConfig) -> Result<impl Layer<S>>
214
276
where
215
276
    S: Subscriber + for<'span> tracing_subscriber::registry::LookupSpan<'span>,
216
{
217
276
    if let Some(filter) = filt_from_opt_str(&config.journald, "logging.journald")? {
218
        Ok(Some(tracing_journald::layer()?.with_filter(filter)))
219
    } else {
220
        // Fortunately, Option<Layer> implements Layer, so we can just return None here.
221
276
        Ok(None)
222
    }
223
276
}
224

            
225
/// Try to construct a tracing [`Layer`] for logging to syslog, if one is
226
/// configured.
227
#[cfg(all(feature = "syslog", unix))]
228
276
fn syslog_layer<S>(config: &LoggingConfig) -> Result<impl Layer<S>>
229
276
where
230
276
    S: Subscriber + for<'span> tracing_subscriber::registry::LookupSpan<'span>,
231
{
232
    use syslog_tracing::{Facility, Options, Syslog};
233

            
234
276
    let identity = c"arti";
235

            
236
276
    if let Some(filter) = filt_from_opt_str(&config.syslog, "logging.syslog")? {
237
        let options = Options::LOG_PID;
238
        let facility = Facility::Daemon;
239

            
240
        let syslog_maker = Syslog::new(identity, options, facility).ok_or_else(|| {
241
            anyhow::anyhow!("syslog already initialized; only one logger allowed")
242
        })?;
243

            
244
        let layer = tracing_subscriber::fmt::layer()
245
            .with_writer(syslog_maker)
246
            // Syslog doesn't support ANSI colors, and we usually want
247
            // the system log to handle the timestamping.
248
            .with_ansi(false)
249
            .without_time()
250
            .with_filter(filter);
251

            
252
        Ok(Some(layer))
253
    } else {
254
276
        Ok(None)
255
    }
256
276
}
257

            
258
/// Try to construct a tracing [`Layer`] for exporting spans via OpenTelemetry.
259
///
260
/// This doesn't allow for filtering, since most of our spans are exported at the trace level
261
/// anyways, and filtering can easily be done when viewing the data.
262
#[cfg(feature = "opentelemetry")]
263
276
fn otel_layer<S>(config: &LoggingConfig, path_resolver: &CfgPathResolver) -> Result<impl Layer<S>>
264
276
where
265
276
    S: Subscriber + for<'span> tracing_subscriber::registry::LookupSpan<'span>,
266
{
267
    use opentelemetry::trace::TracerProvider;
268
    use opentelemetry_otlp::WithExportConfig;
269

            
270
276
    if config.opentelemetry.file().is_some() && config.opentelemetry.http().is_some() {
271
        return Err(ConfigBuildError::Invalid {
272
            field: "logging.opentelemetry".into(),
273
            problem: "Only one OpenTelemetry exporter can be enabled at once.".into(),
274
        }
275
        .into());
276
276
    }
277

            
278
276
    let resource = opentelemetry_sdk::Resource::builder()
279
276
        .with_service_name("arti")
280
276
        .build();
281

            
282
276
    let span_processor = if let Some(otel_file_config) = &config.opentelemetry.file() {
283
        let file = std::fs::File::options()
284
            .create(true)
285
            .append(true)
286
            .open(otel_file_config.path().path(path_resolver)?)?;
287

            
288
        let exporter = otlp_file_exporter::FileExporter::new(file, resource.clone());
289

            
290
        opentelemetry_sdk::trace::BatchSpanProcessor::builder(exporter)
291
            .with_batch_config(otel_file_config.batch().clone().into())
292
            .build()
293
276
    } else if let Some(otel_http_config) = &config.opentelemetry.http() {
294
        if otel_http_config.endpoint().starts_with("http://")
295
            && !(otel_http_config.endpoint().starts_with("http://localhost")
296
                || otel_http_config.endpoint().starts_with("http://127.0.0.1"))
297
        {
298
            return Err(ConfigBuildError::Invalid {
299
                field: "logging.opentelemetry.http.endpoint".into(),
300
                problem: "OpenTelemetry endpoint is set to HTTP on a non-localhost address! For security reasons, this is not supported.".into(),
301
            }
302
            .into());
303
        }
304
        let exporter = opentelemetry_otlp::SpanExporter::builder()
305
            .with_http()
306
            .with_endpoint(otel_http_config.endpoint().clone())
307
            .with_timeout(*otel_http_config.timeout())
308
            .build()?;
309

            
310
        opentelemetry_sdk::trace::BatchSpanProcessor::builder(exporter)
311
            .with_batch_config(otel_http_config.batch().clone().into())
312
            .build()
313
    } else {
314
276
        return Ok(None);
315
    };
316

            
317
    let tracer_provider = opentelemetry_sdk::trace::SdkTracerProvider::builder()
318
        .with_resource(resource.clone())
319
        .with_span_processor(span_processor)
320
        .build();
321

            
322
    let tracer = tracer_provider.tracer("otel_file_tracer");
323

            
324
    Ok(Some(tracing_opentelemetry::layer().with_tracer(tracer)))
325
276
}
326

            
327
/// Try to construct a non-blocking tracing [`Layer`] for writing data to an
328
/// optionally rotating logfile.
329
///
330
/// On success, return that layer, along with a WorkerGuard that needs to be
331
/// dropped when the program exits, to flush buffered messages.
332
fn logfile_layer<S>(
333
    config: &LogfileConfig,
334
    granularity: std::time::Duration,
335
    mistrust: &Mistrust,
336
    path_resolver: &CfgPathResolver,
337
) -> Result<(impl Layer<S> + Send + Sync + Sized + use<S>, WorkerGuard)>
338
where
339
    S: Subscriber + for<'span> tracing_subscriber::registry::LookupSpan<'span> + Send + Sync,
340
{
341
    use tracing_appender::{
342
        non_blocking,
343
        rolling::{RollingFileAppender, Rotation},
344
    };
345
    let timer = time::new_formatter(granularity);
346

            
347
    let filter = filt_from_str_verbose(&config.filter, "logging.files.filter")?;
348
    let rotation = match config.rotate {
349
        LogRotation::Daily => Rotation::DAILY,
350
        LogRotation::Hourly => Rotation::HOURLY,
351
        _ => Rotation::NEVER,
352
    };
353
    let path = config.path.path(path_resolver)?;
354

            
355
    let directory = match path.parent() {
356
        None => {
357
            return Err(anyhow!(
358
                "Logfile path \"{}\" did not have a parent directory",
359
                path.display_lossy()
360
            ));
361
        }
362
        Some(p) if p == Path::new("") => Path::new("."),
363
        Some(d) => d,
364
    };
365
    mistrust.make_directory(directory).with_context(|| {
366
        format!(
367
            "Unable to create parent directory for logfile \"{}\"",
368
            path.display_lossy()
369
        )
370
    })?;
371
    let fname = path
372
        .file_name()
373
        .ok_or_else(|| anyhow!("No path for log file"))
374
        .map(Path::new)?;
375

            
376
    let appender = RollingFileAppender::new(rotation, directory, fname);
377
    let (nonblocking, guard) = non_blocking(appender);
378
    let layer = fmt::layer()
379
        // we apply custom field formatting so that error fields are listed last
380
        .fmt_fields(fields::ErrorsLastFieldFormatter)
381
        .with_ansi(false)
382
        .with_writer(nonblocking)
383
        .with_timer(timer)
384
        .with_filter(filter);
385
    Ok((layer, guard))
386
}
387

            
388
/// Try to construct a tracing [`Layer`] for all of the configured logfiles.
389
///
390
/// On success, return that layer along with a list of [`WorkerGuard`]s that
391
/// need to be dropped when the program exits.
392
276
fn logfile_layers<S>(
393
276
    config: &LoggingConfig,
394
276
    mistrust: &Mistrust,
395
276
    path_resolver: &CfgPathResolver,
396
276
) -> Result<(impl Layer<S> + use<S>, Vec<WorkerGuard>)>
397
276
where
398
276
    S: Subscriber + for<'span> tracing_subscriber::registry::LookupSpan<'span> + Send + Sync,
399
{
400
276
    let mut guards = Vec::new();
401
276
    if config.files.is_empty() {
402
        // As above, we have Option<Layer> implements Layer, so we can return
403
        // None in this case.
404
276
        return Ok((None, guards));
405
    }
406

            
407
    let (layer, guard) = logfile_layer(
408
        &config.files[0],
409
        config.time_granularity,
410
        mistrust,
411
        path_resolver,
412
    )?;
413
    guards.push(guard);
414

            
415
    // We have to use a dyn pointer here so we can build up linked list of
416
    // arbitrary depth.
417
    let mut layer: Box<dyn Layer<S> + Send + Sync + 'static> = Box::new(layer);
418

            
419
    for logfile in &config.files[1..] {
420
        let (new_layer, guard) =
421
            logfile_layer(logfile, config.time_granularity, mistrust, path_resolver)?;
422
        layer = Box::new(layer.and_then(new_layer));
423
        guards.push(guard);
424
    }
425

            
426
    Ok((Some(layer), guards))
427
276
}
428

            
429
/// Configure a panic handler to send everything to tracing, in addition to our
430
/// default panic behavior.
431
276
fn install_panic_handler() {
432
    // TODO library support: There's a library called `tracing-panic` that
433
    // provides a hook we could use instead, but that doesn't have backtrace
434
    // support.  We should consider using it if it gets backtrace support in the
435
    // future.  We should also keep an eye on `tracing` to see if it learns how
436
    // to do this for us.
437
276
    let default_handler = std::panic::take_hook();
438
276
    std::panic::set_hook(Box::new(move |panic_info| {
439
        // Note that if we were ever to _not_ call this handler,
440
        // we would want to abort on nested panics and !can_unwind cases.
441
        default_handler(panic_info);
442

            
443
        // This statement is copied from stdlib.
444
        let msg = match panic_info.payload().downcast_ref::<&'static str>() {
445
            Some(s) => *s,
446
            None => match panic_info.payload().downcast_ref::<String>() {
447
                Some(s) => s.as_str(),
448
                None => "Box<dyn Any>",
449
            },
450
        };
451

            
452
        let backtrace = std::backtrace::Backtrace::force_capture();
453
        match panic_info.location() {
454
            Some(location) => error!("Panic at {}: {}\n{}", location, msg, backtrace),
455
            None => error!("Panic at ???: {}\n{}", msg, backtrace),
456
        };
457
    }));
458
276
}
459

            
460
/// Opaque structure that gets dropped when the program is shutting down,
461
/// after logs are no longer needed.  The `Drop` impl flushes buffered messages.
462
#[cfg_attr(feature = "experimental-api", visibility::make(pub))]
463
pub(crate) struct LogGuards {
464
    /// The actual list of guards we're returning.
465
    #[allow(unused)]
466
    guards: Vec<WorkerGuard>,
467

            
468
    /// A safelog guard, for use if we have decided to disable safe logging.
469
    #[allow(unused)]
470
    safelog_guard: Option<safelog::Guard>,
471
}
472

            
473
/// Set up logging.
474
///
475
/// Note that the returned LogGuard must be dropped precisely when the program
476
/// quits; they're used to ensure that all the log messages are flushed.
477
276
#[cfg_attr(feature = "experimental-api", visibility::make(pub))]
478
276
#[cfg_attr(docsrs, doc(cfg(feature = "experimental-api")))]
479
276
pub(crate) fn setup_logging(
480
276
    config: &LoggingConfig,
481
276
    mistrust: &Mistrust,
482
276
    path_resolver: &CfgPathResolver,
483
276
    cli: Option<&str>,
484
276
) -> Result<LogGuards> {
485
    // Important: We have to make sure that the individual layers we add here
486
    // are not filters themselves.  That means, for example, that we can't add
487
    // an `EnvFilter` layer unless we want it to apply globally to _all_ layers.
488
    //
489
    // For a bit of discussion on the difference between per-layer filters and filters
490
    // that apply to the entire registry, see
491
    // https://docs.rs/tracing-subscriber/0.3.5/tracing_subscriber/layer/index.html#global-filtering
492

            
493
276
    let registry = registry().with(console_layer(config, cli)?);
494

            
495
    #[cfg(feature = "journald")]
496
276
    let registry = registry.with(journald_layer(config)?);
497

            
498
    #[cfg(all(feature = "syslog", unix))]
499
276
    let registry = registry.with(syslog_layer(config)?);
500

            
501
    #[cfg(feature = "opentelemetry")]
502
276
    let registry = registry.with(otel_layer(config, path_resolver)?);
503

            
504
    #[cfg(feature = "tokio-console")]
505
276
    let registry = {
506
        // Note 1: We can't enable console_subscriber unconditionally when the `tokio-console`
507
        // feature is enabled, since it panics unless tokio is built with  `--cfg tokio_unstable`,
508
        // but we want arti to work with --all-features without any special --cfg.
509
        //
510
        // Note 2: We have to use an `Option` here, since the type of the registry changes
511
        // with whatever you add to it.
512
276
        let tokio_layer = if config.tokio_console.enabled {
513
            Some(console_subscriber::spawn())
514
        } else {
515
276
            None
516
        };
517
276
        registry.with(tokio_layer)
518
    };
519

            
520
276
    let (layer, guards) = logfile_layers(config, mistrust, path_resolver)?;
521
276
    let registry = registry.with(layer);
522

            
523
276
    registry.init();
524

            
525
276
    let safelog_guard = if config.log_sensitive_information {
526
        match safelog::disable_safe_logging() {
527
            Ok(guard) => Some(guard),
528
            Err(e) => {
529
                // We don't need to propagate this error; it isn't the end of
530
                // the world if we were unable to disable safe logging.
531
                warn_report!(e, "Unable to disable safe logging");
532
                None
533
            }
534
        }
535
    } else {
536
276
        None
537
    };
538

            
539
276
    let mode = if config.protocol_warnings {
540
        tor_error::tracing::ProtocolWarningMode::Warn
541
    } else {
542
276
        tor_error::tracing::ProtocolWarningMode::Off
543
    };
544
276
    tor_error::tracing::set_protocol_warning_mode(mode);
545

            
546
276
    install_panic_handler();
547

            
548
276
    Ok(LogGuards {
549
276
        guards,
550
276
        safelog_guard,
551
276
    })
552
276
}