From 8eff499a630f951bbcca563268eed7b5d7b06fcc Mon Sep 17 00:00:00 2001 From: Byron Hambly Date: Tue, 26 Jul 2022 14:08:55 +0200 Subject: [PATCH] fix: change logs to UTC due to bug in time crate On Linux and macOS, no program output was being observed. This is referenced in the [LocalTime] docs for `tracing-subscriber`, which links to this [unsoundness issue] in the time crate. Rather than introducing a possible vector for undefined behaviour and segfaults, I have just changed the logging to use UTC time instead. When running the ASB as a systemd service, one would generally use the `--disable-timestamps` flag anyway as systemd adds its own timestamps which can be local to the server. If the situation with `tracing-subscriber` and the time crate is fixed then this can be updated. This commit also updates the `tracing-subscriber` and `tracing-appender` dependencies, closing #987. [LocalTime]: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/fmt/time/struct.LocalTime.html [unsoundness issue]: https://github.com/time-rs/time/issues/293#issuecomment-748151025 --- .gitignore | 3 ++ CHANGELOG.md | 2 +- Cargo.lock | 66 ++++++++++++++++++++++++++++------------- swap/Cargo.toml | 4 +-- swap/src/asb/tracing.rs | 4 +-- swap/src/cli/tracing.rs | 13 ++++---- swap/src/tracing_ext.rs | 2 +- 7 files changed, 62 insertions(+), 32 deletions(-) diff --git a/.gitignore b/.gitignore index c0b0db30..905e678b 100644 --- a/.gitignore +++ b/.gitignore @@ -157,3 +157,6 @@ flycheck_*.el .swap-db/ # End of https://www.toptal.com/developers/gitignore/api/rust,clion+all,emacs + +*.log +.vscode \ No newline at end of file diff --git a/CHANGELOG.md b/CHANGELOG.md index e49dd774..a2bce431 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -10,9 +10,9 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Changed - Change Monero nodes to [Rino tool nodes](https://community.rino.io/nodes.html) -- Revert logs to use rfc3339 local time formatting. - Update from monero v17.2.0 to monero v17.3.0 - Always write logs as JSON to files +- Change to UTC time for log messages, due to a bug causing no logging at all to be printed (linux/macos), and an [unsoundness issue](https://docs.rs/tracing-subscriber/latest/tracing_subscriber/fmt/time/struct.LocalTime.html) with local time in [the time crate](https://github.com/time-rs/time/issues/293#issuecomment-748151025) ### Added diff --git a/Cargo.lock b/Cargo.lock index 903b7695..4a1d3c0f 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -523,7 +523,6 @@ dependencies = [ "libc", "num-integer", "num-traits", - "time 0.1.43", "winapi 0.3.9", ] @@ -2172,6 +2171,15 @@ dependencies = [ "regex-automata", ] +[[package]] +name = "matchers" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8263075bb86c5a1b1427b5ae862e8889656f126e9f77c484496e8b47cf5c5558" +dependencies = [ + "regex-automata", +] + [[package]] name = "matches" version = "0.1.8" @@ -2285,7 +2293,7 @@ dependencies = [ "testcontainers 0.12.0", "tokio", "tracing", - "tracing-subscriber", + "tracing-subscriber 0.2.25", ] [[package]] @@ -2319,7 +2327,7 @@ dependencies = [ "rand 0.7.3", "testcontainers 0.12.0", "tokio", - "tracing-subscriber", + "tracing-subscriber 0.2.25", ] [[package]] @@ -2533,9 +2541,9 @@ dependencies = [ [[package]] name = "once_cell" -version = "1.7.2" +version = "1.13.0" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "af8b08b04175473088b46763e51ee54da5f9a164bc162f615b91bc179dbf15a3" +checksum = "18a6dbe30758c9f83eb00cbea4ac95966305f5a7772f3f42ebfc7fc7eddbd8e1" [[package]] name = "opaque-debug" @@ -4088,7 +4096,7 @@ dependencies = [ "tracing", "tracing-appender", "tracing-futures", - "tracing-subscriber", + "tracing-subscriber 0.3.15", "url", "uuid", "vergen", @@ -4205,9 +4213,9 @@ dependencies = [ [[package]] name = "thread_local" -version = "1.1.3" +version = "1.1.4" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "8018d24e04c95ac8790716a5987d0fec4f8b27249ffa0f7d33f1369bdfb88cbd" +checksum = "5516c27b78311c50bf42c071425c560ac799b11c30b31f87e3081965fe5e0180" dependencies = [ "once_cell", ] @@ -4428,9 +4436,9 @@ checksum = "360dfd1d6d30e05fda32ace2c8c70e9c0a9da713275777f5a4dbb8a1893930c6" [[package]] name = "tracing" -version = "0.1.34" +version = "0.1.35" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "5d0ecdcb44a79f0fe9844f0c4f33a342cbcbb5117de8001e6ba0dc2351327d09" +checksum = "a400e31aa60b9d44a52a8ee0343b5b18566b03a8321e0d321f695cf56e940160" dependencies = [ "cfg-if 1.0.0", "pin-project-lite 0.2.8", @@ -4440,13 +4448,13 @@ dependencies = [ [[package]] name = "tracing-appender" -version = "0.1.2" +version = "0.2.2" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "9965507e507f12c8901432a33e31131222abac31edd90cabbcf85cf544b7127a" +checksum = "09d48f71a791638519505cefafe162606f706c25592e4bde4d97600c0195312e" dependencies = [ - "chrono", "crossbeam-channel", - "tracing-subscriber", + "time 0.3.9", + "tracing-subscriber 0.3.15", ] [[package]] @@ -4462,11 +4470,11 @@ dependencies = [ [[package]] name = "tracing-core" -version = "0.1.25" +version = "0.1.28" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "6dfce9f3241b150f36e8e54bb561a742d5daa1a47b5dd9a5ce369fd4a4db2210" +checksum = "7b7358be39f2f274f322d2aaed611acc57f382e8eb1e5b48cb9ae30933495ce7" dependencies = [ - "lazy_static", + "once_cell", "valuable", ] @@ -4495,9 +4503,9 @@ dependencies = [ [[package]] name = "tracing-serde" -version = "0.1.2" +version = "0.1.3" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "fb65ea441fbb84f9f6748fd496cf7f63ec9af5bca94dd86456978d055e8eb28b" +checksum = "bc6b213177105856957181934e4920de57730fc69bf42c37ee5bb664d406d9e1" dependencies = [ "serde", "tracing-core", @@ -4512,12 +4520,30 @@ dependencies = [ "ansi_term 0.12.1", "chrono", "lazy_static", - "matchers", + "matchers 0.0.1", + "regex", + "sharded-slab", + "thread_local", + "tracing", + "tracing-core", + "tracing-log", +] + +[[package]] +name = "tracing-subscriber" +version = "0.3.15" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "60db860322da191b40952ad9affe65ea23e7dd6a5c442c2c42865810c6ab8e6b" +dependencies = [ + "ansi_term 0.12.1", + "matchers 0.1.0", + "once_cell", "regex", "serde", "serde_json", "sharded-slab", "thread_local", + "time 0.3.9", "tracing", "tracing-core", "tracing-log", diff --git a/swap/Cargo.toml b/swap/Cargo.toml index b2fdd741..b708a84e 100644 --- a/swap/Cargo.toml +++ b/swap/Cargo.toml @@ -60,9 +60,9 @@ tokio-util = { version = "0.7", features = [ "io", "codec" ] } toml = "0.5" torut = { version = "0.2", default-features = false, features = [ "v3", "control" ] } tracing = { version = "0.1", features = [ "attributes" ] } -tracing-appender = "0.1" +tracing-appender = "0.2" tracing-futures = { version = "0.2", features = [ "std-future", "futures-03" ] } -tracing-subscriber = { version = "0.2", default-features = false, features = [ "fmt", "ansi", "env-filter", "chrono", "tracing-log", "json" ] } +tracing-subscriber = { version = "0.3", default-features = false, features = [ "fmt", "ansi", "env-filter", "time", "tracing-log", "json" ] } url = { version = "2", features = [ "serde" ] } uuid = { version = "1.0", features = [ "serde", "v4" ] } void = "1" diff --git a/swap/src/asb/tracing.rs b/swap/src/asb/tracing.rs index dc3f7cca..c21c1e70 100644 --- a/swap/src/asb/tracing.rs +++ b/swap/src/asb/tracing.rs @@ -1,6 +1,6 @@ use anyhow::Result; use tracing_subscriber::filter::LevelFilter; -use tracing_subscriber::fmt::time::ChronoLocal; +use tracing_subscriber::fmt::time::UtcTime; use tracing_subscriber::FmtSubscriber; pub fn init(level: LevelFilter, json_format: bool, timestamp: bool) -> Result<()> { @@ -14,7 +14,7 @@ pub fn init(level: LevelFilter, json_format: bool, timestamp: bool) -> Result<() .with_env_filter(format!("asb={},swap={}", level, level)) .with_writer(std::io::stderr) .with_ansi(is_terminal) - .with_timer(ChronoLocal::with_format("%F %T".to_owned())) + .with_timer(UtcTime::rfc_3339()) .with_target(false); match (json_format, timestamp) { diff --git a/swap/src/cli/tracing.rs b/swap/src/cli/tracing.rs index 3bafc229..e759e0d0 100644 --- a/swap/src/cli/tracing.rs +++ b/swap/src/cli/tracing.rs @@ -1,10 +1,11 @@ use anyhow::Result; use std::option::Option::Some; use std::path::Path; +use time::format_description::well_known::Rfc3339; use tracing::subscriber::set_global_default; use tracing::{Event, Level, Subscriber}; use tracing_subscriber::fmt::format::{DefaultFields, Format, JsonFields}; -use tracing_subscriber::fmt::time::ChronoLocal; +use tracing_subscriber::fmt::time::UtcTime; use tracing_subscriber::layer::{Context, SubscriberExt}; use tracing_subscriber::{fmt, EnvFilter, FmtSubscriber, Layer, Registry}; use uuid::Uuid; @@ -47,7 +48,7 @@ pub fn init(debug: bool, json: bool, dir: impl AsRef, swap_id: Option = tracing_subscriber::fmt::Layer< fn() -> std::io::Stderr, >; -fn debug_terminal_printer() -> StdErrPrinter> { +fn debug_terminal_printer() -> StdErrPrinter>> { let is_terminal = atty::is(atty::Stream::Stderr); StdErrPrinter { inner: fmt::layer() .with_ansi(is_terminal) .with_target(false) - .with_timer(ChronoLocal::with_format("%F %T".to_owned())) + .with_timer(UtcTime::rfc_3339()) .with_writer(std::io::stderr), level: Level::DEBUG, } } -fn debug_json_terminal_printer() -> StdErrPrinter> { +fn debug_json_terminal_printer() -> StdErrPrinter>> { let is_terminal = atty::is(atty::Stream::Stderr); StdErrPrinter { inner: fmt::layer() .with_ansi(is_terminal) .with_target(false) - .with_timer(ChronoLocal::with_format("%F %T".to_owned())) + .with_timer(UtcTime::rfc_3339()) .json() .with_writer(std::io::stderr), level: Level::DEBUG, diff --git a/swap/src/tracing_ext.rs b/swap/src/tracing_ext.rs index 912187fd..6fd7eaba 100644 --- a/swap/src/tracing_ext.rs +++ b/swap/src/tracing_ext.rs @@ -41,7 +41,7 @@ impl MakeCapturingWriter { } } -impl MakeWriter for MakeCapturingWriter { +impl<'a> MakeWriter<'a> for MakeCapturingWriter { type Writer = CapturingWriter; fn make_writer(&self) -> Self::Writer {