Add support for changing tracing directives at runtime (#3565)

* Add handler to update tracing filter

* Add documentation for 'hermes logs' commands

* Add documentation regarding ZMQ interaction in guide

* Add comments

* Rename 'logs' subcommands

* Remove unnecessary error

* Fix config example

* Use TCP client/server instead of ZMQ

* Cleanup

* Only start tracing server for `start` command

* Show message returned by server when setting log level

* Fix for server hanging

* Add changelog entry

---------

Co-authored-by: Romain Ruetschi <[email protected]>

.changelog/unreleased/features/ibc-relayer-cli/3564-tracing-filter.md

@@ -0,0 +1,5 @@
+- Add support for changing `tracing` directives at runtime.
+  Please see the [corresponding page in the Hermes guide][tracing-guide] for more information.
+  ([\#3564](https://github.com/informalsystems/hermes/issues/3564))
+
+[tracing-guide]: https://hermes.informal.systems/advanced/troubleshooting/log-level.html

config.toml

@@ -123,6 +123,15 @@ port = 3001
 # [1000, 3900, 6800, 9700, 12600, 15500, 18400, 21300, 24200, 27100, 30000]
 # latency_confirmed = { start = 1000, end = 30000, buckets = 10 }
 
+# The tracing server section defines parameters for Hermes' server allowing updates to the tracing directives.
+#
+# https://hermes.informal.systems/advanced/troubleshooting/log-level.html#overriding-the-tracing-filter-during-runtime
+[tracing_server]
+# Whether or not to enable the tracing server. Default: false
+enabled = false
+
+# Specify the port over which the built-in TCP server will serve the directives. Default: 5555
+port = 5555
 
 # A chains section includes parameters related to a chain and the full node to which
 # the relayer can send transactions and queries.

crates/relayer-cli/Cargo.toml

@@ -55,7 +55,6 @@ tokio                    = { version = "1.0", features = ["full"] }
 tracing                  = "0.1.36"
 tracing-subscriber       = { version = "0.3.14", features = ["fmt", "env-filter", "json"]}
 time                     = "0.3"
-
 [dependencies.tendermint]
 version = "0.33.0"
 features = ["secp256k1"]

crates/relayer-cli/src/application.rs

@@ -1,6 +1,6 @@
 //! Definition of the application, based on the Abscissa framework
 
-use std::path::PathBuf;
+use std::{path::PathBuf, thread};
 
 use abscissa_core::{
     application::{self, AppCell},
@@ -10,12 +10,17 @@ use abscissa_core::{
     terminal::ColorChoice,
     Application, Configurable, FrameworkError, FrameworkErrorKind, StandardPaths,
 };
-use ibc_relayer::{config::Config, util::debug_section::DebugSection};
+use ibc_relayer::{
+    config::{Config, TracingServerConfig},
+    util::debug_section::DebugSection,
+};
 
 use crate::{
+    commands::CliCmd,
     components::{JsonTracing, PrettyTracing},
     config::validate_config,
     entry::EntryPoint,
+    tracing_handle::{spawn_reload_handler, ReloadHandle},
 };
 
 /// Application state
@@ -195,13 +200,24 @@ impl Application for CliApp {
         let enable_json = self.debug_enabled(DebugSection::ProfilingJson);
         ibc_relayer::util::profiling::enable(enable_console, enable_json);
 
+        let is_start_cmd = command
+            .command
+            .as_ref()
+            .map_or(false, |cmd| matches!(cmd, CliCmd::Start(_)));
+
         if command.json {
             // Enable JSON by using the crate-level `Tracing`
             let tracing = JsonTracing::new(config.global, &self.debug_sections)?;
             Ok(vec![Box::new(terminal), Box::new(tracing)])
         } else {
             // Use abscissa's tracing, which pretty-prints to the terminal obeying log levels
-            let tracing = PrettyTracing::new(config.global, &self.debug_sections)?;
+            let (tracing, reload_handle) =
+                PrettyTracing::new_with_reload_handle(config.global, &self.debug_sections)?;
+
+            if is_start_cmd {
+                spawn_tracing_reload_server(reload_handle, config.tracing_server.clone());
+            }
+
             Ok(vec![Box::new(terminal), Box::new(tracing)])
         }
     }
@@ -212,3 +228,21 @@ impl Application for CliApp {
         ColorChoice::Never
     }
 }
+
+fn spawn_tracing_reload_server<S: 'static>(
+    reload_handle: ReloadHandle<S>,
+    config: TracingServerConfig,
+) {
+    thread::spawn(move || {
+        let rt = tokio::runtime::Builder::new_current_thread()
+            .enable_all()
+            .build()
+            .unwrap();
+
+        let result = rt.block_on(spawn_reload_handler(reload_handle, config));
+
+        if let Err(e) = result {
+            eprintln!("ERROR: failed to spawn tracing reload handler: {e}");
+        }
+    });
+}

crates/relayer-cli/src/commands.rs

@@ -8,6 +8,7 @@ mod fee;
 mod health;
 mod keys;
 mod listen;
+mod logs;
 mod misbehaviour;
 mod query;
 mod start;
@@ -18,7 +19,7 @@ mod version;
 
 use self::{
     clear::ClearCmds, completions::CompletionsCmd, config::ConfigCmd, create::CreateCmds,
-    fee::FeeCmd, health::HealthCheckCmd, keys::KeysCmd, listen::ListenCmd,
+    fee::FeeCmd, health::HealthCheckCmd, keys::KeysCmd, listen::ListenCmd, logs::LogsCmd,
     misbehaviour::MisbehaviourCmd, query::QueryCmd, start::StartCmd, tx::TxCmd, update::UpdateCmds,
     upgrade::UpgradeCmds, version::VersionCmd,
 };
@@ -85,6 +86,10 @@ pub enum CliCmd {
     /// Listen to and display IBC events emitted by a chain
     Listen(ListenCmd),
 
+    /// Update tracing log directives
+    #[clap(subcommand)]
+    Logs(LogsCmd),
+
     /// Listen to client update IBC events and handles misbehaviour
     Misbehaviour(MisbehaviourCmd),
 

crates/relayer-cli/src/commands/logs.rs

@@ -0,0 +1,20 @@
+use abscissa_core::clap::Parser;
+use abscissa_core::Command;
+use abscissa_core::Runnable;
+
+pub mod log_level;
+pub mod raw;
+pub mod reset;
+
+/// `logs` subcommand
+#[derive(Command, Debug, Parser, Runnable)]
+pub enum LogsCmd {
+    /// Subcommand used to easily update the lowest log level displayed
+    SetLogLevel(log_level::SetLogLevelCmd),
+
+    /// Subcommand used to send a raw filter directive for logs displayed
+    SetRawFilter(raw::SetRawFilterCmd),
+
+    /// Subcommand to restore the log level by using the configuration defined in the config.toml file
+    Reset(reset::ResetCmd),
+}

crates/relayer-cli/src/commands/logs/log_level.rs

@@ -0,0 +1,60 @@
+use abscissa_core::clap::Parser;
+use abscissa_core::Command;
+use abscissa_core::Runnable;
+use tracing::info;
+use tracing::Level;
+
+use crate::prelude::app_config;
+use crate::tracing_handle::send_command;
+
+#[derive(Clone, Command, Debug, Parser, PartialEq, Eq)]
+pub struct SetLogLevelCmd {
+    #[clap(
+        long = "log-level",
+        required = true,
+        value_name = "LOG_LEVEL",
+        help = "The new lowest log level which will be displayed. Possible values are `trace`, `debug`, `info`, `warn` or `error`"
+    )]
+    log_level: Level,
+
+    #[clap(
+        long = "log-filter",
+        help_heading = "FLAGS",
+        value_name = "LOG_FILTER",
+        help = "The target of the log level to update, if left empty all the targets will be updated. Example `ibc` or `tendermint_rpc`"
+    )]
+    log_filter: Option<String>,
+}
+
+impl Runnable for SetLogLevelCmd {
+    fn run(&self) {
+        let rt = tokio::runtime::Builder::new_current_thread()
+            .enable_all()
+            .build()
+            .unwrap();
+
+        rt.block_on(run(&self.log_level, self.log_filter.as_ref()));
+    }
+}
+
+async fn run(log_level: &Level, log_filter: Option<&String>) {
+    let config = app_config();
+
+    let port = config.tracing_server.port;
+
+    let str_log = log_level.to_string();
+
+    let result = if let Some(log_filter) = log_filter {
+        let log_cmd = format!("{log_filter}={str_log}");
+        info!("Setting log level to: {log_cmd}");
+        send_command(&log_cmd, port).await
+    } else {
+        info!("Setting log level to: {str_log}");
+        send_command(&str_log, port).await
+    };
+
+    match result {
+        Ok(msg) => info!("{msg}"),
+        Err(e) => info!("Failed to set log level: {e}"),
+    }
+}

