chore: tidy up logging — radicle-ci-broker

modified ci-broker.md

@@ -849,7 +849,7 @@ 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: run"
 then stderr contains "Action: shutdown"
 when I run cibtool --db ci-broker.db event list

modified src/ci_event.rs

@@ -14,8 +14,6 @@ use radicle::{

     storage::RefUpdate,
 };
 use crate::logger;
 #[derive(Debug, Eq, PartialEq, Clone, Serialize, Deserialize)]
 #[non_exhaustive]
 pub enum CiEvent {

@@ -188,11 +186,8 @@ impl CiEvent {

 }
 fn originator(name: RefString) -> Result<PublicKey, CiEventError> {
     logger::trace2(format!("originator: name={name:?}"));
     if let Some(qualified) = name.clone().into_qualified() {
         logger::trace2(format!("originator: qualified={qualified:?}"));
         if let Some(namespaced) = qualified.to_namespaced() {
             logger::trace2(format!("originator: namespaced={namespaced:?}"));
             return PublicKey::from_namespaced(&namespaced)
                 .map_err(|err| CiEventError::key_from_namespaced(&name, err));
         }

modified src/ci_event_source.rs

@@ -23,7 +23,7 @@ impl CiEventSource {

     pub fn event(&mut self) -> Result<Option<Vec<CiEvent>>, CiEventSourceError> {
         let result = self.source.node_event();
         logger::debug2(format!("ci_event_source: result={result:?}"));
         logger::trace2(format!("ci_event_source: result={result:?}"));
         match result {
             Err(err) if matches!(err, NodeEventError::BrokenConnection) => {
                 logger::ci_event_source_disconnected();

modified src/logger.rs

@@ -125,14 +125,14 @@ pub fn end_cib_in_error() {

 pub fn node_event_source_created(source: &NodeEventSource) {
     debug!(
         kind = %Kind::Debug,
         source = format!("{source:#?}"),
         kind = %Kind::Startup,
         node_event_source = ?source,
         "created node event source"
     );
 }
 pub fn node_event_source_got_event(event: &Event) {
     debug!(
     trace!(
         kind = %Kind::GotEvent,
         node_event = ?event,
         "node event source received event"

@@ -141,18 +141,18 @@ pub fn node_event_source_got_event(event: &Event) {

 pub fn node_event_source_eof(source: &NodeEventSource) {
     debug!(
         kind = %Kind::Debug,
         kind = %Kind::Shutdown,
         node_event_source = ?source,
         "node event source end of file on control socket"
     );
 }
 pub fn ci_event_source_created(source: &CiEventSource) {
     debug!(kind = %Kind::Debug, ?source, "created CI event source");
     debug!(kind = %Kind::Startup, ?source, "created CI event source");
 }
 pub fn ci_event_source_got_events(events: &[CiEvent]) {
     debug!(
     trace!(
         kind = %Kind::GotEvent,
         ?events,
         "CI event source received events"

@@ -160,7 +160,7 @@ pub fn ci_event_source_got_events(events: &[CiEvent]) {

 }
 pub fn ci_event_source_disconnected() {
     info!(kind = %Kind::Debug, "CI event source received disconnection");
     info!(kind = %Kind::Shutdown, "CI event source received disconnection");
 }
 pub fn ci_event_source_end() {

@@ -175,15 +175,15 @@ pub fn ci_event_source_eof(source: &CiEventSource) {

 }
 pub fn loaded_config(config: &Config) {
     debug!(kind = %Kind::Debug, config=format!("{config:#?}"), "loaded configuration");
     debug!(kind = %Kind::Startup, ?config, "loaded configuration");
 }
 pub fn adapter_config(config: &Config) {
     debug!(kind = %Kind::Debug, "adapter configuration {config:#?}");
     trace!(kind = %Kind::Debug, ?config, "adapter configuration");
 }
 pub fn queueproc_start() {
     debug!(kind = %Kind::Debug, "start thread to process events until a shutdown event");
     debug!(kind = %Kind::Startup, "start thread to process events until a shutdown event");
 }
 pub fn queueproc_end() {

@@ -199,15 +199,15 @@ pub fn queueproc_queue_length(len: usize) {

 }
 pub fn queueproc_picked_event(id: &QueueId, event: &QueuedCiEvent) {
     info!(kind = %Kind::GotEvent, "picked event from queue: {id}: {event:#?}");
     info!(kind = %Kind::GotEvent, ?id, ?event, "picked event from queue");
 }
 pub fn queueproc_remove_event(id: &QueueId) {
     info!(kind = %Kind::Debug, "remove event from queue: {id}");
     info!(kind = %Kind::Debug, ?id, "remove event from queue");
 }
 pub fn queueproc_action_run(rid: &RepoId, oid: &Oid) {
     info!(kind = %Kind::Debug, "Action: run: {rid} {oid}");
     info!(kind = %Kind::Debug, ?rid, ?oid, "Action: run");
 }
 pub fn queueproc_action_shutdown() {

@@ -222,8 +222,8 @@ pub fn queueadd_control_socket_close() {

     info!(kind = %Kind::Debug, "no more events from node control socket");
 }
 pub fn queueadd_push_event(e: &CiEvent) {
     debug!(kind = %Kind::GotEvent, event = ?e, "insert broker event into queue: {e:?}");
 pub fn queueadd_push_event(event: &CiEvent) {
     debug!(kind = %Kind::GotEvent, ?event, "insert broker event into queue");
 }
 pub fn queueadd_end() {

@@ -235,7 +235,7 @@ pub fn pages_directory_unset() {

 }
 pub fn pages_interval(interval: Duration) {
     debug!(
     trace!(
         kind = %Kind::Debug,
         interval = interval.as_secs(),
         "interval for waiting between HTML page updates",

@@ -263,7 +263,7 @@ pub fn event_end() {

 }
 pub fn broker_db(filename: &Path) {
     info!(kind = %Kind::Debug, filename = %filename.display(), "broker database");
     info!(kind = %Kind::Startup, filename = %filename.display(), "broker database");
 }
 pub fn broker_start_run(trigger: &Request) {

@@ -273,7 +273,7 @@ pub fn broker_start_run(trigger: &Request) {

 pub fn broker_end_run(run: &Run) {
     info!(kind = %Kind::FinishRun, "Finish CI run");
     debug!(kind = %Kind::Debug, run = ?run, "finished CI run");
     debug!(kind = %Kind::Debug, ?run, "finished CI run");
 }
 pub fn adapter_no_first_response() {

@@ -305,7 +305,7 @@ pub fn adapter_did_not_exit() {

 }
 pub fn timeoutcmd_request_termination(result: Result<(), std::sync::mpsc::SendError<()>>) {
     trace!(kind = %Kind::Debug, "request termination of child process: {result:?}");
     trace!(kind = %Kind::Debug, ?result, "request termination of child process");
 }
 pub fn timeoutcmd_wait_word_from_nanny() {

@@ -380,58 +380,59 @@ pub fn timeoutcmd_nanny_ends() {

     trace!(kind = %Kind::Debug, "nanny: ends");
 }
 pub fn timeoutcmd_line_reader_try_byte(name: &'static str) {
     trace!(kind = %Kind::Debug, "line receiver {}: try to receive next byte", name);
 pub fn timeoutcmd_line_reader_try_byte(thread: &'static str) {
     trace!(kind = %Kind::Debug, %thread, "line receiver: try to receive next byte");
 }
 pub fn timeoutcmd_line_reader_tried_byte(
     name: &'static str,
     thread: &'static str,
     result: Result<u8, std::sync::mpsc::TryRecvError>,
 ) {
     trace!(kind = %Kind::Debug, ?result, "line receiver {}: tried to read line", name);
     trace!(kind = %Kind::Debug, ?result, %thread, "line receiver: tried to read line");
 }
 pub fn timeoutcmd_line_reader_got_line(name: &'static str, line: &str) {
     trace!(kind = %Kind::Debug, ?line, "line-receiver {}: received line", name);
 pub fn timeoutcmd_line_reader_got_line(thread: &'static str, line: &str) {
     trace!(kind = %Kind::Debug, ?line, %thread, "line-receiver: received line");
 }
 pub fn timeoutcmd_line_reader_got_disconnected(name: &'static str) {
 pub fn timeoutcmd_line_reader_got_disconnected(thread: &'static str) {
     trace!(
         kind = %Kind::Debug,
         "line-receiver {}: disconnected", name);
         kind = %Kind::Debug,
         %thread,
         "line-receiver: disconnected");
 }
 pub fn timeoutcmd_line_reader_did_child_die(name: &'static str) {
     trace!("line-receiver {}: has child terminated?", name);
 pub fn timeoutcmd_line_reader_did_child_die(thread: &'static str) {
     trace!(%thread, "line-receiver: has child terminated?");
 }
 pub fn timeoutcmd_line_reader_child_died(name: &'static str) {
 pub fn timeoutcmd_line_reader_child_died(thread: &'static str) {
     trace!(
         kind = %Kind::Debug,
         "line receiver {}: OK: child has terminated, not returning line",
         name
         %thread,
         "line receiver: OK: child has terminated, not returning line",
     );
 }
 pub fn timeoutcmd_line_reader_child_channel_disconnected(name: &'static str) {
 pub fn timeoutcmd_line_reader_child_channel_disconnected(thread: &'static str) {
     trace!(
         kind = %Kind::Debug,
         "line receiver {}: Disconnected: child has terminated, not returning line",
         name
         %thread,
         "line receiver: Disconnected: child has terminated, not returning line",
     );
 }
 pub fn timeoutcmd_nonblocking_try_byte(name: &'static str, count: usize) {
 pub fn timeoutcmd_nonblocking_try_byte(thread: &'static str, count: usize) {
     trace!(
         kind = %Kind::Debug,
         received_so_far = count,
         "read_to_end {}: try to receive next byte",
         name,
         %thread,
         "read_to_end: try to receive next byte",
     );
 }
 pub fn timeoutcmd_nonblocking_tried_byte(
     name: &'static str,
     thread: &'static str,
     result: &Result<usize, std::io::Error>,
     byte: &[u8],
 ) {

@@ -439,17 +440,17 @@ pub fn timeoutcmd_nonblocking_tried_byte(

         kind = %Kind::Debug,
         ?result,
         ?byte,
         "read_to_end {}: tried to receive byte",
         name,
         %thread,
         "read_to_end: tried to receive byte",
     );
 }
 pub fn timeoutcmd_nonblocking_eof(name: &'static str) {
     trace!(kind = %Kind::Debug, "read_to_end {}: got end of file", name,);
 pub fn timeoutcmd_nonblocking_eof(thread: &'static str) {
     trace!(kind = %Kind::Debug, %thread, "read_to_end: got end of file");
 }
 pub fn timeoutcmd_nonblocking_got_too_much(
     name: &'static str,
     thread: &'static str,
     result: Result<usize, std::io::Error>,
     byte: &[u8],
 ) {

@@ -457,17 +458,17 @@ pub fn timeoutcmd_nonblocking_got_too_much(

         kind = %Kind::Debug,
         ?result,
         ?byte,
         "read_to_end {}: received too much",
         name,
         %thread,
         "read_to_end: received too much",
     );
 }
 pub fn timeoutcmd_nonblocking_read_error(name: &'static str, err: &std::io::Error) {
     trace!(kind = %Kind::Debug, ?err, "read_to_end {}: read error", name);
 pub fn timeoutcmd_nonblocking_read_error(thread: &'static str, err: &std::io::Error) {
     trace!(kind = %Kind::Debug, ?err, %thread, "read_to_end: read error");
 }
 pub fn timeoutcmd_nonblocking_ends(name: &'static str) {
     trace!(kind = %Kind::Debug, "read_to_end {}: ends", name,);
 pub fn timeoutcmd_nonblocking_ends(thread: &'static str) {
     trace!(kind = %Kind::Debug, %thread, "read_to_end: ends");
 }
 pub fn debug(msg: &str) {

modified src/node_event_source.rs

@@ -46,7 +46,7 @@ impl NodeEventSource {

     /// A closed or broken connection to the node is not an error,
     /// it's treated as end of file.
     pub fn node_event(&mut self) -> Result<Option<Event>, NodeEventError> {
         logger::debug("node_event: try to get an event");
         logger::trace("node_event: try to get an event");
         if let Some(event) = self.events.next() {
             match event {
                 Ok(event) => {

@@ -73,7 +73,7 @@ impl NodeEventSource {

 impl fmt::Debug for NodeEventSource {
     fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
         write!(f, "NodeEventSource<path={}", self.profile_path.display())
         write!(f, "NodeEventSource<path={}>", self.profile_path.display())
     }
 }

modified src/queueadd.rs

@@ -65,7 +65,7 @@ impl QueueAdder {

         // event from the node.
         'event_loop: loop {
             let events = source.event();
             logger::debug2(format!("queueadd: events={events:?}"));
             logger::trace2(format!("queueadd: events={events:?}"));
             match events {
                 Err(e) => {
                     logger::queueadd_control_socket_close();