From 171d8fcb2de834b6d46463979f8643756c599e86 Mon Sep 17 00:00:00 2001
From: ZanCorDX <126988525+ZanCorDX@users.noreply.github.com>
Date: Fri, 13 Dec 2024 14:29:28 -0300
Subject: [PATCH] Better logs. (#287)
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

slot timings

## 📝 Summary

- Timing info about "Received payload"
- Watchdog kill reason.

## 💡 Motivation and Context

Help problem identification on prod.

## ✅ I have completed the following steps:

* [X] Run `make lint`
* [X] Run `make test`
* [ ] Added tests (if applicable)
---
 crates/rbuilder/src/live_builder/mod.rs      | 10 ++++++++--
 crates/rbuilder/src/live_builder/watchdog.rs | 10 +++++++---
 2 files changed, 15 insertions(+), 5 deletions(-)

diff --git a/crates/rbuilder/src/live_builder/mod.rs b/crates/rbuilder/src/live_builder/mod.rs
index d4110fe8..5b7c78e2 100644
--- a/crates/rbuilder/src/live_builder/mod.rs
+++ b/crates/rbuilder/src/live_builder/mod.rs
@@ -181,7 +181,10 @@ where
         );
 
         let watchdog_sender = match self.watchdog_timeout {
-            Some(duration) => Some(spawn_watchdog_thread(duration)?),
+            Some(duration) => Some(spawn_watchdog_thread(
+                duration,
+                "block build started".to_string(),
+            )?),
             None => {
                 info!("Watchdog not enabled");
                 None
@@ -203,11 +206,14 @@ where
             }) {
                 continue;
             }
+            let current_time = OffsetDateTime::now_utc();
             // see if we can get parent header in a reasonable time
-            let time_to_slot = payload.timestamp() - OffsetDateTime::now_utc();
+            let time_to_slot = payload.timestamp() - current_time;
             debug!(
                 slot = payload.slot(),
                 block = payload.block(),
+                ?current_time,
+                payload_timestamp = ?payload.timestamp(),
                 ?time_to_slot,
                 "Received payload, time till slot timestamp",
             );
diff --git a/crates/rbuilder/src/live_builder/watchdog.rs b/crates/rbuilder/src/live_builder/watchdog.rs
index 1dd95d3f..3d91eb49 100644
--- a/crates/rbuilder/src/live_builder/watchdog.rs
+++ b/crates/rbuilder/src/live_builder/watchdog.rs
@@ -4,7 +4,8 @@ use tracing::{error, info};
 
 /// Spawns a thread that will kill the process if there is no events sent on the channel
 /// for the timeout time.
-pub fn spawn_watchdog_thread(timeout: Duration) -> io::Result<flume::Sender<()>> {
+/// context is a string to be logged to be able to distinguish different types of deaths.
+pub fn spawn_watchdog_thread(timeout: Duration, context: String) -> io::Result<flume::Sender<()>> {
     let (sender, receiver) = flume::unbounded();
     std::thread::Builder::new()
         .name(String::from("watchdog"))
@@ -13,7 +14,7 @@ pub fn spawn_watchdog_thread(timeout: Duration) -> io::Result<flume::Sender<()>>
                 match receiver.recv_timeout(timeout) {
                     Ok(()) => {}
                     Err(RecvTimeoutError::Timeout) => {
-                        error!("Watchdog timeout");
+                        error!(context, "Watchdog timeout");
                         std::process::exit(1);
                     }
                     Err(RecvTimeoutError::Disconnected) => {
@@ -21,7 +22,10 @@ pub fn spawn_watchdog_thread(timeout: Duration) -> io::Result<flume::Sender<()>>
                     }
                 }
             }
-            info!("Watchdog finished, will kill application in 12 seconds");
+            info!(
+                context,
+                "Watchdog finished, will kill application in 12 seconds"
+            );
 
             std::thread::sleep(Duration::from_secs(12));
             std::process::exit(1);