feat: use the tracing crate for structured logging — radicle-ci-broker

rad:zwTxygwuz5LDGBq255RA2CbNGrz8

Radicle CI broker

feat: use the tracing crate for structured logging

Merged liw opened 1 year ago

Switch from the “slog” family of crates for structured logging to the “tracing” family. There should be no significant changes to the log messages, so I don’t consider this to be a breaking change.

The benefit of this change is that it opens up the possibility to add extra fields to the log messages as JSON values, instead of strings that contain the values as JSON.

With slog we currently have this message::

{“msg”:“broker database: /home/_rad/ci-broker.db”}

With slog or tracing we can change this to:

{“msg”:“open database”, “filename”: “/home/_rad/ci-broker.db”}

With tracing we can have this:

{“msg”:“open database”,“db”:{“type”:“sqlite”,“filename”:“/home/_rad/ci-broker.db”,“size”:12765}}

which would be, formatted prettily

{ “msg”: “open database”, “db”: { “type”: “sqlite”, “filename”: “/home/_rad/ci-broker.db”, “size”: 12765 } }

Such extra fields can then be easily queried or otherwise processed with programs, much more easily than having such programs parse text fields as JSON before they can be processed.

Doing this with slog is supposed to be possible, but I have failed to get it to work. The slog and tracing families of libraries seem otherwise similar for our purposes.

Signed-off-by: Lars Wirzenius liw@liw.fi

Activity Changes +161 -310

5 files changed +161 -310 84cfab01 → cf395350

modified Cargo.lock

@@ -179,12 +179,6 @@ source = "registry+https://github.com/rust-lang/crates.io-index"

 checksum = "4c95c10ba0b00a02636238b814946408b1322d5ac4760326e6fb8ec956d85775"
 [[package]]
 name = "arc-swap"
 version = "1.7.1"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "69f7f8c3906b62b754cd5326047894316021dcfe5a194c8ea52bdd94934a3457"
 [[package]]
 name = "arraydeque"
 version = "0.5.1"
 source = "registry+https://github.com/rust-lang/crates.io-index"

