Start using tracing for logging

This follows @pjenvey's suggestion to start by switching the app-level
logger and forward the slog records from the existing code to tracing
events.

Depends on:

- tracing-slog for slog forwarding
- tracing-appender for offloading log writes to a thread
- tracing-subscriber as a framework for event subscription/formatting

I hand-wrote the code to convert tracing events to MozLog entries, since
`tracing-actix-web-mozlog` didn't quite format them how we wanted.

Author: bendk

Cargo.lock

@@ -55,13 +55,12 @@ slog = { version = "2.5", features = [
   "release_max_level_info",
   "dynamic-keys",
 ] }
-slog-async = "2.5"
-slog-envlogger = "2.2.0"
-slog-mozlog-json = "0.1"
 slog-scope = "4.3"
-slog-stdlog = "4.1"
-slog-term = "2.6"
 tokio = "1"
+tracing = "0.1.40"
+tracing-appender = "0.2.3"
+tracing-slog = "0.2.0"
+tracing-subscriber = { version = "0.3.18", features = ["ansi", "env-filter", "json", "registry", "std", "tracing-log"] }
 
 [profile.release]
 # Enables line numbers in Sentry reporting

Cargo.toml

@@ -26,12 +26,11 @@ serde_derive.workspace = true
 serde_json.workspace = true
 sha2.workspace = true
 slog.workspace = true
-slog-async.workspace = true
-slog-envlogger.workspace = true
-slog-mozlog-json.workspace = true
 slog-scope.workspace = true
-slog-stdlog.workspace = true
-slog-term.workspace = true
+tracing.workspace = true
+tracing-appender.workspace = true
+tracing-slog.workspace = true
+tracing-subscriber.workspace = true
 
 actix-http = "3"
 actix-rt = "2"

syncserver/Cargo.toml

@@ -167,6 +167,12 @@ impl From<std::io::Error> for ApiError {
     }
 }
 
