feat: make INFO log messages for a typical CI run easier to follow — radicle-ci-broker

rad:zwTxygwuz5LDGBq255RA2CbNGrz8

Radicle CI broker

feat: make INFO log messages for a typical CI run easier to follow

Merged liw opened 5 months ago

Drop several messages to DEBUG level, since they’re really meant for CI broker developer debugging. At INFO level they obscure the log story.

Changed run id to be logged as a string, not debug.

Added broker run ID to run start and end messages, for clarity.:q

2 files changed +26 -29 24c95c85 → c60c427e

modified src/broker.rs

@@ -83,7 +83,7 @@ impl Broker {

         run_notification: &NotificationSender,
         child_info: Sender<ChildInfo>,
     ) -> Result<Run, BrokerError> {
         logger::broker_start_run(trigger);
         logger::broker_start_run(trigger, &broker_run_id);
         let (common, whence, oid) = match &trigger {
             Request::Trigger {
                 common,

@@ -154,7 +154,7 @@ impl Broker {

             logger::error("failed to run adapter or it failed to run CI", &e);
         }
         logger::broker_end_run(&run);
         logger::broker_end_run(&run, run.broker_run_id());
         self.db.update_run(&run)?;

modified src/logger.rs

@@ -124,7 +124,6 @@ enum Id {

     BrokerDatabase,
     BrokerRunEnd,
     BrokerRunStart,
     BrokerTriggerMessage,
     CiEventSourceCreated,
     CiEventSourceDisconnected,

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

 }
 pub fn ci_event_source_disconnected() {
     info!(
     debug!(
         msg_id = ?Id::CiEventSourceDisconnected,
         kind = %Kind::Shutdown,
         "CI event source received disconnection"

@@ -383,7 +382,7 @@ pub fn ci_event_source_disconnected() {

 }
 pub fn ci_event_source_end() {
     info!(
     debug!(
         msg_id = ?Id::CiEventSourceEnd,
         kind = %Kind::Debug,
         "CI event source was notified end of events"

@@ -426,7 +425,7 @@ pub fn queueproc_end(result: &Result<(), QueueError>) {

             "thread to process events ends"
         );
     } else {
         info!(
         debug!(
             msg_id = ?Id::QueueProcEnd,
             kind = %Kind::Debug,
             ?result,

@@ -452,7 +451,7 @@ pub fn queueproc_end_result_receiver() {

 }
 pub fn queueproc_channel_disconnect() {
     info!(
     debug!(
         msg_id = ?Id::QueueProcDisconnected,
         kind = %Kind::Debug,
         "event notification channel disconnected"

@@ -501,17 +500,18 @@ pub fn queueproc_predicate_decision(event: &CiEvent, filter: &EventFilter, allow

 }
 pub fn queueproc_picked_event(id: &QueueId, event: &QueuedCiEvent) {
     let id = id.to_string();
     info!(
         msg_id = ?Id::QueueProcPickedEvent,
         kind = %Kind::GotEvent,
         ?id,
         %id,
         ?event,
         "picked an event from event queue"
     );
 }
 pub fn queueproc_processing_event(event: &CiEvent, adapter: &Adapter) {
     info!(
     debug!(
         msg_id = ?Id::QueueProcProcessingEvent,
         kind = %Kind::GotEvent,
         ?event,

@@ -547,7 +547,7 @@ pub fn queueproc_thread_join() {

 }
 pub fn queueproc_trigger(result: &Result<Request, QueueError>) {
     info!(
     debug!(
         msg_id = ?Id::QueueProcTrigger,
         kind = %Kind::GotEvent,
         ?result,

@@ -565,7 +565,7 @@ pub fn queueproc_processed_event(result: &Result<MaybeShutdown, QueueError>) {

 }
 pub fn queueproc_remove_event(event: &QueuedCiEvent) {
     info!(
     debug!(
         msg_id = ?Id::QueueProcRemoveEvent,
         kind = %Kind::Debug,
         ?event,

@@ -574,7 +574,7 @@ pub fn queueproc_remove_event(event: &QueuedCiEvent) {

 }
 pub fn queueproc_finished_run(repoid: &Option<RepoId>) {
     info!(
     debug!(
         msg_id = ?Id::QueueProcFinishedRun,
         kind = %Kind::FinishRun,
         ?repoid,

@@ -583,7 +583,7 @@ pub fn queueproc_finished_run(repoid: &Option<RepoId>) {

 }
 pub fn queueproc_action_run(event: &CiEvent) {
     info!(
     debug!(
         msg_id = ?Id::QueueProcActionRun,
         kind = %Kind::Debug,
         ?event,

@@ -617,7 +617,7 @@ pub fn queueadd_start() {

 }
 pub fn queueadd_control_socket_close(error: &CiEventSourceError) {
     info!(
     debug!(
         msg_id = ?Id::QueueAddEndEvents,
         kind = %Kind::Debug,
         ?error,

@@ -644,7 +644,7 @@ pub fn queueadd_end(result: &Result<(), AdderError>) {

             "thread to process events ends"
         );
     } else {
         info!(
         debug!(
             msg_id = ?Id::QueueAddEnd,
             kind = %Kind::Debug,
             ?result,

@@ -680,7 +680,7 @@ pub fn pages_interval(interval: Duration) {

 }
 pub fn pages_disconnected() {
     info!(
     debug!(
         msg_id = ?Id::PagesDisconnected,
         kind = %Kind::Debug,
         "page updater: run notification channel disconnected"

@@ -704,7 +704,7 @@ pub fn pages_end(result: &Result<(), PageError>) {

             "end page updater thread"
         );
     } else {
         info!(
         debug!(
             msg_id = ?Id::PagesEnd,
             kind = %Kind::Debug,
             ?result,

@@ -714,7 +714,7 @@ pub fn pages_end(result: &Result<(), PageError>) {

 }
 pub fn event_disconnected() {
     info!(
     debug!(
         msg_id = ?Id::NodeEventSourceDisconnected,
         kind = %Kind::Debug,
         "connection to node control socket broke"

@@ -722,7 +722,7 @@ pub fn event_disconnected() {

 }
 pub fn event_end() {
     info!(
     debug!(
         msg_id = ?Id::NodeEventSourceEnd,
         kind = %Kind::Debug,
         "no more node events from control socket: iterator ended"

@@ -738,25 +738,22 @@ pub fn broker_db(filename: &Path) {

     );
 }
 pub fn broker_start_run(trigger: &Request) {
 pub fn broker_start_run(trigger: &Request, broker_run_id: &RunId) {
     info!(
         msg_id = ?Id::BrokerRunStart,
         kind = %Kind::StartRun,
         ?trigger,
         %broker_run_id,
         "start CI run"
     );
     debug!(
         msg_id = ?Id::BrokerTriggerMessage,
         kind = %Kind::Debug,
         event = ?trigger,
         "trigger message"
     );
 }
 pub fn broker_end_run(run: &Run) {
 pub fn broker_end_run(run: &Run, broker_run_id: &RunId) {
     info!(
         msg_id = ?Id::BrokerRunEnd,
         kind = %Kind::FinishRun,
         ?run,
         %broker_run_id,
         "Finish CI run"
     );
 }

@@ -937,7 +934,7 @@ pub fn error(msg: &str, e: &impl std::error::Error) {

 }
 pub fn worker_start(name: &str) {
     info!(
     debug!(
         msg_id = ?Id::WorkerStart,
         name,
         "worker starts"

@@ -945,7 +942,7 @@ pub fn worker_start(name: &str) {

 }
 pub fn worker_end(name: &str, result: &Result<(), impl std::error::Error>) {
     info!(
     debug!(
         msg_id = ?Id::WorkerEnd,
         name,
         ?result,