feat: add a "message id" field to each log message — radicle-ci-broker

rad:zwTxygwuz5LDGBq255RA2CbNGrz8

Radicle CI broker

feat: add a "message id" field to each log message

Merged liw opened 1 year ago

This identifies what the message is, without having to parse the message text, which is free form and may change and may some day get translated.

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

test: in acceptance scenarios, search for log ids, not message texts

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

Activity Changes +449 -73

2 files changed +449 -73 a7c9bd13 → 3ce84a47

modified ci-broker.md

@@ -299,9 +299,9 @@ when I run ./env.sh synthetic-events synt.sock event.json --log log.txt

 given a directory reports
 when I run ./env.sh cib --config broker.yaml process-events
 then stderr contains "CI broker starts"
 then stderr contains "loaded configuration"
 then stderr contains "CI broker ends successfully"
 then stderr contains "CibStart"
 then stderr contains "CibConfig"
 then stderr contains "CibEndSuccess"
 then file reports/index.html exists
 then file reports/status.json exists
 then file reports/index.rss exists

@@ -614,7 +614,7 @@ _Who:_ `node-ops`

 given a Radicle node, with CI configured with broker.yaml and adapter dummy.sh
 when I run ./env.sh cib --config broker.yaml config
 then stderr contains "CI broker starts"
 then stderr contains "CibStart"
 when I run ./env.sh cib --config broker.yaml --log-level error config
 then stderr is exactly ""

@@ -891,8 +891,8 @@ when I run cibtool --db ci-broker.db event shutdown

 given a directory reports
 when I run ./env.sh cib --config broker.yaml queued
 then stderr contains "Action: run"
 then stderr contains "Action: shutdown"
 then stderr contains "QueueProcActionRun"
 then stderr contains "QueueProcActionShutdown"
 when I run cibtool --db ci-broker.db event list
 then stdout is empty

@@ -1490,8 +1490,8 @@ given a Radicle node, with CI configured with broker.yaml and adapter dummy.sh

 given a directory reports
 when I run ./env.sh cib --config broker.yaml queued
 then stderr contains "CI broker starts"
 then stderr contains "CI broker ends successfully"
 then stderr contains "CibStart"
 then stderr contains "CibEndSuccess"
 ~~~
 ## Logs termination due to error

@@ -1510,8 +1510,8 @@ an error it can't recover from.

 ~~~scenario
 given a Radicle node, with CI configured with broker.yaml and adapter dummy.sh
 when I try to run env RAD_HOME=/does/not/exist cib --config broker.yaml queued
 then stderr contains "CI broker starts"
 then stderr contains "CI broker ends in unrecoverable error"
 then stderr contains "CibStart"
 then stderr contains "CibEndFailure"
 ~~~
 # Acceptance criteria for reports

modified src/logger.rs