+impl From<tracing::subscriber::SetGlobalDefaultError> for ApiError {
+    fn from(_: tracing::subscriber::SetGlobalDefaultError) -> Self {
+        ApiErrorKind::Internal("Logging failed to initialize".to_string()).into()
+    }
+}
+
 impl From<ApiErrorKind> for ApiError {
     fn from(kind: ApiErrorKind) -> Self {
         let status = match &kind {

syncserver/src/error.rs

@@ -0,0 +1,75 @@
+mod mozlog;
+
+use crate::error::ApiResult;
+use slog::{self, slog_o};
+use std::{io::stdout, sync::Once};
+use tracing_appender::non_blocking::WorkerGuard;
+use tracing_subscriber::{fmt::MakeWriter, EnvFilter};
+
+/// Initialize logging for the main process
+///
+/// This sets the global tracing subscriber and must only be called once at startup time.
+/// Subsequent calls will panic.
+///
+/// Returns a `tracing_appender::WorkerGuard` that keeps the logging thread alive.  The caller must
+/// ensure this this value is not dropped while the server is running.
+pub fn init_logging(json: bool) -> ApiResult<WorkerGuard> {
+    let (writer, guard) = tracing_appender::non_blocking(stdout());
+    if json {
+        tracing::subscriber::set_global_default(json_subscriber(writer))?;
+    } else {
+        tracing::subscriber::set_global_default(human_subscriber(writer))?;
+    };
+    init_slog_drain();
+    Ok(guard)
+}
+
+/// Initialize logging for the tests
+///
+/// Returns a DefaultGuard that must be kept alive for the duration of the test
+pub fn init_test_logging() -> tracing::subscriber::DefaultGuard {
+    init_slog_drain();
+    tracing::subscriber::set_default(human_subscriber(stdout))
+}
+
+fn json_subscriber<W>(writer: W) -> impl tracing::Subscriber + Send + Sync + 'static
+where
+    W: for<'writer> MakeWriter<'writer> + Send + Sync + 'static,
+{
+    tracing_subscriber::fmt()
+        .event_format(mozlog::EventFormatter::new())
+        .with_env_filter(EnvFilter::from_default_env())
+        .with_writer(writer)
+        .finish()
+}
+
+fn human_subscriber<W>(writer: W) -> impl tracing::Subscriber + Send + Sync + 'static
+where
+    W: for<'writer> MakeWriter<'writer> + Send + Sync + 'static,
+{
+    tracing_subscriber::fmt()
+        .pretty()
+        .with_ansi(true)
+        .with_env_filter(EnvFilter::from_default_env())
+        .with_writer(writer)
+        .finish()
+}
+
+fn init_slog_drain() {
+    static ONCE: Once = Once::new();
+
+    ONCE.call_once(|| {
+        let drain = tracing_slog::TracingSlogDrain;
+        let logger = slog::Logger::root(drain, slog_o!());
+        // XXX: cancel slog_scope's NoGlobalLoggerSet for now, it's difficult to
+        // prevent it from potentially panicing during tests. reset_logging resets
+        // the global logger during shutdown anyway:
+        // https://github.com/slog-rs/slog/issues/169
+        slog_scope::set_global_logger(logger).cancel_reset();
+    });
+}
+
+pub fn reset_logging() {
+    let logger = slog::Logger::root(slog::Discard, slog_o!());
+    slog_scope::set_global_logger(logger).cancel_reset();
+}

syncserver/src/logging.rs

@@ -0,0 +1,224 @@
+//! MozLog formatting for tracing events
+
+use serde::{ser::SerializeMap, Serialize, Serializer};
+use std::{fmt, io, time::SystemTime};
+use tracing::{field::Visit, Event, Level, Subscriber};
+use tracing_subscriber::{
+    fmt::{
+        format::{self, FormatEvent, FormatFields},
+        FmtContext,
+    },
+    registry::LookupSpan,
+};
+
+/// Top-level formatter for a tracing [Event]
+pub struct EventFormatter {
+    logger: String,
+    hostname: String,
+    pid: u32,
+}
+
+impl EventFormatter {
+    pub fn new() -> Self {
+        Self {
+            logger: format!("{}-{}", env!("CARGO_PKG_NAME"), env!("CARGO_PKG_VERSION")),
+            hostname: match hostname::get() {
+                Ok(h) => h.to_string_lossy().to_string(),
+                Err(_) => "<unknown>".to_owned(),
+            },
+            pid: std::process::id(),
+        }
+    }
+}
+
+impl<S, N> FormatEvent<S, N> for EventFormatter
+where
+    S: Subscriber + for<'a> LookupSpan<'a>,
+    N: for<'a> FormatFields<'a> + 'static,
+{
+    fn format_event(
+        &self,
+        _ctx: &FmtContext<'_, S, N>,
+        writer: format::Writer<'_>,
+        event: &Event<'_>,
+    ) -> fmt::Result {
+        // This closure returns a `serde_json::Result` which allows for nicer ergonomics with the
+        // `?` operator.  We map this to a `fmt::Result` at the bottom of the method.
+        //
+        // It serializes `event`, writes it out to `writer`, then returns the writer back so we can
+        // write out the trailing newline.
+        let format_with_serde = move || -> serde_json::Result<format::Writer<'_>> {
+            let mut serializer = serde_json::Serializer::new(WriteAdaptor(writer));
+            let mut map = serializer.serialize_map(Some(7))?;
+            map.serialize_entry(
+                "Timestamp",
+                &SystemTime::now()
+                    .duration_since(SystemTime::UNIX_EPOCH)
+                    .unwrap_or_default()
+                    .as_nanos(),
+            )?;
+            map.serialize_entry("Type", "syncserver:log")?;
+            map.serialize_entry("Logger", &self.logger)?;
+            map.serialize_entry("Hostname", &self.hostname)?;
+            map.serialize_entry("EnvVersion", "2.0")?;
+            map.serialize_entry("Pid", &self.pid)?;
+            map.serialize_entry(
+                "Severity",
+                &match *event.metadata().level() {
+                    Level::ERROR => 3,
+                    Level::WARN => 4,
+                    Level::INFO => 5,
+                    Level::DEBUG => 6,
+                    Level::TRACE => 7,
+                },
+            )?;
+            map.serialize_entry("Fields", &SerializableEvent(event))?;
+            map.end()?;
+            Ok(serializer.into_inner().0)
+        };
+        let mut writer = format_with_serde().map_err(|_| fmt::Error)?;
+        writeln!(writer)
+    }
+}
+
+/// Newtype that wraps `tracing::Event` and implements `serde::Serialize`.  This allows us to
+/// serialize the event into the `Fields` field.
+struct SerializableEvent<'a, 'event>(&'a Event<'event>);
+
+impl<'a, 'event> Serialize for SerializableEvent<'a, 'event> {
+    fn serialize<S: Serializer>(&self, serializer: S) -> Result<S::Ok, S::Error> {
+        let map = serializer.serialize_map(self.0.fields().size_hint().1)?;
+        let mut visitor = SerdeFieldVisitor::new(map);
+        self.0.record(&mut visitor);
+        visitor.end()
+    }
+}
+
+/// Implements `tracing::Visit` by serializing the fields to a `serde` map.  This is how we
+/// serialize the `tracing::Event` with `serde`.
+struct SerdeFieldVisitor<S>
+where
+    S: SerializeMap,
+{
+    map: S,
+    error: Option<S::Error>,
+}
+
+impl<S> SerdeFieldVisitor<S>
+where
+    S: SerializeMap,
+{
+    fn new(serializer: S) -> Self {
+        Self {
+            map: serializer,
+            error: None,
+        }
+    }
+
+    fn should_serialize_field(&self, field: &tracing::field::Field) -> bool {
+        !field.name().starts_with("slog.")
+    }
+
+    fn serialize_entry<V: Serialize + ?Sized>(&mut self, name: &str, value: &V) {
+        if let Err(e) = self.map.serialize_entry(name, value) {
+            // This is a bit awkward because serde's methods are failable, while the tracing::Visit
+            // methods aren't.  The best we can do is store the error and return it when
+            // `check_error()` is eventually called.  In practice this will probably be okay, since
+            // the serializer will only fail on IO errors
+            self.error = Some(e)
+        }
+    }
+
+    fn end(mut self) -> Result<S::Ok, S::Error> {
+        match self.error.take() {
+            Some(e) => Err(e),
+            None => self.map.end(),
+        }
+    }
+}
+
+impl<S> Visit for SerdeFieldVisitor<S>
+where
+    S: SerializeMap,
+{
+    fn record_f64(&mut self, field: &tracing::field::Field, value: f64) {
+        if self.should_serialize_field(field) {
+            self.serialize_entry(field.name(), &value)
+        }
+    }
+
+    fn record_i64(&mut self, field: &tracing::field::Field, value: i64) {
+        if self.should_serialize_field(field) {
+            self.serialize_entry(field.name(), &value)
+        }
+    }
+
+    fn record_u64(&mut self, field: &tracing::field::Field, value: u64) {
+        if self.should_serialize_field(field) {
+            self.serialize_entry(field.name(), &value)
+        }
+    }
+
+    fn record_i128(&mut self, field: &tracing::field::Field, value: i128) {
+        if self.should_serialize_field(field) {
+            self.serialize_entry(field.name(), &value)
+        }
+    }
+
+    fn record_u128(&mut self, field: &tracing::field::Field, value: u128) {
+        if self.should_serialize_field(field) {
+            self.serialize_entry(field.name(), &value)
+        }
+    }
+
+    fn record_bool(&mut self, field: &tracing::field::Field, value: bool) {
+        if self.should_serialize_field(field) {
+            self.serialize_entry(field.name(), &value)
+        }
+    }
+
+    fn record_str(&mut self, field: &tracing::field::Field, value: &str) {
+        if self.should_serialize_field(field) {
+            self.serialize_entry(field.name(), value)
+        }
+    }
+
+    fn record_error(
+        &mut self,
+        field: &tracing::field::Field,
+        value: &(dyn std::error::Error + 'static),
+    ) {
+        if self.should_serialize_field(field) {
+            self.serialize_entry(field.name(), &value.to_string())
+        }
+    }
+
+    fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) {
+        if self.should_serialize_field(field) {
+            self.serialize_entry(field.name(), &format!("{value:?}"))
+        }
+    }
+}
+
+// Adapts tracing-subscriber's `Writer` struct to implement `std::io::Write`
+//
+// This is needed because `tracing` using the `std::fmt::Write` trait while `serde` uses
+// `std::io::Write`.
+struct WriteAdaptor<'writer>(format::Writer<'writer>);
+
+impl<'writer> io::Write for WriteAdaptor<'writer> {
+    fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
+        let s =
+            std::str::from_utf8(buf).map_err(|e| io::Error::new(io::ErrorKind::InvalidData, e))?;
+
+        self.0
+            .write_str(s)
+            .map_err(|e| io::Error::new(io::ErrorKind::Other, e))?;
+
+        Ok(s.as_bytes().len())
+    }
+
+    fn flush(&mut self) -> io::Result<()> {
+        Ok(())
+    }
+}