From 68d5a49ae41c368f88c6a2631ec9728359cf40dc Mon Sep 17 00:00:00 2001
From: Federico Franzoni <8609060+fed-franz@users.noreply.github.com>
Date: Fri, 20 Dec 2024 13:14:55 +0100
Subject: [PATCH] consensus: update INFO logs

---
 consensus/src/aggregator.rs       |  7 ++++---
 consensus/src/execution_ctx.rs    | 16 +++++-----------
 consensus/src/phase.rs            | 14 ++++++++++----
 consensus/src/proposal/handler.rs | 16 ++++++++++++++++
 4 files changed, 35 insertions(+), 18 deletions(-)

diff --git a/consensus/src/aggregator.rs b/consensus/src/aggregator.rs
index a2532cae9..f8e41490d 100644
--- a/consensus/src/aggregator.rs
+++ b/consensus/src/aggregator.rs
@@ -176,10 +176,11 @@ impl<V: StepVote> Aggregator<V> {
         let quorum_reached = total >= quorum_target;
         if quorum_reached {
             tracing::info!(
-                event = "quorum reached",
-                ?vote,
-                iter = v.header().iteration,
+                event = "Quorum reached",
                 step = ?V::STEP_NAME,
+                round = v.header().round,
+                iter = v.header().iteration,
+                ?vote,
                 total,
                 target = quorum_target,
                 bitset,
diff --git a/consensus/src/execution_ctx.rs b/consensus/src/execution_ctx.rs
index d880675f5..e9f3080ef 100644
--- a/consensus/src/execution_ctx.rs
+++ b/consensus/src/execution_ctx.rs
@@ -138,12 +138,11 @@ impl<'a, T: Operations + 'static, DB: Database> ExecutionCtx<'a, T, DB> {
         let step_timeout = self.iter_ctx.get_timeout(step);
         let timeout = step_timeout + additional_timeout.unwrap_or_default();
 
-        info!(
-            event = "Start Step",
+        debug!(
+            event = "Start step loop",
             ?step,
             round,
             iter,
-            ?timeout,
             ?step_timeout,
             ?additional_timeout
         );
@@ -167,13 +166,6 @@ impl<'a, T: Operations + 'static, DB: Database> ExecutionCtx<'a, T, DB> {
                                 .process_inbound_msg(phase.clone(), msg.clone())
                                 .await
                             {
-                                info!(
-                                    event = "Step completed",
-                                    round,
-                                    ?step,
-                                    info = ?msg.header
-                                );
-
                                 // In the normal case, we just return the result
                                 // to Consensus
                                 if !open_consensus_mode {
@@ -352,9 +344,11 @@ impl<'a, T: Operations + 'static, DB: Database> ExecutionCtx<'a, T, DB> {
                 // Timeout event. Phase could not reach its final goal.
                 // Increase timeout for next execution of this step and move on.
                 Err(_) => {
-                    info!(event = "Step timeout expired", round, iter, ?step);
+                    info!(event = "Step timeout expired", ?step, round, iter);
 
                     if self.is_last_step() {
+                        info!(event = "Step ended", ?step, round, iter);
+
                         // If the last step expires, we enter Open Consensus
                         // mode. In this mode, the last step (Ratification)
                         // keeps running indefinitely, until a block is
diff --git a/consensus/src/phase.rs b/consensus/src/phase.rs
index b351b41d5..18ac77445 100644
--- a/consensus/src/phase.rs
+++ b/consensus/src/phase.rs
@@ -6,7 +6,7 @@
 
 use node_data::message::Message;
 use node_data::StepName;
-use tracing::{debug, trace};
+use tracing::{info, trace};
 
 use crate::commons::Database;
 use crate::execution_ctx::ExecutionCtx;
@@ -54,10 +54,16 @@ impl<T: Operations + 'static, D: Database + 'static> Phase<T, D> {
     pub async fn run(&mut self, mut ctx: ExecutionCtx<'_, T, D>) -> Message {
         ctx.set_start_time();
 
-        let timeout = ctx.iter_ctx.get_timeout(ctx.step_name());
-        debug!(event = "execute_step", ?timeout);
+        let step = ctx.step_name();
+        let round = ctx.round_update.round;
+        let iter = ctx.iteration;
+        let timeout = ctx.iter_ctx.get_timeout(step);
 
         // Execute step
-        await_phase!(self, run(ctx))
+        info!(event = "Step started", ?step, round, iter, ?timeout);
+        let msg = await_phase!(self, run(ctx));
+        info!(event = "Step ended", ?step, round, iter);
+
+        msg
     }
 }
diff --git a/consensus/src/proposal/handler.rs b/consensus/src/proposal/handler.rs
index 248aeb2fc..5ccd950c2 100644
--- a/consensus/src/proposal/handler.rs
+++ b/consensus/src/proposal/handler.rs
@@ -67,6 +67,14 @@ impl<D: Database> MsgHandler for ProposalHandler<D> {
             .store_candidate_block(p.candidate.clone())
             .await;
 
+        info!(
+            event = "New Candidate",
+            hash = &to_str(&p.candidate.header().hash),
+            round = p.candidate.header().height,
+            iter = p.candidate.header().iteration,
+            prev_block = &to_str(&p.candidate.header().prev_block_hash)
+        );
+
         Ok(StepOutcome::Ready(msg))
     }
 
@@ -84,6 +92,14 @@ impl<D: Database> MsgHandler for ProposalHandler<D> {
             .store_candidate_block(p.candidate.clone())
             .await;
 
+        info!(
+            event = "New Candidate",
+            hash = &to_str(&p.candidate.header().hash),
+            round = p.candidate.header().height,
+            iter = p.candidate.header().iteration,
+            prev_block = &to_str(&p.candidate.header().prev_block_hash)
+        );
+
         Ok(StepOutcome::Ready(msg))
     }