feat: drop timeoutcmd.rs log messages to trace level — radicle-ci-broker

Also move them to logger.rs.

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

     fmt,
     io::Write,
     path::Path,
     process::ExitStatus,
     sync::{Arc, Mutex},
     time::Duration,
 };

     /// Terminate sub-process with extreme prejudice.
     pub fn kill(&self) -> Result<(), TimeoutError> {
         let x = self.kill_tx.send(());
         logger::debug2(format!("request termination of child process: {x:?}"));
         logger::timeoutcmd_request_termination(x);
         Ok(())
     }

     /// progress. This may be unwanted. The blocking won't affect the
     /// sub-process getting terminated due to running for too long.
     pub fn wait(mut self) -> Result<TimeoutResult, TimeoutError> {
         logger::debug("wait: wait for word from nanny");
         logger::timeoutcmd_wait_word_from_nanny();
         let (mut child, timed_out) = self.timed_out_rx.recv().map_err(TimeoutError::ChildRecv)?;
         logger::debug("got word from nanny");
         logger::timeoutcmd_wait_got_word_from_nanny();
         if let Some(monitor) = self.child_monitor.take() {
             logger::debug("wait: wait on nanny thread to end");
             logger::timeoutcmd_wait_on_nanny_to_end();
             monitor
                 .join()
                 .map_err(|_| TimeoutError::JoinChildMonitor)??;
         }
         logger::debug("wait: wait for stdin writer to terminate");
         logger::timeoutcmd_wait_on_stdin_writer_to_end();
         self.stdin_writer.join().ok();
         logger::debug("wait: wait for stdout reader to terminate");
         logger::timeoutcmd_wait_on_stdout_reader_to_end();
         self.stdout_reader.join().ok();
         logger::debug("wait: wait for stderr reader to terminate");
         logger::timeoutcmd_wait_on_stderr_reader_to_end();
         self.stderr_reader.join().ok();
         logger::debug("wait: wait for child to terminate");
         logger::timeoutcmd_wait_on_child_to_end();
         let status = child.wait().map_err(TimeoutError::Wait)?;
         logger::debug2(format!("wait: wait status: {status:?}"));
         logger::debug("wait: return Ok result");
         logger::timeoutcmd_wait_status(status);
         logger::timeoutcmd_ok();
         Ok(TimeoutResult { timed_out, status })
     }
 }

         };
         let started = Instant::now();
         let mut timed_out = false;
         logger::debug("nanny: start monitoring child");
         logger::timeoutcmd_nanny_start();
         loop {
             let elapsed = started.elapsed();
             if self.kill_rx.try_recv().is_ok() {
                 let x = child.kill();
                 logger::debug2(format!("nanny: terminated child by request: {x:?}"));
                 logger::timeoutcmd_nanny_terminated_as_requested(x);
                 break;
             } else if elapsed > self.max_duration {
                 logger::debug2(format!(
                     "nanny: child has run for too long ({} ms > {} ms)",
                     elapsed.as_millis(),
                     self.max_duration.as_millis(),
                 ));
                 logger::debug2(format!(
                     "nanny: terminate child process {} with extreme prejudice",
                     child.id(),
                 ));
                 let x = child.kill();
                 logger::timeoutcmd_nanny_too_long(child.id(), elapsed, self.max_duration, x);
                 timed_out = true;
                 logger::debug2(format!("nanny: termination result: {x:?}"));
                 break;
             }
             if matches!(child.try_wait(), Ok(None)) {
                 logger::debug2(format!(
                     "nanny: child is still running, that's fine ({} ms <= {} ms)",
                     elapsed.as_millis(),
                     self.max_duration.as_millis(),
                 ));
                 sleep(WAIT_FOR_IDLE_CHILD);
             } else {
                 logger::debug("nanny: child has terminated");
                 logger::timeoutcmd_nanny_child_died();
                 break;
             }
         }
         logger::debug("nanny: tell RunningProcess it's time");
         logger::timeoutcmd_nanny_time_to_end();
         self.tx
             .send((child, timed_out))
             .map_err(TimeoutError::ChildSend)?;
         for tx in self.term_tx.iter() {
             logger::debug("nanny: tell line receiver it's time");
             tx.send(()).map_err(TimeoutError::ChildSendToLine)?;
         }
         logger::debug("nanny ends");
         logger::timeoutcmd_nanny_ends();
         Ok(())
     }
 }

         // Or async.
         let n = stream.write(&data[written..written + 1])?;
         written += n;
         logger::debug("writer wrote {n:?}");
         stream.flush()?;
     }

     );
 }
 pub fn timeoutcmd_request_termination(result: Result<(), std::sync::mpsc::SendError<()>>) {
     trace!(
         slog_scope::logger(),
         "request termination of child process: {result:?}"
     );
 }
 pub fn timeoutcmd_wait_word_from_nanny() {
     trace!(slog_scope::logger(), "wait: wait for word from nanny");
 }
 pub fn timeoutcmd_wait_got_word_from_nanny() {
     trace!(slog_scope::logger(), "got word from nanny");
 }
 pub fn timeoutcmd_wait_on_nanny_to_end() {
     trace!(slog_scope::logger(), "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"
     );
 }
 pub fn timeoutcmd_wait_on_stdout_reader_to_end() {
     trace!(
         slog_scope::logger(),
         "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"
     );
 }
 pub fn timeoutcmd_wait_on_child_to_end() {
     trace!(slog_scope::logger(), "wait: wait for child to terminate");
 }
 pub fn timeoutcmd_wait_status(status: ExitStatus) {
     trace!(slog_scope::logger(), "wait: wait status: {status:?}");
 }
 pub fn timeoutcmd_ok() {
     trace!(slog_scope::logger(), "wait: return Ok result");
 }
 pub fn timeoutcmd_nanny_start() {
     trace!(slog_scope::logger(), "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:?}"
     );
 }
 pub fn timeoutcmd_nanny_too_long(
     id: u32,
     elapsed: Duration,
     max: Duration,
     result: Result<(), std::io::Error>,
 ) {
     trace!(
         slog_scope::logger(),
         "nanny: child {} has run for too long ({} ms > {} ms); terminated it: {:?}",
         id,
         elapsed.as_millis(),
         max.as_millis(),
         result,
     );
 }
 pub fn timeoutcmd_nanny_child_died() {
     trace!(slog_scope::logger(), "nanny: child has terminated");
 }
 pub fn timeoutcmd_nanny_time_to_end() {
     trace!(
         slog_scope::logger(),
         "nanny: tell other threads it's time to end"
     );
 }
 pub fn timeoutcmd_nanny_ends() {
     trace!(slog_scope::logger(), "nanny: ends");
 }
 pub fn timeoutcmd_line_reader_try_byte(name: &'static str) {
     trace!(
         slog_scope::logger(),
         "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
     );
 }
 pub fn timeoutcmd_line_reader_got_line(name: &'static str, line: &str) {
     trace!(
         slog_scope::logger(),
         "line-receiver {}: received line={line:?}",
         name,
     );
 }
 pub fn timeoutcmd_line_reader_got_disconnected(name: &'static str) {
     trace!(slog_scope::logger(), "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
     );
 }
 pub fn timeoutcmd_line_reader_child_died(name: &'static str) {
     trace!(
         slog_scope::logger(),
         "line receiver {}: OK: child has terminated, not returning line",
         name
     );
 }
 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
     );
 }
 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
     );
 }
 pub fn timeoutcmd_nonblocking_tried_byte(
     name: &'static str,
     result: &Result<usize, std::io::Error>,
     byte: &[u8],
 ) {
     trace!(
         slog_scope::logger(),
         "read_to_end {}: tried to receive byte: result={:?} byte={:?}",
         name,
         result,
         byte
     );
 }
 pub fn timeoutcmd_nonblocking_eof(name: &'static str) {
     trace!(
         slog_scope::logger(),
         "read_to_end {}: got end of file",
         name,
     );
 }
 pub fn timeoutcmd_nonblocking_got_too_much(
     name: &'static str,
     result: Result<usize, std::io::Error>,
     byte: &[u8],
 ) {
     trace!(
         slog_scope::logger(),
         "read_to_end {}: received too much: result={:?} byte={:?}",
         name,
         result,
         byte
     );
 }
 pub fn timeoutcmd_nonblocking_read_error(name: &'static str, err: &std::io::Error) {
     trace!(
         slog_scope::logger(),
         "read_to_end {}: read error: {}",
         name,
         err
     );
 }
 pub fn timeoutcmd_nonblocking_ends(name: &'static str) {
     trace!(slog_scope::logger(), "read_to_end {}: ends", name,);
 }
 pub fn debug(msg: &str) {
     debug!(slog_scope::logger(), "{msg}");
 }

         loop {
             // Get a byte if there is one.
             logger::debug2(format!(
                 "line receiver {}: try to receive next byte",
                 self.name
             ));
             logger::timeoutcmd_line_reader_try_byte(self.name);
             let y = self.bytes.try_recv();
             logger::debug2(format!(
                 "line receiver {}: tried to read line: {y:?}",
                 self.name
             ));
             logger::timeoutcmd_line_reader_tried_byte(self.name, y);
             match y {
                 Ok(byte) => {
                     line.push(byte);
                     if byte == b'\n' {
                         let line = String::from_utf8_lossy(&line).to_string();
                         logger::debug2(format!(
                             "line-receiver {}: received line={line:?}",
                             self.name
                         ));
                         logger::timeoutcmd_line_reader_got_line(self.name, &line);
                         return Some(line);
                     }
                 }

                 Err(TryRecvError::Disconnected) => {
                     if line.is_empty() {
                         // Sender has closed the channel, there will be no more lines.
                         logger::debug2(format!("line-receiver {}: disconnected", self.name));
                         logger::timeoutcmd_line_reader_got_disconnected(self.name);
                         return None;
                     } else {
                         let line = String::from_utf8_lossy(&line).to_string();
                         logger::debug2(format!(
                             "line-receiver {}: received line={line:?}",
                             self.name
                         ));
                         logger::timeoutcmd_line_reader_got_line(self.name, &line);
                         return Some(line);
                     }
                 }
             }
             logger::debug("line-receiver: has child terminated?");
             logger::timeoutcmd_line_reader_did_child_die(self.name);
             let x = self.child_terminated.try_recv();
             // logger::debug("line receiver {}: x={x:?}", self.name);
             match x {
                 Ok(_) => {
                     logger::debug2(format!(
                         "line receiver {}: OK: child has terminated, not returning line",
                         self.name,
                     ));
                     logger::timeoutcmd_line_reader_child_died(self.name);
                 }
                 Err(std::sync::mpsc::TryRecvError::Disconnected) => {
                     logger::debug2(format!(
                         "line receiver {}: Disconnected: child has terminated, not returning line",
                         self.name,
                     ));
                     logger::timeoutcmd_line_reader_child_channel_disconnected(self.name);
                 }
                 _ => {}
             }

             // If this becomes too inefficient, this needs to be
             // rewritten to use non-blocking I/O or async.
             logger::debug2(format!(
                 "read_to_end {}: try to receive next byte ({count} so far)",
                 self.name,
             ));
             logger::timeoutcmd_nonblocking_try_byte(self.name, count);
             let mut byte = vec![0; 1];
             let x = self.stream.read(&mut byte);
             logger::debug2(format!("read_to_end {}: x={x:?} byte={byte:?}", self.name));
             logger::timeoutcmd_nonblocking_tried_byte(self.name, &x, &byte);
             match x {
                 Ok(0) => {
                     logger::debug2(format!("read_to_end {}: end of file", self.name));
                     logger::timeoutcmd_nonblocking_eof(self.name);
                     break;
                 }
                 Ok(1) => {

                         .map_err(|_| TimeoutError::TooMuch(self.name))?;
                 }
                 Ok(_) => {
                     logger::debug2(format!("read_to_end {}: read too much", self.name));
                     logger::timeoutcmd_nonblocking_got_too_much(self.name, x, &byte);
                     return Err(TimeoutError::ReadMucn);
                 }
                 Err(err) => {
                     logger::debug2(format!("read_to_end {}: read error: {err}", self.name));
                     logger::timeoutcmd_nonblocking_read_error(self.name, &err);
                     return Err(TimeoutError::Read(err));
                 }
             }
         }
         logger::debug2(format!("read_to_end {}: terminate", self.name));
         logger::timeoutcmd_nonblocking_ends(self.name);
         Ok(())
     }
 }