test and fix #282

Sessions' last use updates weren't getting persisted to the database
because the update statement wasn't passing through the hash.

Also address a TODO of tracing in tests by using the same tracing
setup as in production.

server/base/Cargo.toml

@@ -13,6 +13,7 @@ nightly = []
 path = "lib.rs"
 
 [dependencies]
+chrono = "0.4.23"
 failure = "0.1.1"
 futures = "0.3"
 libc = "0.2"
@@ -22,3 +23,6 @@ serde_json = "1.0"
 slab = "0.4"
 time = "0.1"
 tracing = "0.1.37"
+tracing-core = "0.1.30"
+tracing-log = "0.1.3"
+tracing-subscriber = { version = "0.3.16", features = ["env-filter", "json"] }

server/base/lib.rs

@@ -7,5 +7,6 @@ mod error;
 pub mod shutdown;
 pub mod strutil;
 pub mod time;
+pub mod tracing_setup;
 
 pub use crate::error::{prettify_failure, Error, ErrorKind, ResultExt};

server/base/tracing_setup.rs

@@ -0,0 +1,153 @@
+// This file is part of Moonfire NVR, a security camera network video recorder.
+// Copyright (C) 2023 The Moonfire NVR Authors; see AUTHORS and LICENSE.txt.
+// SPDX-License-Identifier: GPL-v3.0-or-later WITH GPL-3.0-linking-exception.
+
+//! Logic for setting up a `tracing` subscriber according to our preferences
+//! and [OpenTelemetry conventions](https://opentelemetry.io/docs/reference/specification/logs/).
+
+use tracing::error;
+use tracing_core::{Event, Level, Subscriber};
+use tracing_log::NormalizeEvent;
+use tracing_subscriber::{
+    fmt::{format::Writer, time::FormatTime, FmtContext, FormatFields, FormattedFields},
+    layer::SubscriberExt,
+    registry::LookupSpan,
+    Layer,
+};
+
+struct FormatSystemd;
+
+struct ChronoTimer;
+
+impl FormatTime for ChronoTimer {
+    fn format_time(&self, w: &mut Writer<'_>) -> std::fmt::Result {
+        const TIME_FORMAT: &str = "%Y-%m-%dT%H:%M:%S%.6f";
+        write!(w, "{}", chrono::Local::now().format(TIME_FORMAT))
+    }
+}
+
+fn systemd_prefix(level: Level) -> &'static str {
+    if level >= Level::TRACE {
+        "<7>" // SD_DEBUG
+    } else if level >= Level::DEBUG {
+        "<6>" // SD_INFO
+    } else if level >= Level::INFO {
+        "<5>" // SD_NOTICE
+    } else if level >= Level::WARN {
+        "<4>" // SD_WARN
+    } else {
+        "<3>" // SD_ERROR
+    }
+}
+
+impl<S, N> tracing_subscriber::fmt::FormatEvent<S, N> for FormatSystemd
+where
+    S: Subscriber + for<'a> LookupSpan<'a>,
+    N: for<'a> FormatFields<'a> + 'static,
+{
+    fn format_event(
+        &self,
+        ctx: &FmtContext<'_, S, N>,
+        mut writer: Writer<'_>,
+        event: &Event<'_>,
+    ) -> std::fmt::Result {
+        let normalized_meta = event.normalized_metadata();
+        let meta = normalized_meta.as_ref().unwrap_or_else(|| event.metadata());
+        let prefix = systemd_prefix(*meta.level());
+
+        let thread = std::thread::current();
+        let thread_name = thread.name().unwrap_or("unnamed-thread");
+        write!(writer, "{prefix}{thread_name} ")?;
+        if let Some(scope) = ctx.event_scope() {
+            let mut seen = false;
+
+            for span in scope.from_root() {
+                write!(writer, "{}", span.metadata().name())?;
+                seen = true;
+
+                let ext = span.extensions();
+                if let Some(fields) = &ext.get::<FormattedFields<N>>() {
+                    if !fields.is_empty() {
+                        write!(writer, "{{{fields}}}")?;
+                    }
+                }
+                writer.write_char(':')?;
+            }
+
+            if seen {
+                writer.write_char(' ')?;
+            }
+        }
+
+        write!(writer, "{}: ", meta.target())?;
+        ctx.format_fields(writer.by_ref(), event)?;
+        writeln!(writer)
+    }
+}
+
+/// Custom panic hook that logs instead of directly writing to stderr.
+///
+/// This means it includes a timestamp, follows [OpenTelemetry Semantic
+/// Conventions for Exceptions](https://opentelemetry.io/docs/reference/specification/logs/semantic_conventions/exceptions/),
+/// etc.
+fn panic_hook(p: &std::panic::PanicInfo) {
+    let payload: Option<&str> = if let Some(s) = p.payload().downcast_ref::<&str>() {
+        Some(*s)
+    } else if let Some(s) = p.payload().downcast_ref::<String>() {
+        Some(s)
+    } else {
+        None
+    };
+    error!(
+        target: std::env!("CARGO_CRATE_NAME"),
+        location = p.location().map(tracing::field::display),
+        payload = payload.map(tracing::field::display),
+        backtrace = %std::backtrace::Backtrace::force_capture(),
+        "panic",
+    );
+}
+
+pub fn install() {
+    let filter = tracing_subscriber::EnvFilter::builder()
+        .with_default_directive(tracing_subscriber::filter::LevelFilter::INFO.into())
+        .with_env_var("MOONFIRE_LOG")
+        .from_env_lossy();
+    tracing_log::LogTracer::init().unwrap();
+
+    match std::env::var("MOONFIRE_FORMAT") {
+        Ok(s) if s == "systemd" => {
+            let sub = tracing_subscriber::registry().with(
+                tracing_subscriber::fmt::Layer::new()
+                    .with_ansi(false)
+                    .event_format(FormatSystemd)
+                    .with_filter(filter),
+            );
+            tracing::subscriber::set_global_default(sub).unwrap();
+        }
+        Ok(s) if s == "json" => {
+            let sub = tracing_subscriber::registry().with(
+                tracing_subscriber::fmt::Layer::new()
+                    .with_thread_names(true)
+                    .json()
+                    .with_filter(filter),
+            );
+            tracing::subscriber::set_global_default(sub).unwrap();
+        }
+        _ => {
+            let sub = tracing_subscriber::registry().with(
+                tracing_subscriber::fmt::Layer::new()
+                    .with_timer(ChronoTimer)
+                    .with_thread_names(true)
+                    .with_filter(filter),
+            );
+            tracing::subscriber::set_global_default(sub).unwrap();
+        }
+    }
+
+    let use_panic_hook = ::std::env::var("MOONFIRE_PANIC_HOOK")
+        .map(|s| s != "false" && s != "0")
+        .unwrap_or(true);
+    if use_panic_hook {
+        std::panic::set_hook(Box::new(&panic_hook));
+    }
+}