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
2 years ago · 8eff499a63
parent 7023e75bb5
commit 8eff499a63
7 changed files with 62 additions and 32 deletions
--- 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
--- 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

--- 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",
--- 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"
--- 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) {
--- 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<Path>, swap_id: Option<Uuid
            .with_env_filter(format!("swap={}", 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);

        if json {
@ -79,25 +80,25 @@ type StdErrJsonLayer<S, T> = tracing_subscriber::fmt::Layer<
    fn() -> std::io::Stderr,
 >;

-fn debug_terminal_printer<S>() -> StdErrPrinter<StdErrLayer<S, ChronoLocal>> {
+fn debug_terminal_printer<S>() -> StdErrPrinter<StdErrLayer<S, UtcTime<Rfc3339>>> {
    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<S>() -> StdErrPrinter<StdErrJsonLayer<S, ChronoLocal>> {
+fn debug_json_terminal_printer<S>() -> StdErrPrinter<StdErrJsonLayer<S, UtcTime<Rfc3339>>> {
    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,
--- 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 {