crates/relayer-cli/src/commands/logs/raw.rs

@@ -0,0 +1,45 @@
+use abscissa_core::clap::Parser;
+use abscissa_core::Command;
+use abscissa_core::Runnable;
+use tracing::error;
+use tracing::info;
+
+use crate::prelude::app_config;
+use crate::tracing_handle::send_command;
+
+// TODO `hermes set-raw-filter`
+#[derive(Clone, Command, Debug, Parser, PartialEq, Eq)]
+pub struct SetRawFilterCmd {
+    #[clap(
+        long = "raw-filter",
+        required = true,
+        value_name = "RAW_FILTER",
+        help = "Raw filter used as new tracing directive. Use with caution"
+    )]
+    raw_filter: String,
+}
+
+impl Runnable for SetRawFilterCmd {
+    fn run(&self) {
+        let config = app_config();
+
+        let rt = tokio::runtime::Builder::new_current_thread()
+            .enable_all()
+            .build()
+            .unwrap();
+
+        let port = config.tracing_server.port;
+
+        rt.block_on(run(&self.raw_filter, port));
+    }
+}
+
+async fn run(raw_filter: &str, port: u16) {
+    info!("Setting raw log filter to: {raw_filter}");
+    let result = send_command(raw_filter, port).await;
+
+    match result {
+        Ok(_) => info!("Successfully set raw filter"),
+        Err(e) => error!("Failed to set raw filter: {e}"),
+    }
+}

