From 82e12ebe52bf355a3ac7376678efc167b5907f3b Mon Sep 17 00:00:00 2001
From: Daiderd Jordan <daiderd@gmail.com>
Date: Fri, 1 May 2020 20:13:50 +0200
Subject: [PATCH] add some basic structured logging to the builder

---
 ofborg/src/config.rs      |  6 +-----
 ofborg/src/easylapin.rs   | 13 ++++++++-----
 ofborg/src/tasks/build.rs | 11 +++++++++--
 3 files changed, 18 insertions(+), 12 deletions(-)

diff --git a/ofborg/src/config.rs b/ofborg/src/config.rs
index 5b4ab3e..1f3fc81 100644
--- a/ofborg/src/config.rs
+++ b/ofborg/src/config.rs
@@ -126,11 +126,7 @@ impl Config {
 
     pub fn nix(&self) -> Nix {
         if self.nix.build_timeout_seconds < 1200 {
-            error!(
-                "Note: {} is way too low for build_timeout_seconds!",
-                self.nix.build_timeout_seconds
-            );
-            error!("Please set build_timeout_seconds to at least 1200");
+            error!(?self.nix.build_timeout_seconds, "Please set build_timeout_seconds to at least 1200");
             panic!();
         }
 
diff --git a/ofborg/src/easylapin.rs b/ofborg/src/easylapin.rs
index f060519..0ef08a0 100644
--- a/ofborg/src/easylapin.rs
+++ b/ofborg/src/easylapin.rs
@@ -96,6 +96,7 @@ impl<W: SimpleWorker + 'static> ConsumerExt<W> for CloseOnDrop<Channel> {
         ))?;
         Ok(Box::pin(async move {
             while let Some(Ok(deliver)) = consumer.next().await {
+                debug!(?deliver.delivery_tag, "consumed delivery");
                 let content_type = deliver.properties.content_type();
                 let job = worker
                     .msg_to_job(
@@ -110,6 +111,7 @@ impl<W: SimpleWorker + 'static> ConsumerExt<W> for CloseOnDrop<Channel> {
                         .await
                         .expect("action deliver failure");
                 }
+                debug!(?deliver.delivery_tag, "done");
             }
         }))
     }
@@ -147,7 +149,7 @@ impl<W: SimpleNotifyWorker + 'static> ConsumerExt<W> for NotifyChannel {
         let mut chan = self.0;
         Ok(Box::pin(async move {
             while let Some(Ok(deliver)) = consumer.next().await {
-                debug!("delivery {}", deliver.delivery_tag);
+                debug!(?deliver.delivery_tag, "consumed delivery");
                 let mut receiver = ChannelNotificationReceiver {
                     channel: &mut chan,
                     deliver: &deliver,
@@ -163,6 +165,7 @@ impl<W: SimpleNotifyWorker + 'static> ConsumerExt<W> for NotifyChannel {
                     .expect("worker unexpected message consumed");
 
                 worker.consumer(&job, &mut receiver);
+                debug!(?deliver.delivery_tag, "done");
             }
         }))
     }
@@ -175,25 +178,25 @@ async fn action_deliver(
 ) -> Result<(), lapin::Error> {
     match action {
         Action::Ack => {
-            debug!("action ack");
+            debug!(?deliver.delivery_tag, "action ack");
             chan.basic_ack(deliver.delivery_tag, BasicAckOptions::default())
                 .await
         }
         Action::NackRequeue => {
-            debug!("action nack requeue");
+            debug!(?deliver.delivery_tag, "action nack requeue");
             let mut opts = BasicNackOptions::default();
             opts.requeue = true;
             chan.basic_nack(deliver.delivery_tag, opts).await
         }
         Action::NackDump => {
-            debug!("action nack dump");
+            debug!(?deliver.delivery_tag, "action nack dump");
             chan.basic_nack(deliver.delivery_tag, BasicNackOptions::default())
                 .await
         }
         Action::Publish(mut msg) => {
             let exch = msg.exchange.take().unwrap_or_else(|| "".to_owned());
             let key = msg.routing_key.take().unwrap_or_else(|| "".to_owned());
-            debug!("action publish {}", exch);
+            debug!(?exch, ?key, "action publish");
 
             let mut props = BasicProperties::default().with_delivery_mode(2); // persistent.
 
diff --git a/ofborg/src/tasks/build.rs b/ofborg/src/tasks/build.rs
index 4d3b5dc..4f0721c 100644
--- a/ofborg/src/tasks/build.rs
+++ b/ofborg/src/tasks/build.rs
@@ -8,8 +8,8 @@ use crate::worker;
 
 use std::collections::VecDeque;
 
+use tracing::{debug, debug_span, error, info};
 use uuid::Uuid;
-use tracing::{error, info};
 
 pub struct BuildWorker {
     cloner: checkout::CachedCloner,
@@ -276,14 +276,21 @@ impl notifyworker::SimpleNotifyWorker for BuildWorker {
         job: &buildjob::BuildJob,
         notifier: &mut dyn notifyworker::NotificationReceiver,
     ) {
+        let span = debug_span!("job", pr = ?job.pr.number);
+        let _enter = span.enter();
+
         let mut actions = self.actions(&job, notifier);
 
         if job.attrs.is_empty() {
+            debug!("No attrs to build");
             actions.nothing_to_do();
             return;
         }
 
-        info!("Working on {}", job.pr.number);
+        info!(
+            "Working on https://github.com/{}/pull/{}",
+            job.repo.full_name, job.pr.number
+        );
         let project = self
             .cloner
             .project(&job.repo.full_name, job.repo.clone_url.clone());