From 1e1f43ced3a28cd95b5c335c9ca38fe1251640f8 Mon Sep 17 00:00:00 2001 From: Jason White Date: Sat, 28 Dec 2024 14:54:57 -0800 Subject: [PATCH] Switch to tracing crate for logging --- Cargo.lock | 189 +++++++++++++++++++++++++----------------- Cargo.toml | 5 +- src/app.rs | 2 +- src/lib.rs | 14 ++-- src/logger.rs | 4 +- src/main.rs | 36 ++++---- src/storage/cached.rs | 20 ++--- src/storage/s3.rs | 6 +- src/storage/verify.rs | 2 +- tests/common/mod.rs | 15 ++-- tests/test_local.rs | 4 +- tests/test_s3.rs | 4 +- 12 files changed, 173 insertions(+), 128 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 0d76900..32f507f 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -428,32 +428,6 @@ dependencies = [ "shared_child", ] -[[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 = "env_logger" -version = "0.9.3" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "a12e6657c4c97ebab115a42dcee77225f7f482cdd841cf7088c657a42e9e00e7" -dependencies = [ - "atty", - "humantime 2.1.0", - "log", - "regex", - "termcolor", -] - [[package]] name = "equivalent" version = "1.0.1" @@ -727,15 +701,6 @@ dependencies = [ "libm", ] -[[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" @@ -1049,6 +1014,15 @@ version = "0.4.22" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "a7a70ba024b9dc04c27ea2f0c0548feb474ec5c54bba33a7f72f873a39d07b24" +[[package]] +name = "matchers" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8263075bb86c5a1b1427b5ae862e8889656f126e9f77c484496e8b47cf5c5558" +dependencies = [ + "regex-automata 0.1.10", +] + [[package]] name = "md-5" version = "0.9.1" @@ -1118,6 +1092,16 @@ dependencies = [ "minimal-lexical", ] +[[package]] +name = "nu-ansi-term" +version = "0.46.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "77a8165726e8236064dbb45459242600304b42a5ea24ee2948e18e023bf7ba84" +dependencies = [ + "overload", + "winapi", +] + [[package]] name = "num-traits" version = "0.2.19" @@ -1164,6 +1148,12 @@ dependencies = [ "windows-sys 0.59.0", ] +[[package]] +name = "overload" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39" + [[package]] name = "parking_lot" version = "0.12.3" @@ -1214,16 +1204,6 @@ dependencies = [ "zerocopy", ] -[[package]] -name = "pretty_env_logger" -version = "0.4.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "926d36b9553851b8b0005f1275891b392ee4d2d833852c417ed025477350fb9d" -dependencies = [ - "env_logger 0.7.1", - "log", -] - [[package]] name = "proc-macro-error" version = "1.0.4" @@ -1257,12 +1237,6 @@ dependencies = [ "unicode-ident", ] -[[package]] -name = "quick-error" -version = "1.2.3" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "a1d01941d82fa2ab50be1e79e6714289dd7cde78eba4c074bc5a4374f650dfe0" - [[package]] name = "quote" version = "1.0.38" @@ -1330,8 +1304,17 @@ checksum = "b544ef1b4eac5dc2db33ea63606ae9ffcfac26c1416a2806ae0bf5f56b201191" dependencies = [ "aho-corasick", "memchr", - "regex-automata", - "regex-syntax", + "regex-automata 0.4.9", + "regex-syntax 0.8.5", +] + +[[package]] +name = "regex-automata" +version = "0.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132" +dependencies = [ + "regex-syntax 0.6.29", ] [[package]] @@ -1342,9 +1325,15 @@ checksum = "809e8dc61f6de73b46c85f4c96486310fe304c434cfa43669d7b40f711150908" dependencies = [ "aho-corasick", "memchr", - "regex-syntax", + "regex-syntax 0.8.5", ] +[[package]] +name = "regex-syntax" +version = "0.6.29" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f162c6dd7b008981e4d40210aca20b4bd0f9b60ca9271061b07f78537722f2e1" + [[package]] name = "regex-syntax" version = "0.8.5" @@ -1393,18 +1382,15 @@ dependencies = [ "chacha", "derive_more", "duct", - "env_logger 0.9.3", "futures", "generic-array", "hex", "http", "human-size", "humansize 2.1.3", - "humantime 2.1.0", + "humantime", "hyper", "linked-hash-map", - "log", - "pretty_env_logger", "rand", "rusoto_core", "rusoto_credential", @@ -1418,6 +1404,8 @@ dependencies = [ "tokio", "tokio-util", "toml", + "tracing", + "tracing-subscriber", "url", "uuid", ] @@ -1708,6 +1696,15 @@ dependencies = [ "digest 0.10.7", ] +[[package]] +name = "sharded-slab" +version = "0.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f40ca3c46823713e0d4209592e8d6e826aa57e928f09752619fc696c499637f6" +dependencies = [ + "lazy_static", +] + [[package]] name = "shared_child" version = "1.0.1" @@ -1858,15 +1855,6 @@ dependencies = [ "windows-sys 0.59.0", ] -[[package]] -name = "termcolor" -version = "1.4.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "06794f8f6c5c898b3275aebefa6b8a1cb24cd2c6c79397ab15774837a0bc5755" -dependencies = [ - "winapi-util", -] - [[package]] name = "textwrap" version = "0.11.0" @@ -1896,6 +1884,16 @@ dependencies = [ "syn 2.0.93", ] +[[package]] +name = "thread_local" +version = "1.1.8" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8b9ef9bad013ada3808854ceac7b46812a6465ba368859a37e2100283d2d719c" +dependencies = [ + "cfg-if", + "once_cell", +] + [[package]] name = "tinystr" version = "0.7.6" @@ -1985,9 +1983,21 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "784e0ac535deb450455cbfa28a6f0df145ea1bb7ae51b821cf5e7927fdcfbdd0" dependencies = [ "pin-project-lite", + "tracing-attributes", "tracing-core", ] +[[package]] +name = "tracing-attributes" +version = "0.1.28" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "395ae124c09f9e6918a2310af6038fba074bcf474ac352496d5910dd59a2226d" +dependencies = [ + "proc-macro2", + "quote", + "syn 2.0.93", +] + [[package]] name = "tracing-core" version = "0.1.33" @@ -1995,6 +2005,36 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "e672c95779cf947c5311f83787af4fa8fffd12fb27e4993211a84bdfd9610f9c" dependencies = [ "once_cell", + "valuable", +] + +[[package]] +name = "tracing-log" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3" +dependencies = [ + "log", + "once_cell", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.3.19" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "e8189decb5ac0fa7bc8b96b7cb9b2701d60d48805aca84a238004d665fcc4008" +dependencies = [ + "matchers", + "nu-ansi-term", + "once_cell", + "regex", + "sharded-slab", + "smallvec", + "thread_local", + "tracing", + "tracing-core", + "tracing-log", ] [[package]] @@ -2083,6 +2123,12 @@ dependencies = [ "getrandom", ] +[[package]] +name = "valuable" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d" + [[package]] name = "vec_map" version = "0.8.2" @@ -2200,15 +2246,6 @@ version = "0.4.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ac3b87c63620426dd9b991e5ce0329eff545bccbbb34f3be09ff6fb6ab51b7b6" -[[package]] -name = "winapi-util" -version = "0.1.9" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "cf221c93e13a30d793f7645a0e7762c55d169dbb0a49671918a2319d289b10bb" -dependencies = [ - "windows-sys 0.59.0", -] - [[package]] name = "winapi-x86_64-pc-windows-gnu" version = "0.4.0" diff --git a/Cargo.toml b/Cargo.toml index 1aca329..4624282 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -31,8 +31,6 @@ humansize = "2" humantime = "2" hyper = { version = "0.14", features = ["server", "http1", "http2", "tcp", "stream"] } linked-hash-map = { version = "0.5", features = ["serde_impl"] } -log = "0.4" -pretty_env_logger = "0.4" rand = { version = "0.8", optional = true } serde = { version = "1", features = ["derive"] } serde_json = "1" @@ -40,6 +38,8 @@ sha2 = "0.10" structopt = "0.3" tokio = { version = "1", features = ["full"] } tokio-util = { version = "0.7", features = ["full"] } +tracing = "0.1" +tracing-subscriber = { version = "0.3", features = ["env-filter"] } url = "2" uuid = { version = "1.1", features = ["v4"] } @@ -47,7 +47,6 @@ uuid = { version = "1.1", features = ["v4"] } rand = "0.8" tempfile = "3" duct = "0.13" -env_logger = "0.9" toml = "0.5" [dependencies.rusoto_core] diff --git a/src/app.rs b/src/app.rs index 682367b..b393cb9 100644 --- a/src/app.rs +++ b/src/app.rs @@ -336,7 +336,7 @@ where let size = match size { Ok(size) => size, Err(err) => { - log::error!("batch response error: {}", err); + tracing::error!("batch response error: {err}"); // Return a generic "500 - Internal Server Error" for objects that // we failed to get the size of. This is usually caused by some diff --git a/src/lib.rs b/src/lib.rs index 51a5c9f..a08c0a1 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -141,13 +141,13 @@ impl S3ServerBuilder { let prefix = self.prefix.unwrap_or_else(|| String::from("lfs")); if self.cdn.is_some() { - log::warn!( + tracing::warn!( "A CDN was specified. Since uploads and downloads do not flow \ through Rudolfs in this case, they will *not* be encrypted." ); if self.cache.take().is_some() { - log::warn!( + tracing::warn!( "A local disk cache does not work with a CDN and will be \ disabled." ); @@ -207,7 +207,7 @@ impl S3ServerBuilder { ) -> Result<(), Box> { let server = self.spawn(addr).await?; - log::info!("Listening on {}", server.addr()); + tracing::info!("Listening on {}", server.addr()); server.await?; Ok(()) @@ -260,12 +260,14 @@ impl LocalServerBuilder { match self.key { Some(key) => { let storage = Verify::new(Encrypted::new(key, storage)); - log::info!("Local disk storage initialized (with encryption)."); + tracing::info!( + "Local disk storage initialized (with encryption)." + ); Ok(Box::new(spawn_server(storage, &addr))) } None => { let storage = Verify::new(storage); - log::info!( + tracing::info!( "Local disk storage initialized (without encryption)." ); Ok(Box::new(spawn_server(storage, &addr))) @@ -281,7 +283,7 @@ impl LocalServerBuilder { ) -> Result<(), Box> { let server = self.spawn(addr).await?; - log::info!("Listening on {}", server.addr()); + tracing::info!("Listening on {}", server.addr()); server.await?; Ok(()) diff --git a/src/logger.rs b/src/logger.rs index 0aca513..c252090 100644 --- a/src/logger.rs +++ b/src/logger.rs @@ -68,7 +68,7 @@ where Box::pin(self.service.call(req).inspect( move |response| match response { - Ok(response) => log::info!( + Ok(response) => tracing::info!( "[{}] {} {} - {} ({})", remote_addr.ip(), method, @@ -76,7 +76,7 @@ where response.status(), format_duration(start.elapsed()), ), - Err(err) => log::error!( + Err(err) => tracing::error!( "[{}] {} {} - {} ({})", remote_addr.ip(), method, diff --git a/src/main.rs b/src/main.rs index 7cfc6a6..51d68a9 100644 --- a/src/main.rs +++ b/src/main.rs @@ -23,6 +23,9 @@ use std::path::PathBuf; use hex::FromHex; use structopt::StructOpt; +use tracing_subscriber::filter::EnvFilter; +use tracing_subscriber::filter::LevelFilter; + use rudolfs::{Cache, LocalServerBuilder, S3ServerBuilder}; // Additional help to append to the end when `--help` is specified. @@ -83,13 +86,13 @@ struct GlobalArgs { )] max_cache_size: human_size::Size, - /// Logging level to use. + /// Logging level to use. Example: "debug" #[structopt( long = "log-level", default_value = "info", env = "RUDOLFS_LOG" )] - log_level: log::LevelFilter, + log_level: LevelFilter, } #[derive(StructOpt)] @@ -119,16 +122,21 @@ struct LocalArgs { impl Args { async fn main(self) -> Result<(), Box> { // Initialize logging. - let mut logger_builder = pretty_env_logger::formatted_timed_builder(); - logger_builder.filter_module("rudolfs", self.global.log_level); - - if let Ok(env) = std::env::var("RUST_LOG") { - // Support the addition of RUST_LOG to help with debugging - // dependencies, such as Hyper. - logger_builder.parse_filters(&env); - } - - logger_builder.init(); + tracing_subscriber::fmt() + .with_env_filter( + EnvFilter::from_default_env().add_directive( + // Filter directive for this crate specifically. This will + // not override any directives from RUST_LOG unless it + // overlaps. + format!( + "{}={}", + env!("CARGO_PKG_NAME"), + self.global.log_level + ) + .parse()?, + ), + ) + .init(); // Find a socket address to bind to. This will resolve domain names. let addr = match self.global.host { @@ -139,7 +147,7 @@ impl Args { None => SocketAddr::from(([0, 0, 0, 0], self.global.port)), }; - log::info!("Initializing storage..."); + tracing::info!("Initializing storage..."); match self.backend { Backend::S3(s3) => s3.run(addr, self.global).await?, @@ -206,7 +214,7 @@ impl LocalArgs { #[tokio::main] async fn main() { let exit_code = if let Err(err) = Args::from_args().main().await { - log::error!("{}", err); + tracing::error!("{err}"); 1 } else { 0 diff --git a/src/storage/cached.rs b/src/storage/cached.rs index f9006ee..b9ba40d 100644 --- a/src/storage/cached.rs +++ b/src/storage/cached.rs @@ -105,7 +105,7 @@ where ) -> Result { let lru = Cache::from_stream(cache.list()).await?; - log::info!( + tracing::info!( "Prepopulated cache with {} entries ({})", lru.len(), humansize::format_size(lru.size(), humansize::DECIMAL), @@ -120,7 +120,7 @@ where let count = prune_cache(lru.clone(), max_size, cache.clone()).await?; if count > 0 { - log::info!("Pruned {} entries from the cache", count); + tracing::info!("Pruned {} entries from the cache", count); } Ok(Backend { @@ -153,7 +153,7 @@ where while lru.size() > max_size { if let Some((key, _)) = lru.pop() { - log::debug!("Pruning '{}' from cache", key); + tracing::debug!("Pruning '{}' from cache", key); let _ = storage.delete(&key).await; deleted += 1; } @@ -176,9 +176,9 @@ where let oid = *key.oid(); - log::debug!("Caching {}", oid); + tracing::debug!("Caching {}", oid); cache.put(key.clone(), obj).await?; - log::debug!("Finished caching {}", oid); + tracing::debug!("Finished caching {}", oid); // Add the object info to our LRU cache once the download from // permanent storage is complete. @@ -190,13 +190,13 @@ where match prune_cache(lru, max_size, cache).await { Ok(count) => { if count > 0 { - log::info!("Pruned {} entries from the cache", count); + tracing::info!("Pruned {} entries from the cache", count); } Ok(()) } Err(err) => { - log::error!("Error caching {} ({})", oid, err); + tracing::error!("Error caching {} ({})", oid, err); Err(err) } } @@ -268,7 +268,7 @@ where future::try_join(f.map_err(Error::from_stream), cache) .map_ok(|((), ())| ()) .map_err(move |err: Self::Error| { - log::error!("Error caching {} ({})", key, err); + tracing::error!("Error caching {} ({})", key, err); }), ); @@ -312,7 +312,7 @@ where .put(key.clone(), a) .map_ok(move |()| { // Send a signal to the cache so that it can complete its write. - log::debug!("Received last chunk from server."); + tracing::debug!("Received last chunk from server."); signal_sender.send(()).unwrap_or(()) }) .map_err(Error::from_storage); @@ -360,7 +360,7 @@ where async fn delete(&self, key: &StorageKey) -> Result<(), Self::Error> { // Only ever delete items from the cache. This may be called when // a corrupted object is detected. - log::info!("Deleted {} from the cache", key); + tracing::info!("Deleted {} from the cache", key); self.cache.delete(key).await.map_err(Error::from_cache) } diff --git a/src/storage/s3.rs b/src/storage/s3.rs index 232881a..d7eae42 100644 --- a/src/storage/s3.rs +++ b/src/storage/s3.rs @@ -176,7 +176,7 @@ impl Backend { Region::default() }; - log::info!( + tracing::info!( "Connecting to S3 bucket '{}' at region '{}'", bucket, region.name() @@ -187,7 +187,7 @@ impl Backend { let (client, credential_provider): (_, BoxedCredentialProvider) = if k8s_provider.credentials().await.is_ok() { - log::info!("Using credentials from Kubernetes"); + tracing::info!("Using credentials from Kubernetes"); let provider = AutoRefreshingProvider::new(k8s_provider)?; let client = S3Client::new_with( HttpClient::new()?, @@ -248,7 +248,7 @@ impl Backend { }) .await?; - log::info!("Successfully authorized with AWS"); + tracing::info!("Successfully authorized with AWS"); Ok(Backend { client, diff --git a/src/storage/verify.rs b/src/storage/verify.rs index 826e801..f764219 100644 --- a/src/storage/verify.rs +++ b/src/storage/verify.rs @@ -92,7 +92,7 @@ where let stream = stream.map_err(move |err| { match err { Error::Verify(err) => { - log::error!( + tracing::error!( "Found corrupted object {} ({})", key.oid(), err diff --git a/tests/common/mod.rs b/tests/common/mod.rs index d7f955c..1ce05c6 100644 --- a/tests/common/mod.rs +++ b/tests/common/mod.rs @@ -161,14 +161,13 @@ where Ok(()) } -pub fn init_logger() { - let _ = env_logger::builder() - // Include all events in tests - .filter_module("rudolfs", log::LevelFilter::max()) - // Ensure events are captured by `cargo test` - .is_test(true) - // Ignore errors initializing the logger if tests race to configure it - .try_init(); +/// Sets the default subscriber for the current thread until the guard is +/// dropped. +/// +/// NOTE: Use `cargo test -- --nocapture` to see server logs. +pub fn init_logger() -> tracing::subscriber::DefaultGuard { + let subscriber = tracing_subscriber::fmt().with_test_writer().finish(); + tracing::subscriber::set_default(subscriber) } /// Runs `git lfs install`, but serializes it across unit tests. Tests are flaky diff --git a/tests/test_local.rs b/tests/test_local.rs index c10560a..e96540b 100644 --- a/tests/test_local.rs +++ b/tests/test_local.rs @@ -35,7 +35,7 @@ use common::{init_logger, GitRepo, SERVER_ADDR}; #[tokio::test(flavor = "multi_thread")] async fn local_smoke_test_encrypted() -> Result<(), Box> { - init_logger(); + let _guard = init_logger(); // Make sure our seed is deterministic. This makes it easier to reproduce // the same repo every time. @@ -68,7 +68,7 @@ async fn local_smoke_test_encrypted() -> Result<(), Box> #[tokio::test(flavor = "multi_thread")] async fn local_smoke_test_unencrypted() -> Result<(), Box> { - init_logger(); + let _guard = init_logger(); // Make sure our seed is deterministic. This makes it easier to reproduce // the same repo every time. diff --git a/tests/test_s3.rs b/tests/test_s3.rs index 4479f63..0f13c32 100644 --- a/tests/test_s3.rs +++ b/tests/test_s3.rs @@ -77,7 +77,7 @@ fn load_s3_credentials() -> io::Result { #[tokio::test(flavor = "multi_thread")] async fn s3_smoke_test_encrypted() -> Result<(), Box> { - init_logger(); + let _guard = init_logger(); let creds = match load_s3_credentials() { Ok(creds) => creds, @@ -119,7 +119,7 @@ async fn s3_smoke_test_encrypted() -> Result<(), Box> { #[tokio::test(flavor = "multi_thread")] async fn s3_smoke_test_unencrypted() -> Result<(), Box> { - init_logger(); + let _guard = init_logger(); let creds = match load_s3_credentials() { Ok(creds) => creds,