crates/relayer-cli/src/commands/logs/reset.rs

@@ -0,0 +1,36 @@
+use abscissa_core::clap::Parser;
+use abscissa_core::Command;
+use abscissa_core::Runnable;
+
+use crate::components::default_directive;
+use crate::prelude::*;
+use crate::tracing_handle::send_command;
+
+#[derive(Clone, Command, Debug, Parser, PartialEq, Eq)]
+pub struct ResetCmd {}
+
+impl Runnable for ResetCmd {
+    fn run(&self) {
+        let config = app_config();
+
+        let rt = tokio::runtime::Builder::new_current_thread()
+            .enable_all()
+            .build()
+            .unwrap();
+
+        let port = config.tracing_server.port;
+        let directive = default_directive(config.global.log_level);
+
+        rt.block_on(run(&directive, port));
+    }
+}
+
+async fn run(directive: &str, port: u16) {
+    info!("Resetting log filter to: {directive}");
+    let result = send_command(directive, port).await;
+
+    match result {
+        Ok(_) => info!("Successfully reset log filter"),
+        Err(e) => error!("Failed to reset log filter: {e}"),
+    }
+}

crates/relayer-cli/src/components.rs

@@ -9,6 +9,7 @@ use ibc_relayer::{
 };
 
 use crate::config::Error;
+use crate::tracing_handle::ReloadHandle;
 
 /// The name of the environment variable through which one can override
 /// the tracing filter built in [`build_tracing_filter`].
@@ -74,6 +75,29 @@ impl PrettyTracing {
 
         Ok(Self)
     }
+
+    pub fn new_with_reload_handle(
+        cfg: GlobalConfig,
+        debug_sections: &[DebugSection],
+    ) -> Result<(Self, ReloadHandle<impl tracing::Subscriber + 'static>), FrameworkError> {
+        let filter = build_tracing_filter(cfg.log_level, debug_sections)?;
+
+        // Construct a tracing subscriber with the supplied filter and enable reloading.
+        let builder = FmtSubscriber::builder()
+            .with_target(false)
+            .with_env_filter(filter)
+            .with_writer(std::io::stderr)
+            .with_ansi(enable_ansi())
+            .with_thread_ids(true)
+            .with_filter_reloading();
+
+        let reload_handle = builder.reload_handle();
+
+        let subscriber = builder.finish();
+        subscriber.init();
+
+        Ok((Self, reload_handle))
+    }
 }
 
 /// Check if both stdout and stderr are proper terminal (tty),
@@ -90,7 +114,7 @@ const TARGET_CRATES: [&str; 2] = ["ibc_relayer", "ibc_relayer_cli"];
 
 /// Build a tracing directive setting the log level for the relayer crates to the
 /// given `log_level`.
-fn default_directive(log_level: LogLevel) -> String {
+pub fn default_directive(log_level: LogLevel) -> String {
     use itertools::Itertools;
 
     TARGET_CRATES

crates/relayer-cli/src/lib.rs

@@ -33,6 +33,7 @@ pub mod config;
 pub mod entry;
 pub mod error;
 pub mod prelude;
+pub mod tracing_handle;
 
 /// The path to the default configuration file, relative to the home directory.
 pub const DEFAULT_CONFIG_PATH: &str = ".hermes/config.toml";