@@ -45,6 +45,93 @@ impl std::fmt::Display for Kind {

     }
 }
 // An identifier for the specific log message, to avoid having to
 // match on message text.
 #[derive(Debug, Copy, Clone)]
 enum Id {
     AdapterConfig,
     AdapterExitCode,
     AdapterInvoluntaryExit,
     AdapterNoExit,
     AdapterNoFirstMessage,
     AdapterNoSecondMessage,
     AdapterStderrLine,
     AdapterTooManyMessages,
     AdHoc,
     BrokerDatabase,
     BrokerRunEnd,
     BrokerRunStart,
     BrokerTriggerMessage,
     CiEventSourceCreated,
     CiEventSourceDisconnected,
     CiEventSourceEnd,
     CiEventSourceEndOfFile,
     CiEventSourceGotEvents,
     CibConfig,
     CibEndFailure,
     CibEndSuccess,
     CibStart,
     NodeEventSourceCreated,
     NodeEventSourceDisconnected,
     NodeEventSourceEnd,
     NodeEventSourceEndOfFile,
     NodeEventSourceReceivedEvent,
     PagesDisconnected,
     PagesEnd,
     PagesInterval,
     PagesNoDirSet,
     PagesStart,
     QueueAddEnd,
     QueueAddEndEvents,
     QueueAddEnqueueEvent,
     QueueAddStart,
     QueueProcActionRun,
     QueueProcActionShutdown,
     QueueProcDisconnected,
     QueueProcEnd,
     QueueProcPickedEvent,
     QueueProcProcessedEvent,
     QueueProcQueueLength,
     QueueProcRemoveEvent,
     QueueProcStart,
     TimeoutLineReceiverCheckChild,
     TimeoutLineReceiverChildDisconnected,
     TimeoutLineReceiverDisconnected,
     TimeoutLineReceiverLine,
     TimeoutLineReceiverLostChild,
     TimeoutLineReceiverTried,
     TimeoutLineReceiverTry,
     TimeoutNannyEnd,
     TimeoutNannyLostChild,
     TimeoutNannyNotifyTooLong,
     TimeoutNannyStart,
     TimeoutNannyTooLong,
     TimeoutNannyWaitEnd,
     TimeoutNannyWaitWord,
     TimeoutNannyWord,
     TimeoutNonblockingEnd,
     TimeoutNonblockingEndOfFile,
     TimeoutNonblockingError,
     TimeoutNonblockingTooMuch,
     TimeoutNonblockingTried,
     TimeoutNonblockingTry,
     TimeoutOk,
     TimeoutRequestEnd,
     TimeoutWaitChildEnd,
     TimeoutWaitChildExitStatus,
     TimeoutWaitStderrReaderEnd,
     TimeoutWaitStdinWriterEnd,
     TimeoutWaitStdoutReaderEnd,
 }
 // We define our own type for log levels so that we can apply
 // clap::ValueEnum on it.
 #[derive(ValueEnum, Eq, PartialEq, Copy, Clone, Debug)]

