Tracing infrastructure (#2257)

* `linera-base`: add standardized `tracing::init()` function

* `linera-core`: add `tracing::instrument` to client functionality

* `linera-service`: attach spans for node service port and chain ID

* `linera-core`: include more fields in traces

* `linera-service`: instrument futures properly

Cargo.toml

@@ -87,6 +87,7 @@ http = "1.1.0"
 glob = "0.3.1"
 indexed_db_futures = "0.4.1"
 insta = "1.36.1"
+is-terminal = "0.4.12"
 linera-alloy = { version = "0.1.0", default-features = false }
 log = "0.4.21"
 lru = "0.12.3"
@@ -143,7 +144,7 @@ tokio-util = "0.7.10"
 toml = "0.8.10"
 tower-http = "0.5.2"
 tower = "0.4.13"
-tracing = "0.1.40"
+tracing = { version = "0.1.40", features = ["release_max_level_debug"] }
 tracing-subscriber = { version = "0.3.18", default-features = false, features = ["env-filter"] }
 trait-variant = "0.1.1"
 url = "2.4"

clippy.toml

@@ -1 +1 @@
-future-size-threshold = 5000
+future-size-threshold = 7000

linera-base/Cargo.toml

@@ -29,6 +29,7 @@ ed25519-dalek.workspace = true
 generic-array.workspace = true
 getrandom = { workspace = true, optional = true }
 hex.workspace = true
+is-terminal.workspace = true
 linera-witty = { workspace = true, features = ["macros"] }
 prometheus = { workspace = true, optional = true }
 proptest = { workspace = true, optional = true, features = ["alloc"] }
@@ -39,13 +40,14 @@ serde_bytes.workspace = true
 sha3.workspace = true
 test-strategy = { workspace = true, optional = true }
 thiserror.workspace = true
+tracing.workspace = true
+tracing-subscriber = { workspace = true, features = ["json", "fmt", "ansi"] }
 web-time = { workspace = true, optional = true }
 
 [target.'cfg(not(target_arch = "wasm32"))'.dependencies]
 chrono.workspace = true
 rand = { workspace = true, features = ["getrandom", "std", "std_rng"] }
 tokio = { workspace = true, features = ["process", "rt-multi-thread"] }
-tracing.workspace = true
 prometheus.workspace = true
 
 [dev-dependencies]

linera-base/src/lib.rs

@@ -22,6 +22,7 @@ pub mod ownership;
 #[cfg(with_metrics)]
 pub mod prometheus_util;
 pub mod sync;
+pub mod tracing;
 #[cfg(test)]
 mod unit_tests;
 

linera-base/src/tracing.rs

@@ -0,0 +1,59 @@
+// Copyright (c) Zefchain Labs, Inc.
+// SPDX-License-Identifier: Apache-2.0
+
+//! This module provides unified handling for tracing subscribers within Linera binaries.
+
+use is_terminal::IsTerminal as _;
+use tracing_subscriber::fmt::format::FmtSpan;
+
+fn fmt_span_from_str(events: &str) -> FmtSpan {
+    let mut fmt_span = FmtSpan::NONE;
+    for event in events.split(",") {
+        fmt_span |= match event {
+            "new" => FmtSpan::NEW,
+            "enter" => FmtSpan::ENTER,
+            "exit" => FmtSpan::EXIT,
+            "close" => FmtSpan::CLOSE,
+            "active" => FmtSpan::ACTIVE,
+            "full" => FmtSpan::FULL,
+            _ => FmtSpan::NONE,
+        };
+    }
+    fmt_span
+}
+
+/// Initializes tracing in a standard way.
+/// The environment variables `RUST_LOG`, `RUST_LOG_SPAN_EVENTS`, and `RUST_LOG_FORMAT`
+/// can be used to control the verbosity, the span event verbosity, and the output format,
+/// respectively.
+pub fn init() {
+    let span_events = std::env::var("RUST_LOG_SPAN_EVENTS")
+        .ok()
+        .map(|s| fmt_span_from_str(&s))
+        .unwrap_or(FmtSpan::NONE);
+
+    let subscriber = tracing_subscriber::fmt()
+        .with_span_events(span_events)
+        .with_writer(std::io::stderr)
+        .with_env_filter(
+            tracing_subscriber::EnvFilter::builder()
+                .with_default_directive(tracing_subscriber::filter::LevelFilter::INFO.into())
+                .from_env_lossy(),
+        );
+
+    if let Ok(format) = std::env::var("RUST_LOG_FORMAT") {
+        match format.as_str() {
+            "json" => subscriber.json().init(),
+            "pretty" => subscriber.pretty().init(),
+            _ => {
+                panic!("Invalid RUST_LOG_FORMAT: `{format}`.  Valid values are `json` or `pretty`.")
+            }
+        }
+    } else if cfg!(feature = "web") {
+        subscriber.with_ansi(false).init();
+    } else if std::io::stderr().is_terminal() {
+        subscriber.init();
+    } else {
+        subscriber.json().init();
+    }
+}

linera-client/src/chain_listener.rs

@@ -23,7 +23,7 @@ use linera_core::{
 use linera_execution::{Message, SystemMessage};
 use linera_storage::Storage;
 use linera_views::views::ViewError;
-use tracing::{error, info, warn};
+use tracing::{error, info, warn, Instrument as _};
 
 use crate::{chain_clients::ChainClients, wallet::Wallet};
 
@@ -110,6 +110,7 @@ where
         }
     }
 
+    #[tracing::instrument(level = "trace", skip_all, fields(?chain_id))]
     fn run_with_chain_id<C>(
         chain_id: ChainId,
         clients: ChainClients<P, S>,
@@ -119,15 +120,19 @@ where
     ) where
         C: ClientContext<ValidatorNodeProvider = P, Storage = S> + Send + 'static,
     {
-        let _handle = tokio::task::spawn(async move {
-            if let Err(err) =
-                Self::run_client_stream(chain_id, clients, context, storage, config).await
-            {
-                error!("Stream for chain {} failed: {}", chain_id, err);
+        let _handle = tokio::task::spawn(
+            async move {
+                if let Err(err) =
+                    Self::run_client_stream(chain_id, clients, context, storage, config).await
+                {
+                    error!("Stream for chain {} failed: {}", chain_id, err);
+                }
             }
-        });
+            .in_current_span(),
+        );
     }
 
+    #[tracing::instrument(level = "trace", skip_all, fields(?chain_id))]
     async fn run_client_stream<C>(
         chain_id: ChainId,
         clients: ChainClients<P, S>,
@@ -153,7 +158,7 @@ where
         };
         let (listener, _listen_handle, mut local_stream) = client.listen().await?;
         client.synchronize_from_validators().await?;
-        tokio::spawn(listener);
+        tokio::spawn(listener.in_current_span());
         let mut timeout = storage.clock().current_time();
         loop {
             let sleep = Box::pin(storage.clock().sleep_until(timeout));

linera-client/src/lib.rs

@@ -3,6 +3,8 @@
 
 //! This module provides a convenient library for writing a Linera client application.
 
+#![recursion_limit = "256"]
+
 pub mod chain_clients;
 pub mod chain_listener;
 pub mod client_context;