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

Radicle CI broker

feat: use the tracing crate for structured logging

Lars Wirzenius committed 1 year ago

commit cf395350eade13c1c739e96375111d2957bf921e
parent 84cfab01debee84dfa0be219bc2f00ac2450ee73

5 files changed +161 -310

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();
     }
 }