From f5e6b813432c98c6accc0b34bbcbd67f1ca328b2 Mon Sep 17 00:00:00 2001 From: Ben Dean-Kawamura Date: Fri, 19 Jan 2024 11:40:37 -0500 Subject: [PATCH] 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. --- Cargo.lock | 284 ++++++++++++++----------------- Cargo.toml | 9 +- syncserver/Cargo.toml | 9 +- syncserver/src/error.rs | 6 + syncserver/src/logging.rs | 47 ----- syncserver/src/logging/mod.rs | 75 ++++++++ syncserver/src/logging/mozlog.rs | 202 ++++++++++++++++++++++ syncserver/src/main.rs | 5 +- syncserver/src/server/test.rs | 51 +++++- 9 files changed, 460 insertions(+), 228 deletions(-) delete mode 100644 syncserver/src/logging.rs create mode 100644 syncserver/src/logging/mod.rs create mode 100644 syncserver/src/logging/mozlog.rs diff --git a/Cargo.lock b/Cargo.lock index a355f4533f..738a47070b 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -798,27 +798,6 @@ dependencies = [ "subtle", ] -[[package]] -name = "dirs-next" -version = "2.0.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "b98cf8ebf19c3d1b223e151f99a4f9f0690dca41414773390fc824184ac833e1" -dependencies = [ - "cfg-if", - "dirs-sys-next", -] - -[[package]] -name = "dirs-sys-next" -version = "0.1.2" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "4ebda144c4fe02d1f7ea1a7d9641b6fc6b580adcfa024ae48797ecdeb6825b4d" -dependencies = [ - "libc", - "redox_users", - "winapi", -] - [[package]] name = "docopt" version = "1.1.1" @@ -884,15 +863,6 @@ version = "1.0.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "5443807d6dff69373d433ab9ef5378ad8df50ca6298caf15de6e52e24aaf54d5" -[[package]] -name = "erased-serde" -version = "0.3.31" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "6c138974f9d5e7fe373eb04df7cae98833802ae4b11c24ac7039a21d5af4b26c" -dependencies = [ - "serde 1.0.195", -] - [[package]] name = "errno" version = "0.3.8" @@ -1492,17 +1462,6 @@ dependencies = [ "windows-sys 0.48.0", ] -[[package]] -name = "libredox" -version = "0.0.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "85c833ca1e66078851dba29046874e38f08b2c883700aa29a03ddd3b23814ee8" -dependencies = [ - "bitflags 2.4.2", - "libc", - "redox_syscall", -] - [[package]] name = "libz-sys" version = "1.1.14" @@ -1566,6 +1525,15 @@ version = "0.1.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ffbee8634e0d45d258acb448e7eaab3fce7a0a467395d4d9f228e3c1f01fb2e4" +[[package]] +name = "matchers" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8263075bb86c5a1b1427b5ae862e8889656f126e9f77c484496e8b47cf5c5558" +dependencies = [ + "regex-automata 0.1.10", +] + [[package]] name = "matches" version = "0.1.10" @@ -1708,6 +1676,16 @@ dependencies = [ "minimal-lexical", ] +[[package]] +name = "nu-ansi-term" +version = "0.46.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "77a8165726e8236064dbb45459242600304b42a5ea24ee2948e18e023bf7ba84" +dependencies = [ + "overload", + "winapi", +] + [[package]] name = "num-traits" version = "0.1.43" @@ -1736,15 +1714,6 @@ dependencies = [ "libc", ] -[[package]] -name = "num_threads" -version = "0.1.6" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "2819ce041d2ee131036f4fc9d6ae7ae125a3a40e97ba64d04fe799ad9dabbb44" -dependencies = [ - "libc", -] - [[package]] name = "object" version = "0.32.2" @@ -1815,6 +1784,12 @@ dependencies = [ "winapi", ] +[[package]] +name = "overload" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39" + [[package]] name = "parking_lot" version = "0.12.1" @@ -2051,17 +2026,6 @@ dependencies = [ "bitflags 1.3.2", ] -[[package]] -name = "redox_users" -version = "0.4.4" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "a18479200779601e498ada4e8c1e1f50e3ee19deb0259c25825a98b5603b2cb4" -dependencies = [ - "getrandom", - "libredox", - "thiserror", -] - [[package]] name = "regex" version = "1.10.2" @@ -2070,8 +2034,17 @@ checksum = "380b951a9c5e80ddfd6136919eef32310721aa4aacd4889a8d39124b026ab343" dependencies = [ "aho-corasick", "memchr", - "regex-automata", - "regex-syntax", + "regex-automata 0.4.3", + "regex-syntax 0.8.2", +] + +[[package]] +name = "regex-automata" +version = "0.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132" +dependencies = [ + "regex-syntax 0.6.29", ] [[package]] @@ -2082,9 +2055,15 @@ checksum = "5f804c7828047e88b2d32e2d7fe5a105da8ee3264f01902f796c8e067dc2483f" dependencies = [ "aho-corasick", "memchr", - "regex-syntax", + "regex-syntax 0.8.2", ] +[[package]] +name = "regex-syntax" +version = "0.6.29" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f162c6dd7b008981e4d40210aca20b4bd0f9b60ca9271061b07f78537722f2e1" + [[package]] name = "regex-syntax" version = "0.8.2" @@ -2234,12 +2213,6 @@ dependencies = [ "untrusted 0.9.0", ] -[[package]] -name = "rustversion" -version = "1.0.14" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "7ffc183a10b4478d04cbbbfc96d0873219d962dd5accaff2ffbd4ceb7df837f4" - [[package]] name = "ryu" version = "1.0.16" @@ -2510,6 +2483,15 @@ dependencies = [ "digest", ] +[[package]] +name = "sharded-slab" +version = "0.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f40ca3c46823713e0d4209592e8d6e826aa57e928f09752619fc696c499637f6" +dependencies = [ + "lazy_static", +] + [[package]] name = "shlex" version = "1.2.0" @@ -2539,48 +2521,6 @@ name = "slog" version = "2.7.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "8347046d4ebd943127157b94d63abb990fcf729dc4e9978927fdf4ac3c998d06" -dependencies = [ - "erased-serde", -] - -[[package]] -name = "slog-async" -version = "2.8.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "72c8038f898a2c79507940990f05386455b3a317d8f18d4caea7cbc3d5096b84" -dependencies = [ - "crossbeam-channel", - "slog", - "take_mut", - "thread_local", -] - -[[package]] -name = "slog-envlogger" -version = "2.2.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "906a1a0bc43fed692df4b82a5e2fbfc3733db8dad8bb514ab27a4f23ad04f5c0" -dependencies = [ - "log", - "regex", - "slog", - "slog-async", - "slog-scope", - "slog-stdlog", - "slog-term", -] - -[[package]] -name = "slog-mozlog-json" -version = "0.1.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "f400f1c5db96f1f52065e8931ca0c524cceb029f7537c9e6d5424488ca137ca0" -dependencies = [ - "chrono", - "serde 1.0.195", - "serde_json", - "slog", -] [[package]] name = "slog-scope" @@ -2593,30 +2533,6 @@ dependencies = [ "slog", ] -[[package]] -name = "slog-stdlog" -version = "4.1.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "6706b2ace5bbae7291d3f8d2473e2bfab073ccd7d03670946197aec98471fa3e" -dependencies = [ - "log", - "slog", - "slog-scope", -] - -[[package]] -name = "slog-term" -version = "2.9.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "87d29185c55b7b258b4f120eab00f48557d4d9bc814f41713f449d35b0f8977c" -dependencies = [ - "atty", - "slog", - "term", - "thread_local", - "time", -] - [[package]] name = "smallvec" version = "1.13.0" @@ -2734,12 +2650,7 @@ dependencies = [ "serde_json", "sha2", "slog", - "slog-async", - "slog-envlogger", - "slog-mozlog-json", "slog-scope", - "slog-stdlog", - "slog-term", "syncserver-common", "syncserver-db-common", "syncserver-settings", @@ -2752,6 +2663,10 @@ dependencies = [ "tokenserver-db", "tokenserver-settings", "tokio", + "tracing", + "tracing-appender", + "tracing-slog", + "tracing-subscriber", "urlencoding", "validator", "validator_derive", @@ -2924,12 +2839,6 @@ dependencies = [ "libc", ] -[[package]] -name = "take_mut" -version = "0.2.2" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "f764005d11ee5f36500a149ace24e00e3da98b0158b3e2d53a7495660d3f4d60" - [[package]] name = "target-lexicon" version = "0.12.13" @@ -2949,17 +2858,6 @@ dependencies = [ "windows-sys 0.52.0", ] -[[package]] -name = "term" -version = "0.7.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "c59df8ac95d96ff9bede18eb7300b0fda5e5d8d90960e76f8e14ae765eedbf1f" -dependencies = [ - "dirs-next", - "rustversion", - "winapi", -] - [[package]] name = "termcolor" version = "1.4.1" @@ -3016,8 +2914,6 @@ checksum = "f657ba42c3f86e7680e53c8cd3af8abbe56b5491790b46e22e19c0d57463583e" dependencies = [ "deranged", "itoa", - "libc", - "num_threads", "powerfmt", "serde 1.0.195", "time-core", @@ -3204,9 +3100,33 @@ checksum = "c3523ab5a71916ccf420eebdf5521fcef02141234bbc0b8a49f2fdc4544364ef" dependencies = [ "log", "pin-project-lite", + "tracing-attributes", "tracing-core", ] +[[package]] +name = "tracing-appender" +version = "0.2.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3566e8ce28cc0a3fe42519fc80e6b4c943cc4c8cef275620eb8dac2d3d4e06cf" +dependencies = [ + "crossbeam-channel", + "thiserror", + "time", + "tracing-subscriber", +] + +[[package]] +name = "tracing-attributes" +version = "0.1.27" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "34704c8d6ebcbc939824180af020566b01a7c01f80641264eba0999f6c2b6be7" +dependencies = [ + "proc-macro2", + "quote", + "syn 2.0.48", +] + [[package]] name = "tracing-core" version = "0.1.32" @@ -3217,13 +3137,57 @@ dependencies = [ "valuable", ] +[[package]] +name = "tracing-log" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3" +dependencies = [ + "log", + "once_cell", + "tracing-core", +] + +[[package]] +name = "tracing-serde" +version = "0.1.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "bc6b213177105856957181934e4920de57730fc69bf42c37ee5bb664d406d9e1" +dependencies = [ + "serde 1.0.195", + "tracing-core", +] + +[[package]] +name = "tracing-slog" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6ffd12d2d54fb99df994fde4e3320959e32208420bfe375a664c5d8cd894a23b" +dependencies = [ + "once_cell", + "slog", + "tracing-core", +] + [[package]] name = "tracing-subscriber" version = "0.3.18" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ad0f048c97dbd9faa9b7df56362b8ebcaa52adb06b498c050d2f4e32f90a7a8b" dependencies = [ + "matchers", + "nu-ansi-term", + "once_cell", + "regex", + "serde 1.0.195", + "serde_json", + "sharded-slab", + "smallvec", + "thread_local", + "tracing", "tracing-core", + "tracing-log", + "tracing-serde", ] [[package]] diff --git a/Cargo.toml b/Cargo.toml index fd875a0709..9d85a9b1c3 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -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 diff --git a/syncserver/Cargo.toml b/syncserver/Cargo.toml index 8b715057dc..4cd387e21b 100644 --- a/syncserver/Cargo.toml +++ b/syncserver/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" diff --git a/syncserver/src/error.rs b/syncserver/src/error.rs index fc0c53b11f..278c23c648 100644 --- a/syncserver/src/error.rs +++ b/syncserver/src/error.rs @@ -167,6 +167,12 @@ impl From for ApiError { } } +impl From for ApiError { + fn from(_: tracing::subscriber::SetGlobalDefaultError) -> Self { + ApiErrorKind::Internal("Logging failed to initialize".to_string()).into() + } +} + impl From for ApiError { fn from(kind: ApiErrorKind) -> Self { let status = match &kind { diff --git a/syncserver/src/logging.rs b/syncserver/src/logging.rs deleted file mode 100644 index b182fa65f7..0000000000 --- a/syncserver/src/logging.rs +++ /dev/null @@ -1,47 +0,0 @@ -use std::io; - -use crate::error::ApiResult; - -use slog::{self, slog_o, Drain}; -use slog_mozlog_json::MozLogJson; - -pub fn init_logging(json: bool) -> ApiResult<()> { - let logger = if json { - let hostname = hostname::get() - .expect("Couldn't get hostname") - .into_string() - .expect("Couldn't get hostname"); - - let drain = MozLogJson::new(io::stdout()) - .logger_name(format!( - "{}-{}", - env!("CARGO_PKG_NAME"), - env!("CARGO_PKG_VERSION") - )) - .msg_type(format!("{}:log", env!("CARGO_PKG_NAME"))) - .hostname(hostname) - .build() - .fuse(); - let drain = slog_envlogger::new(drain); - let drain = slog_async::Async::new(drain).build().fuse(); - slog::Logger::root(drain, slog_o!()) - } else { - let decorator = slog_term::TermDecorator::new().build(); - let drain = slog_term::FullFormat::new(decorator).build().fuse(); - let drain = slog_envlogger::new(drain); - let drain = slog_async::Async::new(drain).build().fuse(); - 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(); - slog_stdlog::init().ok(); - Ok(()) -} - -pub fn reset_logging() { - let logger = slog::Logger::root(slog::Discard, slog_o!()); - slog_scope::set_global_logger(logger).cancel_reset(); -} diff --git a/syncserver/src/logging/mod.rs b/syncserver/src/logging/mod.rs new file mode 100644 index 0000000000..a7076d86ae --- /dev/null +++ b/syncserver/src/logging/mod.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 { + 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(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(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(); +} diff --git a/syncserver/src/logging/mozlog.rs b/syncserver/src/logging/mozlog.rs new file mode 100644 index 0000000000..5484e15999 --- /dev/null +++ b/syncserver/src/logging/mozlog.rs @@ -0,0 +1,202 @@ +//! 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(_) => "".to_owned(), + }, + pid: std::process::id(), + } + } +} + +impl FormatEvent 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> { + 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(&self, serializer: S) -> Result { + 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 +where + S: SerializeMap, +{ + map: S, + error: Option, +} + +impl SerdeFieldVisitor +where + S: SerializeMap, +{ + fn new(serializer: S) -> Self { + Self { + map: serializer, + error: None, + } + } + + fn serialize_entry(&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 { + match self.error.take() { + Some(e) => Err(e), + None => self.map.end(), + } + } +} + +impl Visit for SerdeFieldVisitor +where + S: SerializeMap, +{ + fn record_f64(&mut self, field: &tracing::field::Field, value: f64) { + self.serialize_entry(field.name(), &value) + } + + fn record_i64(&mut self, field: &tracing::field::Field, value: i64) { + self.serialize_entry(field.name(), &value) + } + + fn record_u64(&mut self, field: &tracing::field::Field, value: u64) { + self.serialize_entry(field.name(), &value) + } + + fn record_i128(&mut self, field: &tracing::field::Field, value: i128) { + self.serialize_entry(field.name(), &value) + } + + fn record_u128(&mut self, field: &tracing::field::Field, value: u128) { + self.serialize_entry(field.name(), &value) + } + + fn record_bool(&mut self, field: &tracing::field::Field, value: bool) { + self.serialize_entry(field.name(), &value) + } + + fn record_str(&mut self, field: &tracing::field::Field, value: &str) { + self.serialize_entry(field.name(), value) + } + + fn record_error( + &mut self, + field: &tracing::field::Field, + value: &(dyn std::error::Error + 'static), + ) { + self.serialize_entry(field.name(), &value.to_string()) + } + + fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) { + 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 { + 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(()) + } +} diff --git a/syncserver/src/main.rs b/syncserver/src/main.rs index e5d56f214e..291bf7162a 100644 --- a/syncserver/src/main.rs +++ b/syncserver/src/main.rs @@ -6,6 +6,7 @@ use std::{error::Error, sync::Arc}; use docopt::Docopt; use serde::Deserialize; +use tracing::info; use logging::init_logging; use syncserver::{logging, server}; @@ -30,7 +31,7 @@ async fn main() -> Result<(), Box> { .and_then(|d| d.deserialize()) .unwrap_or_else(|e| e.exit()); let settings = Settings::with_env_and_config_file(args.flag_config.as_deref())?; - init_logging(!settings.human_logs).expect("Logging failed to initialize"); + let _logging_guard = init_logging(!settings.human_logs).expect("Logging failed to initialize"); debug!("Starting up..."); // Set SENTRY_DSN environment variable to enable Sentry. @@ -60,7 +61,7 @@ async fn main() -> Result<(), Box> { } else { server::Server::with_settings(settings).await.unwrap() }; - info!("Server running on {}", banner); + info!(server = banner, "Server starting up"); server.await?; info!("Server closing"); logging::reset_logging(); diff --git a/syncserver/src/server/test.rs b/syncserver/src/server/test.rs index ec09879196..c1e64cfb7e 100644 --- a/syncserver/src/server/test.rs +++ b/syncserver/src/server/test.rs @@ -102,6 +102,38 @@ async fn get_test_state(settings: &Settings) -> ServerState { } } +/// Wrapper around an `actix_web::Service` used to run the tests. +/// +/// It also stores the tracing subscriber guard to ensure that logging is setup while running the +/// test. +struct TestService { + service: S, + _subscriber_guard: tracing::subscriber::DefaultGuard, +} + +impl TestService { + fn new(service: S) -> Self { + Self { + service, + _subscriber_guard: crate::logging::init_test_logging(), + } + } +} + +impl std::ops::Deref for TestService { + type Target = S; + + fn deref(&self) -> &S { + &self.service + } +} + +impl std::ops::DerefMut for TestService { + fn deref_mut(&mut self) -> &mut S { + &mut self.service + } +} + macro_rules! init_app { () => { async { @@ -111,17 +143,18 @@ macro_rules! init_app { }; ($settings:expr) => { async { - crate::logging::init_logging(false).unwrap(); let limits = Arc::new($settings.syncstorage.limits.clone()); let state = get_test_state(&$settings).await; - test::init_service(build_app!( - state, - None::, - Arc::clone(&SECRETS), - limits, - build_cors(&$settings) - )) - .await + TestService::new( + test::init_service(build_app!( + state, + None::, + Arc::clone(&SECRETS), + limits, + build_cors(&$settings) + )) + .await, + ) } }; }