Repository: shell-pool/shpool (rust)

Issue:
shpool log levels should be dynamically adjustable
The daemon is long running, and sometimes it gets into bad states that it would be nice to log at more granularity about after running for a long time with little chance of easy reproduction by restarting the daemon. It would make debugging a lot easier if people could issue a command like `shpoo set-log-levels 'libshpool=trace'` or something (also a `shpool get-log-level` command that normally returns `libshpool=info,default=warn`).

Unfortunately, I think our current log framework needs to be created with the log levels baked in from the start, so this will likely mean looking around for a more flexibile log framework.


Pull request description:
feat: allow daemon log level to dynamically change
This patch adds a new subcommand to allow dynamically changing
the log level. This should hopefully make it easier to debug
some issues where we can't restart to crank up the verbosity.

Fixes #117

BREAKING CHANGE: the libshpool api has has a new enum variant

Patch:
diff --git a/libshpool/src/daemon/mod.rs b/libshpool/src/daemon/mod.rs
index f6be95ec..5f18e473 100644
--- a/libshpool/src/daemon/mod.rs
+++ b/libshpool/src/daemon/mod.rs
@@ -37,6 +37,10 @@ pub fn run(
     config_manager: config::Manager,
     runtime_dir: PathBuf,
     hooks: Box<dyn hooks::Hooks + Send + Sync>,
+    log_level_handle: tracing_subscriber::reload::Handle<
+        tracing_subscriber::filter::LevelFilter,
+        tracing_subscriber::registry::Registry,
+    >,
     socket: PathBuf,
 ) -> anyhow::Result<()> {
     if let Ok(daemonize) = env::var(consts::AUTODAEMONIZE_VAR) {
@@ -52,7 +56,7 @@ pub fn run(
 
     info!("\n\n======================== STARTING DAEMON ============================\n\n");
 
-    let server = server::Server::new(config_manager, hooks, runtime_dir)?;
+    let server = server::Server::new(config_manager, hooks, runtime_dir, log_level_handle)?;
 
     let (cleanup_socket, listener) = match systemd::activation_socket() {
         Ok(l) => {
diff --git a/libshpool/src/daemon/server.rs b/libshpool/src/daemon/server.rs
index 2c0692e3..12743f2a 100644
--- a/libshpool/src/daemon/server.rs
+++ b/libshpool/src/daemon/server.rs
@@ -33,9 +33,9 @@ use anyhow::{anyhow, Context};
 use nix::unistd;
 use shpool_protocol::{
     AttachHeader, AttachReplyHeader, AttachStatus, ConnectHeader, DetachReply, DetachRequest,
-    KillReply, KillRequest, ListReply, ResizeReply, Session, SessionMessageDetachReply,
+    KillReply, KillRequest, ListReply, LogLevel, ResizeReply, Session, SessionMessageDetachReply,
     SessionMessageReply, SessionMessageRequest, SessionMessageRequestPayload, SessionStatus,
-    VersionHeader,
+    SetLogLevelReply, SetLogLevelRequest, VersionHeader,
 };
 use tracing::{error, info, instrument, span, warn, Level};
 
@@ -73,6 +73,10 @@ pub struct Server {
     register_new_reapable_session: crossbeam_channel::Sender<(String, Instant)>,
     hooks: Box<dyn hooks::Hooks + Send + Sync>,
     daily_messenger: Arc<show_motd::DailyMessenger>,
+    log_level_handle: tracing_subscriber::reload::Handle<
+        tracing_subscriber::filter::LevelFilter,
+        tracing_subscriber::registry::Registry,
+    >,
 }
 
 impl Server {
@@ -81,6 +85,10 @@ impl Server {
         config: config::Manager,
         hooks: Box<dyn hooks::Hooks + Send + Sync>,
         runtime_dir: PathBuf,
+        log_level_handle: tracing_subscriber::reload::Handle<
+            tracing_subscriber::filter::LevelFilter,
+            tracing_subscriber::registry::Registry,
+        >,
     ) -> anyhow::Result<Arc<Self>> {
         let shells = Arc::new(Mutex::new(HashMap::new()));
         // buffered so that we are unlikely to block when setting up a
@@ -101,6 +109,7 @@ impl Server {
             register_new_reapable_session: new_sess_tx,
             hooks,
             daily_messenger,
+            log_level_handle,
         }))
     }
 
@@ -189,7 +198,7 @@ impl Server {
             ConnectHeader::Kill(r) => self.handle_kill(stream, r),
             ConnectHeader::List => self.handle_list(stream),
             ConnectHeader::SessionMessage(header) => self.handle_session_message(stream, header),
-            ConnectHeader::SetLogLevel(_) => unimplemented!(),
+            ConnectHeader::SetLogLevel(r) => self.handle_set_log_level(stream, r),
         }
     }
 
@@ -493,6 +502,28 @@ impl Server {
         Ok(())
     }
 
+    #[instrument(skip_all)]
+    fn handle_set_log_level(
+        &self,
+        mut stream: UnixStream,
+        request: SetLogLevelRequest,
+    ) -> anyhow::Result<()> {
+        let level_filter = match request.level {
+            LogLevel::Off => tracing_subscriber::filter::LevelFilter::OFF,
+            LogLevel::Error => tracing_subscriber::filter::LevelFilter::ERROR,
+            LogLevel::Warn => tracing_subscriber::filter::LevelFilter::WARN,
+            LogLevel::Info => tracing_subscriber::filter::LevelFilter::INFO,
+            LogLevel::Debug => tracing_subscriber::filter::LevelFilter::DEBUG,
+            LogLevel::Trace => tracing_subscriber::filter::LevelFilter::TRACE,
+        };
+        if let Err(e) = self.log_level_handle.modify(|filter| *filter = level_filter) {
+            error!("modifying log level: {}", e);
+        }
+
+        write_reply(&mut stream, SetLogLevelReply {}).context("writing set log level reply")?;
+        Ok(())
+    }
+
     #[instrument(skip_all)]
     fn handle_kill(&self, mut stream: UnixStream, request: KillRequest) -> anyhow::Result<()> {
         let mut not_found_sessions = vec![];
diff --git a/libshpool/src/lib.rs b/libshpool/src/lib.rs
index b2319837..5ac6cf24 100644
--- a/libshpool/src/lib.rs
+++ b/libshpool/src/lib.rs
@@ -18,14 +18,14 @@ use std::{
     hash::{Hash, Hasher},
     io,
     path::PathBuf,
-    sync::Mutex,
+    sync::{Mutex, MutexGuard},
 };
 
 use anyhow::{anyhow, Context};
 use clap::{Parser, Subcommand};
 pub use hooks::Hooks;
 use tracing::error;
-use tracing_subscriber::fmt::format::FmtSpan;
+use tracing_subscriber::{fmt::format::FmtSpan, prelude::*};
 
 mod attach;
 mod common;
@@ -40,6 +40,7 @@ mod hooks;
 mod kill;
 mod list;
 mod protocol;
+mod set_log_level;
 mod test_hooks;
 mod tty;
 mod user;
@@ -52,7 +53,7 @@ mod user;
 /// NOTE: You must check `version()` and handle it yourself
 /// if it is set. Clap won't do a good job with its
 /// automatic version support for a library.
-#[derive(Parser, Debug)]
+#[derive(Parser, Debug, Default)]
 #[clap(author, about)]
 pub struct Args {
     #[clap(
@@ -99,18 +100,30 @@ the daemon is launched by systemd."
 
     #[clap(subcommand)]
     pub command: Commands,
+
+    // A hidden field rather than using the #[non_exhaustive] attribute
+    // allows users to build this struct using the default value plus
+    // modifications, while the #[non_exhaustive] attribute would not.
+    // See https://rust-lang.github.io/rfcs/2008-non-exhaustive.html#functional-record-updates
+    // (the attribute behaves as if there is implicitly a field like this
+    // that is private).
+    #[doc(hidden)]
+    pub __non_exhaustive: (),
 }
 
 /// The subcommds that shpool supports.
-#[derive(Subcommand, Debug)]
+#[derive(Subcommand, Debug, Default)]
+#[non_exhaustive]
 pub enum Commands {
     #[clap(about = "Print version")]
+    #[default]
     Version,
 
     #[clap(about = "Starts running a daemon that holds a pool of shells")]
     Daemon,
 
     #[clap(about = "Creates or attaches to an existing shell session")]
+    #[non_exhaustive]
     Attach {
         #[clap(short, long, help = "If a tty is already attached to the session, detach it first")]
         force: bool,
@@ -146,6 +159,7 @@ pass to the binary using the shell-words crate."
 This does not close the shell. If no session name is provided
 $SHPOOL_SESSION_NAME will be used if it is present in the
 environment.")]
+    #[non_exhaustive]
     Detach {
         #[clap(help = "sessions to detach")]
         sessions: Vec<String>,
@@ -157,13 +171,26 @@ This detaches the session if it is attached and kills the underlying
 shell with a SIGHUP followed by a SIGKILL if the shell fails to exit
 quickly enough. If no session name is provided $SHPOOL_SESSION_NAME
 will be used if it is present in the environment.")]
+    #[non_exhaustive]
     Kill {
         #[clap(help = "sessions to kill")]
         sessions: Vec<String>,
     },
 
     #[clap(about = "lists all the running shell sessions")]
+    #[non_exhaustive]
     List,
+
+    #[clap(about = "Dynamically change daemon log level
+
+This command changes the log level of the shpool daemon without
+restarting. It may to useful if the daemon gets into a state that
+needs debugging, but would be clobbered by a restart.")]
+    #[non_exhaustive]
+    SetLogLevel {
+        #[clap(help = "new log level")]
+        level: shpool_protocol::LogLevel,
+    },
 }
 
 impl Args {
@@ -174,6 +201,61 @@ impl Args {
     }
 }
 
+// Copied from the tracing-subscriber crate. This is public in
+// a future version of the crate, but for now we don't have
+// access to it. If tracing-subscriber is 0.3.19 or better,
+// it is worth checking to see if we can rip this out.
+#[derive(Debug)]
+pub struct MutexGuardWriter<'a, W>(MutexGuard<'a, W>);
+impl<W> io::Write for MutexGuardWriter<'_, W>
+where
+    W: io::Write,
+{
+    #[inline]
+    fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
+        self.0.write(buf)
+    }
+
+    #[inline]
+    fn flush(&mut self) -> io::Result<()> {
+        self.0.flush()
+    }
+
+    #[inline]
+    fn write_vectored(&mut self, bufs: &[io::IoSlice<'_>]) -> io::Result<usize> {
+        self.0.write_vectored(bufs)
+    }
+
+    #[inline]
+    fn write_all(&mut self, buf: &[u8]) -> io::Result<()> {
+        self.0.write_all(buf)
+    }
+
+    #[inline]
+    fn write_fmt(&mut self, fmt: std::fmt::Arguments<'_>) -> io::Result<()> {
+        self.0.write_fmt(fmt)
+    }
+}
+
+struct LogWriterBuilder {
+    log_file: Option<Mutex<fs::File>>,
+    is_daemon: bool,
+}
+
+impl<'writer> tracing_subscriber::fmt::MakeWriter<'writer> for LogWriterBuilder {
+    type Writer = Box<dyn io::Write + 'writer>;
+
+    fn make_writer(&'writer self) -> Self::Writer {
+        if let Some(log_file) = &self.log_file {
+            Box::new(MutexGuardWriter(log_file.lock().expect("poisoned")))
+        } else if self.is_daemon {
+            Box::new(io::stderr())
+        } else {
+            Box::new(io::empty())
+        }
+    }
+}
+
 /// Run the shpool tool with the given arguments. If hooks is provided,
 /// inject the callbacks into the daemon.
 pub fn run(args: Args, hooks: Option<Box<dyn hooks::Hooks + Send + Sync>>) -> anyhow::Result<()> {
@@ -189,33 +271,35 @@ pub fn run(args: Args, hooks: Option<Box<dyn hooks::Hooks + Send + Sync>>) -> an
         _ => {}
     }
 
-    let trace_level = if args.verbose == 0 {
-        tracing::Level::INFO
+    let log_level_filter = if args.verbose == 0 {
+        tracing_subscriber::filter::LevelFilter::INFO
     } else if args.verbose == 1 {
-        tracing::Level::DEBUG
+        tracing_subscriber::filter::LevelFilter::DEBUG
     } else {
-        tracing::Level::TRACE
+        tracing_subscriber::filter::LevelFilter::TRACE
     };
-    if let Some(log_file) = args.log_file.clone() {
-        let file = fs::File::create(log_file)?;
-        tracing_subscriber::fmt()
-            .with_ansi(false)
-            .with_max_level(trace_level)
-            .with_thread_ids(true)
-            .with_target(false)
-            .with_span_events(FmtSpan::NEW | FmtSpan::CLOSE)
-            .with_writer(Mutex::new(file))
-            .init();
-    } else if let Commands::Daemon = args.command {
-        tracing_subscriber::fmt()
-            .with_ansi(false)
-            .with_max_level(trace_level)
-            .with_thread_ids(true)
-            .with_target(false)
-            .with_span_events(FmtSpan::NEW | FmtSpan::CLOSE)
-            .with_writer(io::stderr)
-            .init();
-    }
+    let (log_level_layer, log_level_handle) =
+        tracing_subscriber::reload::Layer::new(log_level_filter);
+
+    let log_writer_builder = LogWriterBuilder {
+        log_file: if let Some(lf) = &args.log_file {
+            Some(Mutex::new(fs::File::create(lf).context("unable to create log file")?))
+        } else {
+            None
+        },
+        is_daemon: matches!(args.command, Commands::Daemon),
+    };
+    tracing_subscriber::registry::Registry::default()
+        .with(log_level_layer)
+        .with(
+            tracing_subscriber::fmt::layer()
+                .with_ansi(false)
+                .with_thread_ids(true)
+                .with_target(false)
+                .with_span_events(FmtSpan::NEW | FmtSpan::CLOSE)
+                .with_writer(log_writer_builder),
+        )
+        .init();
 
     let mut runtime_dir = match env::var("XDG_RUNTIME_DIR") {
         Ok(runtime_dir) => PathBuf::from(runtime_dir),
@@ -269,6 +353,7 @@ pub fn run(args: Args, hooks: Option<Box<dyn hooks::Hooks + Send + Sync>>) -> an
             config_manager,
             runtime_dir,
             hooks.unwrap_or(Box::new(NoopHooks {})),
+            log_level_handle,
             socket,
         ),
         Commands::Attach { force, ttl, cmd, name } => {
@@ -277,6 +362,7 @@ pub fn run(args: Args, hooks: Option<Box<dyn hooks::Hooks + Send + Sync>>) -> an
         Commands::Detach { sessions } => detach::run(sessions, socket),
         Commands::Kill { sessions } => kill::run(sessions, socket),
         Commands::List => list::run(socket),
+        Commands::SetLogLevel { level } => set_log_level::run(level, socket),
     };
 
     if let Err(err) = res {
diff --git a/libshpool/src/set_log_level.rs b/libshpool/src/set_log_level.rs
new file mode 100644
index 00000000..515fd140
--- /dev/null
+++ b/libshpool/src/set_log_level.rs
@@ -0,0 +1,44 @@
+// Copyright 2025 Google LLC
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+use std::{io, path::PathBuf};
+
+use anyhow::Context;
+use shpool_protocol::{ConnectHeader, LogLevel, SetLogLevelReply, SetLogLevelRequest};
+
+use crate::{protocol, protocol::ClientResult};
+
+pub fn run(level: LogLevel, socket: PathBuf) -> anyhow::Result<()> {
+    let mut client = match protocol::Client::new(socket) {
+        Ok(ClientResult::JustClient(c)) => c,
+        Ok(ClientResult::VersionMismatch { warning, client }) => {
+            eprintln!("warning: {}, try restarting your daemon", warning);
+            client
+        }
+        Err(err) => {
+            let io_err = err.downcast::<io::Error>()?;
+            if io_err.kind() == io::ErrorKind::NotFound {
+                eprintln!("could not connect to daemon");
+            }
+            return Err(io_err).context("connecting to daemon");
+        }
+    };
+
+    client
+        .write_connect_header(ConnectHeader::SetLogLevel(SetLogLevelRequest { level }))
+        .context("sending set-log-level header")?;
+    let _reply: SetLogLevelReply = client.read_reply().context("reading reply")?;
+
+    Ok(())
+}


Test patch:
diff --git a/shpool/tests/daemon.rs b/shpool/tests/daemon.rs
index 016f3506..f2a8dabc 100644
--- a/shpool/tests/daemon.rs
+++ b/shpool/tests/daemon.rs
@@ -297,3 +297,36 @@ fn echo_sentinel() -> anyhow::Result<()> {
         Ok(())
     })
 }
+
+#[test]
+#[timeout(30000)]
+fn allows_dynamic_log_adjustments() -> anyhow::Result<()> {
+    support::dump_err(|| {
+        let mut daemon_proc = support::daemon::Proc::new(
+            "norc.toml",
+            DaemonArgs { verbosity: 0, ..Default::default() },
+        )
+        .context("starting daemon proc")?;
+
+        daemon_proc.set_log_level("trace")?;
+
+        // Loop because the data might not get flushed the first time through.
+        loop {
+            let mut sh1 = daemon_proc.attach("sh1", AttachArgs::default())?;
+            // let mut line_matcher1 = sh1.line_matcher()?;
+            sh1.run_cmd("echo hi")?;
+            // line_matcher1.scan_until_re("hi$")?;
+
+            // Make sure trace level data landed in the log despite the fact
+            // that we started the daemon with a verbosity level of 0.
+            let log_data = std::fs::read_to_string(&daemon_proc.log_file)?;
+            if log_data.contains("echo hi") {
+                break;
+            }
+
+            std::thread::sleep(time::Duration::from_millis(300));
+        }
+
+        Ok(())
+    })
+}
diff --git a/shpool/tests/list.rs b/shpool/tests/list.rs
index 74c9ef07..c703faa8 100644
--- a/shpool/tests/list.rs
+++ b/shpool/tests/list.rs
@@ -43,6 +43,7 @@ fn version_mismatch_client_newer() -> anyhow::Result<()> {
                     String::from("SHPOOL_TEST__OVERRIDE_VERSION"),
                     String::from("0.0.0"),
                 )],
+                ..Default::default()
             },
         )
         .context("starting daemon proc")?;
@@ -69,6 +70,7 @@ fn version_mismatch_client_older() -> anyhow::Result<()> {
                     String::from("SHPOOL_TEST__OVERRIDE_VERSION"),
                     String::from("99999.0.0"),
                 )],
+                ..Default::default()
             },
         )
         .context("starting daemon proc")?;