@@ -2019,9 +2013,6 @@ dependencies = [

  "serde",
  "serde_json",
  "serde_yml",
  "slog",
  "slog-json",
  "slog-scope",
  "sqlite",
  "sqlite3-sys",
  "subplot-build",

@@ -2029,7 +2020,10 @@ dependencies = [

  "tempfile",
  "thiserror",
  "time",
  "tracing",
  "tracing-subscriber",
  "uuid",
  "valuable",
 ]
 [[package]]

@@ -2477,35 +2471,6 @@ source = "registry+https://github.com/rust-lang/crates.io-index"

 checksum = "56199f7ddabf13fe5074ce809e7d3f42b42ae711800501b5b16ea82ad029c39d"
 [[package]]
 name = "slog"
 version = "2.7.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "8347046d4ebd943127157b94d63abb990fcf729dc4e9978927fdf4ac3c998d06"
 [[package]]
 name = "slog-json"
 version = "2.6.1"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "3e1e53f61af1e3c8b852eef0a9dee29008f55d6dd63794f3f12cef786cf0f219"
 dependencies = [
  "serde",
  "serde_json",
  "slog",
  "time",
 ]
 [[package]]
 name = "slog-scope"
 version = "4.4.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "2f95a4b4c3274cd2869549da82b57ccc930859bdbf5bcea0424bc5f140b3c786"
 dependencies = [
  "arc-swap",
  "lazy_static",
  "slog",
 ]
 [[package]]
 name = "slug"
 version = "0.1.6"
 source = "registry+https://github.com/rust-lang/crates.io-index"

@@ -2977,6 +2942,18 @@ dependencies = [

 ]
 [[package]]
 name = "tracing-serde"
 version = "0.1.3"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "bc6b213177105856957181934e4920de57730fc69bf42c37ee5bb664d406d9e1"
 dependencies = [
  "serde",
  "tracing-core",
  "valuable",
  "valuable-serde",
 ]
 [[package]]
 name = "tracing-subscriber"
 version = "0.3.18"
 source = "registry+https://github.com/rust-lang/crates.io-index"

@@ -2986,12 +2963,17 @@ dependencies = [

  "nu-ansi-term",
  "once_cell",
  "regex",
  "serde",
  "serde_json",
  "sharded-slab",
  "smallvec",
  "thread_local",
  "tracing",
  "tracing-core",
  "tracing-log",
  "tracing-serde",
  "valuable",
  "valuable-serde",
 ]
 [[package]]

@@ -3155,6 +3137,30 @@ name = "valuable"

 version = "0.1.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d"
 dependencies = [
  "valuable-derive",
 ]
 [[package]]
 name = "valuable-derive"
 version = "0.1.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "9d44690c645190cfce32f91a1582281654b2338c6073fa250b0949fd25c55b32"
 dependencies = [
  "proc-macro2",
  "quote",
  "syn 1.0.109",
 ]
 [[package]]
 name = "valuable-serde"
 version = "0.1.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "5285cfff30cdabe26626736a54d989687dd9cab84f51f4048b61d6d0ae8b0907"
 dependencies = [
  "serde",
  "valuable",
 ]
 [[package]]
 name = "vcpkg"

modified Cargo.toml

@@ -22,16 +22,16 @@ rss = "2.0.9"

 serde = { version = "1.0.204", features = ["derive"] }
 serde_json = "1.0.121"
 serde_yml = "0.0.11"
 slog = { version = "2.7.0", features = ["release_max_level_trace"] }
 slog-json = "2.6.1"
 slog-scope = "4.4.0"
 sqlite = "0.32.0"
 sqlite3-sys = "0.15.0"
 subplotlib = "0.11.0"
 tempfile = { version = "3.10.1" }
 thiserror = "1.0.63"
 time = { version = "0.3.36", features = ["formatting", "macros"] }
 tracing = { version = "0.1.40", features = ["max_level_trace", "release_max_level_trace", "valuable"] }
 tracing-subscriber = { version = "0.3.18", features = ["env-filter", "fmt", "json", "valuable"] }
 uuid = { version = "1.10.0", features = ["v4"] }
 valuable = { version = "0.1.0", features = ["derive"] }
 [dependencies.radicle]
 version = "0.13.0"

modified src/bin/cib.rs

@@ -25,9 +25,7 @@ use radicle_ci_broker::{

 };
 fn main() {
     let logger = logger::open();
     if let Err(e) = fallible_main(&logger) {
     if let Err(e) = fallible_main() {
         logger::error("ERROR", &e);
         logger::end_cib_in_error();
         exit(1);

@@ -35,9 +33,9 @@ fn main() {

     logger::end_cib_successfully();
 }
 fn fallible_main(logger: &logger::Logger) -> Result<(), CibError> {
 fn fallible_main() -> Result<(), CibError> {
     let args = Args::parse();
     logger.set_minimum_level(args.minimum_log_level());
     logger::open(args.minimum_log_level());
     // We only log this after setting the minimum log level from the
     // command line.

modified src/bin/cibtool.rs

@@ -43,7 +43,7 @@ use radicle_ci_broker::{

 mod cibtoolcmd;
 fn main() {
     let _logger = logger::open();
     let _logger = logger::open(logger::LogLevel::Info);
     if let Err(e) = fallible_main() {
         eprintln!("ERROR: {}", e);
         let mut e = e.source();

modified src/logger.rs

@@ -3,7 +3,6 @@

 #[cfg(test)]
 use std::sync::Once;
 use std::{
     fmt,
     io::Write,
     path::Path,
     process::ExitStatus,

@@ -13,8 +12,9 @@ use std::{

 use clap::ValueEnum;
 use radicle::{git::raw::Oid, identity::RepoId, node::Event};
 use slog::{debug, error, info, o, trace, warn, Drain};
 use slog_scope::GlobalLoggerGuard;
 use tracing::{debug, error, info, trace, warn, Level};
 use tracing_subscriber::{fmt, layer::SubscriberExt, util::SubscriberInitExt, EnvFilter};
 //use valuable::Valuable;
 use crate::{
     ci_event::CiEvent,

@@ -35,24 +35,30 @@ pub enum LogLevel {

     Info,
     Warning,
     Error,
     Critical,
 }
 impl fmt::Display for LogLevel {
     fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
         write!(f, "<{:?}>", self)
 impl std::fmt::Display for LogLevel {
     fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
         let s = match self {
             Self::Trace => "trace",
             Self::Debug => "debug",
             Self::Info => "info",
             Self::Warning => "warn",
             Self::Error => "error",
         };
         write!(f, "{s}")
     }
 }
 impl From<LogLevel> for slog::Level {
 impl From<LogLevel> for tracing::Level {
     fn from(log_level: LogLevel) -> Self {
         match log_level {
             LogLevel::Trace => slog::Level::Trace,
             LogLevel::Debug => slog::Level::Debug,
             LogLevel::Info => slog::Level::Info,
             LogLevel::Warning => slog::Level::Warning,
             LogLevel::Error => slog::Level::Error,
             LogLevel::Critical => slog::Level::Critical,
             LogLevel::Trace => Level::TRACE,
             LogLevel::Debug => Level::DEBUG,
             LogLevel::Info => Level::INFO,
             LogLevel::Warning => Level::WARN,
             LogLevel::Error => Level::ERROR,
         }
     }
 }

@@ -97,12 +103,7 @@ impl Write for LogWriter {

 }
 pub struct Logger {
     minimum_log_level: Arc<Mutex<slog::Level>>,
     // We need to keep this for as long as need to log. But we don't
     // refer to it directly.
     #[allow(dead_code)]
     guard: GlobalLoggerGuard,
     minimum_log_level: Arc<Mutex<tracing::Level>>,
 }
 impl Logger {

@@ -114,22 +115,27 @@ impl Logger {

     }
 }
 pub fn open() -> Logger {
     let underlying_logger = slog_json::Json::new(LogWriter::default())
         .add_default_keys()
         .set_flush(true)
         .set_newlines(true)
         .build();
 #[allow(clippy::unwrap_used)]
 pub fn open(level: LogLevel) -> Logger {
     #[cfg(test)]
     let writer = fmt::TestWriter::new();
     #[cfg(not(test))]
     let writer = std::io::stderr;
     let fmt_layer = fmt::layer().with_target(false).with_writer(writer).json();
     let filter_layer = EnvFilter::try_new(level.to_string()).unwrap();
     tracing_subscriber::registry()
         .with(filter_layer)
         .with(fmt_layer)
         .init();
     // Set the default log level. Trace is good for tests.
     let level = Arc::new(Mutex::new(LogLevel::Trace.into()));
     let filter = LogLevelFilter::new(underlying_logger, level.clone());
     let log = slog::Logger::root(Mutex::new(filter).fuse(), o!());
     let guard = slog_scope::set_global_logger(log);
     Logger {
         guard,
         minimum_log_level: level,
     }
 }

@@ -156,363 +162,239 @@ static INIT: Once = Once::new();

 #[cfg(test)]
 static mut LOGGER: Option<Logger> = None;
 struct LogLevelFilter<D> {
     drain: D,
     minimum_log_level: Arc<Mutex<slog::Level>>,
 }
 impl<D> LogLevelFilter<D> {
     pub fn new(drain: D, minimum_log_level: Arc<Mutex<slog::Level>>) -> Self {
         Self {
             drain,
             minimum_log_level,
         }
     }
 }
 impl<D> Drain for LogLevelFilter<D>
 where
     D: Drain,
 {
     type Ok = Option<D::Ok>;
     type Err = Option<D::Err>;
     fn log(
         &self,
         record: &slog::Record,
         values: &slog::OwnedKVList,
     ) -> Result<Self::Ok, Self::Err> {
         #[allow(clippy::unwrap_used)] // We have no good way to report an error
         let min = *self
             .minimum_log_level
             .lock()
             .expect("lock log level filter minimum level");
         if record.level().is_at_least(min) {
             self.drain.log(record, values).map(Some).map_err(Some)
         } else {
             Ok(None)
         }
     }
 }
 #[cfg(test)]
 #[ctor::ctor]
 fn open_for_tests() {
     INIT.call_once(|| unsafe {
         LOGGER = Some(open());
         LOGGER = Some(open(LogLevel::Trace));
     });
 }
 pub fn start_cib() {
     info!(slog_scope::logger(), "CI broker starts"; "version" => env!("GIT_HEAD"));
     info!(version = env!("GIT_HEAD"), "CI broker starts");
 }
 pub fn end_cib_successfully() {
     info!(slog_scope::logger(), "CI broker ends successfully");
     info!("CI broker ends successfully");
 }
 pub fn end_cib_in_error() {
     error!(
         slog_scope::logger(),
         "CI broker ends in unrecoverable error"
     );
     error!("CI broker ends in unrecoverable error");
 }
 pub fn node_event_source_created(source: &NodeEventSource) {
     debug!(
         slog_scope::logger(),
         "created node event source";
         "source" => format!("{source:#?}")
     );
     debug!(source = format!("{source:#?}"), "created node event source");
 }
 pub fn node_event_source_got_event(event: &Event) {
     debug!(
         slog_scope::logger(),
         "node event source received event";
         "node_event" => format!("{event:#?}")
         node_event = ?event,
         "node event source received event"
     );
 }
 pub fn node_event_source_eof(source: &NodeEventSource) {
     debug!(
         slog_scope::logger(),
         "node event source end of file on control socket";
         "node_event_source" => format!("{source:#?}")
         node_event_source = ?source,
         "node event source end of file on control socket"
     );
 }
 pub fn ci_event_source_created(source: &CiEventSource) {
     debug!(
         slog_scope::logger(),
         "created CI event source";
         "source" => format!("{source:#?}")
     );
     debug!(?source, "created CI event source");
 }
 pub fn ci_event_source_got_events(events: &[CiEvent]) {
     debug!(
         slog_scope::logger(),
         "CI event source received events";
         "ci_events" => format!("{events:#?}")
     );
     debug!(?events, "CI event source received events");
 }
 pub fn ci_event_source_disconnected() {
     info!(
         slog_scope::logger(),
         "CI event source received disconnection"
     );
     info!("CI event source received disconnection");
 }
 pub fn ci_event_source_end() {
     info!(
         slog_scope::logger(),
         "CI event source was notified end of events"
     );
     info!("CI event source was notified end of events");
 }
 pub fn ci_event_source_eof(source: &CiEventSource) {
     info!(
         slog_scope::logger(),
         "CI event source end of file";
         "ci_event_source" => format!("{source:#?}")
     );
     info!(?source, "CI event source end of file");
 }
 pub fn loaded_config(config: &Config) {
     debug!(slog_scope::logger(), "loaded configuration {config:#?}");
     debug!("loaded configuration {config:#?}");
 }
 pub fn adapter_config(config: &Config) {
     debug!(slog_scope::logger(), "adapter configuration {config:#?}");
     debug!("adapter configuration {config:#?}");
 }
 pub fn queueproc_start() {
     debug!(
         slog_scope::logger(),
         "start thread to process events until a shutdown event"
     );
     debug!("start thread to process events until a shutdown event");
 }
 pub fn queueproc_end() {
     debug!(slog_scope::logger(), "thread to process events ends");
     debug!("thread to process events ends");
 }
 pub fn queueproc_channel_disconnect() {
     info!(
         slog_scope::logger(),
         "event notification channel disconnected"
     );
     info!("event notification channel disconnected");
 }
 pub fn queueproc_queue_length(len: usize) {
     trace!(
         slog_scope::logger(),
         "event queue length"; "length" => len);
     trace!(?len, "event queue length");
 }
 pub fn queueproc_picked_event(id: &QueueId, event: &QueuedCiEvent) {
     info!(
         slog_scope::logger(),
         "picked event from queue: {id}: {event:#?}"
     );
     info!("picked event from queue: {id}: {event:#?}");
 }
 pub fn queueproc_remove_event(id: &QueueId) {
     info!(slog_scope::logger(), "remove event from queue: {id}");
     info!("remove event from queue: {id}");
 }
 pub fn queueproc_action_run(rid: &RepoId, oid: &Oid) {
     info!(slog_scope::logger(), "Action: run: {rid} {oid}");
     info!("Action: run: {rid} {oid}");
 }
 pub fn queueproc_action_shutdown() {
     info!(slog_scope::logger(), "Action: shutdown");
     info!("Action: shutdown");
 }
 pub fn queueadd_start() {
     debug!(
         slog_scope::logger(),
         "start thread to add events from node to event queue"
     );
     debug!("start thread to add events from node to event queue");
 }
 pub fn queueadd_control_socket_close() {
     info!(
         slog_scope::logger(),
         "no more events from node control socket"
     );
     info!("no more events from node control socket");
 }
 pub fn queueadd_push_event(e: &CiEvent) {
     debug!(
         slog_scope::logger(),
         "insert broker event into queue: {e:?}"
     );
     debug!("insert broker event into queue: {e:?}");
 }
 pub fn queueadd_end() {
     debug!(slog_scope::logger(), "thread to process events ends");
     debug!("thread to process events ends");
 }
 pub fn pages_directory_unset() {
     warn!(
         slog_scope::logger(),
         "not writing HTML report pages as output directory has not been set"
     );
     warn!("not writing HTML report pages as output directory has not been set");
 }
 pub fn pages_interval(interval: Duration) {
     debug!(
         slog_scope::logger(),
         "wait about {} seconds to update HTML report pages again",
         interval.as_secs()
     );
 }
 pub fn pages_disconnected() {
     info!(
         slog_scope::logger(),
         "page updater: run notification channel disconnected"
     );
     info!("page updater: run notification channel disconnected");
 }
 pub fn pages_start() {
     debug!(slog_scope::logger(), "start page updater thread");
     debug!("start page updater thread");
 }
 pub fn pages_end() {
     debug!(slog_scope::logger(), "end page updater thread");
     debug!("end page updater thread");
 }
 pub fn event_disconnected() {
     info!(
         slog_scope::logger(),
         "connection to node control socket broke"
     );
     info!("connection to node control socket broke");
 }
 pub fn event_end() {
     info!(
         slog_scope::logger(),
         "no more node events from control socket: iterator ended"
     );
     info!("no more node events from control socket: iterator ended");
 }
 pub fn broker_db(filename: &Path) {
     info!(
         slog_scope::logger(),
         "broker database: {}",
         filename.display()
     );
     info!("broker database: {}", filename.display());
 }
 pub fn broker_start_run(trigger: &Request) {
     info!(slog_scope::logger(), "start CI run");
     debug!(slog_scope::logger(), "trigger event: {trigger:#?}");
     info!("start CI run");
     debug!("trigger event: {trigger:#?}");
 }
 pub fn broker_end_run(run: &Run) {
     info!(slog_scope::logger(), "Finish CI run");
     debug!(slog_scope::logger(), "finished CI run: {run:#?}");
     info!("Finish CI run");
     debug!("finished CI run: {run:#?}");
 }
 pub fn adapter_no_first_response() {
     error!(slog_scope::logger(), "no first response message");
     error!("no first response message");
 }
 pub fn adapter_no_second_response() {
     error!(slog_scope::logger(), "no second response message");
     error!("no second response message");
 }
 pub fn adapter_too_many_responses() {
     error!(slog_scope::logger(), "too many response messages");
     error!("too many response messages");
 }
 pub fn adapter_stderr_line(line: &str) {
     debug!(slog_scope::logger(), "adapter stderr"; "stderr" => line);
     debug!(stderr_line = line, "adapter stderr");
 }
 pub fn adapter_result(exit: i32) {
     debug!(slog_scope::logger(), "adapter exit code"; "exit_code" => exit);
     debug!(exit_code = exit, "adapter exit code");
 }
 pub fn adapter_did_not_exit_voluntarily() {
     warn!(
         slog_scope::logger(),
         "adapter did not exit voluntarily: terminated for taking too long"
     );
     warn!("adapter did not exit voluntarily: terminated for taking too long");
 }
 pub fn adapter_did_not_exit() {
     warn!(
         slog_scope::logger(),
         "adapter did not exit: probably killed by signal"
     );
     warn!("adapter did not exit: probably killed by signal");
 }
 pub fn timeoutcmd_request_termination(result: Result<(), std::sync::mpsc::SendError<()>>) {
     trace!(
         slog_scope::logger(),
         "request termination of child process: {result:?}"
     );
     trace!("request termination of child process: {result:?}");
 }
 pub fn timeoutcmd_wait_word_from_nanny() {
     trace!(slog_scope::logger(), "wait: wait for word from nanny");
     trace!("wait: wait for word from nanny");
 }
 pub fn timeoutcmd_wait_got_word_from_nanny() {
     trace!(slog_scope::logger(), "got word from nanny");
     trace!("got word from nanny");
 }
 pub fn timeoutcmd_wait_on_nanny_to_end() {
     trace!(slog_scope::logger(), "wait: wait on nanny thread to end");
     trace!("wait: wait on nanny thread to end");
 }
 pub fn timeoutcmd_wait_on_stdin_writer_to_end() {
     trace!(
         slog_scope::logger(),
         "wait: wait for stdin writer to terminate"
     );
     trace!("wait: wait for stdin writer to terminate");
 }
 pub fn timeoutcmd_wait_on_stdout_reader_to_end() {
     trace!(
         slog_scope::logger(),
         "wait: wait for stdout reader to terminate"
     );
     trace!("wait: wait for stdout reader to terminate");
 }
 pub fn timeoutcmd_wait_on_stderr_reader_to_end() {
     trace!(
         slog_scope::logger(),
         "wait: wait for stderr reader to terminate"
     );
     trace!("wait: wait for stderr reader to terminate");
 }
 pub fn timeoutcmd_wait_on_child_to_end() {
     trace!(slog_scope::logger(), "wait: wait for child to terminate");
     trace!("wait: wait for child to terminate");
 }
 pub fn timeoutcmd_wait_status(status: ExitStatus) {
     trace!(slog_scope::logger(), "wait: wait status: {status:?}");
     trace!("wait: wait status: {status:?}");
 }
 pub fn timeoutcmd_ok() {
     trace!(slog_scope::logger(), "wait: return Ok result");
     trace!("wait: return Ok result");
 }
 pub fn timeoutcmd_nanny_start() {
     trace!(slog_scope::logger(), "nanny: start monitoring child");
     trace!("nanny: start monitoring child");
 }
 pub fn timeoutcmd_nanny_terminated_as_requested(result: Result<(), std::io::Error>) {
     trace!(
         slog_scope::logger(),
         "nanny: terminated child by request: {result:?}"
     );
     trace!("nanny: terminated child by request: {result:?}");
 }
 pub fn timeoutcmd_nanny_too_long(

@@ -522,7 +404,6 @@ pub fn timeoutcmd_nanny_too_long(

     result: Result<(), std::io::Error>,
 ) {
     trace!(
         slog_scope::logger(),
         "nanny: child {} has run for too long ({} ms > {} ms); terminated it: {:?}",
         id,
         elapsed.as_millis(),

@@ -532,63 +413,42 @@ pub fn timeoutcmd_nanny_too_long(

 }
 pub fn timeoutcmd_nanny_child_died() {
     trace!(slog_scope::logger(), "nanny: child has terminated");
     trace!("nanny: child has terminated");
 }
 pub fn timeoutcmd_nanny_time_to_end() {
     trace!(
         slog_scope::logger(),
         "nanny: tell other threads it's time to end"
     );
     trace!("nanny: tell other threads it's time to end");
 }
 pub fn timeoutcmd_nanny_ends() {
     trace!(slog_scope::logger(), "nanny: ends");
     trace!("nanny: ends");
 }
 pub fn timeoutcmd_line_reader_try_byte(name: &'static str) {
     trace!(
         slog_scope::logger(),
         "line receiver {}: try to receive next byte",
         name
     );
     trace!("line receiver {}: try to receive next byte", name);
 }
 pub fn timeoutcmd_line_reader_tried_byte(
     name: &'static str,
     result: Result<u8, std::sync::mpsc::TryRecvError>,
 ) {
     trace!(
         slog_scope::logger(),
         "line receiver {}: tried to read line: {:?}",
         name,
         result
     );
     trace!("line receiver {}: tried to read line: {:?}", name, result);
 }
 pub fn timeoutcmd_line_reader_got_line(name: &'static str, line: &str) {
     trace!(
         slog_scope::logger(),
         "line-receiver {}: received line={line:?}",
         name,
     );
     trace!("line-receiver {}: received line={line:?}", name,);
 }
 pub fn timeoutcmd_line_reader_got_disconnected(name: &'static str) {
     trace!(slog_scope::logger(), "line-receiver {}: disconnected", name);
     trace!("line-receiver {}: disconnected", name);
 }
 pub fn timeoutcmd_line_reader_did_child_die(name: &'static str) {
     trace!(
         slog_scope::logger(),
         "line-receiver {}: has child terminated?",
         name
     );
     trace!("line-receiver {}: has child terminated?", name);
 }
 pub fn timeoutcmd_line_reader_child_died(name: &'static str) {
     trace!(
         slog_scope::logger(),
         "line receiver {}: OK: child has terminated, not returning line",
         name
     );

@@ -596,7 +456,6 @@ pub fn timeoutcmd_line_reader_child_died(name: &'static str) {

 pub fn timeoutcmd_line_reader_child_channel_disconnected(name: &'static str) {
     trace!(
         slog_scope::logger(),
         "line receiver {}: Disconnected: child has terminated, not returning line",
         name
     );

@@ -604,7 +463,6 @@ pub fn timeoutcmd_line_reader_child_channel_disconnected(name: &'static str) {

 pub fn timeoutcmd_nonblocking_try_byte(name: &'static str, count: usize) {
     trace!(
         slog_scope::logger(),
         "read_to_end {}: try to receive next byte ({} so far)",
         name,
         count

@@ -617,7 +475,6 @@ pub fn timeoutcmd_nonblocking_tried_byte(

     byte: &[u8],
 ) {
     trace!(
         slog_scope::logger(),
         "read_to_end {}: tried to receive byte: result={:?} byte={:?}",
         name,
         result,

@@ -626,11 +483,7 @@ pub fn timeoutcmd_nonblocking_tried_byte(

 }
 pub fn timeoutcmd_nonblocking_eof(name: &'static str) {
     trace!(
         slog_scope::logger(),
         "read_to_end {}: got end of file",
         name,
     );
     trace!("read_to_end {}: got end of file", name,);
 }
 pub fn timeoutcmd_nonblocking_got_too_much(

@@ -639,7 +492,6 @@ pub fn timeoutcmd_nonblocking_got_too_much(

     byte: &[u8],
 ) {
     trace!(
         slog_scope::logger(),
         "read_to_end {}: received too much: result={:?} byte={:?}",
         name,
         result,

@@ -648,31 +500,26 @@ pub fn timeoutcmd_nonblocking_got_too_much(

 }
 pub fn timeoutcmd_nonblocking_read_error(name: &'static str, err: &std::io::Error) {
     trace!(
         slog_scope::logger(),
         "read_to_end {}: read error: {}",
         name,
         err
     );
     trace!("read_to_end {}: read error: {}", name, err);
 }
 pub fn timeoutcmd_nonblocking_ends(name: &'static str) {
     trace!(slog_scope::logger(), "read_to_end {}: ends", name,);
     trace!("read_to_end {}: ends", name,);
 }
 pub fn debug(msg: &str) {
     debug!(slog_scope::logger(), "{msg}");
     debug!("{msg}");
 }
 pub fn debug2(msg: String) {
     debug!(slog_scope::logger(), "{msg}");
     debug!("{msg}");
 }
 pub fn error(msg: &str, e: &impl std::error::Error) {
     error!(slog_scope::logger(), "{msg}: {e}");
     error!("{msg}: {e}");
     let mut e = e.source();
     while let Some(source) = e {
         error!(slog_scope::logger(), "caused by: {}", source);
         error!("caused by: {}", source);
         e = source.source();
     }
 }