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

Radicle CI broker

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

Lars Wirzenius committed 1 year ago

commit cdd6a6c212d935b19e8e94058bd6fa4e502a2272
parent a7c9bd13c537bf09351a0e7ba03dd74730448d26

1 file changed +439 -63

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,
     TimeoutLineReceiverDisconnected,
     TimeoutLineReceiverChildDisconnected,
     TimeoutLineReceiverLostChild,
     TimeoutLineReceiverLine,
     TimeoutLineReceiverTried,
     TimeoutLineReceiverTry,
     TimeoutNonblockingEnd,
     TimeoutNonblockingEndOfFile,
     TimeoutNonblockingError,
     TimeoutNonblockingTooMuch,
     TimeoutNonblockingTried,
     TimeoutNonblockingTry,
     TimeoutOk,
     TimeoutRequestEnd,
     TimeoutNannyEnd,
     TimeoutNannyLostChild,
     TimeoutNannyNotifyTooLong,
     TimeoutNannyStart,
     TimeoutNannyTooLong,
     TimeoutNannyWaitEnd,
     TimeoutNannyWaitWord,
     TimeoutNannyWord,
     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) {