@@ -102,6 +189,7 @@ pub fn open(level: LogLevel) {

 pub fn start_cib() {
     info!(
         msg_id = ?Id::CibStart,
         kind = %Kind::Startup,
         version = env!("GIT_HEAD"),
         "CI broker starts"

@@ -110,6 +198,7 @@ pub fn start_cib() {

 pub fn end_cib_successfully() {
     info!(
         msg_id = ?Id::CibEndSuccess,
         kind = %Kind::Shutdown,
         success = true,
         "CI broker ends successfully"

@@ -118,6 +207,7 @@ pub fn end_cib_successfully() {

 pub fn end_cib_in_error() {
     error!(
         msg_id = ?Id::CibEndFailure,
         kind = %Kind::Shutdown,
         success = false,
         "CI broker ends in unrecoverable error"

@@ -126,6 +216,7 @@ pub fn end_cib_in_error() {

 pub fn node_event_source_created(source: &NodeEventSource) {
     debug!(
         msg_id = ?Id::NodeEventSourceCreated,
         kind = %Kind::Startup,
         node_event_source = ?source,
         "created node event source"

@@ -134,6 +225,7 @@ pub fn node_event_source_created(source: &NodeEventSource) {

 pub fn node_event_source_got_event(event: &Event) {
     trace!(
         msg_id = ?Id::NodeEventSourceReceivedEvent,
         kind = %Kind::GotEvent,
         node_event = ?event,
         "node event source received event"

@@ -142,6 +234,7 @@ pub fn node_event_source_got_event(event: &Event) {

 pub fn node_event_source_eof(source: &NodeEventSource) {
     debug!(
         msg_id = ?Id::NodeEventSourceEndOfFile,
         kind = %Kind::Shutdown,
         node_event_source = ?source,
         "node event source end of file on control socket"

@@ -149,11 +242,17 @@ pub fn node_event_source_eof(source: &NodeEventSource) {

 }
 pub fn ci_event_source_created(source: &CiEventSource) {
     debug!(kind = %Kind::Startup, ?source, "created CI event source");
     debug!(
         msg_id = ?Id::CiEventSourceCreated,
         kind = %Kind::Startup,
         ?source,
         "created CI event source"
     );
 }
 pub fn ci_event_source_got_events(events: &[CiEvent]) {
     trace!(
         msg_id = ?Id::CiEventSourceGotEvents,
         kind = %Kind::GotEvent,
         ?events,
         "CI event source received events"

@@ -161,86 +260,171 @@ pub fn ci_event_source_got_events(events: &[CiEvent]) {

 }
 pub fn ci_event_source_disconnected() {
     info!(kind = %Kind::Shutdown, "CI event source received disconnection");
     info!(
         msg_id = ?Id::CiEventSourceDisconnected,
         kind = %Kind::Shutdown,
         "CI event source received disconnection"
     );
 }
 pub fn ci_event_source_end() {
     info!(
         msg_id = ?Id::CiEventSourceEnd,
         kind = %Kind::Debug,
         "CI event source was notified end of events"
     );
 }
 pub fn ci_event_source_eof(source: &CiEventSource) {
     info!(kind = %Kind::Debug, ?source, "CI event source end of file");
     info!(
         msg_id = ?Id::CiEventSourceEndOfFile,
         kind = %Kind::Debug,
         ?source,
         "CI event source end of file"
     );
 }
 pub fn loaded_config(config: &Config) {
     debug!(kind = %Kind::Startup, ?config, "loaded configuration");
     debug!(
         msg_id = ?Id::CibConfig,
         kind = %Kind::Startup,
         ?config,
         "loaded configuration"
     );
 }
 pub fn adapter_config(config: &Config) {
     trace!(kind = %Kind::Debug, ?config, "adapter configuration");
     trace!(
         msg_id = ?Id::AdapterConfig,
         kind = %Kind::Debug,
         ?config,
         "adapter configuration"
     );
 }
 pub fn queueproc_start() {
     debug!(kind = %Kind::Startup, "start thread to process events until a shutdown event");
     debug!(
         msg_id = ?Id::QueueProcStart,
         kind = %Kind::Startup,
         "start thread to process events until a shutdown event"
     );
 }
 pub fn queueproc_end() {
     debug!(kind = %Kind::Debug, "thread to process events ends");
     debug!(
         msg_id = ?Id::QueueProcEnd,
         kind = %Kind::Debug,
         "thread to process events ends"
     );
 }
 pub fn queueproc_channel_disconnect() {
     info!(kind = %Kind::Debug, "event notification channel disconnected");
     info!(
         msg_id = ?Id::QueueProcDisconnected,
         kind = %Kind::Debug,
         "event notification channel disconnected"
     );
 }
 pub fn queueproc_queue_length(len: usize) {
     trace!(kind = %Kind::Debug, ?len, "event queue length");
     trace!(
         msg_id = ?Id::QueueProcQueueLength,
         kind = %Kind::Debug,
         ?len,
         "event queue length"
     );
 }
 pub fn queueproc_picked_event(id: &QueueId, event: &QueuedCiEvent) {
     info!(kind = %Kind::GotEvent, ?id, ?event, "picked event from queue");
     info!(
         msg_id = ?Id::QueueProcPickedEvent,
         kind = %Kind::GotEvent,
         ?id,
         ?event,
         "picked event from queue"
     );
 }
 pub fn queueproc_processed_event(result: &Result<bool, QueueError>) {
     info!(kind = %Kind::GotEvent, ?result, "result of processing event");
     info!(
         msg_id = ?Id::QueueProcProcessedEvent,
         kind = %Kind::GotEvent,
         ?result,
         "result of processing event"
     );
 }
 pub fn queueproc_remove_event(id: &QueueId) {
     info!(kind = %Kind::Debug, ?id, "remove event from queue");
     info!(
         msg_id = ?Id::QueueProcRemoveEvent,
         kind = %Kind::Debug,
         ?id,
         "remove event from queue"
     );
 }
 pub fn queueproc_action_run(rid: &RepoId, oid: &Oid) {
     info!(kind = %Kind::Debug, ?rid, ?oid, "Action: run");
     info!(
         msg_id = ?Id::QueueProcActionRun,
         kind = %Kind::Debug,
         ?rid,
         ?oid,
         "Action: run"
     );
 }
 pub fn queueproc_action_shutdown() {
     info!(kind = %Kind::Debug, "Action: shutdown");
     info!(
         msg_id = ?Id::QueueProcActionShutdown,
         kind = %Kind::Debug,
         "Action: shutdown"
     );
 }
 pub fn queueadd_start() {
     debug!(kind = %Kind::Debug, "start thread to add events from node to event queue");
     debug!(
         msg_id = ?Id::QueueAddStart,
         kind = %Kind::Debug,
         "start thread to add events from node to event queue"
     );
 }
 pub fn queueadd_control_socket_close() {
     info!(kind = %Kind::Debug, "no more events from node control socket");
     info!(
         msg_id = ?Id::QueueAddEndEvents,
         kind = %Kind::Debug,
         "no more events from node control socket"
     );
 }
 pub fn queueadd_push_event(event: &CiEvent) {
     debug!(kind = %Kind::GotEvent, ?event, "insert broker event into queue");
     debug!(
         msg_id = ?Id::QueueAddEnqueueEvent,
         kind = %Kind::GotEvent,
         ?event,
         "insert broker event into queue"
     );
 }
 pub fn queueadd_end() {
     debug!(kind = %Kind::Debug, "thread to process events ends");
     debug!(
         msg_id = ?Id::QueueAddEnd,
         kind = %Kind::Debug,
         "thread to process events ends"
     );
 }
 pub fn pages_directory_unset() {
     warn!(kind = %Kind::Debug, "not writing HTML report pages as output directory has not been set");
     warn!(
         msg_id = ?Id::PagesNoDirSet,
         kind = %Kind::Debug,
         "not writing HTML report pages as output directory has not been set"
     );
 }
 pub fn pages_interval(interval: Duration) {
     trace!(
         msg_id = ?Id::PagesInterval,
         kind = %Kind::Debug,
         interval = interval.as_secs(),
         "interval for waiting between HTML page updates",

@@ -248,113 +432,231 @@ pub fn pages_interval(interval: Duration) {

 }
 pub fn pages_disconnected() {
     info!(kind = %Kind::Debug, "page updater: run notification channel disconnected");
     info!(
         msg_id = ?Id::PagesDisconnected,
         kind = %Kind::Debug,
         "page updater: run notification channel disconnected"
     );
 }
 pub fn pages_start() {
     debug!(kind = %Kind::Debug, "start page updater thread");
     debug!(
         msg_id = ?Id::PagesStart,
         kind = %Kind::Debug,
         "start page updater thread"
     );
 }
 pub fn pages_end() {
     debug!(kind = %Kind::Debug, "end page updater thread");
     debug!(
         msg_id = ?Id::PagesEnd,
         kind = %Kind::Debug,
         "end page updater thread"
     );
 }
 pub fn event_disconnected() {
     info!(kind = %Kind::Debug, "connection to node control socket broke");
     info!(
         msg_id = ?Id::NodeEventSourceDisconnected,
         kind = %Kind::Debug,
         "connection to node control socket broke"
     );
 }
 pub fn event_end() {
     info!(kind = %Kind::Debug, "no more node events from control socket: iterator ended");
     info!(
         msg_id = ?Id::NodeEventSourceEnd,
         kind = %Kind::Debug,
         "no more node events from control socket: iterator ended"
     );
 }
 pub fn broker_db(filename: &Path) {
     info!(kind = %Kind::Startup, filename = %filename.display(), "broker database");
     info!(
         msg_id = ?Id::BrokerDatabase,
         kind = %Kind::Startup,
         filename = %filename.display(),
         "broker database"
     );
 }
 pub fn broker_start_run(trigger: &Request) {
     info!(kind = %Kind::StartRun, "start CI run");
     debug!(kind = %Kind::Debug, event = ?trigger, "trigger event");
     info!(
         msg_id = ?Id::BrokerRunStart,
         kind = %Kind::StartRun,
         "start CI run"
     );
     debug!(
         msg_id = ?Id::BrokerTriggerMessage,
         kind = %Kind::Debug,
         event = ?trigger,
         "trigger message"
     );
 }
 pub fn broker_end_run(run: &Run) {
     info!(kind = %Kind::FinishRun, "Finish CI run");
     debug!(kind = %Kind::Debug, ?run, "finished CI run");
     info!(
         msg_id = ?Id::BrokerRunEnd,
         kind = %Kind::FinishRun,
         ?run,
         "Finish CI run"
     );
 }
 pub fn adapter_no_first_response() {
     error!(kind = %Kind::AdapterMessage, "no first response message");
     error!(
         msg_id = ?Id::AdapterNoFirstMessage,
         kind = %Kind::AdapterMessage,
         "no first response message"
     );
 }
 pub fn adapter_no_second_response() {
     error!(kind = %Kind::AdapterMessage, "no second response message");
     error!(
         msg_id = ?Id::AdapterNoSecondMessage,
         kind = %Kind::AdapterMessage,
         "no second response message"
     );
 }
 pub fn adapter_too_many_responses() {
     error!(kind = %Kind::AdapterMessage, "too many response messages");
     error!(
         msg_id = ?Id::AdapterTooManyMessages,
         kind = %Kind::AdapterMessage,
         "too many response messages"
     );
 }
 pub fn adapter_stderr_line(line: &str) {
     debug!(kind = %Kind::Debug, stderr_line = line, "adapter stderr");
     debug!(
         msg_id = ?Id::AdapterStderrLine,
         kind = %Kind::Debug,
         stderr_line = line,
         "adapter stderr"
     );
 }
 pub fn adapter_result(exit: i32) {
     debug!(kind = %Kind::Debug, exit_code = exit, "adapter exit code");
     debug!(
         msg_id = ?Id::AdapterExitCode,
         kind = %Kind::Debug,
         exit_code = exit,
         "adapter exit code"
     );
 }
 pub fn adapter_did_not_exit_voluntarily() {
     warn!(kind = %Kind::Debug, "adapter did not exit voluntarily: terminated for taking too long");
     warn!(
         msg_id = ?Id::AdapterInvoluntaryExit,
         kind = %Kind::Debug,
         "adapter did not exit voluntarily: terminated for taking too long"
     );
 }
 pub fn adapter_did_not_exit() {
     warn!(kind = %Kind::Debug, "adapter did not exit: probably killed by signal");
     warn!(
         msg_id = ?Id::AdapterNoExit,
         kind = %Kind::Debug,
         "adapter did not exit: probably killed by signal"
     );
 }
 pub fn timeoutcmd_request_termination(result: Result<(), std::sync::mpsc::SendError<()>>) {
     trace!(kind = %Kind::Debug, ?result, "request termination of child process");
     trace!(
         msg_id = ?Id::TimeoutRequestEnd,
         kind = %Kind::Debug,
         ?result,
         "request termination of child process"
     );
 }
 pub fn timeoutcmd_wait_word_from_nanny() {
     trace!(kind = %Kind::Debug, "wait: wait for word from nanny");
     trace!(
         msg_id = ?Id::TimeoutNannyWaitWord,
         kind = %Kind::Debug,
         "wait: wait for word from nanny"
     );
 }
 pub fn timeoutcmd_wait_got_word_from_nanny() {
     trace!(kind = %Kind::Debug, "got word from nanny");
     trace!(
         msg_id = ?Id::TimeoutNannyWord,
         kind = %Kind::Debug,
         "got word from nanny"
     );
 }
 pub fn timeoutcmd_wait_on_nanny_to_end() {
     trace!(kind = %Kind::Debug, "wait: wait on nanny thread to end");
     trace!(
         msg_id = ?Id::TimeoutNannyWaitEnd,
         kind = %Kind::Debug,
         "wait: wait on nanny thread to end"
     );
 }
 pub fn timeoutcmd_wait_on_stdin_writer_to_end() {
     trace!(kind = %Kind::Debug, "wait: wait for stdin writer to terminate");
     trace!(
         msg_id = ?Id::TimeoutWaitStdinWriterEnd,
         kind = %Kind::Debug,
         "wait: wait for stdin writer to terminate"
     );
 }
 pub fn timeoutcmd_wait_on_stdout_reader_to_end() {
     trace!(kind = %Kind::Debug, "wait: wait for stdout reader to terminate");
     trace!(
         msg_id = ?Id::TimeoutWaitStdoutReaderEnd,
         kind = %Kind::Debug,
         "wait: wait for stdout reader to terminate"
     );
 }
 pub fn timeoutcmd_wait_on_stderr_reader_to_end() {
     trace!(kind = %Kind::Debug, "wait: wait for stderr reader to terminate");
     trace!(
         msg_id = ?Id::TimeoutWaitStderrReaderEnd,
         kind = %Kind::Debug,
         "wait: wait for stderr reader to terminate"
     );
 }
 pub fn timeoutcmd_wait_on_child_to_end() {
     trace!(kind = %Kind::Debug, "wait: wait for child to terminate");
     trace!(
         msg_id = ?Id::TimeoutWaitChildEnd,
         lkind = %Kind::Debug,
         "wait: wait for child to terminate"
     );
 }
 pub fn timeoutcmd_wait_status(status: ExitStatus) {
     trace!(kind = %Kind::Debug, ?status, "wait: wait status");
     trace!(
         msg_id = ?Id::TimeoutWaitChildExitStatus,
         kind = %Kind::Debug,
         ?status,
         "wait: wait status"
     );
 }
 pub fn timeoutcmd_ok() {
     trace!(kind = %Kind::Debug, "wait: return Ok result");
     trace!(
         msg_id = ?Id::TimeoutOk,
         kind = %Kind::Debug,
         "wait: return Ok result"
     );
 }
 pub fn timeoutcmd_nanny_start() {
     trace!(kind = %Kind::Debug, "nanny: start monitoring child");
     trace!(
         kind = %Kind::Debug,
         "nanny: start monitoring child"
     );
 }
 pub fn timeoutcmd_nanny_terminated_as_requested(result: Result<(), std::io::Error>) {
     trace!(kind = %Kind::Debug, ?result, "nanny: terminated child by request");
     trace!(
         msg_id = ?Id::TimeoutNannyStart,
         kind = %Kind::Debug,
         ?result,
         "nanny: terminated child by request"
     );
 }
 pub fn timeoutcmd_nanny_too_long(

@@ -364,6 +666,7 @@ pub fn timeoutcmd_nanny_too_long(

     result: Result<(), std::io::Error>,
 ) {
     trace!(
         msg_id = ?Id::TimeoutNannyTooLong,
         kind = %Kind::Debug,
         %id,
         elapsed_ms = elapsed.as_millis(),

@@ -374,45 +677,82 @@ pub fn timeoutcmd_nanny_too_long(

 }
 pub fn timeoutcmd_nanny_child_died() {
     trace!(kind = %Kind::Debug, "nanny: child has terminated");
     trace!(
         msg_id = ?Id::TimeoutNannyLostChild,
         kind = %Kind::Debug,
         "nanny: child has terminated"
     );
 }
 pub fn timeoutcmd_nanny_time_to_end() {
     trace!(kind = %Kind::Debug, "nanny: tell other threads it's time to end");
     trace!(
         msg_id = ?Id::TimeoutNannyNotifyTooLong,
         kind = %Kind::Debug,
         "nanny: tell other threads it's time to end"
     );
 }
 pub fn timeoutcmd_nanny_ends() {
     trace!(kind = %Kind::Debug, "nanny: ends");
     trace!(
         msg_id = ?Id::TimeoutNannyEnd,
         kind = %Kind::Debug,
         "nanny: ends"
     );
 }
 pub fn timeoutcmd_line_reader_try_byte(thread: &'static str) {
     trace!(kind = %Kind::Debug, %thread, "line receiver: try to receive next byte");
     trace!(
         msg_id = ?Id::TimeoutLineReceiverTry,
         kind = %Kind::Debug,
         %thread,
         "line receiver: try to receive next byte"
     );
 }
 pub fn timeoutcmd_line_reader_tried_byte(
     thread: &'static str,
     result: Result<u8, std::sync::mpsc::TryRecvError>,
 ) {
     trace!(kind = %Kind::Debug, ?result, %thread, "line receiver: tried to read line");
     trace!(
         msg_id = ?Id::TimeoutLineReceiverTried,
         kind = %Kind::Debug,
         ?result,
         %thread,
         "line receiver: tried to read line"
     );
 }
 pub fn timeoutcmd_line_reader_got_line(thread: &'static str, line: &str) {
     trace!(kind = %Kind::Debug, ?line, %thread, "line-receiver: received line");
     trace!(
         msg_id = ?Id::TimeoutLineReceiverLine,
         kind = %Kind::Debug,
         ?line,
         %thread,
         "line-receiver: received line"
     );
 }
 pub fn timeoutcmd_line_reader_got_disconnected(thread: &'static str) {
     trace!(
         msg_id = ?Id::TimeoutLineReceiverDisconnected,
         kind = %Kind::Debug,
         %thread,
         "line-receiver: disconnected");
         "line-receiver: disconnected"
     );
 }
 pub fn timeoutcmd_line_reader_did_child_die(thread: &'static str) {
     trace!(%thread, "line-receiver: has child terminated?");
     trace!(
         msg_id = ?Id::TimeoutLineReceiverCheckChild,
         kind = %Kind::Debug,
         %thread,
         "line-receiver: has child terminated?"
     );
 }
 pub fn timeoutcmd_line_reader_child_died(thread: &'static str) {
     trace!(
         msg_id = ?Id::TimeoutLineReceiverLostChild,
         kind = %Kind::Debug,
         %thread,
         "line receiver: OK: child has terminated, not returning line",

@@ -421,6 +761,7 @@ pub fn timeoutcmd_line_reader_child_died(thread: &'static str) {

 pub fn timeoutcmd_line_reader_child_channel_disconnected(thread: &'static str) {
     trace!(
         msg_id = ?Id::TimeoutLineReceiverChildDisconnected,
         kind = %Kind::Debug,
         %thread,
         "line receiver: Disconnected: child has terminated, not returning line",

@@ -429,6 +770,7 @@ pub fn timeoutcmd_line_reader_child_channel_disconnected(thread: &'static str) {

 pub fn timeoutcmd_nonblocking_try_byte(thread: &'static str, count: usize) {
     trace!(
         msg_id = ?Id::TimeoutNonblockingTry,
         kind = %Kind::Debug,
         received_so_far = count,
         %thread,

@@ -442,6 +784,7 @@ pub fn timeoutcmd_nonblocking_tried_byte(

     byte: &[u8],
 ) {
     trace!(
         msg_id = ?Id::TimeoutNonblockingTried,
         kind = %Kind::Debug,
         ?result,
         ?byte,

@@ -451,7 +794,12 @@ pub fn timeoutcmd_nonblocking_tried_byte(

 }
 pub fn timeoutcmd_nonblocking_eof(thread: &'static str) {
     trace!(kind = %Kind::Debug, %thread, "read_to_end: got end of file");
     trace!(
         msg_id = ?Id::TimeoutNonblockingEndOfFile,
         kind = %Kind::Debug,
         %thread,
         "read_to_end: got end of file"
     );
 }
 pub fn timeoutcmd_nonblocking_got_too_much(

@@ -460,6 +808,7 @@ pub fn timeoutcmd_nonblocking_got_too_much(

     byte: &[u8],
 ) {
     trace!(
         msg_id = ?Id::TimeoutNonblockingTooMuch,
         kind = %Kind::Debug,
         ?result,
         ?byte,

@@ -469,27 +818,54 @@ pub fn timeoutcmd_nonblocking_got_too_much(

 }
 pub fn timeoutcmd_nonblocking_read_error(thread: &'static str, err: &std::io::Error) {
     trace!(kind = %Kind::Debug, ?err, %thread, "read_to_end: read error");
     trace!(
         msg_id = ?Id::TimeoutNonblockingError,
         kind = %Kind::Debug,
         ?err,
         %thread,
         "read_to_end: read error"
     );
 }
 pub fn timeoutcmd_nonblocking_ends(thread: &'static str) {
     trace!(kind = %Kind::Debug, %thread, "read_to_end: ends");
     trace!(
         msg_id = ?Id::TimeoutNonblockingEnd,
         kind = %Kind::Debug,
         %thread,
         "read_to_end: ends"
     );
 }
 pub fn debug(msg: &str) {
     debug!(kind = %Kind::Debug, "{msg}");
     debug!(
         msg_id = ?Id::AdHoc,
         kind = %Kind::Debug,
         "{msg}"
     );
 }
 pub fn debug2(msg: String) {
     debug!(kind = %Kind::Debug, "{msg}");
     debug!(
         msg_id = ?Id::AdHoc,
         kind = %Kind::Debug,
         "{msg}"
     );
 }
 pub fn trace(msg: &str) {
     trace!(kind = %Kind::Debug, "{msg}");
     trace!(
         msg_id = ?Id::AdHoc,
         kind = %Kind::Debug,
         "{msg}"
     );
 }
 pub fn trace2(msg: String) {
     trace!(kind = %Kind::Debug, "{msg}");
     trace!(
         msg_id = ?Id::AdHoc,
         kind = %Kind::Debug,
         "{msg}"
     );
 }
 pub fn error(msg: &str, e: &impl std::error::Error) {