Merge #1062

1062: fix: change logs to UTC due to bug in time crate r=delta1 a=delta1

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

Co-authored-by: Byron Hambly <bhambly@blockstream.com>

.gitignore

@@ -157,3 +157,6 @@ flycheck_*.el
 .swap-db/
 
 # End of https://www.toptal.com/developers/gitignore/api/rust,clion+all,emacs
+
+*.log
+.vscode

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
 

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",

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"

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) {

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,

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 {