From ee1243b52222c1e3d3cbad5254ac865a7f226aa5 Mon Sep 17 00:00:00 2001 From: Sebastian Zivota Date: Wed, 25 Aug 2021 10:34:18 +0200 Subject: [PATCH 01/16] WIP --- Cargo.lock | 167 ++++++++++++------ crates/symbolicator/Cargo.toml | 8 +- crates/symbolicator/src/cache.rs | 40 +++-- crates/symbolicator/src/cli.rs | 6 +- crates/symbolicator/src/config.rs | 46 ++++- crates/symbolicator/src/logging.rs | 146 ++++++--------- crates/symbolicator/src/metrics.rs | 14 +- crates/symbolicator/src/server.rs | 5 +- crates/symbolicator/src/services/bitcode.rs | 9 +- crates/symbolicator/src/services/cacher.rs | 18 +- crates/symbolicator/src/services/cficaches.rs | 6 +- .../src/services/download/filesystem.rs | 3 +- .../symbolicator/src/services/download/gcs.rs | 25 ++- .../src/services/download/http.rs | 17 +- .../symbolicator/src/services/download/mod.rs | 12 +- .../symbolicator/src/services/download/s3.rs | 13 +- .../src/services/download/sentry.rs | 28 ++- .../src/services/objects/data_cache.rs | 9 +- .../src/services/objects/meta_cache.rs | 12 +- .../symbolicator/src/services/objects/mod.rs | 7 +- .../src/services/symbolication.rs | 40 +++-- crates/symbolicator/src/services/symcaches.rs | 9 +- crates/symbolicator/src/test.rs | 9 +- crates/symbolicator/src/utils/http.rs | 4 +- 24 files changed, 404 insertions(+), 249 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index fc397e33f..18884fec9 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -161,6 +161,15 @@ dependencies = [ "winapi 0.3.9", ] +[[package]] +name = "ansi_term" +version = "0.12.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d52a9bb7ec0cf484c551830a7ce27bd20d67eac647e1befb56b0be4ee39a55d2" +dependencies = [ + "winapi 0.3.9", +] + [[package]] name = "anyhow" version = "1.0.41" @@ -462,7 +471,7 @@ version = "2.33.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "37e58ac78573c40708d45522f0d80fa2f01cc4f9b4e2bf749807255454312002" dependencies = [ - "ansi_term", + "ansi_term 0.11.0", "atty", "bitflags", "strsim", @@ -906,19 +915,6 @@ dependencies = [ "syn 1.0.73", ] -[[package]] -name = "env_logger" -version = "0.7.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "44533bbbb3bb3c1fa17d9f2e4e38bbbaf8396ba82193c4cb1b6445d711445d36" -dependencies = [ - "atty", - "humantime 1.3.0", - "log", - "regex", - "termcolor", -] - [[package]] name = "error-chain" version = "0.8.1" @@ -1401,15 +1397,6 @@ version = "1.0.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "6456b8a6c8f33fee7d958fcd1b60d55b11940a79e63ae87013e6d22e26034440" -[[package]] -name = "humantime" -version = "1.3.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "df004cfca50ef23c36850aaaa59ad52cc70d0e90243c3c7737a4dd32dc7a3c4f" -dependencies = [ - "quick-error", -] - [[package]] name = "humantime" version = "2.1.0" @@ -1422,7 +1409,7 @@ version = "1.0.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ac34a56cfd4acddb469cc7fff187ed5ac36f498ba085caf8bbc725e3ff474058" dependencies = [ - "humantime 2.1.0", + "humantime", "serde", ] @@ -1748,7 +1735,6 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "51b9bbe6c47d51fc3e1a9b945965946b4c44142ab8792c50835a980d362c2710" dependencies = [ "cfg-if 1.0.0", - "serde", ] [[package]] @@ -1781,6 +1767,15 @@ version = "0.1.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ffbee8634e0d45d258acb448e7eaab3fce7a0a467395d4d9f228e3c1f01fb2e4" +[[package]] +name = "matchers" +version = "0.0.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f099785f7595cc4b4553a174ce30dd7589ef93391ff414dbb67f62392b9e0ce1" +dependencies = [ + "regex-automata", +] + [[package]] name = "matches" version = "0.1.8" @@ -2355,16 +2350,6 @@ version = "0.1.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "925383efa346730478fb4838dbe9137d2a47675ad789c546d150a6e1dd4ab31c" -[[package]] -name = "pretty_env_logger" -version = "0.4.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "926d36b9553851b8b0005f1275891b392ee4d2d833852c417ed025477350fb9d" -dependencies = [ - "env_logger", - "log", -] - [[package]] name = "proc-macro-error" version = "1.0.4" @@ -2745,6 +2730,15 @@ dependencies = [ "regex-syntax", ] +[[package]] +name = "regex-automata" +version = "0.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132" +dependencies = [ + "regex-syntax", +] + [[package]] name = "regex-syntax" version = "0.6.25" @@ -3099,8 +3093,8 @@ dependencies = [ "sentry-contexts", "sentry-core", "sentry-debug-images", - "sentry-log", "sentry-panic", + "sentry-tracing", "tokio 1.6.1", ] @@ -3157,23 +3151,24 @@ dependencies = [ ] [[package]] -name = "sentry-log" +name = "sentry-panic" version = "0.23.0" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "66da5759b0704a2fb0d420863b0795ea3429739e188ff67fff82bb13dcd3cc50" +checksum = "692bf989f0c99f025e33d7f58e62822c3771f56d189698c66dcc863122255d95" dependencies = [ - "log", + "sentry-backtrace", "sentry-core", ] [[package]] -name = "sentry-panic" +name = "sentry-tracing" version = "0.23.0" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "692bf989f0c99f025e33d7f58e62822c3771f56d189698c66dcc863122255d95" +checksum = "d291df287241b0ef97f5bf9e9a595691ef8dfb49bc6acfd55b9dc2ade681f1c9" dependencies = [ - "sentry-backtrace", "sentry-core", + "tracing-core", + "tracing-subscriber", ] [[package]] @@ -3302,6 +3297,15 @@ dependencies = [ "opaque-debug 0.3.0", ] +[[package]] +name = "sharded-slab" +version = "0.1.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "740223c51853f3145fe7c90360d2d4232f2b62e3449489c207eccde818979982" +dependencies = [ + "lazy_static", +] + [[package]] name = "shlex" version = "0.1.1" @@ -3619,7 +3623,6 @@ dependencies = [ "cadence", "chrono", "console", - "env_logger", "failure", "filetime", "flate2", @@ -3633,11 +3636,9 @@ dependencies = [ "ipnetwork", "jsonwebtoken", "lazy_static", - "log", "lru", "num_cpus", "parking_lot 0.11.1", - "pretty_env_logger", "procspawn", "regex", "reqwest 0.11.0", @@ -3655,6 +3656,9 @@ dependencies = [ "thiserror", "tokio 0.1.22", "tokio 1.6.1", + "tracing", + "tracing-serde", + "tracing-subscriber", "url 2.2.2", "uuid 0.8.2", "warp", @@ -3734,15 +3738,6 @@ dependencies = [ "winapi 0.3.9", ] -[[package]] -name = "termcolor" -version = "1.1.2" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "2dfed899f0eb03f32ee8c6a0aabdb8a7949659e3466561fc0adf54e26d88c5f4" -dependencies = [ - "winapi-util", -] - [[package]] name = "terminal_size" version = "0.1.17" @@ -3782,6 +3777,15 @@ dependencies = [ "syn 1.0.73", ] +[[package]] +name = "thread_local" +version = "1.1.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8018d24e04c95ac8790716a5987d0fec4f8b27249ffa0f7d33f1369bdfb88cbd" +dependencies = [ + "once_cell", +] + [[package]] name = "time" version = "0.1.44" @@ -4158,9 +4162,21 @@ dependencies = [ "cfg-if 1.0.0", "log", "pin-project-lite", + "tracing-attributes", "tracing-core", ] +[[package]] +name = "tracing-attributes" +version = "0.1.15" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "c42e6fa53307c8a17e4ccd4dc81cf5ec38db9209f59b222210375b54ee40d1e2" +dependencies = [ + "proc-macro2 1.0.27", + "quote 1.0.9", + "syn 1.0.73", +] + [[package]] name = "tracing-core" version = "0.1.18" @@ -4170,6 +4186,49 @@ dependencies = [ "lazy_static", ] +[[package]] +name = "tracing-log" +version = "0.1.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a6923477a48e41c1951f1999ef8bb5a3023eb723ceadafe78ffb65dc366761e3" +dependencies = [ + "lazy_static", + "log", + "tracing-core", +] + +[[package]] +name = "tracing-serde" +version = "0.1.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "fb65ea441fbb84f9f6748fd496cf7f63ec9af5bca94dd86456978d055e8eb28b" +dependencies = [ + "serde", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.2.20" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b9cbe87a2fa7e35900ce5de20220a582a9483a7063811defce79d7cbd59d4cfe" +dependencies = [ + "ansi_term 0.12.1", + "chrono", + "lazy_static", + "matchers", + "regex", + "serde", + "serde_json", + "sharded-slab", + "smallvec 1.6.1", + "thread_local", + "tracing", + "tracing-core", + "tracing-log", + "tracing-serde", +] + [[package]] name = "trust-dns-proto" version = "0.5.0" diff --git a/crates/symbolicator/Cargo.toml b/crates/symbolicator/Cargo.toml index 9c90f5212..9a1300a94 100644 --- a/crates/symbolicator/Cargo.toml +++ b/crates/symbolicator/Cargo.toml @@ -14,7 +14,6 @@ base64 = "0.13.0" cadence = "0.25.0" chrono = { version = "0.4.19", features = ["serde"] } console = "0.14.0" -env_logger = "0.7.1" failure = "0.1.8" filetime = "0.2.14" flate2 = "1.0.0" @@ -27,18 +26,16 @@ humantime-serde = "1.0.1" ipnetwork = "0.18.0" jsonwebtoken = "7.2.0" lazy_static = "1.4.0" -log = { version = "0.4.13", features = ["serde"] } lru = "0.6.3" num_cpus = "1.13.0" parking_lot = "0.11.1" -pretty_env_logger = "0.4.0" procspawn = { version = "0.10.0", features = ["backtrace", "json"] } regex = "1.4.3" reqwest = { git = "https://github.com/jan-auer/reqwest", tag = "v0.11.0", features = ["gzip", "json", "stream", "trust-dns"] } rusoto_core = "0.46.0" rusoto_credential = "0.46.0" rusoto_s3 = "0.46.0" -sentry = { version = "0.23.0", features = ["debug-images", "log"] } +sentry = { version = "0.23.0", features = ["debug-images", "tracing"] } serde = { version = "1.0.119", features = ["derive", "rc"] } serde_json = "1.0.61" serde_yaml = "0.8.15" @@ -48,6 +45,9 @@ tempfile = "3.2.0" thiserror = "1.0.26" tokio = { version = "1.0.2", features = ["rt", "macros", "fs"] } tokio01 = { version = "0.1.22", package = "tokio" } +tracing = "0.1.26" +tracing-serde = "0.1.2" +tracing-subscriber = "0.2.20" url = { version = "2.2.0", features = ["serde"] } uuid = { version = "0.8.2", features = ["v4", "serde"] } zstd = "0.9.0" diff --git a/crates/symbolicator/src/cache.rs b/crates/symbolicator/src/cache.rs index d065762db..19ae7e01d 100644 --- a/crates/symbolicator/src/cache.rs +++ b/crates/symbolicator/src/cache.rs @@ -171,8 +171,9 @@ impl Cache { self.cache_dir.as_deref() } + #[tracing::instrument(fields(cache = self.name))] pub fn cleanup(&self) -> Result<()> { - log::info!("Cleaning up cache: {}", self.name); + tracing::info!("Cleaning up cache: {}", self.name); let cache_dir = self.cache_dir.clone().ok_or_else(|| { anyhow!("no caching configured! Did you provide a path to your config file?") })?; @@ -181,10 +182,12 @@ impl Cache { while !directories.is_empty() { let directory = directories.pop().unwrap(); + let span = tracing::info_span!("directory cleanup", directory = %directory.display()); + let _guard = span.enter(); let entries = match catch_not_found(|| read_dir(directory))? { Some(x) => x, None => { - log::warn!("Directory not found"); + tracing::warn!("Directory not found"); return Ok(()); } }; @@ -197,20 +200,20 @@ impl Cache { } else if let Err(e) = self.try_cleanup_path(&path) { sentry::with_scope( |scope| scope.set_extra("path", path.display().to_string().into()), - || log::error!("Failed to clean cache file: {:?}", e), + || tracing::error!(error = ?e, "Failed to clean cache file: {:?}", e), ); } } } - Ok(()) } + #[tracing::instrument(fields(cache = self.name))] fn try_cleanup_path(&self, path: &Path) -> Result<()> { - log::trace!("Checking {}", path.display()); + tracing::trace!("Checking {}", path.display()); anyhow::ensure!(path.is_file(), "not a file"); if catch_not_found(|| self.check_expiry(path))?.is_none() { - log::debug!("Removing {}", path.display()); + tracing::debug!("Removing {}", path.display()); catch_not_found(|| remove_file(path))?; } @@ -220,6 +223,7 @@ impl Cache { /// Validate cache expiration of path. If cache should not be used, /// `Err(io::ErrorKind::NotFound)` is returned. If cache is usable, `Ok(x)` is returned, where /// `x` indicates whether the file should be touched before using. + #[tracing::instrument(fields(cache.name = self.name), skip(self))] fn check_expiry(&self, path: &Path) -> io::Result { // We use `mtime` to keep track of both "cache last used" and "cache created" depending on // whether the file is a negative cache item or not, because literally every other @@ -237,7 +241,11 @@ impl Cache { // of last use. let metadata = path.metadata()?; - log::trace!("File length: {}", metadata.len()); + tracing::trace!( + metadata.len = metadata.len(), + "File length: {}", + metadata.len() + ); let expiration_strategy = expiration_strategy(&self.cache_config, path)?; @@ -256,7 +264,11 @@ impl Cache { }; if created_at < self.start_time || retry_malformed { - log::trace!("Created at is older than start time"); + tracing::trace!( + ?created_at, + start_time = ?self.start_time, + "Created at is older than start time" + ); return Err(io::ErrorKind::NotFound.into()); } } @@ -329,6 +341,7 @@ enum ExpirationStrategy { /// Reads a cache item at a given path and returns the cleanup strategy that should be used /// for the item. +#[tracing::instrument(skip(cache_config, path))] fn expiration_strategy(cache_config: &CacheConfig, path: &Path) -> io::Result { let metadata = path.metadata()?; @@ -339,7 +352,13 @@ fn expiration_strategy(cache_config: &CacheConfig, path: &Path) -> io::Result Result<()> { // Destructure so we do not accidentally forget to cleanup one of our members. let Self { @@ -490,7 +510,7 @@ impl Caches { for result in results { if let Err(err) = result { let stderr: &dyn std::error::Error = &*err; - log::error!("Failed to cleanup cache: {}", LogError(stderr)); + tracing::error!(error = %LogError(stderr), "Failed to cleanup cache: {}", LogError(stderr)); if first_error.is_none() { first_error = Some(err); } diff --git a/crates/symbolicator/src/cli.rs b/crates/symbolicator/src/cli.rs index 474758233..394a7ba84 100644 --- a/crates/symbolicator/src/cli.rs +++ b/crates/symbolicator/src/cli.rs @@ -80,7 +80,7 @@ pub fn execute() -> Result<()> { if let Some(hostname) = hostname::get().ok().and_then(|s| s.into_string().ok()) { tags.insert(hostname_tag, hostname); } else { - log::error!("could not read host name"); + tracing::error!("could not read host name"); } }; if let Some(environment_tag) = config.metrics.environment_tag.clone() { @@ -88,7 +88,7 @@ pub fn execute() -> Result<()> { { tags.insert(environment_tag, environment); } else { - log::error!("environment name not available"); + tracing::error!("environment name not available"); } }; @@ -97,7 +97,7 @@ pub fn execute() -> Result<()> { procspawn::ProcConfig::new() .config_callback(|| { - log::trace!("[procspawn] initializing in sub process"); + tracing::trace!("[procspawn] initializing in sub process"); metric!(counter("procspawn.init") += 1); }) .init(); diff --git a/crates/symbolicator/src/config.rs b/crates/symbolicator/src/config.rs index ff6ee6e4a..8e10d3a59 100644 --- a/crates/symbolicator/src/config.rs +++ b/crates/symbolicator/src/config.rs @@ -1,13 +1,14 @@ use std::env; +use std::fmt; use std::fs; use std::path::{Path, PathBuf}; use std::sync::Arc; use std::time::Duration; use anyhow::{Context, Result}; -use log::LevelFilter; use sentry::types::Dsn; -use serde::Deserialize; +use serde::{de, Deserialize, Deserializer}; +use tracing::level_filters::LevelFilter; use crate::sources::SourceConfig; @@ -30,6 +31,7 @@ pub enum LogFormat { #[serde(default)] pub struct Logging { /// The log level for the relay. + #[serde(deserialize_with = "deserialize_level_filter")] pub level: LevelFilter, /// Controls the log format. pub format: LogFormat, @@ -40,7 +42,7 @@ pub struct Logging { impl Default for Logging { fn default() -> Self { Logging { - level: LevelFilter::Info, + level: LevelFilter::INFO, format: LogFormat::Auto, enable_backtraces: true, } @@ -366,6 +368,44 @@ impl Config { } } +#[derive(Debug)] +struct LevelFilterVisitor; + +impl<'de> de::Visitor<'de> for LevelFilterVisitor { + type Value = LevelFilter; + + fn expecting(&self, formatter: &mut fmt::Formatter) -> std::fmt::Result { + write!( + formatter, + r#"one of the strings "off", "error", "warn", "info", "debug", or "trace""# + ) + } + + fn visit_str(self, v: &str) -> Result + where + E: de::Error, + { + match v { + "off" => Ok(LevelFilter::OFF), + "error" => Ok(LevelFilter::ERROR), + "warn" => Ok(LevelFilter::WARN), + "info" => Ok(LevelFilter::INFO), + "debug" => Ok(LevelFilter::DEBUG), + "trace" => Ok(LevelFilter::TRACE), + _ => Err(de::Error::unknown_variant( + v, + &["off", "error", "warn", "info", "debug", "trace"], + )), + } + } +} + +fn deserialize_level_filter<'de, D: Deserializer<'de>>( + deserializer: D, +) -> Result { + deserializer.deserialize_str(LevelFilterVisitor) +} + #[cfg(test)] mod tests { use super::*; diff --git a/crates/symbolicator/src/logging.rs b/crates/symbolicator/src/logging.rs index 6ff1d1866..01590baf9 100644 --- a/crates/symbolicator/src/logging.rs +++ b/crates/symbolicator/src/logging.rs @@ -3,28 +3,31 @@ use std::fmt; use std::io::{self, Write}; use chrono::{DateTime, Utc}; -use log::{Level, LevelFilter}; -use sentry::integrations::log::{breadcrumb_from_record, event_from_record}; +use sentry::integrations::tracing::{breadcrumb_from_event, event_from_event}; use serde::{Deserialize, Serialize}; +use tracing::level_filters::LevelFilter; +use tracing::{span, Level, Subscriber}; +use tracing_subscriber::fmt::{fmt, SubscriberBuilder}; +use tracing_subscriber::EnvFilter; use crate::config::{Config, LogFormat}; fn get_rust_log(level: LevelFilter) -> &'static str { match level { - LevelFilter::Off => "", - LevelFilter::Error => "ERROR", - LevelFilter::Warn => "WARN", - LevelFilter::Info => { + LevelFilter::OFF => "", + LevelFilter::ERROR => "ERROR", + LevelFilter::WARN => "WARN", + LevelFilter::INFO => { "INFO,\ trust_dns_proto=WARN" } - LevelFilter::Debug => { + LevelFilter::DEBUG => { "INFO,\ trust_dns_proto=WARN,\ actix_web::pipeline=DEBUG,\ symbolicator=DEBUG" } - LevelFilter::Trace => { + LevelFilter::TRACE => { "INFO,\ trust_dns_proto=WARN,\ actix_web::pipeline=DEBUG,\ @@ -33,58 +36,6 @@ fn get_rust_log(level: LevelFilter) -> &'static str { } } -fn pretty_logger() -> env_logger::Builder { - pretty_env_logger::formatted_builder() -} - -fn simplified_logger() -> env_logger::Builder { - let mut builder = env_logger::Builder::new(); - builder.format(|buf, record| { - writeln!( - buf, - "{} [{}] {}: {}", - buf.timestamp(), - record.module_path().unwrap_or(""), - record.level(), - record.args() - ) - }); - builder -} - -#[derive(Serialize, Deserialize, Debug)] -struct LogRecord<'a> { - timestamp: DateTime, - level: Level, - logger: &'a str, - message: String, - module_path: Option<&'a str>, - filename: Option<&'a str>, - lineno: Option, -} - -fn json_logger() -> env_logger::Builder { - let mut builder = env_logger::Builder::new(); - builder.format(|mut buf, record| -> io::Result<()> { - let record = LogRecord { - timestamp: Utc::now(), - level: record.level(), - logger: record.target(), - message: record.args().to_string(), - module_path: record.module_path(), - filename: record.file(), - lineno: record.line(), - }; - - serde_json::to_writer(&mut buf, &record) - .map_err(|err| io::Error::new(io::ErrorKind::Other, err))?; - - buf.write_all(b"\n")?; - Ok(()) - }); - builder -} - /// A delegating logger that also logs breadcrumbs. pub struct BreadcrumbLogger { inner: L, @@ -97,28 +48,49 @@ impl BreadcrumbLogger { } } -impl log::Log for BreadcrumbLogger +impl Subscriber for BreadcrumbLogger where - L: log::Log, + L: Subscriber, { - fn enabled(&self, md: &log::Metadata<'_>) -> bool { + fn enabled(&self, md: &tracing::Metadata<'_>) -> bool { self.inner.enabled(md) } - fn log(&self, record: &log::Record<'_>) { - if self.inner.enabled(record.metadata()) { - if record.level() == log::Level::Error { - sentry::capture_event(event_from_record(record)); + fn new_span(&self, span: &span::Attributes<'_>) -> span::Id { + self.inner.new_span(span) + } + + fn record(&self, span: &span::Id, values: &span::Record<'_>) { + self.inner.record(span, values); + } + + fn record_follows_from(&self, span: &span::Id, follows: &span::Id) { + self.inner.record_follows_from(span, follows); + } + + fn enter(&self, span: &span::Id) { + self.inner.enter(span); + } + + fn exit(&self, span: &span::Id) { + self.inner.exit(span); + } + + fn event(&self, event: &tracing::Event<'_>) { + if self.enabled(event.metadata()) { + if *event.metadata().level() == Level::ERROR { + sentry::capture_event(event_from_event(event)); } - sentry::add_breadcrumb(|| breadcrumb_from_record(record)); - self.inner.log(record); + sentry::add_breadcrumb(|| breadcrumb_from_event(event)); + self.inner.event(event); } } +} - fn flush(&self) { - self.inner.flush(); - } +fn set_global_logger(logger: L) { + tracing::subscriber::set_global_default(BreadcrumbLogger::new(logger)) + .expect("setting global default subscriber") } /// Initializes logging for the symbolicator. @@ -138,22 +110,16 @@ pub fn init_logging(config: &Config) { env::set_var("RUST_LOG", rust_log); } - let mut builder = match (config.logging.format, console::user_attended()) { - (LogFormat::Auto, true) | (LogFormat::Pretty, _) => pretty_logger(), - (LogFormat::Auto, false) | (LogFormat::Simplified, _) => simplified_logger(), - (LogFormat::Json, _) => json_logger(), - }; - - match env::var("RUST_LOG") { - Ok(rust_log) => builder.parse_filters(&rust_log), - Err(_) => builder.filter_level(config.logging.level), + let builder = fmt().with_env_filter(EnvFilter::from_default_env()); + match (config.logging.format, console::user_attended()) { + (LogFormat::Auto, true) | (LogFormat::Pretty, _) => { + set_global_logger(builder.pretty().finish()) + } + (LogFormat::Auto, false) | (LogFormat::Simplified, _) => { + set_global_logger(builder.compact().finish()) + } + (LogFormat::Json, _) => set_global_logger(builder.json().finish()), }; - - let logger = builder.build(); - log::set_max_level(logger.filter()); - - let breadcrumb_logger = Box::new(BreadcrumbLogger::new(logger)); - log::set_boxed_logger(breadcrumb_logger).unwrap(); } /// A wrapper around an [`Error`](std::error::Error) that prints its causes. @@ -174,8 +140,10 @@ impl<'a> fmt::Display for LogError<'a> { /// Logs an error to the configured logger or `stderr` if not yet configured. pub fn ensure_log_error(error: &anyhow::Error) { - if log::log_enabled!(log::Level::Error) { - log::error!("{:?}", error); + if tracing::Level::ERROR <= tracing::level_filters::STATIC_MAX_LEVEL + && tracing::Level::ERROR <= LevelFilter::current() + { + tracing::error!("{:?}", error); } else { eprintln!("{:?}", error); } diff --git a/crates/symbolicator/src/metrics.rs b/crates/symbolicator/src/metrics.rs index 2aec298ba..3bd841bf0 100644 --- a/crates/symbolicator/src/metrics.rs +++ b/crates/symbolicator/src/metrics.rs @@ -1,5 +1,6 @@ //! Provides access to the metrics sytem. use std::collections::BTreeMap; +use std::fmt; use std::net::ToSocketAddrs; use std::ops::{Deref, DerefMut}; use std::sync::Arc; @@ -69,10 +70,19 @@ pub fn set_client(client: MetricsClient) { } /// Tell the metrics system to report to statsd. -pub fn configure_statsd(prefix: &str, host: A, tags: BTreeMap) { +#[tracing::instrument] +pub fn configure_statsd( + prefix: &str, + host: A, + tags: BTreeMap, +) { let addrs: Vec<_> = host.to_socket_addrs().unwrap().collect(); if !addrs.is_empty() { - log::info!("Reporting metrics to statsd at {}", addrs[0]); + tracing::info!( + statsd = %addrs[0], + "Reporting metrics to statsd at {}", + addrs[0] + ); } let socket = std::net::UdpSocket::bind("0.0.0.0:0").unwrap(); socket.set_nonblocking(true).unwrap(); diff --git a/crates/symbolicator/src/server.rs b/crates/symbolicator/src/server.rs index 7c925257b..07624391c 100644 --- a/crates/symbolicator/src/server.rs +++ b/crates/symbolicator/src/server.rs @@ -18,6 +18,7 @@ pub fn create_app(state: Service) -> App { } /// Starts all actors and HTTP server based on loaded config. +#[tracing::instrument(skip(config))] pub fn run(config: Config) -> Result<()> { // Log this metric before actually starting the server. This allows to see restarts even if // service creation fails. The HTTP server is bound before the actix system runs. @@ -36,12 +37,12 @@ pub fn run(config: Config) -> Result<()> { let _guard = runtime.enter(); let service = Service::create(config).context("failed to create service state")?; - log::info!("Starting http server: {}", bind); + tracing::info!(server = %bind, "Starting http server: {}", bind); HttpServer::new(move || create_app(service.clone())) .bind(&bind) .context("failed to bind to the port")? .run(); - log::info!("System shutdown complete"); + tracing::info!("System shutdown complete"); Ok(()) } diff --git a/crates/symbolicator/src/services/bitcode.rs b/crates/symbolicator/src/services/bitcode.rs index 809a18b32..906a2eeeb 100644 --- a/crates/symbolicator/src/services/bitcode.rs +++ b/crates/symbolicator/src/services/bitcode.rs @@ -89,6 +89,7 @@ impl FetchFileRequest { /// Downloads the file and saves it to `path`. /// /// Actual implementation of [`FetchFileRequest::compute`]. + #[tracing::instrument] async fn fetch_file(self, path: PathBuf) -> Result { let download_file = self.cache.tempfile()?; let cache_key = self.get_cache_key(); @@ -100,11 +101,11 @@ impl FetchFileRequest { match result { Ok(DownloadStatus::NotFound) => { - log::debug!("No auxiliary DIF file found for {}", cache_key); + tracing::debug!(%cache_key, "No auxiliary DIF file found"); return Ok(CacheStatus::Negative); } Err(e) => { - log::debug!("Error while downloading file: {}", LogError(&e)); + tracing::debug!(error = %LogError(&e), "Error while downloading file"); return Ok(CacheStatus::CacheSpecificError(e.for_cache())); } Ok(DownloadStatus::Completed) => { @@ -132,7 +133,7 @@ impl FetchFileRequest { if let Err(err) = BcSymbolMap::parse(&view) { let kind = self.kind.to_string(); metric!(counter("services.bitcode.loaderrror") += 1, "kind" => &kind); - log::debug!("Failed to parse bcsymbolmap: {}", err); + tracing::debug!(error = %err, "Failed to parse bcsymbolmap"); return Ok(CacheStatus::Malformed(err.to_string())); } } @@ -140,7 +141,7 @@ impl FetchFileRequest { if let Err(err) = UuidMapping::parse_plist(self.uuid, &view) { let kind = self.kind.to_string(); metric!(counter("services.bitcode.loaderrror") += 1, "kind" => &kind); - log::debug!("Failed to parse plist: {}", err); + tracing::debug!(error = %err, "Failed to parse plist"); return Ok(CacheStatus::Malformed(err.to_string())); } } diff --git a/crates/symbolicator/src/services/cacher.rs b/crates/symbolicator/src/services/cacher.rs index 303b6a357..426bd2249 100644 --- a/crates/symbolicator/src/services/cacher.rs +++ b/crates/symbolicator/src/services/cacher.rs @@ -127,11 +127,11 @@ fn safe_path_segment(s: &str) -> String { } pub trait CacheItemRequest: 'static + Send { - type Item: 'static + Send + Sync; + type Item: 'static + Send + Sync + fmt::Debug; // XXX: Probably should have our own concrete error type for cacheactor instead of forcing our // ioerrors into other errors - type Error: 'static + From + Send + Sync; + type Error: 'static + From + Send + Sync + fmt::Debug; /// Returns the key by which this item is cached. fn get_cache_key(&self) -> CacheKey; @@ -158,7 +158,7 @@ pub trait CacheItemRequest: 'static + Send { ) -> Self::Item; } -impl Cacher { +impl Cacher { /// Constructs the path corresponding to the given [`CacheKey`]. /// /// Returns [`None`] if caching is disabled. @@ -180,6 +180,7 @@ impl Cacher { /// # Errors /// /// If there is an I/O error reading the cache [`CacheItemRequest::Error`] is returned. + #[tracing::instrument(fields(cacher.name, key = %key), skip(self, request))] fn lookup_cache( &self, request: &T, @@ -187,6 +188,9 @@ impl Cacher { path: &Path, ) -> Result, T::Error> { let name = self.config.name(); + + tracing::Span::current().record("cacher.name", &name); + sentry::configure_scope(|scope| { scope.set_extra( &format!("cache.{}.cache_path", name), @@ -201,7 +205,7 @@ impl Cacher { let status = CacheStatus::from_content(&byteview); if status == CacheStatus::Positive && !request.should_load(&byteview) { - log::trace!("Discarding {} at path {:?}", name, path); + tracing::trace!("Discarding {} at path {:?}", name, path); metric!(counter(&format!("caches.{}.file.discarded", name)) += 1); return Ok(None); } @@ -215,7 +219,7 @@ impl Cacher { ); let path = path.to_path_buf(); - log::trace!("Loading {} at path {:?}", name, path); + tracing::trace!("Loading {} at path {:?}", name, path); let item = request.load(key.scope.clone(), status, byteview, CachePath::Cached(path)); Ok(Some(item)) } @@ -228,6 +232,7 @@ impl Cacher { /// /// This method does not take care of ensuring the computation only happens once even /// for concurrent requests, see the public [`Cacher::compute_memoized`] for this. + #[tracing::instrument(fields(cacher.name, key = %key), skip(self, request))] async fn compute(&self, request: T, key: CacheKey) -> Result { // cache_path is None when caching is disabled. let cache_path = self.get_cache_path(&key); @@ -239,6 +244,7 @@ impl Cacher { let name = self.config.name(); let key = request.get_cache_key(); + tracing::Span::current().record("cacher.name", &name); // A file was not found. If this spikes, it's possible that the filesystem cache // just got pruned. @@ -256,7 +262,7 @@ impl Cacher { ); }); - log::trace!("Creating {} at path {:?}", name, cache_path); + tracing::trace!("Creating {} at path {:?}", name, cache_path); } let byteview = ByteView::open(temp_file.path())?; diff --git a/crates/symbolicator/src/services/cficaches.rs b/crates/symbolicator/src/services/cficaches.rs index e628ec28b..4036e1ca3 100644 --- a/crates/symbolicator/src/services/cficaches.rs +++ b/crates/symbolicator/src/services/cficaches.rs @@ -119,6 +119,7 @@ impl CacheItemRequest for FetchCfiCacheInternal { /// /// The extracted CFI is written to `path` in symbolic's /// [`CfiCache`](symbolic::minidump::cfi::CfiCache) format. + #[tracing::instrument] fn compute(&self, path: &Path) -> BoxedFuture> { let path = path.to_owned(); let threadpool = self.threadpool.clone(); @@ -141,7 +142,7 @@ impl CacheItemRequest for FetchCfiCacheInternal { } let status = if let Err(e) = write_cficache(&path, &*object) { - log::warn!("Could not write cficache: {}", e); + tracing::warn!(error = %e, "Could not write cficache: {}", e); sentry::capture_error(&e); CacheStatus::Malformed(e.to_string()) @@ -266,6 +267,7 @@ impl CfiCacheActor { /// /// The source file is probably an executable or so, the resulting file is in the format of /// [symbolic::minidump::cfi::CfiCache]. +#[tracing::instrument] fn write_cficache(path: &Path, object_handle: &ObjectHandle) -> Result<(), CfiCacheError> { configure_scope(|scope| { scope.set_transaction(Some("compute_cficache")); @@ -280,7 +282,7 @@ fn write_cficache(path: &Path, object_handle: &ObjectHandle) -> Result<(), CfiCa let file = File::create(&path)?; let writer = BufWriter::new(file); - log::debug!("Converting cficache for {}", object_handle.cache_key()); + tracing::debug!(cache_key = %object_handle.cache_key(), "Converting cficache for {}", object_handle.cache_key()); CfiCache::from_object(&object)?.write_to(writer)?; diff --git a/crates/symbolicator/src/services/download/filesystem.rs b/crates/symbolicator/src/services/download/filesystem.rs index 3379b24d0..04c72331e 100644 --- a/crates/symbolicator/src/services/download/filesystem.rs +++ b/crates/symbolicator/src/services/download/filesystem.rs @@ -58,6 +58,7 @@ impl FilesystemDownloader { } /// Download from a filesystem source. + #[tracing::instrument(skip(self))] pub async fn download_source( &self, file_source: FilesystemRemoteDif, @@ -65,7 +66,7 @@ impl FilesystemDownloader { ) -> Result { // All file I/O in this function is blocking! let abspath = file_source.path(); - log::debug!("Fetching debug file from {:?}", abspath); + tracing::debug!(abs_path = ?abspath, "Fetching debug file from {:?}", abspath); match fs::copy(abspath, &dest).await { Ok(_) => Ok(DownloadStatus::Completed), Err(e) => match e.kind() { diff --git a/crates/symbolicator/src/services/download/gcs.rs b/crates/symbolicator/src/services/download/gcs.rs index 968d3fa25..78723b3b3 100644 --- a/crates/symbolicator/src/services/download/gcs.rs +++ b/crates/symbolicator/src/services/download/gcs.rs @@ -157,6 +157,7 @@ impl GcsDownloader { } /// Requests a new GCS OAuth token. + #[tracing::instrument(skip(source_key))] async fn request_new_token(&self, source_key: &GcsSourceKey) -> Result { let expires_at = Utc::now() + Duration::minutes(58); let auth_jwt = get_auth_jwt(source_key, expires_at.timestamp() + 30)?; @@ -170,7 +171,7 @@ impl GcsDownloader { }); let response = request.send().await.map_err(|err| { - log::debug!("Failed to authenticate against gcs: {}", err); + tracing::debug!(error = %err, "Failed to authenticate against gcs: {}", err); GcsError::Auth(err) })?; @@ -212,6 +213,7 @@ impl GcsDownloader { /// - [`DownloadError::Reqwest`] /// - [`DownloadError::Rejected`] /// - [`DownloadError::Canceled`] + #[tracing::instrument(fields(key, bucket))] pub async fn download_source( &self, file_source: GcsRemoteDif, @@ -219,9 +221,13 @@ impl GcsDownloader { ) -> Result { let key = file_source.key(); let bucket = file_source.source.bucket.clone(); - log::debug!("Fetching from GCS: {} (from {})", &key, bucket); + + tracing::Span::current().record("key", &key.as_str()); + tracing::Span::current().record("bucket", &bucket.as_str()); + + tracing::debug!("Fetching from GCS: {} (from {})", &key, bucket); let token = self.get_token(&file_source.source.source_key).await?; - log::debug!("Got valid GCS token"); + tracing::debug!("Got valid GCS token"); let mut url = Url::parse("https://www.googleapis.com/download/storage/v1/b?alt=media") .map_err(|_| GcsError::InvalidUrl)?; @@ -242,7 +248,7 @@ impl GcsDownloader { match request.await { Ok(Ok(response)) => { if response.status().is_success() { - log::trace!("Success hitting GCS {} (from {})", &key, bucket); + tracing::trace!("Success hitting GCS {} (from {})", &key, bucket); let content_length = response .headers() @@ -259,7 +265,7 @@ impl GcsDownloader { response.status(), StatusCode::FORBIDDEN | StatusCode::UNAUTHORIZED ) { - log::debug!( + tracing::debug!( "Insufficient permissions to download from GCS {} (from {})", &key, &bucket, @@ -267,7 +273,8 @@ impl GcsDownloader { Err(DownloadError::Permissions) // If it's a client error, chances are either it's a 404 or it's permission-related. } else if response.status().is_client_error() { - log::debug!( + tracing::debug!( + response.status = %response.status(), "Unexpected client error status code from GCS {} (from {}): {}", &key, &bucket, @@ -275,7 +282,8 @@ impl GcsDownloader { ); Ok(DownloadStatus::NotFound) } else { - log::debug!( + tracing::debug!( + response.status = %response.status(), "Unexpected status code from GCS {} (from {}): {}", &key, &bucket, @@ -285,7 +293,8 @@ impl GcsDownloader { } } Ok(Err(e)) => { - log::debug!( + tracing::debug!( + error = %e, "Skipping response from GCS {} (from {}): {}", &key, &bucket, diff --git a/crates/symbolicator/src/services/download/http.rs b/crates/symbolicator/src/services/download/http.rs index 13155a8e4..5410f10fc 100644 --- a/crates/symbolicator/src/services/download/http.rs +++ b/crates/symbolicator/src/services/download/http.rs @@ -72,6 +72,7 @@ impl HttpDownloader { /// - [`DownloadError::Reqwest`] /// - [`DownloadError::Rejected`] /// - [`DownloadError::Canceled`] + #[tracing::instrument(fields(download_url), skip(self, file_source))] pub async fn download_source( &self, file_source: HttpRemoteDif, @@ -82,7 +83,9 @@ impl HttpDownloader { Err(_) => return Ok(DownloadStatus::NotFound), }; - log::debug!("Fetching debug file from {}", download_url); + tracing::Span::current().record("download_url", &download_url.as_str()); + + tracing::debug!("Fetching debug file from {}", download_url); let mut builder = self.client.get(download_url.clone()); for (key, value) in file_source.source.headers.iter() { @@ -98,7 +101,7 @@ impl HttpDownloader { match request.await { Ok(Ok(response)) => { if response.status().is_success() { - log::trace!("Success hitting {}", download_url); + tracing::trace!("Success hitting {}", download_url); let content_length = response .headers() @@ -116,18 +119,20 @@ impl HttpDownloader { response.status(), StatusCode::FORBIDDEN | StatusCode::UNAUTHORIZED ) { - log::debug!("Insufficient permissions to download from {}", download_url); + tracing::debug!("Insufficient permissions to download from {}", download_url); Err(DownloadError::Permissions) // If it's a client error, chances are either it's a 404 or it's permission-related. } else if response.status().is_client_error() { - log::debug!( + tracing::debug!( + response.status = %response.status(), "Unexpected client error status code from {}: {}", download_url, response.status() ); Ok(DownloadStatus::NotFound) } else { - log::debug!( + tracing::debug!( + response.status = %response.status(), "Unexpected status code from {}: {}", download_url, response.status() @@ -136,7 +141,7 @@ impl HttpDownloader { } } Ok(Err(e)) => { - log::debug!("Skipping response from {}: {}", download_url, e); + tracing::debug!(error = %e, "Skipping response from {}: {}", download_url, e); Err(DownloadError::Reqwest(e)) // must be wrong type } Err(_) => { diff --git a/crates/symbolicator/src/services/download/mod.rs b/crates/symbolicator/src/services/download/mod.rs index c7c6dde65..28fc2e69f 100644 --- a/crates/symbolicator/src/services/download/mod.rs +++ b/crates/symbolicator/src/services/download/mod.rs @@ -150,6 +150,7 @@ impl DownloadService { } /// Dispatches downloading of the given file to the appropriate source. + #[tracing::instrument(skip(self), fields(source = %source))] async fn dispatch_download( self: Arc, source: RemoteDif, @@ -178,16 +179,16 @@ impl DownloadService { Ok(status) => { match status { DownloadStatus::Completed => { - log::debug!("Fetched debug file from {}", source); + tracing::debug!(%source, "Fetched debug file"); } DownloadStatus::NotFound => { - log::debug!("Debug file not found at {}", source); + tracing::debug!(%source, "Debug file not found"); } }; Ok(status) } Err(err) => { - log::debug!("Failed to fetch debug file from {}: {}", source, err); + tracing::debug!(error = %err, %source, "Failed to fetch debug file"); Err(err) } } @@ -286,6 +287,7 @@ impl DownloadService { /// - [`DownloadError::BadDestination`] /// - [`DownloadError::Write`] /// - [`DownloadError::Canceled`] +#[tracing::instrument(fields(source), skip(stream))] async fn download_stream( source: impl Into, stream: impl Stream, DownloadError>>, @@ -294,8 +296,10 @@ async fn download_stream( ) -> Result { let source = source.into(); + tracing::Span::current().record("source", &source.to_string().as_str()); + // All file I/O in this function is blocking! - log::trace!("Downloading from {}", source); + tracing::trace!(%source, "Downloading"); let future = async { let mut file = File::create(&destination) .await diff --git a/crates/symbolicator/src/services/download/s3.rs b/crates/symbolicator/src/services/download/s3.rs index b00040085..af055705d 100644 --- a/crates/symbolicator/src/services/download/s3.rs +++ b/crates/symbolicator/src/services/download/s3.rs @@ -101,6 +101,7 @@ impl S3Downloader { } } + #[tracing::instrument(skip(key))] fn get_s3_client(&self, key: &Arc) -> Arc { let mut container = self.client_cache.lock(); if let Some(client) = container.get(&*key) { @@ -110,9 +111,8 @@ impl S3Downloader { metric!(counter("source.s3.client.create") += 1); let region = key.region.clone(); - log::debug!( - "Using AWS credentials provider: {:?}", - key.aws_credentials_provider + tracing::debug!( + aws_credentials_provider = ?key.aws_credentials_provider, ); let s3 = Arc::new(match key.aws_credentials_provider { AwsCredentialsProvider::Container => { @@ -146,6 +146,7 @@ impl S3Downloader { /// # Directly thrown errors /// - [`DownloadError::Io`] /// - [`DownloadError::Canceled`] + #[tracing::instrument] pub async fn download_source( &self, file_source: S3RemoteDif, @@ -153,7 +154,7 @@ impl S3Downloader { ) -> Result { let key = file_source.key(); let bucket = file_source.bucket(); - log::debug!("Fetching from s3: {} (from {})", &key, &bucket); + tracing::debug!(%key, %bucket, "Fetching from s3: {} (from {})", &key, &bucket); let source_key = &file_source.source.source_key; let client = self.get_s3_client(source_key); @@ -170,7 +171,7 @@ impl S3Downloader { let response = match request.await { Ok(Ok(response)) => response, Ok(Err(err)) => { - log::debug!("Skipping response from s3://{}/{}: {}", bucket, &key, err); + tracing::debug!(%key, %bucket, error = %err, "Skipping response from s3://{}/{}: {}", bucket, &key, err); // Do note that it's possible for Amazon to return different status codes when a // file is missing. 403 is returned if the `ListBucket` permission isn't available, @@ -196,7 +197,7 @@ impl S3Downloader { let stream = match response.body { Some(body) => body.map_err(DownloadError::Io), None => { - log::debug!("Empty response from s3:{}{}", bucket, &key); + tracing::debug!(%key, %bucket, "Empty response from s3:{}{}", bucket, &key); return Ok(DownloadStatus::NotFound); } }; diff --git a/crates/symbolicator/src/services/download/sentry.rs b/crates/symbolicator/src/services/download/sentry.rs index 13bb2b0e3..de250fb50 100644 --- a/crates/symbolicator/src/services/download/sentry.rs +++ b/crates/symbolicator/src/services/download/sentry.rs @@ -120,6 +120,7 @@ impl SentryDownloader { } /// Make a request to sentry, parse the result as a JSON SearchResult list. + #[tracing::instrument] async fn fetch_sentry_json( &self, query: &SearchQuery, @@ -134,10 +135,10 @@ impl SentryDownloader { .await?; if response.status().is_success() { - log::trace!("Success fetching index from Sentry"); + tracing::trace!("Success fetching index from Sentry"); Ok(response.json().await?) } else { - log::warn!("Sentry returned status code {}", response.status()); + tracing::warn!(response.status = %response.status(), "Sentry returned status code {}", response.status()); Err(SentryError::BadStatusCode(response.status())) } } @@ -145,6 +146,7 @@ impl SentryDownloader { /// Return the search results. /// /// If there are cached search results this skips the actual search. + #[tracing::instrument] async fn cached_sentry_search( &self, query: SearchQuery, @@ -167,7 +169,8 @@ impl SentryDownloader { } } - log::debug!( + tracing::debug!( + %query.index_url, "Fetching list of Sentry debug files from {}", &query.index_url ); @@ -250,6 +253,7 @@ impl SentryDownloader { /// - [`DownloadError::Reqwest`] /// - [`DownloadError::Rejected`] /// - [`DownloadError::Canceled`] + #[tracing::instrument(skip(self))] pub async fn download_source( &self, file_source: SentryRemoteDif, @@ -270,7 +274,7 @@ impl SentryDownloader { match request.await { Ok(Ok(response)) => { if response.status().is_success() { - log::trace!("Success hitting {}", download_url); + tracing::trace!(%download_url, "Success hitting {}", download_url); let content_length = response .headers() @@ -287,17 +291,25 @@ impl SentryDownloader { response.status(), StatusCode::FORBIDDEN | StatusCode::UNAUTHORIZED ) { - log::debug!("Insufficient permissions to download from {}", download_url); + tracing::debug!( + %download_url, + "Insufficient permissions to download from {}", + download_url + ); Err(DownloadError::Permissions) } else if response.status().is_client_error() { - log::debug!( + tracing::debug!( + %download_url, + response.status = %response.status(), "Unexpected client error status code from {}: {}", download_url, response.status() ); Ok(DownloadStatus::NotFound) } else { - log::debug!( + tracing::debug!( + %download_url, + response.status = %response.status(), "Unexpected status code from {}: {}", download_url, response.status() @@ -306,7 +318,7 @@ impl SentryDownloader { } } Ok(Err(e)) => { - log::debug!("Skipping response from {}: {}", download_url, e); + tracing::debug!(%download_url, error = %e, "Skipping response from {}: {}", download_url, e); Err(DownloadError::Reqwest(e)) // must be wrong type } // Timed out diff --git a/crates/symbolicator/src/services/objects/data_cache.rs b/crates/symbolicator/src/services/objects/data_cache.rs index f379e2a75..1da432270 100644 --- a/crates/symbolicator/src/services/objects/data_cache.rs +++ b/crates/symbolicator/src/services/objects/data_cache.rs @@ -148,9 +148,10 @@ impl CacheItemRequest for FetchFileDataRequest { /// /// If the object file did not exist on the source an `Ok` with [`CacheStatus::Negative`] will /// be returned. + #[tracing::instrument(skip(self))] fn compute(&self, path: &Path) -> BoxedFuture> { let cache_key = self.get_cache_key(); - log::trace!("Fetching file data for {}", cache_key); + tracing::trace!(%cache_key, "Fetching file data"); let path = path.to_owned(); let object_id = self.0.object_id.clone(); @@ -173,12 +174,12 @@ impl CacheItemRequest for FetchFileDataRequest { match status { Ok(DownloadStatus::NotFound) => { - log::debug!("No debug file found for {}", cache_key); + tracing::debug!(%cache_key, "No debug file found"); return Ok(CacheStatus::Negative); } Err(e) => { - log::debug!("Error while downloading file: {}", LogError(&e)); + tracing::debug!(error = %LogError(&e), "Error while downloading file"); return Ok(CacheStatus::CacheSpecificError(e.for_cache())); } @@ -187,7 +188,7 @@ impl CacheItemRequest for FetchFileDataRequest { } } - log::trace!("Finished download of {}", cache_key); + tracing::trace!(%cache_key, "Finished download"); let decompress_result = decompress_object_file(&download_file, tempfile_in(download_dir)?); diff --git a/crates/symbolicator/src/services/objects/meta_cache.rs b/crates/symbolicator/src/services/objects/meta_cache.rs index 05996b743..713d165b1 100644 --- a/crates/symbolicator/src/services/objects/meta_cache.rs +++ b/crates/symbolicator/src/services/objects/meta_cache.rs @@ -102,9 +102,10 @@ impl CacheItemRequest for FetchFileMetaRequest { /// This returns [`CacheStatus::CacheSpecificError`] if the download failed. If the /// data cache is [`CacheStatus::Negative`] or [`CacheStatus::Malformed`] then the same /// status is returned. + #[tracing::instrument(skip(self))] fn compute(&self, path: &Path) -> BoxedFuture> { let cache_key = self.get_cache_key(); - log::trace!("Fetching file meta for {}", cache_key); + tracing::trace!(%cache_key, "Fetching file meta"); let path = path.to_owned(); let data_cache = self.data_cache.clone(); @@ -126,7 +127,7 @@ impl CacheItemRequest for FetchFileMetaRequest { has_sources: object.has_sources(), }; - log::trace!("Persisting object meta for {}: {:?}", cache_key, meta); + tracing::trace!(%cache_key, ?meta, "Persisting object meta"); serde_json::to_writer(&mut new_cache, &meta)?; } } @@ -153,6 +154,7 @@ impl CacheItemRequest for FetchFileMetaRequest { /// /// If the `status` is [`CacheStatus::Malformed`] or [`CacheStatus::Negative`] the metadata /// returned will contain the default [`ObjectMetaHandle::features`]. + #[tracing::instrument(skip(data))] fn load( &self, scope: Scope, @@ -164,10 +166,8 @@ impl CacheItemRequest for FetchFileMetaRequest { // get the malformed marker. let features = match status { CacheStatus::Positive => serde_json::from_slice(&data).unwrap_or_else(|err| { - log::error!( - "Failed to load positive ObjectFileMeta cache for {:?}: {:?}", - self.get_cache_key(), - err + tracing::error!(cache_key = ?self.get_cache_key(), error = ?err, + "Failed to load positive ObjectFileMeta cache", ); Default::default() }), diff --git a/crates/symbolicator/src/services/objects/mod.rs b/crates/symbolicator/src/services/objects/mod.rs index 92e1a003c..7ffddf69d 100644 --- a/crates/symbolicator/src/services/objects/mod.rs +++ b/crates/symbolicator/src/services/objects/mod.rs @@ -259,10 +259,11 @@ impl ObjectsActor { // the search by debug/code id. We do not surface those errors to the // user (instead we default to an empty search result) and only report // them internally. - log::error!( - "Failed to fetch file list from {}: {}", + tracing::error!( + source_type = type_name, + error = %LogError(&err), + "Failed to fetch file list from {}", type_name, - LogError(&err) ); Vec::new() }) diff --git a/crates/symbolicator/src/services/symbolication.rs b/crates/symbolicator/src/services/symbolication.rs index 8578bb481..163ffdcd4 100644 --- a/crates/symbolicator/src/services/symbolication.rs +++ b/crates/symbolicator/src/services/symbolication.rs @@ -167,6 +167,7 @@ impl CfiCacheModules { /// Extend the CacheModules with the fetched caches represented by /// [`CfiCacheResult`]. + #[tracing::instrument] fn extend(&mut self, cfi_caches: Vec) { self.cache_files.extend( cfi_caches @@ -183,10 +184,10 @@ impl CfiCacheModules { CacheStatus::Negative => ObjectFileStatus::Missing, CacheStatus::Malformed(details) => { let err = CfiCacheError::ObjectParsing(ObjectError::Malformed); - log::warn!( - "Error while parsing cficache: {} ({})", - LogError(&err), - details + tracing::warn!( + error = %LogError(&err), + %details, + "Error while parsing cficache", ); ObjectFileStatus::from(&err) } @@ -194,7 +195,7 @@ impl CfiCacheModules { // from a previous cficache conversion attempt. CacheStatus::CacheSpecificError(details) => { let err = CfiCacheError::ObjectParsing(ObjectError::Malformed); - log::warn!("Cached error from parsing cficache: {}", details); + tracing::warn!(%details, "Cached error from parsing cficache"); ObjectFileStatus::from(&err) } }; @@ -211,7 +212,7 @@ impl CfiCacheModules { } } Err(err) => { - log::debug!("Error while fetching cficache: {}", LogError(err.as_ref())); + tracing::debug!(error = %LogError(err.as_ref()), "Error while fetching cficache" ); CfiModule { cfi_status: ObjectFileStatus::from(err.as_ref()), ..Default::default() @@ -468,7 +469,8 @@ impl SymbolicationActor { sentry::end_session_with_status(status); let response = error.to_symbolication_response(); - log::error!("Symbolication error: {:?}", anyhow::Error::new(error)); + let error = anyhow::Error::new(error); + tracing::error!(%error, "Symbolication error"); response } }; @@ -933,6 +935,7 @@ impl SymCacheLookup { } } +#[tracing::instrument(skip(caches))] fn symbolicate_frame( caches: &SymCacheLookup, registers: &Registers, @@ -953,7 +956,7 @@ fn symbolicate_frame( } } - log::trace!("Loading symcache"); + tracing::trace!("Loading symcache"); let symcache = match lookup_result .symcache .as_ref() @@ -991,7 +994,7 @@ fn symbolicate_frame( .object_info .abs_to_rel_addr(absolute_caller_addr) .ok_or_else(|| { - log::warn!( + tracing::warn!( "Underflow when trying to subtract image start addr from caller address after heuristics" ); metric!(counter("relative_addr.underflow") += 1); @@ -1001,12 +1004,12 @@ fn symbolicate_frame( addr } } else { - log::warn!("Underflow when trying to subtract image start addr from caller address before heuristics"); + tracing::warn!("Underflow when trying to subtract image start addr from caller address before heuristics"); metric!(counter("relative_addr.underflow") += 1); return Err(FrameStatus::MissingSymbol); }; - log::trace!("Symbolicating {:#x}", relative_addr); + tracing::trace!(relative_addr, "Symbolicating {:#x}", relative_addr); let line_infos = match symcache.lookup(relative_addr) { Ok(x) => x, Err(_) => return Err(FrameStatus::Malformed), @@ -1716,7 +1719,7 @@ fn load_cfi_for_processor( .filter_map(|(code_id, cfi_path)| { let bytes = ByteView::open(cfi_path) .map_err(|err| { - log::error!("Error while reading cficache: {}", LogError(&err)); + tracing::error!(error = %LogError(&err), "Error while reading cficache"); err }) .ok()?; @@ -1725,7 +1728,7 @@ fn load_cfi_for_processor( // This mostly never happens since we already checked the files // after downloading and they would have been tagged with // CacheStatus::Malformed. - log::error!("Error while loading cficache: {}", LogError(&err)); + tracing::error!(error = %LogError(&err), "Error while loading cficache"); err }) .ok()?; @@ -1945,6 +1948,7 @@ impl SymbolicationActor { .context("Minidump stackwalk future cancelled")?) } + #[tracing::instrument] async fn do_stackwalk_minidump( self, scope: Scope, @@ -1954,7 +1958,7 @@ impl SymbolicationActor { ) -> Result<(SymbolicateStacktraces, MinidumpState), SymbolicationError> { let future = async move { let len = minidump_file.metadata()?.len(); - log::debug!("Processing minidump ({} bytes)", len); + tracing::debug!(len, "Processing minidump ({} bytes)", len); metric!(time_raw("minidump.upload.size") = len); let mut cfi_caches = CfiCacheModules::new(); @@ -1984,11 +1988,15 @@ impl SymbolicationActor { ); }); } - Err(e) => log::error!("Failed to save minidump {:?}", &e), + Err(e) => { + tracing::error!(error = ?e, "Failed to save minidump") + } }; } } else { - log::debug!("No diagnostics retention configured, not saving minidump"); + tracing::debug!( + "No diagnostics retention configured, not saving minidump" + ); } // we explicitly match and return here, otherwise the borrow checker will diff --git a/crates/symbolicator/src/services/symcaches.rs b/crates/symbolicator/src/services/symcaches.rs index 2e825eb13..0b216bcef 100644 --- a/crates/symbolicator/src/services/symcaches.rs +++ b/crates/symbolicator/src/services/symcaches.rs @@ -160,6 +160,7 @@ struct FetchSymCacheInternal { /// This is the actual implementation of [`CacheItemRequest::compute`] for /// [`FetchSymCacheInternal`] but outside of the trait so it can be written as async/await /// code. +#[tracing::instrument] async fn fetch_difs_and_compute_symcache( path: PathBuf, object_meta: Arc, @@ -185,7 +186,7 @@ async fn fetch_difs_and_compute_symcache( let status = match write_symcache(&path, &*object_handle, bcsymbolmap_handle) { Ok(_) => CacheStatus::Positive, Err(err) => { - log::warn!("Failed to write symcache: {}", err); + tracing::warn!(error = %err, "Failed to write symcache"); sentry::capture_error(&err); CacheStatus::Malformed(err.to_string()) } @@ -342,6 +343,7 @@ impl SymCacheActor { /// /// It is assumed both the `object_handle` contains a positive cache. The /// `bcsymbolmap_handle` can only exist for a positive cache so does not have this issue. +#[tracing::instrument(fields(object_handle = %object_handle))] fn write_symcache( path: &Path, object_handle: &ObjectHandle, @@ -361,7 +363,8 @@ fn write_symcache( let bcsymbolmap = handle .bc_symbol_map() .map_err(SymCacheError::BcSymbolMapError)?; - log::debug!( + tracing::debug!( + uuid = %handle.uuid, "Adding BCSymbolMap {} to dSYM {}", handle.uuid, object_handle @@ -373,7 +376,7 @@ fn write_symcache( let file = File::create(&path)?; let mut writer = BufWriter::new(file); - log::debug!("Converting symcache for {}", object_handle.cache_key()); + tracing::debug!(cache_key = %object_handle.cache_key(), "Converting symcache for {}", object_handle.cache_key()); SymCacheWriter::write_object(&symbolic_object, &mut writer).map_err(SymCacheError::Writing)?; diff --git a/crates/symbolicator/src/test.rs b/crates/symbolicator/src/test.rs index afa9b7b9c..1b80a152a 100644 --- a/crates/symbolicator/src/test.rs +++ b/crates/symbolicator/src/test.rs @@ -23,8 +23,9 @@ use std::sync::atomic::{AtomicUsize, Ordering}; use std::sync::Arc; use futures::{FutureExt, TryFutureExt}; -use log::LevelFilter; use reqwest::Url; +use tracing_subscriber::filter::EnvFilter; +use tracing_subscriber::fmt::fmt; use warp::filters::fs::File; use warp::reject::{Reject, Rejection}; use warp::Filter; @@ -42,9 +43,9 @@ pub use tempfile::TempDir; /// - Initializes logs: The logger only captures logs from the `symbolicator` crate and mutes all /// other logs (such as actix or symbolic). pub(crate) fn setup() { - env_logger::builder() - .filter(Some("symbolicator"), LevelFilter::Trace) - .is_test(true) + fmt() + .with_env_filter(EnvFilter::new("symbolicator=trace")) + .with_test_writer() .try_init() .ok(); } diff --git a/crates/symbolicator/src/utils/http.rs b/crates/symbolicator/src/utils/http.rs index d32eee59e..41cd33055 100644 --- a/crates/symbolicator/src/utils/http.rs +++ b/crates/symbolicator/src/utils/http.rs @@ -13,6 +13,7 @@ lazy_static::lazy_static! { ].into_iter().map(|x| x.parse().unwrap()).collect(); } +#[tracing::instrument] fn is_external_ip(ip: std::net::IpAddr) -> bool { let addr = match ip { IpAddr::V4(x) => x, @@ -26,7 +27,8 @@ fn is_external_ip(ip: std::net::IpAddr) -> bool { for network in &*RESERVED_IP_BLOCKS { if network.contains(addr) { metric!(counter("http.blocked_ip") += 1); - log::debug!( + tracing::debug!( + %addr, "Blocked attempt to connect to reserved IP address: {}", addr ); From 7b40b7af232cb5b07ac7df97aebb46f7f7a068d5 Mon Sep 17 00:00:00 2001 From: Sebastian Zivota Date: Wed, 25 Aug 2021 12:11:08 +0200 Subject: [PATCH 02/16] Rewrite init_logging --- Cargo.lock | 1 - crates/symbolicator/Cargo.toml | 1 - crates/symbolicator/src/logging.rs | 83 +++++------------------------- 3 files changed, 14 insertions(+), 71 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 18884fec9..340b270b5 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3657,7 +3657,6 @@ dependencies = [ "tokio 0.1.22", "tokio 1.6.1", "tracing", - "tracing-serde", "tracing-subscriber", "url 2.2.2", "uuid 0.8.2", diff --git a/crates/symbolicator/Cargo.toml b/crates/symbolicator/Cargo.toml index 9a1300a94..4be719db8 100644 --- a/crates/symbolicator/Cargo.toml +++ b/crates/symbolicator/Cargo.toml @@ -46,7 +46,6 @@ thiserror = "1.0.26" tokio = { version = "1.0.2", features = ["rt", "macros", "fs"] } tokio01 = { version = "0.1.22", package = "tokio" } tracing = "0.1.26" -tracing-serde = "0.1.2" tracing-subscriber = "0.2.20" url = { version = "2.2.0", features = ["serde"] } uuid = { version = "0.8.2", features = ["v4", "serde"] } diff --git a/crates/symbolicator/src/logging.rs b/crates/symbolicator/src/logging.rs index 01590baf9..3f50935be 100644 --- a/crates/symbolicator/src/logging.rs +++ b/crates/symbolicator/src/logging.rs @@ -1,14 +1,10 @@ use std::env; use std::fmt; -use std::io::{self, Write}; -use chrono::{DateTime, Utc}; -use sentry::integrations::tracing::{breadcrumb_from_event, event_from_event}; -use serde::{Deserialize, Serialize}; use tracing::level_filters::LevelFilter; -use tracing::{span, Level, Subscriber}; -use tracing_subscriber::fmt::{fmt, SubscriberBuilder}; -use tracing_subscriber::EnvFilter; +use tracing_subscriber::fmt::Layer; +use tracing_subscriber::prelude::*; +use tracing_subscriber::{EnvFilter, FmtSubscriber}; use crate::config::{Config, LogFormat}; @@ -36,63 +32,6 @@ fn get_rust_log(level: LevelFilter) -> &'static str { } } -/// A delegating logger that also logs breadcrumbs. -pub struct BreadcrumbLogger { - inner: L, -} - -impl BreadcrumbLogger { - /// Initializes a new breadcrumb logger. - pub fn new(inner: L) -> Self { - Self { inner } - } -} - -impl Subscriber for BreadcrumbLogger -where - L: Subscriber, -{ - fn enabled(&self, md: &tracing::Metadata<'_>) -> bool { - self.inner.enabled(md) - } - - fn new_span(&self, span: &span::Attributes<'_>) -> span::Id { - self.inner.new_span(span) - } - - fn record(&self, span: &span::Id, values: &span::Record<'_>) { - self.inner.record(span, values); - } - - fn record_follows_from(&self, span: &span::Id, follows: &span::Id) { - self.inner.record_follows_from(span, follows); - } - - fn enter(&self, span: &span::Id) { - self.inner.enter(span); - } - - fn exit(&self, span: &span::Id) { - self.inner.exit(span); - } - - fn event(&self, event: &tracing::Event<'_>) { - if self.enabled(event.metadata()) { - if *event.metadata().level() == Level::ERROR { - sentry::capture_event(event_from_event(event)); - } - - sentry::add_breadcrumb(|| breadcrumb_from_event(event)); - self.inner.event(event); - } - } -} - -fn set_global_logger(logger: L) { - tracing::subscriber::set_global_default(BreadcrumbLogger::new(logger)) - .expect("setting global default subscriber") -} - /// Initializes logging for the symbolicator. /// /// This considers the `RUST_LOG` environment variable and defaults it to the level specified in the @@ -110,16 +49,22 @@ pub fn init_logging(config: &Config) { env::set_var("RUST_LOG", rust_log); } - let builder = fmt().with_env_filter(EnvFilter::from_default_env()); + let filter = EnvFilter::from_default_env(); + let sentry = sentry::integrations::tracing::layer(); + let subscriber = FmtSubscriber::new().with(filter).with(sentry); + let format = Layer::new(); match (config.logging.format, console::user_attended()) { (LogFormat::Auto, true) | (LogFormat::Pretty, _) => { - set_global_logger(builder.pretty().finish()) + tracing::subscriber::set_global_default(subscriber.with(format.pretty())) } (LogFormat::Auto, false) | (LogFormat::Simplified, _) => { - set_global_logger(builder.compact().finish()) + tracing::subscriber::set_global_default(subscriber.with(format.compact())) + } + (LogFormat::Json, _) => { + tracing::subscriber::set_global_default(subscriber.with(format.json())) } - (LogFormat::Json, _) => set_global_logger(builder.json().finish()), - }; + } + .expect("setting global default subscriber"); } /// A wrapper around an [`Error`](std::error::Error) that prints its causes. From 3cc5546e98e57f2901a6723b32b1791a7f3e6dbc Mon Sep 17 00:00:00 2001 From: Sebastian Zivota Date: Wed, 25 Aug 2021 12:31:37 +0200 Subject: [PATCH 03/16] Keep original log messages This partially reverts commit ee1243b52222c1e3d3cbad5254ac865a7f226aa5. --- crates/symbolicator/src/cache.rs | 32 ++++--------------- crates/symbolicator/src/endpoints/proxy.rs | 2 +- crates/symbolicator/src/server.rs | 3 +- crates/symbolicator/src/services/bitcode.rs | 9 +++--- crates/symbolicator/src/services/cacher.rs | 12 ++----- crates/symbolicator/src/services/cficaches.rs | 6 ++-- .../src/services/download/filesystem.rs | 3 +- .../symbolicator/src/services/download/gcs.rs | 11 +------ .../src/services/download/http.rs | 7 +--- .../symbolicator/src/services/download/mod.rs | 12 +++---- .../symbolicator/src/services/download/s3.rs | 11 +++---- .../src/services/download/sentry.rs | 20 +++--------- .../src/services/objects/data_cache.rs | 9 +++--- .../src/services/objects/meta_cache.rs | 12 +++---- .../symbolicator/src/services/objects/mod.rs | 5 ++- .../src/services/symbolication.rs | 27 +++++++--------- crates/symbolicator/src/services/symcaches.rs | 7 ++-- crates/symbolicator/src/utils/http.rs | 2 -- 18 files changed, 58 insertions(+), 132 deletions(-) diff --git a/crates/symbolicator/src/cache.rs b/crates/symbolicator/src/cache.rs index 19ae7e01d..41a135c1e 100644 --- a/crates/symbolicator/src/cache.rs +++ b/crates/symbolicator/src/cache.rs @@ -171,7 +171,6 @@ impl Cache { self.cache_dir.as_deref() } - #[tracing::instrument(fields(cache = self.name))] pub fn cleanup(&self) -> Result<()> { tracing::info!("Cleaning up cache: {}", self.name); let cache_dir = self.cache_dir.clone().ok_or_else(|| { @@ -182,8 +181,6 @@ impl Cache { while !directories.is_empty() { let directory = directories.pop().unwrap(); - let span = tracing::info_span!("directory cleanup", directory = %directory.display()); - let _guard = span.enter(); let entries = match catch_not_found(|| read_dir(directory))? { Some(x) => x, None => { @@ -200,15 +197,15 @@ impl Cache { } else if let Err(e) = self.try_cleanup_path(&path) { sentry::with_scope( |scope| scope.set_extra("path", path.display().to_string().into()), - || tracing::error!(error = ?e, "Failed to clean cache file: {:?}", e), + || tracing::error!("Failed to clean cache file: {:?}", e), ); } } } + Ok(()) } - #[tracing::instrument(fields(cache = self.name))] fn try_cleanup_path(&self, path: &Path) -> Result<()> { tracing::trace!("Checking {}", path.display()); anyhow::ensure!(path.is_file(), "not a file"); @@ -223,7 +220,6 @@ impl Cache { /// Validate cache expiration of path. If cache should not be used, /// `Err(io::ErrorKind::NotFound)` is returned. If cache is usable, `Ok(x)` is returned, where /// `x` indicates whether the file should be touched before using. - #[tracing::instrument(fields(cache.name = self.name), skip(self))] fn check_expiry(&self, path: &Path) -> io::Result { // We use `mtime` to keep track of both "cache last used" and "cache created" depending on // whether the file is a negative cache item or not, because literally every other @@ -241,11 +237,7 @@ impl Cache { // of last use. let metadata = path.metadata()?; - tracing::trace!( - metadata.len = metadata.len(), - "File length: {}", - metadata.len() - ); + tracing::trace!("File length: {}", metadata.len()); let expiration_strategy = expiration_strategy(&self.cache_config, path)?; @@ -264,11 +256,7 @@ impl Cache { }; if created_at < self.start_time || retry_malformed { - tracing::trace!( - ?created_at, - start_time = ?self.start_time, - "Created at is older than start time" - ); + tracing::trace!("Created at is older than start time"); return Err(io::ErrorKind::NotFound.into()); } } @@ -341,7 +329,6 @@ enum ExpirationStrategy { /// Reads a cache item at a given path and returns the cleanup strategy that should be used /// for the item. -#[tracing::instrument(skip(cache_config, path))] fn expiration_strategy(cache_config: &CacheConfig, path: &Path) -> io::Result { let metadata = path.metadata()?; @@ -352,13 +339,7 @@ fn expiration_strategy(cache_config: &CacheConfig, path: &Path) -> io::Result Result<()> { // Destructure so we do not accidentally forget to cleanup one of our members. let Self { @@ -510,7 +490,7 @@ impl Caches { for result in results { if let Err(err) = result { let stderr: &dyn std::error::Error = &*err; - tracing::error!(error = %LogError(stderr), "Failed to cleanup cache: {}", LogError(stderr)); + tracing::error!("Failed to cleanup cache: {}", LogError(stderr)); if first_error.is_none() { first_error = Some(err); } diff --git a/crates/symbolicator/src/endpoints/proxy.rs b/crates/symbolicator/src/endpoints/proxy.rs index 56f364afe..a0008ae25 100644 --- a/crates/symbolicator/src/endpoints/proxy.rs +++ b/crates/symbolicator/src/endpoints/proxy.rs @@ -22,7 +22,7 @@ async fn load_object(state: &Service, path: &str) -> Result return Ok(None), }; - log::debug!("Searching for {:?} ({:?})", object_id, filetypes); + tracing::debug!("Searching for {:?} ({:?})", object_id, filetypes); let found_object = state .objects() diff --git a/crates/symbolicator/src/server.rs b/crates/symbolicator/src/server.rs index 07624391c..da6bb1463 100644 --- a/crates/symbolicator/src/server.rs +++ b/crates/symbolicator/src/server.rs @@ -18,7 +18,6 @@ pub fn create_app(state: Service) -> App { } /// Starts all actors and HTTP server based on loaded config. -#[tracing::instrument(skip(config))] pub fn run(config: Config) -> Result<()> { // Log this metric before actually starting the server. This allows to see restarts even if // service creation fails. The HTTP server is bound before the actix system runs. @@ -37,7 +36,7 @@ pub fn run(config: Config) -> Result<()> { let _guard = runtime.enter(); let service = Service::create(config).context("failed to create service state")?; - tracing::info!(server = %bind, "Starting http server: {}", bind); + tracing::info!("Starting http server: {}", bind); HttpServer::new(move || create_app(service.clone())) .bind(&bind) .context("failed to bind to the port")? diff --git a/crates/symbolicator/src/services/bitcode.rs b/crates/symbolicator/src/services/bitcode.rs index 906a2eeeb..13f49738e 100644 --- a/crates/symbolicator/src/services/bitcode.rs +++ b/crates/symbolicator/src/services/bitcode.rs @@ -89,7 +89,6 @@ impl FetchFileRequest { /// Downloads the file and saves it to `path`. /// /// Actual implementation of [`FetchFileRequest::compute`]. - #[tracing::instrument] async fn fetch_file(self, path: PathBuf) -> Result { let download_file = self.cache.tempfile()?; let cache_key = self.get_cache_key(); @@ -101,11 +100,11 @@ impl FetchFileRequest { match result { Ok(DownloadStatus::NotFound) => { - tracing::debug!(%cache_key, "No auxiliary DIF file found"); + tracing::debug!("No auxiliary DIF file found for {}", cache_key); return Ok(CacheStatus::Negative); } Err(e) => { - tracing::debug!(error = %LogError(&e), "Error while downloading file"); + tracing::debug!("Error while downloading file: {}", LogError(&e)); return Ok(CacheStatus::CacheSpecificError(e.for_cache())); } Ok(DownloadStatus::Completed) => { @@ -133,7 +132,7 @@ impl FetchFileRequest { if let Err(err) = BcSymbolMap::parse(&view) { let kind = self.kind.to_string(); metric!(counter("services.bitcode.loaderrror") += 1, "kind" => &kind); - tracing::debug!(error = %err, "Failed to parse bcsymbolmap"); + tracing::debug!("Failed to parse bcsymbolmap: {}", err); return Ok(CacheStatus::Malformed(err.to_string())); } } @@ -141,7 +140,7 @@ impl FetchFileRequest { if let Err(err) = UuidMapping::parse_plist(self.uuid, &view) { let kind = self.kind.to_string(); metric!(counter("services.bitcode.loaderrror") += 1, "kind" => &kind); - tracing::debug!(error = %err, "Failed to parse plist"); + tracing::debug!("Failed to parse plist: {}", err); return Ok(CacheStatus::Malformed(err.to_string())); } } diff --git a/crates/symbolicator/src/services/cacher.rs b/crates/symbolicator/src/services/cacher.rs index 426bd2249..9fb5e59eb 100644 --- a/crates/symbolicator/src/services/cacher.rs +++ b/crates/symbolicator/src/services/cacher.rs @@ -127,11 +127,11 @@ fn safe_path_segment(s: &str) -> String { } pub trait CacheItemRequest: 'static + Send { - type Item: 'static + Send + Sync + fmt::Debug; + type Item: 'static + Send + Sync; // XXX: Probably should have our own concrete error type for cacheactor instead of forcing our // ioerrors into other errors - type Error: 'static + From + Send + Sync + fmt::Debug; + type Error: 'static + From + Send + Sync; /// Returns the key by which this item is cached. fn get_cache_key(&self) -> CacheKey; @@ -158,7 +158,7 @@ pub trait CacheItemRequest: 'static + Send { ) -> Self::Item; } -impl Cacher { +impl Cacher { /// Constructs the path corresponding to the given [`CacheKey`]. /// /// Returns [`None`] if caching is disabled. @@ -180,7 +180,6 @@ impl Cacher { /// # Errors /// /// If there is an I/O error reading the cache [`CacheItemRequest::Error`] is returned. - #[tracing::instrument(fields(cacher.name, key = %key), skip(self, request))] fn lookup_cache( &self, request: &T, @@ -188,9 +187,6 @@ impl Cacher { path: &Path, ) -> Result, T::Error> { let name = self.config.name(); - - tracing::Span::current().record("cacher.name", &name); - sentry::configure_scope(|scope| { scope.set_extra( &format!("cache.{}.cache_path", name), @@ -232,7 +228,6 @@ impl Cacher { /// /// This method does not take care of ensuring the computation only happens once even /// for concurrent requests, see the public [`Cacher::compute_memoized`] for this. - #[tracing::instrument(fields(cacher.name, key = %key), skip(self, request))] async fn compute(&self, request: T, key: CacheKey) -> Result { // cache_path is None when caching is disabled. let cache_path = self.get_cache_path(&key); @@ -244,7 +239,6 @@ impl Cacher { let name = self.config.name(); let key = request.get_cache_key(); - tracing::Span::current().record("cacher.name", &name); // A file was not found. If this spikes, it's possible that the filesystem cache // just got pruned. diff --git a/crates/symbolicator/src/services/cficaches.rs b/crates/symbolicator/src/services/cficaches.rs index 4036e1ca3..d731f5440 100644 --- a/crates/symbolicator/src/services/cficaches.rs +++ b/crates/symbolicator/src/services/cficaches.rs @@ -119,7 +119,6 @@ impl CacheItemRequest for FetchCfiCacheInternal { /// /// The extracted CFI is written to `path` in symbolic's /// [`CfiCache`](symbolic::minidump::cfi::CfiCache) format. - #[tracing::instrument] fn compute(&self, path: &Path) -> BoxedFuture> { let path = path.to_owned(); let threadpool = self.threadpool.clone(); @@ -142,7 +141,7 @@ impl CacheItemRequest for FetchCfiCacheInternal { } let status = if let Err(e) = write_cficache(&path, &*object) { - tracing::warn!(error = %e, "Could not write cficache: {}", e); + tracing::warn!("Could not write cficache: {}", e); sentry::capture_error(&e); CacheStatus::Malformed(e.to_string()) @@ -267,7 +266,6 @@ impl CfiCacheActor { /// /// The source file is probably an executable or so, the resulting file is in the format of /// [symbolic::minidump::cfi::CfiCache]. -#[tracing::instrument] fn write_cficache(path: &Path, object_handle: &ObjectHandle) -> Result<(), CfiCacheError> { configure_scope(|scope| { scope.set_transaction(Some("compute_cficache")); @@ -282,7 +280,7 @@ fn write_cficache(path: &Path, object_handle: &ObjectHandle) -> Result<(), CfiCa let file = File::create(&path)?; let writer = BufWriter::new(file); - tracing::debug!(cache_key = %object_handle.cache_key(), "Converting cficache for {}", object_handle.cache_key()); + tracing::debug!("Converting cficache for {}", object_handle.cache_key()); CfiCache::from_object(&object)?.write_to(writer)?; diff --git a/crates/symbolicator/src/services/download/filesystem.rs b/crates/symbolicator/src/services/download/filesystem.rs index 04c72331e..84377679f 100644 --- a/crates/symbolicator/src/services/download/filesystem.rs +++ b/crates/symbolicator/src/services/download/filesystem.rs @@ -58,7 +58,6 @@ impl FilesystemDownloader { } /// Download from a filesystem source. - #[tracing::instrument(skip(self))] pub async fn download_source( &self, file_source: FilesystemRemoteDif, @@ -66,7 +65,7 @@ impl FilesystemDownloader { ) -> Result { // All file I/O in this function is blocking! let abspath = file_source.path(); - tracing::debug!(abs_path = ?abspath, "Fetching debug file from {:?}", abspath); + tracing::debug!("Fetching debug file from {:?}", abspath); match fs::copy(abspath, &dest).await { Ok(_) => Ok(DownloadStatus::Completed), Err(e) => match e.kind() { diff --git a/crates/symbolicator/src/services/download/gcs.rs b/crates/symbolicator/src/services/download/gcs.rs index 78723b3b3..0a143e8f5 100644 --- a/crates/symbolicator/src/services/download/gcs.rs +++ b/crates/symbolicator/src/services/download/gcs.rs @@ -157,7 +157,6 @@ impl GcsDownloader { } /// Requests a new GCS OAuth token. - #[tracing::instrument(skip(source_key))] async fn request_new_token(&self, source_key: &GcsSourceKey) -> Result { let expires_at = Utc::now() + Duration::minutes(58); let auth_jwt = get_auth_jwt(source_key, expires_at.timestamp() + 30)?; @@ -171,7 +170,7 @@ impl GcsDownloader { }); let response = request.send().await.map_err(|err| { - tracing::debug!(error = %err, "Failed to authenticate against gcs: {}", err); + tracing::debug!("Failed to authenticate against gcs: {}", err); GcsError::Auth(err) })?; @@ -213,7 +212,6 @@ impl GcsDownloader { /// - [`DownloadError::Reqwest`] /// - [`DownloadError::Rejected`] /// - [`DownloadError::Canceled`] - #[tracing::instrument(fields(key, bucket))] pub async fn download_source( &self, file_source: GcsRemoteDif, @@ -221,10 +219,6 @@ impl GcsDownloader { ) -> Result { let key = file_source.key(); let bucket = file_source.source.bucket.clone(); - - tracing::Span::current().record("key", &key.as_str()); - tracing::Span::current().record("bucket", &bucket.as_str()); - tracing::debug!("Fetching from GCS: {} (from {})", &key, bucket); let token = self.get_token(&file_source.source.source_key).await?; tracing::debug!("Got valid GCS token"); @@ -274,7 +268,6 @@ impl GcsDownloader { // If it's a client error, chances are either it's a 404 or it's permission-related. } else if response.status().is_client_error() { tracing::debug!( - response.status = %response.status(), "Unexpected client error status code from GCS {} (from {}): {}", &key, &bucket, @@ -283,7 +276,6 @@ impl GcsDownloader { Ok(DownloadStatus::NotFound) } else { tracing::debug!( - response.status = %response.status(), "Unexpected status code from GCS {} (from {}): {}", &key, &bucket, @@ -294,7 +286,6 @@ impl GcsDownloader { } Ok(Err(e)) => { tracing::debug!( - error = %e, "Skipping response from GCS {} (from {}): {}", &key, &bucket, diff --git a/crates/symbolicator/src/services/download/http.rs b/crates/symbolicator/src/services/download/http.rs index 5410f10fc..c363d60c3 100644 --- a/crates/symbolicator/src/services/download/http.rs +++ b/crates/symbolicator/src/services/download/http.rs @@ -72,7 +72,6 @@ impl HttpDownloader { /// - [`DownloadError::Reqwest`] /// - [`DownloadError::Rejected`] /// - [`DownloadError::Canceled`] - #[tracing::instrument(fields(download_url), skip(self, file_source))] pub async fn download_source( &self, file_source: HttpRemoteDif, @@ -83,8 +82,6 @@ impl HttpDownloader { Err(_) => return Ok(DownloadStatus::NotFound), }; - tracing::Span::current().record("download_url", &download_url.as_str()); - tracing::debug!("Fetching debug file from {}", download_url); let mut builder = self.client.get(download_url.clone()); @@ -124,7 +121,6 @@ impl HttpDownloader { // If it's a client error, chances are either it's a 404 or it's permission-related. } else if response.status().is_client_error() { tracing::debug!( - response.status = %response.status(), "Unexpected client error status code from {}: {}", download_url, response.status() @@ -132,7 +128,6 @@ impl HttpDownloader { Ok(DownloadStatus::NotFound) } else { tracing::debug!( - response.status = %response.status(), "Unexpected status code from {}: {}", download_url, response.status() @@ -141,7 +136,7 @@ impl HttpDownloader { } } Ok(Err(e)) => { - tracing::debug!(error = %e, "Skipping response from {}: {}", download_url, e); + tracing::debug!("Skipping response from {}: {}", download_url, e); Err(DownloadError::Reqwest(e)) // must be wrong type } Err(_) => { diff --git a/crates/symbolicator/src/services/download/mod.rs b/crates/symbolicator/src/services/download/mod.rs index 28fc2e69f..495e64c81 100644 --- a/crates/symbolicator/src/services/download/mod.rs +++ b/crates/symbolicator/src/services/download/mod.rs @@ -150,7 +150,6 @@ impl DownloadService { } /// Dispatches downloading of the given file to the appropriate source. - #[tracing::instrument(skip(self), fields(source = %source))] async fn dispatch_download( self: Arc, source: RemoteDif, @@ -179,16 +178,16 @@ impl DownloadService { Ok(status) => { match status { DownloadStatus::Completed => { - tracing::debug!(%source, "Fetched debug file"); + tracing::debug!("Fetched debug file from {}", source); } DownloadStatus::NotFound => { - tracing::debug!(%source, "Debug file not found"); + tracing::debug!("Debug file not found at {}", source); } }; Ok(status) } Err(err) => { - tracing::debug!(error = %err, %source, "Failed to fetch debug file"); + tracing::debug!("Failed to fetch debug file from {}: {}", source, err); Err(err) } } @@ -287,7 +286,6 @@ impl DownloadService { /// - [`DownloadError::BadDestination`] /// - [`DownloadError::Write`] /// - [`DownloadError::Canceled`] -#[tracing::instrument(fields(source), skip(stream))] async fn download_stream( source: impl Into, stream: impl Stream, DownloadError>>, @@ -296,10 +294,8 @@ async fn download_stream( ) -> Result { let source = source.into(); - tracing::Span::current().record("source", &source.to_string().as_str()); - // All file I/O in this function is blocking! - tracing::trace!(%source, "Downloading"); + tracing::trace!("Downloading from {}", source); let future = async { let mut file = File::create(&destination) .await diff --git a/crates/symbolicator/src/services/download/s3.rs b/crates/symbolicator/src/services/download/s3.rs index af055705d..7a1cbc928 100644 --- a/crates/symbolicator/src/services/download/s3.rs +++ b/crates/symbolicator/src/services/download/s3.rs @@ -101,7 +101,6 @@ impl S3Downloader { } } - #[tracing::instrument(skip(key))] fn get_s3_client(&self, key: &Arc) -> Arc { let mut container = self.client_cache.lock(); if let Some(client) = container.get(&*key) { @@ -112,7 +111,8 @@ impl S3Downloader { let region = key.region.clone(); tracing::debug!( - aws_credentials_provider = ?key.aws_credentials_provider, + "Using AWS credentials provider: {:?}", + key.aws_credentials_provider ); let s3 = Arc::new(match key.aws_credentials_provider { AwsCredentialsProvider::Container => { @@ -146,7 +146,6 @@ impl S3Downloader { /// # Directly thrown errors /// - [`DownloadError::Io`] /// - [`DownloadError::Canceled`] - #[tracing::instrument] pub async fn download_source( &self, file_source: S3RemoteDif, @@ -154,7 +153,7 @@ impl S3Downloader { ) -> Result { let key = file_source.key(); let bucket = file_source.bucket(); - tracing::debug!(%key, %bucket, "Fetching from s3: {} (from {})", &key, &bucket); + tracing::debug!("Fetching from s3: {} (from {})", &key, &bucket); let source_key = &file_source.source.source_key; let client = self.get_s3_client(source_key); @@ -171,7 +170,7 @@ impl S3Downloader { let response = match request.await { Ok(Ok(response)) => response, Ok(Err(err)) => { - tracing::debug!(%key, %bucket, error = %err, "Skipping response from s3://{}/{}: {}", bucket, &key, err); + tracing::debug!("Skipping response from s3://{}/{}: {}", bucket, &key, err); // Do note that it's possible for Amazon to return different status codes when a // file is missing. 403 is returned if the `ListBucket` permission isn't available, @@ -197,7 +196,7 @@ impl S3Downloader { let stream = match response.body { Some(body) => body.map_err(DownloadError::Io), None => { - tracing::debug!(%key, %bucket, "Empty response from s3:{}{}", bucket, &key); + tracing::debug!("Empty response from s3:{}{}", bucket, &key); return Ok(DownloadStatus::NotFound); } }; diff --git a/crates/symbolicator/src/services/download/sentry.rs b/crates/symbolicator/src/services/download/sentry.rs index de250fb50..6ee85c03f 100644 --- a/crates/symbolicator/src/services/download/sentry.rs +++ b/crates/symbolicator/src/services/download/sentry.rs @@ -120,7 +120,6 @@ impl SentryDownloader { } /// Make a request to sentry, parse the result as a JSON SearchResult list. - #[tracing::instrument] async fn fetch_sentry_json( &self, query: &SearchQuery, @@ -138,7 +137,7 @@ impl SentryDownloader { tracing::trace!("Success fetching index from Sentry"); Ok(response.json().await?) } else { - tracing::warn!(response.status = %response.status(), "Sentry returned status code {}", response.status()); + tracing::warn!("Sentry returned status code {}", response.status()); Err(SentryError::BadStatusCode(response.status())) } } @@ -146,7 +145,6 @@ impl SentryDownloader { /// Return the search results. /// /// If there are cached search results this skips the actual search. - #[tracing::instrument] async fn cached_sentry_search( &self, query: SearchQuery, @@ -170,7 +168,6 @@ impl SentryDownloader { } tracing::debug!( - %query.index_url, "Fetching list of Sentry debug files from {}", &query.index_url ); @@ -253,7 +250,6 @@ impl SentryDownloader { /// - [`DownloadError::Reqwest`] /// - [`DownloadError::Rejected`] /// - [`DownloadError::Canceled`] - #[tracing::instrument(skip(self))] pub async fn download_source( &self, file_source: SentryRemoteDif, @@ -274,7 +270,7 @@ impl SentryDownloader { match request.await { Ok(Ok(response)) => { if response.status().is_success() { - tracing::trace!(%download_url, "Success hitting {}", download_url); + tracing::trace!("Success hitting {}", download_url); let content_length = response .headers() @@ -291,16 +287,10 @@ impl SentryDownloader { response.status(), StatusCode::FORBIDDEN | StatusCode::UNAUTHORIZED ) { - tracing::debug!( - %download_url, - "Insufficient permissions to download from {}", - download_url - ); + tracing::debug!("Insufficient permissions to download from {}", download_url); Err(DownloadError::Permissions) } else if response.status().is_client_error() { tracing::debug!( - %download_url, - response.status = %response.status(), "Unexpected client error status code from {}: {}", download_url, response.status() @@ -308,8 +298,6 @@ impl SentryDownloader { Ok(DownloadStatus::NotFound) } else { tracing::debug!( - %download_url, - response.status = %response.status(), "Unexpected status code from {}: {}", download_url, response.status() @@ -318,7 +306,7 @@ impl SentryDownloader { } } Ok(Err(e)) => { - tracing::debug!(%download_url, error = %e, "Skipping response from {}: {}", download_url, e); + tracing::debug!("Skipping response from {}: {}", download_url, e); Err(DownloadError::Reqwest(e)) // must be wrong type } // Timed out diff --git a/crates/symbolicator/src/services/objects/data_cache.rs b/crates/symbolicator/src/services/objects/data_cache.rs index 1da432270..2aba839b4 100644 --- a/crates/symbolicator/src/services/objects/data_cache.rs +++ b/crates/symbolicator/src/services/objects/data_cache.rs @@ -148,10 +148,9 @@ impl CacheItemRequest for FetchFileDataRequest { /// /// If the object file did not exist on the source an `Ok` with [`CacheStatus::Negative`] will /// be returned. - #[tracing::instrument(skip(self))] fn compute(&self, path: &Path) -> BoxedFuture> { let cache_key = self.get_cache_key(); - tracing::trace!(%cache_key, "Fetching file data"); + tracing::trace!("Fetching file data for {}", cache_key); let path = path.to_owned(); let object_id = self.0.object_id.clone(); @@ -174,12 +173,12 @@ impl CacheItemRequest for FetchFileDataRequest { match status { Ok(DownloadStatus::NotFound) => { - tracing::debug!(%cache_key, "No debug file found"); + tracing::debug!("No debug file found for {}", cache_key); return Ok(CacheStatus::Negative); } Err(e) => { - tracing::debug!(error = %LogError(&e), "Error while downloading file"); + tracing::debug!("Error while downloading file: {}", LogError(&e)); return Ok(CacheStatus::CacheSpecificError(e.for_cache())); } @@ -188,7 +187,7 @@ impl CacheItemRequest for FetchFileDataRequest { } } - tracing::trace!(%cache_key, "Finished download"); + tracing::trace!("Finished download of {}", cache_key); let decompress_result = decompress_object_file(&download_file, tempfile_in(download_dir)?); diff --git a/crates/symbolicator/src/services/objects/meta_cache.rs b/crates/symbolicator/src/services/objects/meta_cache.rs index 713d165b1..4d2ec28c4 100644 --- a/crates/symbolicator/src/services/objects/meta_cache.rs +++ b/crates/symbolicator/src/services/objects/meta_cache.rs @@ -102,10 +102,9 @@ impl CacheItemRequest for FetchFileMetaRequest { /// This returns [`CacheStatus::CacheSpecificError`] if the download failed. If the /// data cache is [`CacheStatus::Negative`] or [`CacheStatus::Malformed`] then the same /// status is returned. - #[tracing::instrument(skip(self))] fn compute(&self, path: &Path) -> BoxedFuture> { let cache_key = self.get_cache_key(); - tracing::trace!(%cache_key, "Fetching file meta"); + tracing::trace!("Fetching file meta for {}", cache_key); let path = path.to_owned(); let data_cache = self.data_cache.clone(); @@ -127,7 +126,7 @@ impl CacheItemRequest for FetchFileMetaRequest { has_sources: object.has_sources(), }; - tracing::trace!(%cache_key, ?meta, "Persisting object meta"); + tracing::trace!("Persisting object meta for {}: {:?}", cache_key, meta); serde_json::to_writer(&mut new_cache, &meta)?; } } @@ -154,7 +153,6 @@ impl CacheItemRequest for FetchFileMetaRequest { /// /// If the `status` is [`CacheStatus::Malformed`] or [`CacheStatus::Negative`] the metadata /// returned will contain the default [`ObjectMetaHandle::features`]. - #[tracing::instrument(skip(data))] fn load( &self, scope: Scope, @@ -166,8 +164,10 @@ impl CacheItemRequest for FetchFileMetaRequest { // get the malformed marker. let features = match status { CacheStatus::Positive => serde_json::from_slice(&data).unwrap_or_else(|err| { - tracing::error!(cache_key = ?self.get_cache_key(), error = ?err, - "Failed to load positive ObjectFileMeta cache", + tracing::error!( + "Failed to load positive ObjectFileMeta cache for {:?}: {:?}", + self.get_cache_key(), + err ); Default::default() }), diff --git a/crates/symbolicator/src/services/objects/mod.rs b/crates/symbolicator/src/services/objects/mod.rs index 7ffddf69d..368fe2199 100644 --- a/crates/symbolicator/src/services/objects/mod.rs +++ b/crates/symbolicator/src/services/objects/mod.rs @@ -260,10 +260,9 @@ impl ObjectsActor { // user (instead we default to an empty search result) and only report // them internally. tracing::error!( - source_type = type_name, - error = %LogError(&err), - "Failed to fetch file list from {}", + "Failed to fetch file list from {}: {}", type_name, + LogError(&err) ); Vec::new() }) diff --git a/crates/symbolicator/src/services/symbolication.rs b/crates/symbolicator/src/services/symbolication.rs index 163ffdcd4..a7f06cdd7 100644 --- a/crates/symbolicator/src/services/symbolication.rs +++ b/crates/symbolicator/src/services/symbolication.rs @@ -167,7 +167,6 @@ impl CfiCacheModules { /// Extend the CacheModules with the fetched caches represented by /// [`CfiCacheResult`]. - #[tracing::instrument] fn extend(&mut self, cfi_caches: Vec) { self.cache_files.extend( cfi_caches @@ -185,9 +184,9 @@ impl CfiCacheModules { CacheStatus::Malformed(details) => { let err = CfiCacheError::ObjectParsing(ObjectError::Malformed); tracing::warn!( - error = %LogError(&err), - %details, - "Error while parsing cficache", + "Error while parsing cficache: {} ({})", + LogError(&err), + details ); ObjectFileStatus::from(&err) } @@ -195,7 +194,7 @@ impl CfiCacheModules { // from a previous cficache conversion attempt. CacheStatus::CacheSpecificError(details) => { let err = CfiCacheError::ObjectParsing(ObjectError::Malformed); - tracing::warn!(%details, "Cached error from parsing cficache"); + tracing::warn!("Cached error from parsing cficache: {}", details); ObjectFileStatus::from(&err) } }; @@ -212,7 +211,7 @@ impl CfiCacheModules { } } Err(err) => { - tracing::debug!(error = %LogError(err.as_ref()), "Error while fetching cficache" ); + tracing::debug!("Error while fetching cficache: {}", LogError(err.as_ref())); CfiModule { cfi_status: ObjectFileStatus::from(err.as_ref()), ..Default::default() @@ -470,7 +469,7 @@ impl SymbolicationActor { let response = error.to_symbolication_response(); let error = anyhow::Error::new(error); - tracing::error!(%error, "Symbolication error"); + tracing::error!("Symbolication error: {:?}", error); response } }; @@ -935,7 +934,6 @@ impl SymCacheLookup { } } -#[tracing::instrument(skip(caches))] fn symbolicate_frame( caches: &SymCacheLookup, registers: &Registers, @@ -1009,7 +1007,7 @@ fn symbolicate_frame( return Err(FrameStatus::MissingSymbol); }; - tracing::trace!(relative_addr, "Symbolicating {:#x}", relative_addr); + tracing::trace!("Symbolicating {:#x}", relative_addr); let line_infos = match symcache.lookup(relative_addr) { Ok(x) => x, Err(_) => return Err(FrameStatus::Malformed), @@ -1719,7 +1717,7 @@ fn load_cfi_for_processor( .filter_map(|(code_id, cfi_path)| { let bytes = ByteView::open(cfi_path) .map_err(|err| { - tracing::error!(error = %LogError(&err), "Error while reading cficache"); + tracing::error!("Error while reading cficache: {}", LogError(&err)); err }) .ok()?; @@ -1728,7 +1726,7 @@ fn load_cfi_for_processor( // This mostly never happens since we already checked the files // after downloading and they would have been tagged with // CacheStatus::Malformed. - tracing::error!(error = %LogError(&err), "Error while loading cficache"); + tracing::error!("Error while loading cficache: {}", LogError(&err)); err }) .ok()?; @@ -1948,7 +1946,6 @@ impl SymbolicationActor { .context("Minidump stackwalk future cancelled")?) } - #[tracing::instrument] async fn do_stackwalk_minidump( self, scope: Scope, @@ -1958,7 +1955,7 @@ impl SymbolicationActor { ) -> Result<(SymbolicateStacktraces, MinidumpState), SymbolicationError> { let future = async move { let len = minidump_file.metadata()?.len(); - tracing::debug!(len, "Processing minidump ({} bytes)", len); + tracing::debug!("Processing minidump ({} bytes)", len); metric!(time_raw("minidump.upload.size") = len); let mut cfi_caches = CfiCacheModules::new(); @@ -1988,9 +1985,7 @@ impl SymbolicationActor { ); }); } - Err(e) => { - tracing::error!(error = ?e, "Failed to save minidump") - } + Err(e) => tracing::error!("Failed to save minidump {:?}", &e), }; } } else { diff --git a/crates/symbolicator/src/services/symcaches.rs b/crates/symbolicator/src/services/symcaches.rs index 0b216bcef..cee77be69 100644 --- a/crates/symbolicator/src/services/symcaches.rs +++ b/crates/symbolicator/src/services/symcaches.rs @@ -160,7 +160,6 @@ struct FetchSymCacheInternal { /// This is the actual implementation of [`CacheItemRequest::compute`] for /// [`FetchSymCacheInternal`] but outside of the trait so it can be written as async/await /// code. -#[tracing::instrument] async fn fetch_difs_and_compute_symcache( path: PathBuf, object_meta: Arc, @@ -186,7 +185,7 @@ async fn fetch_difs_and_compute_symcache( let status = match write_symcache(&path, &*object_handle, bcsymbolmap_handle) { Ok(_) => CacheStatus::Positive, Err(err) => { - tracing::warn!(error = %err, "Failed to write symcache"); + tracing::warn!("Failed to write symcache: {}", err); sentry::capture_error(&err); CacheStatus::Malformed(err.to_string()) } @@ -343,7 +342,6 @@ impl SymCacheActor { /// /// It is assumed both the `object_handle` contains a positive cache. The /// `bcsymbolmap_handle` can only exist for a positive cache so does not have this issue. -#[tracing::instrument(fields(object_handle = %object_handle))] fn write_symcache( path: &Path, object_handle: &ObjectHandle, @@ -364,7 +362,6 @@ fn write_symcache( .bc_symbol_map() .map_err(SymCacheError::BcSymbolMapError)?; tracing::debug!( - uuid = %handle.uuid, "Adding BCSymbolMap {} to dSYM {}", handle.uuid, object_handle @@ -376,7 +373,7 @@ fn write_symcache( let file = File::create(&path)?; let mut writer = BufWriter::new(file); - tracing::debug!(cache_key = %object_handle.cache_key(), "Converting symcache for {}", object_handle.cache_key()); + tracing::debug!("Converting symcache for {}", object_handle.cache_key()); SymCacheWriter::write_object(&symbolic_object, &mut writer).map_err(SymCacheError::Writing)?; diff --git a/crates/symbolicator/src/utils/http.rs b/crates/symbolicator/src/utils/http.rs index 41cd33055..e30d6804b 100644 --- a/crates/symbolicator/src/utils/http.rs +++ b/crates/symbolicator/src/utils/http.rs @@ -13,7 +13,6 @@ lazy_static::lazy_static! { ].into_iter().map(|x| x.parse().unwrap()).collect(); } -#[tracing::instrument] fn is_external_ip(ip: std::net::IpAddr) -> bool { let addr = match ip { IpAddr::V4(x) => x, @@ -28,7 +27,6 @@ fn is_external_ip(ip: std::net::IpAddr) -> bool { if network.contains(addr) { metric!(counter("http.blocked_ip") += 1); tracing::debug!( - %addr, "Blocked attempt to connect to reserved IP address: {}", addr ); From 67ceb0d5b4f17acc6f18f9728abea11ef24915b2 Mon Sep 17 00:00:00 2001 From: Sebastian Zivota Date: Wed, 25 Aug 2021 12:35:34 +0200 Subject: [PATCH 04/16] Disable displaying targets --- crates/symbolicator/src/logging.rs | 2 +- crates/symbolicator/src/test.rs | 2 ++ 2 files changed, 3 insertions(+), 1 deletion(-) diff --git a/crates/symbolicator/src/logging.rs b/crates/symbolicator/src/logging.rs index 3f50935be..2571329e9 100644 --- a/crates/symbolicator/src/logging.rs +++ b/crates/symbolicator/src/logging.rs @@ -52,7 +52,7 @@ pub fn init_logging(config: &Config) { let filter = EnvFilter::from_default_env(); let sentry = sentry::integrations::tracing::layer(); let subscriber = FmtSubscriber::new().with(filter).with(sentry); - let format = Layer::new(); + let format = Layer::new().with_target(false); match (config.logging.format, console::user_attended()) { (LogFormat::Auto, true) | (LogFormat::Pretty, _) => { tracing::subscriber::set_global_default(subscriber.with(format.pretty())) diff --git a/crates/symbolicator/src/test.rs b/crates/symbolicator/src/test.rs index 1b80a152a..e53a4caf6 100644 --- a/crates/symbolicator/src/test.rs +++ b/crates/symbolicator/src/test.rs @@ -45,6 +45,8 @@ pub use tempfile::TempDir; pub(crate) fn setup() { fmt() .with_env_filter(EnvFilter::new("symbolicator=trace")) + .with_target(false) + .pretty() .with_test_writer() .try_init() .ok(); From 7701c8e9c555546c89619bb689e8ce9d6786d5bd Mon Sep 17 00:00:00 2001 From: Sebastian Zivota Date: Wed, 25 Aug 2021 12:38:54 +0200 Subject: [PATCH 05/16] Minor fix --- crates/symbolicator/src/metrics.rs | 14 ++------------ 1 file changed, 2 insertions(+), 12 deletions(-) diff --git a/crates/symbolicator/src/metrics.rs b/crates/symbolicator/src/metrics.rs index 3bd841bf0..a395d6161 100644 --- a/crates/symbolicator/src/metrics.rs +++ b/crates/symbolicator/src/metrics.rs @@ -1,6 +1,5 @@ //! Provides access to the metrics sytem. use std::collections::BTreeMap; -use std::fmt; use std::net::ToSocketAddrs; use std::ops::{Deref, DerefMut}; use std::sync::Arc; @@ -70,19 +69,10 @@ pub fn set_client(client: MetricsClient) { } /// Tell the metrics system to report to statsd. -#[tracing::instrument] -pub fn configure_statsd( - prefix: &str, - host: A, - tags: BTreeMap, -) { +pub fn configure_statsd(prefix: &str, host: A, tags: BTreeMap) { let addrs: Vec<_> = host.to_socket_addrs().unwrap().collect(); if !addrs.is_empty() { - tracing::info!( - statsd = %addrs[0], - "Reporting metrics to statsd at {}", - addrs[0] - ); + tracing::info!("Reporting metrics to statsd at {}", addrs[0]); } let socket = std::net::UdpSocket::bind("0.0.0.0:0").unwrap(); socket.set_nonblocking(true).unwrap(); From 23731beecc6c8c0acffdf3febf5e58ab747db140 Mon Sep 17 00:00:00 2001 From: Sebastian Zivota Date: Wed, 25 Aug 2021 13:30:27 +0200 Subject: [PATCH 06/16] Changelog --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index d8e745c59..d51e3b5a8 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -23,6 +23,7 @@ - Source candidates which symbolicator has failed to download due to non-400 errors are now being returned in symbolication payloads. These candidates include additional diagnostic info which briefly describes the download error. ([#512](https://github.com/getsentry/symbolicator/pull/512)) - If a DIF object candidate could not be downloaded due to a lack of permissions, their respective entry in a symbolication response will now mention something about permissions instead of marking the candidate as just Missing. ([#512](https://github.com/getsentry/symbolicator/pull/512), [#518](https://github.com/getsentry/symbolicator/pull/518)) - Introduced the `max_concurrent_requests` config setting, which limits the number of requests that will be processed concurrently. It defaults to `None`, i.e., no limit. ([#521](https://github.com/getsentry/symbolicator/pull/521)) +- Use the `tracing` crate for logging ([#534](https://github.com/getsentry/symbolicator/pull/534)) ### Fixes From bc06f4899f2d13d97539c40fdfa1bcecf3d5028c Mon Sep 17 00:00:00 2001 From: Sebastian Zivota Date: Wed, 25 Aug 2021 14:38:24 +0200 Subject: [PATCH 07/16] Log compatibility --- Cargo.lock | 1 + crates/symbolicator/Cargo.toml | 1 + crates/symbolicator/src/logging.rs | 4 ++++ 3 files changed, 6 insertions(+) diff --git a/Cargo.lock b/Cargo.lock index 340b270b5..381ffa724 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3657,6 +3657,7 @@ dependencies = [ "tokio 0.1.22", "tokio 1.6.1", "tracing", + "tracing-log", "tracing-subscriber", "url 2.2.2", "uuid 0.8.2", diff --git a/crates/symbolicator/Cargo.toml b/crates/symbolicator/Cargo.toml index 4be719db8..42410fd52 100644 --- a/crates/symbolicator/Cargo.toml +++ b/crates/symbolicator/Cargo.toml @@ -46,6 +46,7 @@ thiserror = "1.0.26" tokio = { version = "1.0.2", features = ["rt", "macros", "fs"] } tokio01 = { version = "0.1.22", package = "tokio" } tracing = "0.1.26" +tracing-log = "0.1.2" tracing-subscriber = "0.2.20" url = { version = "2.2.0", features = ["serde"] } uuid = { version = "0.8.2", features = ["v4", "serde"] } diff --git a/crates/symbolicator/src/logging.rs b/crates/symbolicator/src/logging.rs index 2571329e9..0532e1d70 100644 --- a/crates/symbolicator/src/logging.rs +++ b/crates/symbolicator/src/logging.rs @@ -52,6 +52,7 @@ pub fn init_logging(config: &Config) { let filter = EnvFilter::from_default_env(); let sentry = sentry::integrations::tracing::layer(); let subscriber = FmtSubscriber::new().with(filter).with(sentry); + let format = Layer::new().with_target(false); match (config.logging.format, console::user_attended()) { (LogFormat::Auto, true) | (LogFormat::Pretty, _) => { @@ -65,6 +66,9 @@ pub fn init_logging(config: &Config) { } } .expect("setting global default subscriber"); + + // "Logger" that captures log records and republishes them as tracing events. + tracing_log::LogTracer::init().expect("setting global default log tracer"); } /// A wrapper around an [`Error`](std::error::Error) that prints its causes. From 5142030efc4a2170e6f7382196ec322552f2008c Mon Sep 17 00:00:00 2001 From: Sebastian Zivota Date: Wed, 25 Aug 2021 16:10:09 +0200 Subject: [PATCH 08/16] Convert tracing events to log records --- Cargo.lock | 154 ++++++++++------------------- crates/symbolicator/Cargo.toml | 9 +- crates/symbolicator/src/config.rs | 46 +-------- crates/symbolicator/src/logging.rs | 147 +++++++++++++++++++++------ crates/symbolicator/src/test.rs | 11 +-- 5 files changed, 181 insertions(+), 186 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 381ffa724..c31d38ac1 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -161,15 +161,6 @@ dependencies = [ "winapi 0.3.9", ] -[[package]] -name = "ansi_term" -version = "0.12.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "d52a9bb7ec0cf484c551830a7ce27bd20d67eac647e1befb56b0be4ee39a55d2" -dependencies = [ - "winapi 0.3.9", -] - [[package]] name = "anyhow" version = "1.0.41" @@ -471,7 +462,7 @@ version = "2.33.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "37e58ac78573c40708d45522f0d80fa2f01cc4f9b4e2bf749807255454312002" dependencies = [ - "ansi_term 0.11.0", + "ansi_term", "atty", "bitflags", "strsim", @@ -915,6 +906,19 @@ dependencies = [ "syn 1.0.73", ] +[[package]] +name = "env_logger" +version = "0.7.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "44533bbbb3bb3c1fa17d9f2e4e38bbbaf8396ba82193c4cb1b6445d711445d36" +dependencies = [ + "atty", + "humantime 1.3.0", + "log", + "regex", + "termcolor", +] + [[package]] name = "error-chain" version = "0.8.1" @@ -1397,6 +1401,15 @@ version = "1.0.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "6456b8a6c8f33fee7d958fcd1b60d55b11940a79e63ae87013e6d22e26034440" +[[package]] +name = "humantime" +version = "1.3.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "df004cfca50ef23c36850aaaa59ad52cc70d0e90243c3c7737a4dd32dc7a3c4f" +dependencies = [ + "quick-error", +] + [[package]] name = "humantime" version = "2.1.0" @@ -1409,7 +1422,7 @@ version = "1.0.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ac34a56cfd4acddb469cc7fff187ed5ac36f498ba085caf8bbc725e3ff474058" dependencies = [ - "humantime", + "humantime 2.1.0", "serde", ] @@ -1735,6 +1748,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "51b9bbe6c47d51fc3e1a9b945965946b4c44142ab8792c50835a980d362c2710" dependencies = [ "cfg-if 1.0.0", + "serde", ] [[package]] @@ -1767,15 +1781,6 @@ version = "0.1.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ffbee8634e0d45d258acb448e7eaab3fce7a0a467395d4d9f228e3c1f01fb2e4" -[[package]] -name = "matchers" -version = "0.0.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "f099785f7595cc4b4553a174ce30dd7589ef93391ff414dbb67f62392b9e0ce1" -dependencies = [ - "regex-automata", -] - [[package]] name = "matches" version = "0.1.8" @@ -2350,6 +2355,16 @@ version = "0.1.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "925383efa346730478fb4838dbe9137d2a47675ad789c546d150a6e1dd4ab31c" +[[package]] +name = "pretty_env_logger" +version = "0.4.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "926d36b9553851b8b0005f1275891b392ee4d2d833852c417ed025477350fb9d" +dependencies = [ + "env_logger", + "log", +] + [[package]] name = "proc-macro-error" version = "1.0.4" @@ -2730,15 +2745,6 @@ dependencies = [ "regex-syntax", ] -[[package]] -name = "regex-automata" -version = "0.1.10" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132" -dependencies = [ - "regex-syntax", -] - [[package]] name = "regex-syntax" version = "0.6.25" @@ -3093,8 +3099,8 @@ dependencies = [ "sentry-contexts", "sentry-core", "sentry-debug-images", + "sentry-log", "sentry-panic", - "sentry-tracing", "tokio 1.6.1", ] @@ -3151,24 +3157,23 @@ dependencies = [ ] [[package]] -name = "sentry-panic" +name = "sentry-log" version = "0.23.0" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "692bf989f0c99f025e33d7f58e62822c3771f56d189698c66dcc863122255d95" +checksum = "66da5759b0704a2fb0d420863b0795ea3429739e188ff67fff82bb13dcd3cc50" dependencies = [ - "sentry-backtrace", + "log", "sentry-core", ] [[package]] -name = "sentry-tracing" +name = "sentry-panic" version = "0.23.0" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "d291df287241b0ef97f5bf9e9a595691ef8dfb49bc6acfd55b9dc2ade681f1c9" +checksum = "692bf989f0c99f025e33d7f58e62822c3771f56d189698c66dcc863122255d95" dependencies = [ + "sentry-backtrace", "sentry-core", - "tracing-core", - "tracing-subscriber", ] [[package]] @@ -3297,15 +3302,6 @@ dependencies = [ "opaque-debug 0.3.0", ] -[[package]] -name = "sharded-slab" -version = "0.1.3" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "740223c51853f3145fe7c90360d2d4232f2b62e3449489c207eccde818979982" -dependencies = [ - "lazy_static", -] - [[package]] name = "shlex" version = "0.1.1" @@ -3623,6 +3619,7 @@ dependencies = [ "cadence", "chrono", "console", + "env_logger", "failure", "filetime", "flate2", @@ -3636,9 +3633,11 @@ dependencies = [ "ipnetwork", "jsonwebtoken", "lazy_static", + "log", "lru", "num_cpus", "parking_lot 0.11.1", + "pretty_env_logger", "procspawn", "regex", "reqwest 0.11.0", @@ -3657,8 +3656,6 @@ dependencies = [ "tokio 0.1.22", "tokio 1.6.1", "tracing", - "tracing-log", - "tracing-subscriber", "url 2.2.2", "uuid 0.8.2", "warp", @@ -3738,6 +3735,15 @@ dependencies = [ "winapi 0.3.9", ] +[[package]] +name = "termcolor" +version = "1.1.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "2dfed899f0eb03f32ee8c6a0aabdb8a7949659e3466561fc0adf54e26d88c5f4" +dependencies = [ + "winapi-util", +] + [[package]] name = "terminal_size" version = "0.1.17" @@ -3777,15 +3783,6 @@ dependencies = [ "syn 1.0.73", ] -[[package]] -name = "thread_local" -version = "1.1.3" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "8018d24e04c95ac8790716a5987d0fec4f8b27249ffa0f7d33f1369bdfb88cbd" -dependencies = [ - "once_cell", -] - [[package]] name = "time" version = "0.1.44" @@ -4186,49 +4183,6 @@ dependencies = [ "lazy_static", ] -[[package]] -name = "tracing-log" -version = "0.1.2" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "a6923477a48e41c1951f1999ef8bb5a3023eb723ceadafe78ffb65dc366761e3" -dependencies = [ - "lazy_static", - "log", - "tracing-core", -] - -[[package]] -name = "tracing-serde" -version = "0.1.2" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "fb65ea441fbb84f9f6748fd496cf7f63ec9af5bca94dd86456978d055e8eb28b" -dependencies = [ - "serde", - "tracing-core", -] - -[[package]] -name = "tracing-subscriber" -version = "0.2.20" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "b9cbe87a2fa7e35900ce5de20220a582a9483a7063811defce79d7cbd59d4cfe" -dependencies = [ - "ansi_term 0.12.1", - "chrono", - "lazy_static", - "matchers", - "regex", - "serde", - "serde_json", - "sharded-slab", - "smallvec 1.6.1", - "thread_local", - "tracing", - "tracing-core", - "tracing-log", - "tracing-serde", -] - [[package]] name = "trust-dns-proto" version = "0.5.0" diff --git a/crates/symbolicator/Cargo.toml b/crates/symbolicator/Cargo.toml index 42410fd52..cc5bca5d7 100644 --- a/crates/symbolicator/Cargo.toml +++ b/crates/symbolicator/Cargo.toml @@ -14,6 +14,7 @@ base64 = "0.13.0" cadence = "0.25.0" chrono = { version = "0.4.19", features = ["serde"] } console = "0.14.0" +env_logger = "0.7.1" failure = "0.1.8" filetime = "0.2.14" flate2 = "1.0.0" @@ -26,16 +27,18 @@ humantime-serde = "1.0.1" ipnetwork = "0.18.0" jsonwebtoken = "7.2.0" lazy_static = "1.4.0" +log = { version = "0.4.13", features = ["serde"] } lru = "0.6.3" num_cpus = "1.13.0" parking_lot = "0.11.1" +pretty_env_logger = "0.4.0" procspawn = { version = "0.10.0", features = ["backtrace", "json"] } regex = "1.4.3" reqwest = { git = "https://github.com/jan-auer/reqwest", tag = "v0.11.0", features = ["gzip", "json", "stream", "trust-dns"] } rusoto_core = "0.46.0" rusoto_credential = "0.46.0" rusoto_s3 = "0.46.0" -sentry = { version = "0.23.0", features = ["debug-images", "tracing"] } +sentry = { version = "0.23.0", features = ["debug-images", "log"] } serde = { version = "1.0.119", features = ["derive", "rc"] } serde_json = "1.0.61" serde_yaml = "0.8.15" @@ -45,9 +48,7 @@ tempfile = "3.2.0" thiserror = "1.0.26" tokio = { version = "1.0.2", features = ["rt", "macros", "fs"] } tokio01 = { version = "0.1.22", package = "tokio" } -tracing = "0.1.26" -tracing-log = "0.1.2" -tracing-subscriber = "0.2.20" +tracing = { version = "0.1.26", features = ["log"] } url = { version = "2.2.0", features = ["serde"] } uuid = { version = "0.8.2", features = ["v4", "serde"] } zstd = "0.9.0" diff --git a/crates/symbolicator/src/config.rs b/crates/symbolicator/src/config.rs index 8e10d3a59..ff6ee6e4a 100644 --- a/crates/symbolicator/src/config.rs +++ b/crates/symbolicator/src/config.rs @@ -1,14 +1,13 @@ use std::env; -use std::fmt; use std::fs; use std::path::{Path, PathBuf}; use std::sync::Arc; use std::time::Duration; use anyhow::{Context, Result}; +use log::LevelFilter; use sentry::types::Dsn; -use serde::{de, Deserialize, Deserializer}; -use tracing::level_filters::LevelFilter; +use serde::Deserialize; use crate::sources::SourceConfig; @@ -31,7 +30,6 @@ pub enum LogFormat { #[serde(default)] pub struct Logging { /// The log level for the relay. - #[serde(deserialize_with = "deserialize_level_filter")] pub level: LevelFilter, /// Controls the log format. pub format: LogFormat, @@ -42,7 +40,7 @@ pub struct Logging { impl Default for Logging { fn default() -> Self { Logging { - level: LevelFilter::INFO, + level: LevelFilter::Info, format: LogFormat::Auto, enable_backtraces: true, } @@ -368,44 +366,6 @@ impl Config { } } -#[derive(Debug)] -struct LevelFilterVisitor; - -impl<'de> de::Visitor<'de> for LevelFilterVisitor { - type Value = LevelFilter; - - fn expecting(&self, formatter: &mut fmt::Formatter) -> std::fmt::Result { - write!( - formatter, - r#"one of the strings "off", "error", "warn", "info", "debug", or "trace""# - ) - } - - fn visit_str(self, v: &str) -> Result - where - E: de::Error, - { - match v { - "off" => Ok(LevelFilter::OFF), - "error" => Ok(LevelFilter::ERROR), - "warn" => Ok(LevelFilter::WARN), - "info" => Ok(LevelFilter::INFO), - "debug" => Ok(LevelFilter::DEBUG), - "trace" => Ok(LevelFilter::TRACE), - _ => Err(de::Error::unknown_variant( - v, - &["off", "error", "warn", "info", "debug", "trace"], - )), - } - } -} - -fn deserialize_level_filter<'de, D: Deserializer<'de>>( - deserializer: D, -) -> Result { - deserializer.deserialize_str(LevelFilterVisitor) -} - #[cfg(test)] mod tests { use super::*; diff --git a/crates/symbolicator/src/logging.rs b/crates/symbolicator/src/logging.rs index 0532e1d70..6ff1d1866 100644 --- a/crates/symbolicator/src/logging.rs +++ b/crates/symbolicator/src/logging.rs @@ -1,29 +1,30 @@ use std::env; use std::fmt; +use std::io::{self, Write}; -use tracing::level_filters::LevelFilter; -use tracing_subscriber::fmt::Layer; -use tracing_subscriber::prelude::*; -use tracing_subscriber::{EnvFilter, FmtSubscriber}; +use chrono::{DateTime, Utc}; +use log::{Level, LevelFilter}; +use sentry::integrations::log::{breadcrumb_from_record, event_from_record}; +use serde::{Deserialize, Serialize}; use crate::config::{Config, LogFormat}; fn get_rust_log(level: LevelFilter) -> &'static str { match level { - LevelFilter::OFF => "", - LevelFilter::ERROR => "ERROR", - LevelFilter::WARN => "WARN", - LevelFilter::INFO => { + LevelFilter::Off => "", + LevelFilter::Error => "ERROR", + LevelFilter::Warn => "WARN", + LevelFilter::Info => { "INFO,\ trust_dns_proto=WARN" } - LevelFilter::DEBUG => { + LevelFilter::Debug => { "INFO,\ trust_dns_proto=WARN,\ actix_web::pipeline=DEBUG,\ symbolicator=DEBUG" } - LevelFilter::TRACE => { + LevelFilter::Trace => { "INFO,\ trust_dns_proto=WARN,\ actix_web::pipeline=DEBUG,\ @@ -32,6 +33,94 @@ fn get_rust_log(level: LevelFilter) -> &'static str { } } +fn pretty_logger() -> env_logger::Builder { + pretty_env_logger::formatted_builder() +} + +fn simplified_logger() -> env_logger::Builder { + let mut builder = env_logger::Builder::new(); + builder.format(|buf, record| { + writeln!( + buf, + "{} [{}] {}: {}", + buf.timestamp(), + record.module_path().unwrap_or(""), + record.level(), + record.args() + ) + }); + builder +} + +#[derive(Serialize, Deserialize, Debug)] +struct LogRecord<'a> { + timestamp: DateTime, + level: Level, + logger: &'a str, + message: String, + module_path: Option<&'a str>, + filename: Option<&'a str>, + lineno: Option, +} + +fn json_logger() -> env_logger::Builder { + let mut builder = env_logger::Builder::new(); + builder.format(|mut buf, record| -> io::Result<()> { + let record = LogRecord { + timestamp: Utc::now(), + level: record.level(), + logger: record.target(), + message: record.args().to_string(), + module_path: record.module_path(), + filename: record.file(), + lineno: record.line(), + }; + + serde_json::to_writer(&mut buf, &record) + .map_err(|err| io::Error::new(io::ErrorKind::Other, err))?; + + buf.write_all(b"\n")?; + Ok(()) + }); + builder +} + +/// A delegating logger that also logs breadcrumbs. +pub struct BreadcrumbLogger { + inner: L, +} + +impl BreadcrumbLogger { + /// Initializes a new breadcrumb logger. + pub fn new(inner: L) -> Self { + Self { inner } + } +} + +impl log::Log for BreadcrumbLogger +where + L: log::Log, +{ + fn enabled(&self, md: &log::Metadata<'_>) -> bool { + self.inner.enabled(md) + } + + fn log(&self, record: &log::Record<'_>) { + if self.inner.enabled(record.metadata()) { + if record.level() == log::Level::Error { + sentry::capture_event(event_from_record(record)); + } + + sentry::add_breadcrumb(|| breadcrumb_from_record(record)); + self.inner.log(record); + } + } + + fn flush(&self) { + self.inner.flush(); + } +} + /// Initializes logging for the symbolicator. /// /// This considers the `RUST_LOG` environment variable and defaults it to the level specified in the @@ -49,26 +138,22 @@ pub fn init_logging(config: &Config) { env::set_var("RUST_LOG", rust_log); } - let filter = EnvFilter::from_default_env(); - let sentry = sentry::integrations::tracing::layer(); - let subscriber = FmtSubscriber::new().with(filter).with(sentry); + let mut builder = match (config.logging.format, console::user_attended()) { + (LogFormat::Auto, true) | (LogFormat::Pretty, _) => pretty_logger(), + (LogFormat::Auto, false) | (LogFormat::Simplified, _) => simplified_logger(), + (LogFormat::Json, _) => json_logger(), + }; - let format = Layer::new().with_target(false); - match (config.logging.format, console::user_attended()) { - (LogFormat::Auto, true) | (LogFormat::Pretty, _) => { - tracing::subscriber::set_global_default(subscriber.with(format.pretty())) - } - (LogFormat::Auto, false) | (LogFormat::Simplified, _) => { - tracing::subscriber::set_global_default(subscriber.with(format.compact())) - } - (LogFormat::Json, _) => { - tracing::subscriber::set_global_default(subscriber.with(format.json())) - } - } - .expect("setting global default subscriber"); + match env::var("RUST_LOG") { + Ok(rust_log) => builder.parse_filters(&rust_log), + Err(_) => builder.filter_level(config.logging.level), + }; + + let logger = builder.build(); + log::set_max_level(logger.filter()); - // "Logger" that captures log records and republishes them as tracing events. - tracing_log::LogTracer::init().expect("setting global default log tracer"); + let breadcrumb_logger = Box::new(BreadcrumbLogger::new(logger)); + log::set_boxed_logger(breadcrumb_logger).unwrap(); } /// A wrapper around an [`Error`](std::error::Error) that prints its causes. @@ -89,10 +174,8 @@ impl<'a> fmt::Display for LogError<'a> { /// Logs an error to the configured logger or `stderr` if not yet configured. pub fn ensure_log_error(error: &anyhow::Error) { - if tracing::Level::ERROR <= tracing::level_filters::STATIC_MAX_LEVEL - && tracing::Level::ERROR <= LevelFilter::current() - { - tracing::error!("{:?}", error); + if log::log_enabled!(log::Level::Error) { + log::error!("{:?}", error); } else { eprintln!("{:?}", error); } diff --git a/crates/symbolicator/src/test.rs b/crates/symbolicator/src/test.rs index ee6d9a988..2e6f07c9c 100644 --- a/crates/symbolicator/src/test.rs +++ b/crates/symbolicator/src/test.rs @@ -23,9 +23,8 @@ use std::sync::atomic::{AtomicUsize, Ordering}; use std::sync::Arc; use futures::{FutureExt, TryFutureExt}; +use log::LevelFilter; use reqwest::Url; -use tracing_subscriber::filter::EnvFilter; -use tracing_subscriber::fmt::fmt; use warp::filters::fs::File; use warp::reject::{Reject, Rejection}; use warp::Filter; @@ -45,11 +44,9 @@ pub use tempfile::TempDir; /// - Initializes logs: The logger only captures logs from the `symbolicator` crate and mutes all /// other logs (such as actix or symbolic). pub(crate) fn setup() { - fmt() - .with_env_filter(EnvFilter::new("symbolicator=trace")) - .with_target(false) - .pretty() - .with_test_writer() + env_logger::builder() + .filter(Some("symbolicator"), LevelFilter::Trace) + .is_test(true) .try_init() .ok(); } From 3b8a151450175b21f5a170971db1d794a390b499 Mon Sep 17 00:00:00 2001 From: Sebastian Zivota Date: Thu, 26 Aug 2021 10:28:54 +0200 Subject: [PATCH 09/16] Revert "Convert tracing events to log records" This reverts commit 5142030efc4a2170e6f7382196ec322552f2008c. --- Cargo.lock | 154 +++++++++++++++++++---------- crates/symbolicator/Cargo.toml | 9 +- crates/symbolicator/src/config.rs | 46 ++++++++- crates/symbolicator/src/logging.rs | 147 ++++++--------------------- crates/symbolicator/src/test.rs | 11 ++- 5 files changed, 186 insertions(+), 181 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index c31d38ac1..381ffa724 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -161,6 +161,15 @@ dependencies = [ "winapi 0.3.9", ] +[[package]] +name = "ansi_term" +version = "0.12.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d52a9bb7ec0cf484c551830a7ce27bd20d67eac647e1befb56b0be4ee39a55d2" +dependencies = [ + "winapi 0.3.9", +] + [[package]] name = "anyhow" version = "1.0.41" @@ -462,7 +471,7 @@ version = "2.33.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "37e58ac78573c40708d45522f0d80fa2f01cc4f9b4e2bf749807255454312002" dependencies = [ - "ansi_term", + "ansi_term 0.11.0", "atty", "bitflags", "strsim", @@ -906,19 +915,6 @@ dependencies = [ "syn 1.0.73", ] -[[package]] -name = "env_logger" -version = "0.7.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "44533bbbb3bb3c1fa17d9f2e4e38bbbaf8396ba82193c4cb1b6445d711445d36" -dependencies = [ - "atty", - "humantime 1.3.0", - "log", - "regex", - "termcolor", -] - [[package]] name = "error-chain" version = "0.8.1" @@ -1401,15 +1397,6 @@ version = "1.0.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "6456b8a6c8f33fee7d958fcd1b60d55b11940a79e63ae87013e6d22e26034440" -[[package]] -name = "humantime" -version = "1.3.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "df004cfca50ef23c36850aaaa59ad52cc70d0e90243c3c7737a4dd32dc7a3c4f" -dependencies = [ - "quick-error", -] - [[package]] name = "humantime" version = "2.1.0" @@ -1422,7 +1409,7 @@ version = "1.0.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ac34a56cfd4acddb469cc7fff187ed5ac36f498ba085caf8bbc725e3ff474058" dependencies = [ - "humantime 2.1.0", + "humantime", "serde", ] @@ -1748,7 +1735,6 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "51b9bbe6c47d51fc3e1a9b945965946b4c44142ab8792c50835a980d362c2710" dependencies = [ "cfg-if 1.0.0", - "serde", ] [[package]] @@ -1781,6 +1767,15 @@ version = "0.1.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ffbee8634e0d45d258acb448e7eaab3fce7a0a467395d4d9f228e3c1f01fb2e4" +[[package]] +name = "matchers" +version = "0.0.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f099785f7595cc4b4553a174ce30dd7589ef93391ff414dbb67f62392b9e0ce1" +dependencies = [ + "regex-automata", +] + [[package]] name = "matches" version = "0.1.8" @@ -2355,16 +2350,6 @@ version = "0.1.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "925383efa346730478fb4838dbe9137d2a47675ad789c546d150a6e1dd4ab31c" -[[package]] -name = "pretty_env_logger" -version = "0.4.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "926d36b9553851b8b0005f1275891b392ee4d2d833852c417ed025477350fb9d" -dependencies = [ - "env_logger", - "log", -] - [[package]] name = "proc-macro-error" version = "1.0.4" @@ -2745,6 +2730,15 @@ dependencies = [ "regex-syntax", ] +[[package]] +name = "regex-automata" +version = "0.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132" +dependencies = [ + "regex-syntax", +] + [[package]] name = "regex-syntax" version = "0.6.25" @@ -3099,8 +3093,8 @@ dependencies = [ "sentry-contexts", "sentry-core", "sentry-debug-images", - "sentry-log", "sentry-panic", + "sentry-tracing", "tokio 1.6.1", ] @@ -3157,23 +3151,24 @@ dependencies = [ ] [[package]] -name = "sentry-log" +name = "sentry-panic" version = "0.23.0" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "66da5759b0704a2fb0d420863b0795ea3429739e188ff67fff82bb13dcd3cc50" +checksum = "692bf989f0c99f025e33d7f58e62822c3771f56d189698c66dcc863122255d95" dependencies = [ - "log", + "sentry-backtrace", "sentry-core", ] [[package]] -name = "sentry-panic" +name = "sentry-tracing" version = "0.23.0" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "692bf989f0c99f025e33d7f58e62822c3771f56d189698c66dcc863122255d95" +checksum = "d291df287241b0ef97f5bf9e9a595691ef8dfb49bc6acfd55b9dc2ade681f1c9" dependencies = [ - "sentry-backtrace", "sentry-core", + "tracing-core", + "tracing-subscriber", ] [[package]] @@ -3302,6 +3297,15 @@ dependencies = [ "opaque-debug 0.3.0", ] +[[package]] +name = "sharded-slab" +version = "0.1.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "740223c51853f3145fe7c90360d2d4232f2b62e3449489c207eccde818979982" +dependencies = [ + "lazy_static", +] + [[package]] name = "shlex" version = "0.1.1" @@ -3619,7 +3623,6 @@ dependencies = [ "cadence", "chrono", "console", - "env_logger", "failure", "filetime", "flate2", @@ -3633,11 +3636,9 @@ dependencies = [ "ipnetwork", "jsonwebtoken", "lazy_static", - "log", "lru", "num_cpus", "parking_lot 0.11.1", - "pretty_env_logger", "procspawn", "regex", "reqwest 0.11.0", @@ -3656,6 +3657,8 @@ dependencies = [ "tokio 0.1.22", "tokio 1.6.1", "tracing", + "tracing-log", + "tracing-subscriber", "url 2.2.2", "uuid 0.8.2", "warp", @@ -3735,15 +3738,6 @@ dependencies = [ "winapi 0.3.9", ] -[[package]] -name = "termcolor" -version = "1.1.2" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "2dfed899f0eb03f32ee8c6a0aabdb8a7949659e3466561fc0adf54e26d88c5f4" -dependencies = [ - "winapi-util", -] - [[package]] name = "terminal_size" version = "0.1.17" @@ -3783,6 +3777,15 @@ dependencies = [ "syn 1.0.73", ] +[[package]] +name = "thread_local" +version = "1.1.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8018d24e04c95ac8790716a5987d0fec4f8b27249ffa0f7d33f1369bdfb88cbd" +dependencies = [ + "once_cell", +] + [[package]] name = "time" version = "0.1.44" @@ -4183,6 +4186,49 @@ dependencies = [ "lazy_static", ] +[[package]] +name = "tracing-log" +version = "0.1.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a6923477a48e41c1951f1999ef8bb5a3023eb723ceadafe78ffb65dc366761e3" +dependencies = [ + "lazy_static", + "log", + "tracing-core", +] + +[[package]] +name = "tracing-serde" +version = "0.1.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "fb65ea441fbb84f9f6748fd496cf7f63ec9af5bca94dd86456978d055e8eb28b" +dependencies = [ + "serde", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.2.20" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b9cbe87a2fa7e35900ce5de20220a582a9483a7063811defce79d7cbd59d4cfe" +dependencies = [ + "ansi_term 0.12.1", + "chrono", + "lazy_static", + "matchers", + "regex", + "serde", + "serde_json", + "sharded-slab", + "smallvec 1.6.1", + "thread_local", + "tracing", + "tracing-core", + "tracing-log", + "tracing-serde", +] + [[package]] name = "trust-dns-proto" version = "0.5.0" diff --git a/crates/symbolicator/Cargo.toml b/crates/symbolicator/Cargo.toml index cc5bca5d7..42410fd52 100644 --- a/crates/symbolicator/Cargo.toml +++ b/crates/symbolicator/Cargo.toml @@ -14,7 +14,6 @@ base64 = "0.13.0" cadence = "0.25.0" chrono = { version = "0.4.19", features = ["serde"] } console = "0.14.0" -env_logger = "0.7.1" failure = "0.1.8" filetime = "0.2.14" flate2 = "1.0.0" @@ -27,18 +26,16 @@ humantime-serde = "1.0.1" ipnetwork = "0.18.0" jsonwebtoken = "7.2.0" lazy_static = "1.4.0" -log = { version = "0.4.13", features = ["serde"] } lru = "0.6.3" num_cpus = "1.13.0" parking_lot = "0.11.1" -pretty_env_logger = "0.4.0" procspawn = { version = "0.10.0", features = ["backtrace", "json"] } regex = "1.4.3" reqwest = { git = "https://github.com/jan-auer/reqwest", tag = "v0.11.0", features = ["gzip", "json", "stream", "trust-dns"] } rusoto_core = "0.46.0" rusoto_credential = "0.46.0" rusoto_s3 = "0.46.0" -sentry = { version = "0.23.0", features = ["debug-images", "log"] } +sentry = { version = "0.23.0", features = ["debug-images", "tracing"] } serde = { version = "1.0.119", features = ["derive", "rc"] } serde_json = "1.0.61" serde_yaml = "0.8.15" @@ -48,7 +45,9 @@ tempfile = "3.2.0" thiserror = "1.0.26" tokio = { version = "1.0.2", features = ["rt", "macros", "fs"] } tokio01 = { version = "0.1.22", package = "tokio" } -tracing = { version = "0.1.26", features = ["log"] } +tracing = "0.1.26" +tracing-log = "0.1.2" +tracing-subscriber = "0.2.20" url = { version = "2.2.0", features = ["serde"] } uuid = { version = "0.8.2", features = ["v4", "serde"] } zstd = "0.9.0" diff --git a/crates/symbolicator/src/config.rs b/crates/symbolicator/src/config.rs index ff6ee6e4a..8e10d3a59 100644 --- a/crates/symbolicator/src/config.rs +++ b/crates/symbolicator/src/config.rs @@ -1,13 +1,14 @@ use std::env; +use std::fmt; use std::fs; use std::path::{Path, PathBuf}; use std::sync::Arc; use std::time::Duration; use anyhow::{Context, Result}; -use log::LevelFilter; use sentry::types::Dsn; -use serde::Deserialize; +use serde::{de, Deserialize, Deserializer}; +use tracing::level_filters::LevelFilter; use crate::sources::SourceConfig; @@ -30,6 +31,7 @@ pub enum LogFormat { #[serde(default)] pub struct Logging { /// The log level for the relay. + #[serde(deserialize_with = "deserialize_level_filter")] pub level: LevelFilter, /// Controls the log format. pub format: LogFormat, @@ -40,7 +42,7 @@ pub struct Logging { impl Default for Logging { fn default() -> Self { Logging { - level: LevelFilter::Info, + level: LevelFilter::INFO, format: LogFormat::Auto, enable_backtraces: true, } @@ -366,6 +368,44 @@ impl Config { } } +#[derive(Debug)] +struct LevelFilterVisitor; + +impl<'de> de::Visitor<'de> for LevelFilterVisitor { + type Value = LevelFilter; + + fn expecting(&self, formatter: &mut fmt::Formatter) -> std::fmt::Result { + write!( + formatter, + r#"one of the strings "off", "error", "warn", "info", "debug", or "trace""# + ) + } + + fn visit_str(self, v: &str) -> Result + where + E: de::Error, + { + match v { + "off" => Ok(LevelFilter::OFF), + "error" => Ok(LevelFilter::ERROR), + "warn" => Ok(LevelFilter::WARN), + "info" => Ok(LevelFilter::INFO), + "debug" => Ok(LevelFilter::DEBUG), + "trace" => Ok(LevelFilter::TRACE), + _ => Err(de::Error::unknown_variant( + v, + &["off", "error", "warn", "info", "debug", "trace"], + )), + } + } +} + +fn deserialize_level_filter<'de, D: Deserializer<'de>>( + deserializer: D, +) -> Result { + deserializer.deserialize_str(LevelFilterVisitor) +} + #[cfg(test)] mod tests { use super::*; diff --git a/crates/symbolicator/src/logging.rs b/crates/symbolicator/src/logging.rs index 6ff1d1866..0532e1d70 100644 --- a/crates/symbolicator/src/logging.rs +++ b/crates/symbolicator/src/logging.rs @@ -1,30 +1,29 @@ use std::env; use std::fmt; -use std::io::{self, Write}; -use chrono::{DateTime, Utc}; -use log::{Level, LevelFilter}; -use sentry::integrations::log::{breadcrumb_from_record, event_from_record}; -use serde::{Deserialize, Serialize}; +use tracing::level_filters::LevelFilter; +use tracing_subscriber::fmt::Layer; +use tracing_subscriber::prelude::*; +use tracing_subscriber::{EnvFilter, FmtSubscriber}; use crate::config::{Config, LogFormat}; fn get_rust_log(level: LevelFilter) -> &'static str { match level { - LevelFilter::Off => "", - LevelFilter::Error => "ERROR", - LevelFilter::Warn => "WARN", - LevelFilter::Info => { + LevelFilter::OFF => "", + LevelFilter::ERROR => "ERROR", + LevelFilter::WARN => "WARN", + LevelFilter::INFO => { "INFO,\ trust_dns_proto=WARN" } - LevelFilter::Debug => { + LevelFilter::DEBUG => { "INFO,\ trust_dns_proto=WARN,\ actix_web::pipeline=DEBUG,\ symbolicator=DEBUG" } - LevelFilter::Trace => { + LevelFilter::TRACE => { "INFO,\ trust_dns_proto=WARN,\ actix_web::pipeline=DEBUG,\ @@ -33,94 +32,6 @@ fn get_rust_log(level: LevelFilter) -> &'static str { } } -fn pretty_logger() -> env_logger::Builder { - pretty_env_logger::formatted_builder() -} - -fn simplified_logger() -> env_logger::Builder { - let mut builder = env_logger::Builder::new(); - builder.format(|buf, record| { - writeln!( - buf, - "{} [{}] {}: {}", - buf.timestamp(), - record.module_path().unwrap_or(""), - record.level(), - record.args() - ) - }); - builder -} - -#[derive(Serialize, Deserialize, Debug)] -struct LogRecord<'a> { - timestamp: DateTime, - level: Level, - logger: &'a str, - message: String, - module_path: Option<&'a str>, - filename: Option<&'a str>, - lineno: Option, -} - -fn json_logger() -> env_logger::Builder { - let mut builder = env_logger::Builder::new(); - builder.format(|mut buf, record| -> io::Result<()> { - let record = LogRecord { - timestamp: Utc::now(), - level: record.level(), - logger: record.target(), - message: record.args().to_string(), - module_path: record.module_path(), - filename: record.file(), - lineno: record.line(), - }; - - serde_json::to_writer(&mut buf, &record) - .map_err(|err| io::Error::new(io::ErrorKind::Other, err))?; - - buf.write_all(b"\n")?; - Ok(()) - }); - builder -} - -/// A delegating logger that also logs breadcrumbs. -pub struct BreadcrumbLogger { - inner: L, -} - -impl BreadcrumbLogger { - /// Initializes a new breadcrumb logger. - pub fn new(inner: L) -> Self { - Self { inner } - } -} - -impl log::Log for BreadcrumbLogger -where - L: log::Log, -{ - fn enabled(&self, md: &log::Metadata<'_>) -> bool { - self.inner.enabled(md) - } - - fn log(&self, record: &log::Record<'_>) { - if self.inner.enabled(record.metadata()) { - if record.level() == log::Level::Error { - sentry::capture_event(event_from_record(record)); - } - - sentry::add_breadcrumb(|| breadcrumb_from_record(record)); - self.inner.log(record); - } - } - - fn flush(&self) { - self.inner.flush(); - } -} - /// Initializes logging for the symbolicator. /// /// This considers the `RUST_LOG` environment variable and defaults it to the level specified in the @@ -138,22 +49,26 @@ pub fn init_logging(config: &Config) { env::set_var("RUST_LOG", rust_log); } - let mut builder = match (config.logging.format, console::user_attended()) { - (LogFormat::Auto, true) | (LogFormat::Pretty, _) => pretty_logger(), - (LogFormat::Auto, false) | (LogFormat::Simplified, _) => simplified_logger(), - (LogFormat::Json, _) => json_logger(), - }; + let filter = EnvFilter::from_default_env(); + let sentry = sentry::integrations::tracing::layer(); + let subscriber = FmtSubscriber::new().with(filter).with(sentry); - match env::var("RUST_LOG") { - Ok(rust_log) => builder.parse_filters(&rust_log), - Err(_) => builder.filter_level(config.logging.level), - }; - - let logger = builder.build(); - log::set_max_level(logger.filter()); + let format = Layer::new().with_target(false); + match (config.logging.format, console::user_attended()) { + (LogFormat::Auto, true) | (LogFormat::Pretty, _) => { + tracing::subscriber::set_global_default(subscriber.with(format.pretty())) + } + (LogFormat::Auto, false) | (LogFormat::Simplified, _) => { + tracing::subscriber::set_global_default(subscriber.with(format.compact())) + } + (LogFormat::Json, _) => { + tracing::subscriber::set_global_default(subscriber.with(format.json())) + } + } + .expect("setting global default subscriber"); - let breadcrumb_logger = Box::new(BreadcrumbLogger::new(logger)); - log::set_boxed_logger(breadcrumb_logger).unwrap(); + // "Logger" that captures log records and republishes them as tracing events. + tracing_log::LogTracer::init().expect("setting global default log tracer"); } /// A wrapper around an [`Error`](std::error::Error) that prints its causes. @@ -174,8 +89,10 @@ impl<'a> fmt::Display for LogError<'a> { /// Logs an error to the configured logger or `stderr` if not yet configured. pub fn ensure_log_error(error: &anyhow::Error) { - if log::log_enabled!(log::Level::Error) { - log::error!("{:?}", error); + if tracing::Level::ERROR <= tracing::level_filters::STATIC_MAX_LEVEL + && tracing::Level::ERROR <= LevelFilter::current() + { + tracing::error!("{:?}", error); } else { eprintln!("{:?}", error); } diff --git a/crates/symbolicator/src/test.rs b/crates/symbolicator/src/test.rs index 2e6f07c9c..ee6d9a988 100644 --- a/crates/symbolicator/src/test.rs +++ b/crates/symbolicator/src/test.rs @@ -23,8 +23,9 @@ use std::sync::atomic::{AtomicUsize, Ordering}; use std::sync::Arc; use futures::{FutureExt, TryFutureExt}; -use log::LevelFilter; use reqwest::Url; +use tracing_subscriber::filter::EnvFilter; +use tracing_subscriber::fmt::fmt; use warp::filters::fs::File; use warp::reject::{Reject, Rejection}; use warp::Filter; @@ -44,9 +45,11 @@ pub use tempfile::TempDir; /// - Initializes logs: The logger only captures logs from the `symbolicator` crate and mutes all /// other logs (such as actix or symbolic). pub(crate) fn setup() { - env_logger::builder() - .filter(Some("symbolicator"), LevelFilter::Trace) - .is_test(true) + fmt() + .with_env_filter(EnvFilter::new("symbolicator=trace")) + .with_target(false) + .pretty() + .with_test_writer() .try_init() .ok(); } From 4a3cb370e5c5905f0d990302fe4e50b6798069bf Mon Sep 17 00:00:00 2001 From: Sebastian Zivota Date: Thu, 26 Aug 2021 11:53:11 +0200 Subject: [PATCH 10/16] WIP --- crates/symbolicator/Cargo.toml | 2 +- crates/symbolicator/src/logging.rs | 73 ++++++++++++++++++++++++++++-- crates/symbolicator/src/server.rs | 1 + 3 files changed, 70 insertions(+), 6 deletions(-) diff --git a/crates/symbolicator/Cargo.toml b/crates/symbolicator/Cargo.toml index 42410fd52..7a1e8476c 100644 --- a/crates/symbolicator/Cargo.toml +++ b/crates/symbolicator/Cargo.toml @@ -47,7 +47,7 @@ tokio = { version = "1.0.2", features = ["rt", "macros", "fs"] } tokio01 = { version = "0.1.22", package = "tokio" } tracing = "0.1.26" tracing-log = "0.1.2" -tracing-subscriber = "0.2.20" +tracing-subscriber = { version = "0.2.20", features = ["chrono"] } url = { version = "2.2.0", features = ["serde"] } uuid = { version = "0.8.2", features = ["v4", "serde"] } zstd = "0.9.0" diff --git a/crates/symbolicator/src/logging.rs b/crates/symbolicator/src/logging.rs index 0532e1d70..3970fe0cf 100644 --- a/crates/symbolicator/src/logging.rs +++ b/crates/symbolicator/src/logging.rs @@ -1,13 +1,70 @@ +use std::collections::BTreeMap; use std::env; use std::fmt; +use chrono::{DateTime, Utc}; +use serde::{Deserialize, Serialize}; use tracing::level_filters::LevelFilter; -use tracing_subscriber::fmt::Layer; +use tracing::{Event, Level, Metadata, Subscriber}; +use tracing_subscriber::fmt::time::ChronoUtc; +use tracing_subscriber::fmt::{FmtContext, FormatEvent, FormatFields, Layer}; use tracing_subscriber::prelude::*; +use tracing_subscriber::registry::LookupSpan; use tracing_subscriber::{EnvFilter, FmtSubscriber}; use crate::config::{Config, LogFormat}; +//#[derive(Serialize, Deserialize, Debug)] +//struct JsonLog<'a> { +// timestamp: DateTime, +// level: Level, +// logger: &'a str, +// message: String, +// module_path: Option<&'a str>, +// filename: Option<&'a str>, +// lineno: Option, +// fields: BTreeMap<&'a str, &'a str>, +//} +// +//impl<'a, 'b> From<&'b Event<'a>> for JsonLog<'a> { +// fn from(event: &'b Event<'a>) -> Self { +// let meta = event.metadata(); +// Self { +// timestamp: Utc::now(), +// level: *meta.level(), +// logger: meta.target(), +// message: event.message(), +// module_path: meta.module_path(), +// filename: meta.file(), +// lineno: meta.line(), +// } +// } +//} +// +//#[derive(Debug)] +//struct Json; +// +//impl FormatEvent for Json +//where +// S: Subscriber + for<'a> LookupSpan<'a>, +// N: for<'a> FormatFields<'a> + 'static, +//{ +// fn format_event( +// &self, +// ctx: &FmtContext<'_, S, N>, +// writer: &mut dyn fmt::Write, +// event: &Event<'_>, +// ) -> fmt::Result { +// let meta = event.metadata(); +// let module_path = meta.module_path(); +// let level = *meta.level(); +// let logger = meta.target(); +// let lineno = meta.line(); +// let timestamp = Utc::now(); +// +// writer.write +// } +//} fn get_rust_log(level: LevelFilter) -> &'static str { match level { LevelFilter::OFF => "", @@ -53,7 +110,7 @@ pub fn init_logging(config: &Config) { let sentry = sentry::integrations::tracing::layer(); let subscriber = FmtSubscriber::new().with(filter).with(sentry); - let format = Layer::new().with_target(false); + let format = Layer::new().with_timer(ChronoUtc::rfc3339()); match (config.logging.format, console::user_attended()) { (LogFormat::Auto, true) | (LogFormat::Pretty, _) => { tracing::subscriber::set_global_default(subscriber.with(format.pretty())) @@ -61,9 +118,15 @@ pub fn init_logging(config: &Config) { (LogFormat::Auto, false) | (LogFormat::Simplified, _) => { tracing::subscriber::set_global_default(subscriber.with(format.compact())) } - (LogFormat::Json, _) => { - tracing::subscriber::set_global_default(subscriber.with(format.json())) - } + (LogFormat::Json, _) => tracing::subscriber::set_global_default( + subscriber.with( + format + .json() + .flatten_event(true) + .with_current_span(false) + .with_span_list(false), + ), + ), } .expect("setting global default subscriber"); diff --git a/crates/symbolicator/src/server.rs b/crates/symbolicator/src/server.rs index 683dda1fd..d3a6eab01 100644 --- a/crates/symbolicator/src/server.rs +++ b/crates/symbolicator/src/server.rs @@ -18,6 +18,7 @@ pub fn create_app(state: Service) -> App { } /// Starts all actors and HTTP server based on loaded config. +#[tracing::instrument(skip(config))] pub fn run(config: Config) -> Result<()> { // Log this metric before actually starting the server. This allows to see restarts even if // service creation fails. The HTTP server is bound before the actix system runs. From 6365eed6f16aacdc6af64f5470cf911e70f01a68 Mon Sep 17 00:00:00 2001 From: Sebastian Zivota Date: Mon, 27 Sep 2021 16:34:41 +0200 Subject: [PATCH 11/16] WIP --- crates/symbolicator/src/logging.rs | 8 +++----- 1 file changed, 3 insertions(+), 5 deletions(-) diff --git a/crates/symbolicator/src/logging.rs b/crates/symbolicator/src/logging.rs index 3970fe0cf..6808f6376 100644 --- a/crates/symbolicator/src/logging.rs +++ b/crates/symbolicator/src/logging.rs @@ -101,12 +101,10 @@ pub fn init_logging(config: &Config) { env::set_var("RUST_BACKTRACE", "1"); } - if env::var("RUST_LOG").is_err() { - let rust_log = get_rust_log(config.logging.level); - env::set_var("RUST_LOG", rust_log); - } + let rust_log = + env::var("RUST_LOG").unwrap_or_else(|_| get_rust_log(config.logging.level).to_string()); - let filter = EnvFilter::from_default_env(); + let filter = EnvFilter::new(rust_log); let sentry = sentry::integrations::tracing::layer(); let subscriber = FmtSubscriber::new().with(filter).with(sentry); From f999b80d06f0e8142941603219b0703972282ae7 Mon Sep 17 00:00:00 2001 From: Sebastian Zivota Date: Thu, 21 Oct 2021 16:07:02 +0200 Subject: [PATCH 12/16] Add tracing-futures --- Cargo.lock | 11 +++++++++++ crates/symbolicator/Cargo.toml | 1 + 2 files changed, 12 insertions(+) diff --git a/Cargo.lock b/Cargo.lock index 42f9c9d77..fd118994a 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3065,6 +3065,7 @@ dependencies = [ "tower-layer", "tower-service", "tracing", + "tracing-futures", "tracing-log", "tracing-subscriber", "url", @@ -3373,6 +3374,16 @@ dependencies = [ "lazy_static", ] +[[package]] +name = "tracing-futures" +version = "0.2.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "97d095ae15e245a057c8e8451bab9b3ee1e1f68e9ba2b4fbc18d0ac5237835f2" +dependencies = [ + "pin-project", + "tracing", +] + [[package]] name = "tracing-log" version = "0.1.2" diff --git a/crates/symbolicator/Cargo.toml b/crates/symbolicator/Cargo.toml index 573ff24d6..7e6f7f1b8 100644 --- a/crates/symbolicator/Cargo.toml +++ b/crates/symbolicator/Cargo.toml @@ -51,6 +51,7 @@ tracing-subscriber = { version = "0.2.20", features = ["chrono"] } url = { version = "2.2.0", features = ["serde"] } uuid = { version = "0.8.2", features = ["v4", "serde"] } zstd = "0.9.0" +tracing-futures = "0.2.5" [dev-dependencies] insta = { version = "1.5.2", features = ["redactions"] } From 0af0521eacc60b20daee59764282c84aebc3bde1 Mon Sep 17 00:00:00 2001 From: Sebastian Zivota Date: Thu, 21 Oct 2021 17:23:39 +0200 Subject: [PATCH 13/16] Revert "Add tracing-futures" This reverts commit f999b80d06f0e8142941603219b0703972282ae7. --- Cargo.lock | 11 ----------- crates/symbolicator/Cargo.toml | 1 - 2 files changed, 12 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index fd118994a..42f9c9d77 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3065,7 +3065,6 @@ dependencies = [ "tower-layer", "tower-service", "tracing", - "tracing-futures", "tracing-log", "tracing-subscriber", "url", @@ -3374,16 +3373,6 @@ dependencies = [ "lazy_static", ] -[[package]] -name = "tracing-futures" -version = "0.2.5" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "97d095ae15e245a057c8e8451bab9b3ee1e1f68e9ba2b4fbc18d0ac5237835f2" -dependencies = [ - "pin-project", - "tracing", -] - [[package]] name = "tracing-log" version = "0.1.2" diff --git a/crates/symbolicator/Cargo.toml b/crates/symbolicator/Cargo.toml index 7e6f7f1b8..573ff24d6 100644 --- a/crates/symbolicator/Cargo.toml +++ b/crates/symbolicator/Cargo.toml @@ -51,7 +51,6 @@ tracing-subscriber = { version = "0.2.20", features = ["chrono"] } url = { version = "2.2.0", features = ["serde"] } uuid = { version = "0.8.2", features = ["v4", "serde"] } zstd = "0.9.0" -tracing-futures = "0.2.5" [dev-dependencies] insta = { version = "1.5.2", features = ["redactions"] } From 55acef97abd435959f1eb0d93dbf2eefab91262a Mon Sep 17 00:00:00 2001 From: Sebastian Zivota Date: Thu, 21 Oct 2021 17:24:14 +0200 Subject: [PATCH 14/16] "Properly" install the subscriber --- Cargo.lock | 1 - crates/symbolicator/Cargo.toml | 1 - crates/symbolicator/src/logging.rs | 104 +++++++---------------------- crates/symbolicator/src/server.rs | 1 - 4 files changed, 23 insertions(+), 84 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 42f9c9d77..84597b17e 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3065,7 +3065,6 @@ dependencies = [ "tower-layer", "tower-service", "tracing", - "tracing-log", "tracing-subscriber", "url", "uuid", diff --git a/crates/symbolicator/Cargo.toml b/crates/symbolicator/Cargo.toml index 573ff24d6..0b729b14a 100644 --- a/crates/symbolicator/Cargo.toml +++ b/crates/symbolicator/Cargo.toml @@ -46,7 +46,6 @@ tokio-util = "0.6" tower-layer = "0.3" tower-service = "0.3" tracing = "0.1.26" -tracing-log = "0.1.2" tracing-subscriber = { version = "0.2.20", features = ["chrono"] } url = { version = "2.2.0", features = ["serde"] } uuid = { version = "0.8.2", features = ["v4", "serde"] } diff --git a/crates/symbolicator/src/logging.rs b/crates/symbolicator/src/logging.rs index 6808f6376..ef8c3c04e 100644 --- a/crates/symbolicator/src/logging.rs +++ b/crates/symbolicator/src/logging.rs @@ -1,70 +1,14 @@ -use std::collections::BTreeMap; use std::env; use std::fmt; -use chrono::{DateTime, Utc}; -use serde::{Deserialize, Serialize}; use tracing::level_filters::LevelFilter; -use tracing::{Event, Level, Metadata, Subscriber}; +use tracing_subscriber::fmt::fmt; use tracing_subscriber::fmt::time::ChronoUtc; -use tracing_subscriber::fmt::{FmtContext, FormatEvent, FormatFields, Layer}; use tracing_subscriber::prelude::*; -use tracing_subscriber::registry::LookupSpan; -use tracing_subscriber::{EnvFilter, FmtSubscriber}; +use tracing_subscriber::util::SubscriberInitExt; use crate::config::{Config, LogFormat}; -//#[derive(Serialize, Deserialize, Debug)] -//struct JsonLog<'a> { -// timestamp: DateTime, -// level: Level, -// logger: &'a str, -// message: String, -// module_path: Option<&'a str>, -// filename: Option<&'a str>, -// lineno: Option, -// fields: BTreeMap<&'a str, &'a str>, -//} -// -//impl<'a, 'b> From<&'b Event<'a>> for JsonLog<'a> { -// fn from(event: &'b Event<'a>) -> Self { -// let meta = event.metadata(); -// Self { -// timestamp: Utc::now(), -// level: *meta.level(), -// logger: meta.target(), -// message: event.message(), -// module_path: meta.module_path(), -// filename: meta.file(), -// lineno: meta.line(), -// } -// } -//} -// -//#[derive(Debug)] -//struct Json; -// -//impl FormatEvent for Json -//where -// S: Subscriber + for<'a> LookupSpan<'a>, -// N: for<'a> FormatFields<'a> + 'static, -//{ -// fn format_event( -// &self, -// ctx: &FmtContext<'_, S, N>, -// writer: &mut dyn fmt::Write, -// event: &Event<'_>, -// ) -> fmt::Result { -// let meta = event.metadata(); -// let module_path = meta.module_path(); -// let level = *meta.level(); -// let logger = meta.target(); -// let lineno = meta.line(); -// let timestamp = Utc::now(); -// -// writer.write -// } -//} fn get_rust_log(level: LevelFilter) -> &'static str { match level { LevelFilter::OFF => "", @@ -104,32 +48,30 @@ pub fn init_logging(config: &Config) { let rust_log = env::var("RUST_LOG").unwrap_or_else(|_| get_rust_log(config.logging.level).to_string()); - let filter = EnvFilter::new(rust_log); - let sentry = sentry::integrations::tracing::layer(); - let subscriber = FmtSubscriber::new().with(filter).with(sentry); + let subscriber = fmt() + .with_timer(ChronoUtc::rfc3339()) + .with_env_filter(rust_log); - let format = Layer::new().with_timer(ChronoUtc::rfc3339()); match (config.logging.format, console::user_attended()) { - (LogFormat::Auto, true) | (LogFormat::Pretty, _) => { - tracing::subscriber::set_global_default(subscriber.with(format.pretty())) - } - (LogFormat::Auto, false) | (LogFormat::Simplified, _) => { - tracing::subscriber::set_global_default(subscriber.with(format.compact())) - } - (LogFormat::Json, _) => tracing::subscriber::set_global_default( - subscriber.with( - format - .json() - .flatten_event(true) - .with_current_span(false) - .with_span_list(false), - ), - ), + (LogFormat::Auto, true) | (LogFormat::Pretty, _) => subscriber + .pretty() + .finish() + .with(sentry::integrations::tracing::layer()) + .init(), + (LogFormat::Auto, false) | (LogFormat::Simplified, _) => subscriber + .compact() + .finish() + .with(sentry::integrations::tracing::layer()) + .init(), + (LogFormat::Json, _) => subscriber + .json() + .flatten_event(true) + .with_current_span(false) + .with_span_list(false) + .finish() + .with(sentry::integrations::tracing::layer()) + .init(), } - .expect("setting global default subscriber"); - - // "Logger" that captures log records and republishes them as tracing events. - tracing_log::LogTracer::init().expect("setting global default log tracer"); } /// A wrapper around an [`Error`](std::error::Error) that prints its causes. diff --git a/crates/symbolicator/src/server.rs b/crates/symbolicator/src/server.rs index 3c65088df..df7ba91b9 100644 --- a/crates/symbolicator/src/server.rs +++ b/crates/symbolicator/src/server.rs @@ -7,7 +7,6 @@ use crate::endpoints; use crate::services::Service; /// Starts all actors and HTTP server based on loaded config. -#[tracing::instrument(skip(config))] pub fn run(config: Config) -> Result<()> { // Log this metric before actually starting the server. This allows to see restarts even if // service creation fails. From 5791e4ed8271d77dd31fa04a63bbc638082c995f Mon Sep 17 00:00:00 2001 From: Sebastian Zivota Date: Tue, 2 Nov 2021 09:58:45 +0100 Subject: [PATCH 15/16] WIP --- crates/symbolicator/Cargo.toml | 2 +- crates/symbolicator/src/logging.rs | 5 +++-- 2 files changed, 4 insertions(+), 3 deletions(-) diff --git a/crates/symbolicator/Cargo.toml b/crates/symbolicator/Cargo.toml index 0b729b14a..c7fbfd5e7 100644 --- a/crates/symbolicator/Cargo.toml +++ b/crates/symbolicator/Cargo.toml @@ -46,7 +46,7 @@ tokio-util = "0.6" tower-layer = "0.3" tower-service = "0.3" tracing = "0.1.26" -tracing-subscriber = { version = "0.2.20", features = ["chrono"] } +tracing-subscriber = { version = "0.2.20", features = ["chrono", "tracing-log"] } url = { version = "2.2.0", features = ["serde"] } uuid = { version = "0.8.2", features = ["v4", "serde"] } zstd = "0.9.0" diff --git a/crates/symbolicator/src/logging.rs b/crates/symbolicator/src/logging.rs index ef8c3c04e..62f9eddda 100644 --- a/crates/symbolicator/src/logging.rs +++ b/crates/symbolicator/src/logging.rs @@ -50,6 +50,7 @@ pub fn init_logging(config: &Config) { let subscriber = fmt() .with_timer(ChronoUtc::rfc3339()) + .with_target(true) .with_env_filter(rust_log); match (config.logging.format, console::user_attended()) { @@ -66,8 +67,8 @@ pub fn init_logging(config: &Config) { (LogFormat::Json, _) => subscriber .json() .flatten_event(true) - .with_current_span(false) - .with_span_list(false) + .with_current_span(true) + .with_span_list(true) .finish() .with(sentry::integrations::tracing::layer()) .init(), From e5f3121643a1131d769b19617eaa49f75301c16d Mon Sep 17 00:00:00 2001 From: Sebastian Zivota Date: Tue, 25 Jan 2022 14:31:25 +0100 Subject: [PATCH 16/16] Add file name & line number to json logs --- crates/symbolicator/src/logging.rs | 2 ++ crates/symbolicator/src/services/shared_cache.rs | 10 ++++++++-- crates/symbolicator/src/test.rs | 2 +- 3 files changed, 11 insertions(+), 3 deletions(-) diff --git a/crates/symbolicator/src/logging.rs b/crates/symbolicator/src/logging.rs index e68334cac..c17d209bc 100644 --- a/crates/symbolicator/src/logging.rs +++ b/crates/symbolicator/src/logging.rs @@ -69,6 +69,8 @@ pub fn init_logging(config: &Config) { .flatten_event(true) .with_current_span(true) .with_span_list(true) + .with_file(true) + .with_line_number(true) .finish() .with(sentry::integrations::tracing::layer()) .init(), diff --git a/crates/symbolicator/src/services/shared_cache.rs b/crates/symbolicator/src/services/shared_cache.rs index 3285711ae..4ba8768eb 100644 --- a/crates/symbolicator/src/services/shared_cache.rs +++ b/crates/symbolicator/src/services/shared_cache.rs @@ -169,7 +169,10 @@ impl GcsState { let status = response.status(); match status { _ if status.is_success() => { - tracing::trace!("Success hitting shared_cache GCS {}", key.gcs_bucket_key()); + tracing::trace!( + "Success hitting shared_cache GCS {}", + key.gcs_bucket_key() + ); let stream = response .bytes_stream() .map_err(|e| std::io::Error::new(std::io::ErrorKind::Other, e)); @@ -236,7 +239,10 @@ impl GcsState { let status = response.status(); match status { successful if successful.is_success() => { - tracing::trace!("Success hitting shared_cache GCS {}", key.gcs_bucket_key()); + tracing::trace!( + "Success hitting shared_cache GCS {}", + key.gcs_bucket_key() + ); Ok(SharedCacheStoreResult::Written(total_bytes)) } StatusCode::PRECONDITION_FAILED => Ok(SharedCacheStoreResult::Skipped), diff --git a/crates/symbolicator/src/test.rs b/crates/symbolicator/src/test.rs index 156dc1c50..a102c09bf 100644 --- a/crates/symbolicator/src/test.rs +++ b/crates/symbolicator/src/test.rs @@ -22,9 +22,9 @@ use std::sync::atomic::{AtomicUsize, Ordering}; use std::sync::Arc; use reqwest::Url; +use serde::{Deserialize, Serialize}; use tracing_subscriber::filter::EnvFilter; use tracing_subscriber::fmt::fmt; -use serde::{Deserialize, Serialize}; use warp::filters::fs::File; use warp::reject::{Reject, Rejection}; use warp::Filter;