diff --git a/shpool/tests/support/daemon.rs b/shpool/tests/support/daemon.rs
index 125600dc..e9adeedb 100644
--- a/shpool/tests/support/daemon.rs
+++ b/shpool/tests/support/daemon.rs
@@ -19,7 +19,7 @@ use super::{attach, events::Events, shpool_bin, testdata_file, wait_until};
 pub struct Proc {
     pub proc: Option<process::Child>,
     subproc_counter: usize,
-    log_file: PathBuf,
+    pub log_file: PathBuf,
     local_tmp_dir: Option<TempDir>,
     pub tmp_dir: PathBuf,
     pub events: Option<Events>,
@@ -31,11 +31,12 @@ pub struct Proc {
 pub struct DaemonArgs {
     pub listen_events: bool,
     pub extra_env: Vec<(String, String)>,
+    pub verbosity: i64,
 }
 
 impl std::default::Default for DaemonArgs {
     fn default() -> Self {
-        DaemonArgs { listen_events: true, extra_env: vec![] }
+        DaemonArgs { listen_events: true, extra_env: vec![], verbosity: 2 }
     }
 }
 
@@ -122,14 +123,21 @@ impl Proc {
         let mut cmd = Command::new(shpool_bin()?);
         cmd.stdout(Stdio::piped())
             .stderr(Stdio::piped())
-            .arg("-vv")
             .arg("--log-file")
             .arg(&log_file)
             .arg("--socket")
             .arg(&socket_path)
             .arg("--config-file")
-            .arg(resolved_config)
-            .arg("daemon");
+            .arg(resolved_config);
+
+        if args.verbosity == 1 {
+            cmd.arg("-v");
+        } else if args.verbosity >= 2 {
+            cmd.arg("-vv");
+        }
+
+        cmd.arg("daemon");
+
         if args.listen_events {
             cmd.env("SHPOOL_TEST_HOOK_SOCKET_PATH", &test_hook_socket_path);
         }
@@ -208,6 +216,7 @@ impl Proc {
             daemonize: false,
             no_daemonize: true,
             command: libshpool::Commands::Daemon,
+            ..libshpool::Args::default()
         };
         let hooks_recorder = Box::new(HooksRecorder {
             records: Arc::new(Mutex::new(HookRecords {
@@ -381,6 +390,24 @@ impl Proc {
             .context("spawning list proc")
     }
 
+    // launches a `shpool set-log-level` process
+    pub fn set_log_level(&mut self, level: &str) -> anyhow::Result<process::Output> {
+        let log_file = self.tmp_dir.join(format!("set_log_level_{}.log", self.subproc_counter));
+        eprintln!("spawning set-log-level proc with log {:?}", &log_file);
+        self.subproc_counter += 1;
+
+        Command::new(shpool_bin()?)
+            .arg("-vv")
+            .arg("--log-file")
+            .arg(&log_file)
+            .arg("--socket")
+            .arg(&self.socket_path)
+            .arg("set-log-level")
+            .arg(level)
+            .output()
+            .context("spawning set-log-level proc")
+    }
+
     pub fn await_event(&mut self, event: &str) -> anyhow::Result<()> {
         if let Some(events) = &mut self.events {
             events.await_event(event)