Repository: dusk-network/rusk (language: rust)

Issue:
Reduce node logs
#### Summary
This is the data logged with a "standard" configuration

```
{"timestamp":"2024-12-07T09:36:29.091866Z","level":"INFO","event":"block accepted","height":397287,"iter":0,"hash":"0486ca867b62bb4b...dcf694dd038d5bbc","txs":0,"state_hash":"62f430dfe6b3d110...89935dc1aa57d3d7","fsv_bitset":3939320110216175,"ssv_bitset":56566594122515,"block_time":10,"generator":"rSGm1CeKgLT7SeUW","dur_ms":"15","label":"Attested(1)","target":"node::chain::acceptor"}
{"timestamp":"2024-12-07T09:36:29.092082Z","level":"INFO","event":"spawn consensus","id":162452,"round":397288,"timeout":"{Validation: 7s, Ratification: 7s, Proposal: 7s}","all":282,"eligible":257,"target":"node::chain::consensus"}
{"timestamp":"2024-12-07T09:36:29.092165Z","level":"INFO","event":"consensus canceled","round":397287,"target":"node::chain"}
{"timestamp":"2024-12-07T09:36:29.336954Z","level":"WARN","event":"msg discarded","topic":"Ratification","info":"ConsensusHeader { prev_block_hash: \"c6997a868380691d...aed1e860dbff1166\", round: 397287, iteration: 0 }","ray_id":"5094a17ecb21c136...9a07ffc0f3a5404c","target":"node::chain::acceptor"}
{"timestamp":"2024-12-07T09:36:29.337232Z","level":"WARN","event":"msg discarded","topic":"Validation","info":"ConsensusHeader { prev_block_hash: \"c6997a868380691d...aed1e860dbff1166\", round: 397287, iteration: 0 }","ray_id":"516f4756f48b3fb5...ae860419ae01595c","target":"node::chain::acceptor"}
{"timestamp":"2024-12-07T09:36:29.606090Z","level":"WARN","event":"msg discarded","topic":"Ratification","info":"ConsensusHeader { prev_block_hash: \"c6997a868380691d...aed1e860dbff1166\", round: 397287, iteration: 0 }","ray_id":"913fca928ac897c9...2162009a8089401d","target":"node::chain::acceptor"}
{"timestamp":"2024-12-07T09:36:29.622206Z","level":"WARN","event":"msg discarded","topic":"Ratification","info":"ConsensusHeader { prev_block_hash: \"c6997a868380691d...aed1e860dbff1166\", round: 397287, iteration: 0 }","ray_id":"e40c106274818399...cc3a3b43d42a8dc6","target":"node::chain::acceptor"}
{"timestamp":"2024-12-07T09:36:29.661839Z","level":"INFO","event":"Step completed","step":"Proposal","info":"ConsensusHeader { prev_block_hash: \"0486ca867b62bb4b...dcf694dd038d5bbc\", round: 397288, iteration: 0 }","target":"dusk_consensus::execution_ctx","spans":[{"iter":0,"name":"Proposal","pk":"y42cbkejKvFwwmAG","round":397288,"name":"main"}]}
{"timestamp":"2024-12-07T09:36:29.661906Z","level":"INFO","event":"next_slot","delay":"8s","target":"dusk_consensus::proposal::step","spans":[{"iter":0,"name":"Proposal","pk":"y42cbkejKvFwwmAG","round":397288,"name":"main"}]}
{"timestamp":"2024-12-07T09:36:29.844112Z","level":"WARN","event":"msg discarded","topic":"Validation","info":"ConsensusHeader { prev_block_hash: \"c6997a868380691d...aed1e860dbff1166\", round: 397287, iteration: 0 }","ray_id":"52d45ce2d2549d45...00650d565b546635","target":"node::chain::acceptor"}
{"timestamp":"2024-12-07T09:36:29.864249Z","level":"WARN","event":"msg discarded","topic":"Ratification","info":"ConsensusHeader { prev_block_hash: \"c6997a868380691d...aed1e860dbff1166\", round: 397287, iteration: 0 }","ray_id":"475399f89e5ef766...11070e7ca0aa192a","target":"node::chain::acceptor"}
{"timestamp":"2024-12-07T09:36:30.082281Z","level":"WARN","event":"msg discarded","topic":"Validation","info":"ConsensusHeader { prev_block_hash: \"c6997a868380691d...aed1e860dbff1166\", round: 397287, iteration: 0 }","ray_id":"824984f7d0399ce1...31ed5a95b090e2a3","target":"node::chain::acceptor"}
{"timestamp":"2024-12-07T09:36:30.082736Z","level":"WARN","event":"msg discarded","topic":"Validation","info":"ConsensusHeader { prev_block_hash: \"c6997a868380691d...aed1e860dbff1166\", round: 397287, iteration: 0 }","ray_id":"eb98aa0d7372ef64...64f6f71961465e79","target":"node::chain::acceptor"}
{"timestamp":"2024-12-07T09:36:30.803192Z","level":"WARN","event":"msg discarded","topic":"Validation","info":"ConsensusHeader { prev_block_hash: \"c6997a868380691d...aed1e860dbff1166\", round: 397287, iteration: 0 }","ray_id":"fd997bc4c4815469...dead9267daaa6841","target":"node::chain::acceptor"}
{"timestamp":"2024-12-07T09:36:30.808207Z","level":"WARN","event":"msg discarded","topic":"Ratification","info":"ConsensusHeader { prev_block_hash: \"c6997a868380691d...aed1e860dbff1166\", round: 397287, iteration: 0 }","ray_id":"ababdca100c66c98...9897fd15bca089b3","target":"node::chain::acceptor"}
{"timestamp":"2024-12-07T09:36:30.924375Z","level":"WARN","event":"msg discarded","topic":"Ratification","info":"ConsensusHeader { prev_block_hash: \"c6997a868380691d...aed1e860dbff1166\", round: 397287, iteration: 0 }","ray_id":"9284db6876a87d04...a8c64e0914a60f11","target":"node::chain::acceptor"}
{"timestamp":"2024-12-07T09:36:30.924899Z","level":"WARN","event":"msg discarded","topic":"Validation","info":"ConsensusHeader { prev_block_hash: \"c6997a868380691d...aed1e860dbff1166\", round: 397287, iteration: 0 }","ray_id":"500a60ea968e359d...00ff62bc9c3792f2","target":"node::chain::acceptor"}
{"timestamp":"2024-12-07T09:36:30.925310Z","level":"WARN","event":"msg discarded","topic":"Ratification","info":"ConsensusHeader { prev_block_hash: \"c6997a868380691d...aed1e860dbff1166\", round: 397287, iteration: 0 }","ray_id":"f6d94bf28afbafea...49e9d99894b3e51f","target":"node::chain::acceptor"}
{"timestamp":"2024-12-07T09:36:31.123727Z","level":"WARN","event":"msg discarded","topic":"Ratification","info":"ConsensusHeader { prev_block_hash: \"c6997a868380691d...aed1e860dbff1166\", round: 397287, iteration: 0 }","ray_id":"6761cb0ed536a84e...1d4864c9ea38c546","target":"node::chain::acceptor"}
{"timestamp":"2024-12-07T09:36:31.416311Z","level":"WARN","event":"msg discarded","topic":"Ratification","info":"ConsensusHeader { prev_block_hash: \"c6997a868380691d...aed1e860dbff1166\", round: 397287, iteration: 0 }","ray_id":"692eb5cbc7095e36...5caac868c75e6d91","target":"node::chain::acceptor"}
{"timestamp":"2024-12-07T09:36:31.417034Z","level":"WARN","event":"msg discarded","topic":"Ratification","info":"ConsensusHeader { prev_block_hash: \"c6997a868380691d...aed1e860dbff1166\", round: 397287, iteration: 0 }","ray_id":"9ea957bfbaa86ddd...84f1a1b651a6a32f","target":"node::chain::acceptor"}
{"timestamp":"2024-12-07T09:36:31.417518Z","level":"WARN","event":"msg discarded","topic":"Ratification","info":"ConsensusHeader { prev_block_hash: \"c6997a868380691d...aed1e860dbff1166\", round: 397287, iteration: 0 }","ray_id":"2bdf68878d0d06c8...f5c6a35f0ff13aed","target":"node::chain::acceptor"}
{"timestamp":"2024-12-07T09:36:31.523560Z","level":"WARN","event":"msg discarded","topic":"Ratification","info":"ConsensusHeader { prev_block_hash: \"c6997a868380691d...aed1e860dbff1166\", round: 397287, iteration: 0 }","ray_id":"ce0d775d76d1c6a6...85bda132eb503fa1","target":"node::chain::acceptor"}
{"timestamp":"2024-12-07T09:36:31.524405Z","level":"WARN","event":"msg discarded","topic":"Validation","info":"ConsensusHeader { prev_block_hash: \"c6997a868380691d...aed1e860dbff1166\", round: 397287, iteration: 0 }","ray_id":"e92c241dd101910e...839a3e611bcddaf9","target":"node::chain::acceptor"}
{"timestamp":"2024-12-07T09:36:32.026841Z","level":"WARN","event":"msg discarded","topic":"Validation","info":"ConsensusHeader { prev_block_hash: \"c6997a868380691d...aed1e860dbff1166\", round: 397287, iteration: 0 }","ray_id":"d51ad07518873476...48f9d2f485044ddb","target":"node::chain::acceptor"}
{"timestamp":"2024-12-07T09:36:33.288709Z","level":"WARN","event":"msg discarded","topic":"Ratification","info":"ConsensusHeader { prev_block_hash: \"c6997a868380691d...aed1e860dbff1166\", round: 397287, iteration: 0 }","ray_id":"be6b2b838151e87a...185fc0a7c5f9016a","target":"node::chain::acceptor"}
{"timestamp":"2024-12-07T09:36:35.898733Z","level":"WARN","event":"msg discarded","topic":"Ratification","info":"ConsensusHeader { prev_block_hash: \"c6997a868380691d...aed1e860dbff1166\", round: 397287, iteration: 0 }","ray_id":"e8573c165e04eaa6...52256a66e69c3fbf","target":"node::chain::acceptor"}
{"timestamp":"2024-12-07T09:36:37.974683Z","level":"INFO","event":"quorum reached","vote":"Vote: Valid(af8ccbdef824ae11...6244f0ed36da00b8)","iter":0,"step":"Validation","total":43,"target":43,"bitset":342593699032318,"step":1,"signature":"b9971978b9210e3a...0b895ef4fe009963","target":"dusk_consensus::aggregator","spans":[{"iter":0,"name":"Validation","pk":"y42cbkejKvFwwmAG","round":397288,"name":"main"}]}
{"timestamp":"2024-12-07T09:36:37.974751Z","level":"INFO","event":"quorum reached","vote":"Vote: Valid(af8ccbdef824ae11...6244f0ed36da00b8)","target":"dusk_consensus::validation::handler","spans":[{"iter":0,"name":"Validation","pk":"y42cbkejKvFwwmAG","round":397288,"name":"main"}]}
{"timestamp":"2024-12-07T09:36:37.974762Z","level":"INFO","event":"Step completed","step":"Validation","info":"ConsensusHeader { prev_block_hash: \"0486ca867b62bb4b...dcf694dd038d5bbc\", round: 397288, iteration: 0 }","target":"dusk_consensus::execution_ctx","spans":[{"iter":0,"name":"Validation","pk":"y42cbkejKvFwwmAG","round":397288,"name":"main"}]}
{"timestamp":"2024-12-07T09:36:39.391946Z","level":"INFO","event":"New block","src":"Quorum msg","height":397288,"iter":0,"hash":"af8ccbdef824ae11...6244f0ed36da00b8","target":"node::chain::fsm"}
{"timestamp":"2024-12-07T09:36:39.439804Z","level":"INFO","message":"Received accept request","target":"rusk::node::vm"}
{"timestamp":"2024-12-07T09:36:39.451738Z","level":"INFO","event":"block confirmed","src":"rolling_finality","current_height":397288,"height":397287,"confirmed_after":1,"hash":"0486ca867b62bb4b...dcf694dd038d5bbc","label":"Attested(1)","target":"node::chain::acceptor"}
{"timestamp":"2024-12-07T09:36:39.451808Z","level":"INFO","event":"block finalized","src":"rolling_finality","current_height":397288,"height":397287,"finalized_after":1,"hash":"0486ca867b62bb4b...dcf694dd038d5bbc","state_root":"62f430dfe6b3d110...89935dc1aa57d3d7","target":"node::chain::acceptor"}
{"timestamp":"2024-12-07T09:36:39.451900Z","level":"INFO","message":"Received finalize request","target":"rusk::node::vm"}
{"timestamp":"2024-12-07T09:36:39.457040Z","level":"INFO","event":"block accepted","height":397288,"iter":0,"hash":"af8ccbdef824ae11...6244f0ed36da00b8","txs":0,"state_hash":"5ff39cc775234f66...6c772f856d2471be","fsv_bitset":342906162089214,"ssv_bitset":786645673959343,"block_time":10,"generator":"stEepsCQ13uvpoDy","dur_ms":"17","label":"Attested(1)","target":"node::chain::acceptor"}

```


#### Possible solution design or implementation
- "WARN msg discarded" should not be a WARN, since that the msg is related to a past round message
- "quorum reached" is duplicated
- "Spawn consensus" and "Consensus canceled" are not so useful (consider moving them to debug"
- "Step completed" is misleading, since there is a "next slot" after it (consider moving the "Step completed" outside the event_loop, more precisely after "await_phase!" macro)

With the following changed, the logs for a single empty block are the following (still too much btw)

```
{"timestamp":"2024-12-07T09:36:29.091866Z","level":"INFO","event":"block accepted","height":397287,"iter":0,"hash":"0486ca867b62bb4b...dcf694dd038d5bbc","txs":0,"state_hash":"62f430dfe6b3d110...89935dc1aa57d3d7","fsv_bitset":3939320110216175,"ssv_bitset":56566594122515,"block_time":10,"generator":"rSGm1CeKgLT7SeUW","dur_ms":"15","label":"Attested(1)","target":"node::chain::acceptor"}
{"timestamp":"2024-12-07T09:36:29.092082Z","level":"INFO","event":"spawn consensus","id":162452,"round":397288,"timeout":"{Validation: 7s, Ratification: 7s, Proposal: 7s}","all":282,"eligible":257,"target":"node::chain::consensus"}
{"timestamp":"2024-12-07T09:36:29.661839Z","level":"INFO","event":"Step completed","step":"Proposal","info":"ConsensusHeader { prev_block_hash: \"0486ca867b62bb4b...dcf694dd038d5bbc\", round: 397288, iteration: 0 }","target":"dusk_consensus::execution_ctx","spans":[{"iter":0,"name":"Proposal","pk":"y42cbkejKvFwwmAG","round":397288,"name":"main"}]}
{"timestamp":"2024-12-07T09:36:37.974683Z","level":"INFO","event":"quorum reached","vote":"Vote: Valid(af8ccbdef824ae11...6244f0ed36da00b8)","iter":0,"step":"Validation","total":43,"target":43,"bitset":342593699032318,"step":1,"signature":"b9971978b9210e3a...0b895ef4fe009963","target":"dusk_consensus::aggregator","spans":[{"iter":0,"name":"Validation","pk":"y42cbkejKvFwwmAG","round":397288,"name":"main"}]}
{"timestamp":"2024-12-07T09:36:37.974762Z","level":"INFO","event":"Step completed","step":"Validation","info":"ConsensusHeader { prev_block_hash: \"0486ca867b62bb4b...dcf694dd038d5bbc\", round: 397288, iteration: 0 }","target":"dusk_consensus::execution_ctx","spans":[{"iter":0,"name":"Validation","pk":"y42cbkejKvFwwmAG","round":397288,"name":"main"}]}
{"timestamp":"2024-12-07T09:36:39.391946Z","level":"INFO","event":"New block","src":"Quorum msg","height":397288,"iter":0,"hash":"af8ccbdef824ae11...6244f0ed36da00b8","target":"node::chain::fsm"}
{"timestamp":"2024-12-07T09:36:37.974762Z","level":"INFO","event":"Step completed","step":"Ratification","info":"ConsensusHeader { prev_block_hash: \"0486ca867b62bb4b...dcf694dd038d5bbc\", round: 397288, iteration: 0 }","target":"dusk_consensus::execution_ctx","spans":[{"iter":0,"name":"Ratification","pk":"y42cbkejKvFwwmAG","round":397288,"name":"main"}]}
{"timestamp":"2024-12-07T09:36:39.439804Z","level":"INFO","message":"Received accept request","target":"rusk::node::vm"}
{"timestamp":"2024-12-07T09:36:39.451738Z","level":"INFO","event":"block confirmed","src":"rolling_finality","current_height":397288,"height":397287,"confirmed_after":1,"hash":"0486ca867b62bb4b...dcf694dd038d5bbc","label":"Attested(1)","target":"node::chain::acceptor"}
{"timestamp":"2024-12-07T09:36:39.451808Z","level":"INFO","event":"block finalized","src":"rolling_finality","current_height":397288,"height":397287,"finalized_after":1,"hash":"0486ca867b62bb4b...dcf694dd038d5bbc","state_root":"62f430dfe6b3d110...89935dc1aa57d3d7","target":"node::chain::acceptor"}
{"timestamp":"2024-12-07T09:36:39.451900Z","level":"INFO","message":"Received finalize request","target":"rusk::node::vm"}
{"timestamp":"2024-12-07T09:36:39.457040Z","level":"INFO","event":"block accepted","height":397288,"iter":0,"hash":"af8ccbdef824ae11...6244f0ed36da00b8","txs":0,"state_hash":"5ff39cc775234f66...6c772f856d2471be","fsv_bitset":342906162089214,"ssv_bitset":786645673959343,"block_time":10,"generator":"stEepsCQ13uvpoDy","dur_ms":"17","label":"Attested(1)","target":"node::chain::acceptor"}
```



Discussion / hints:

Fix patch:
diff --git a/consensus/src/proposal/step.rs b/consensus/src/proposal/step.rs
index 91d2a93720..380dbaef4a 100644
--- a/consensus/src/proposal/step.rs
+++ b/consensus/src/proposal/step.rs
@@ -12,7 +12,7 @@ use node_data::get_current_timestamp;
 use node_data::ledger::IterationsInfo;
 use node_data::message::Message;
 use tokio::sync::Mutex;
-use tracing::{debug, error, info};
+use tracing::{debug, error};
 
 use crate::commons::Database;
 use crate::config;
@@ -137,7 +137,7 @@ impl<T: Operations + 'static, D: Database> ProposalStep<T, D> {
     /// Waits until the next slot is reached
     async fn wait_until_next_slot(tip_timestamp: u64) {
         if let Some(delay) = Self::next_slot_in(tip_timestamp) {
-            info!(event = "next_slot", ?delay);
+            debug!(event = "Wait next block slot for validation", ?delay);
             tokio::time::sleep(delay).await;
         }
     }
diff --git a/consensus/src/validation/handler.rs b/consensus/src/validation/handler.rs
index 600800ecb6..e3fbeb407a 100644
--- a/consensus/src/validation/handler.rs
+++ b/consensus/src/validation/handler.rs
@@ -205,7 +205,6 @@ impl<D: Database> MsgHandler for ValidationHandler<D> {
                     return Err(ConsensusError::InvalidVote(vote));
                 }
             };
-            info!(event = "quorum reached", ?vote);
 
             let vrmsg = self
                 .build_validation_result(sv, vote, quorum_type, &p.header())
diff --git a/node/src/chain.rs b/node/src/chain.rs
index dfe4e1119b..f092ccf2d7 100644
--- a/node/src/chain.rs
+++ b/node/src/chain.rs
@@ -130,7 +130,7 @@ impl<N: Network, DB: database::DB, VM: vm::VMExecution>
                 recv = result_chan.recv() => {
                     match recv? {
                         Err(ConsensusError::Canceled(round)) => {
-                            info!(event = "consensus canceled", round);
+                            debug!(event = "consensus canceled", round);
                         }
                         Err(err) => {
                             // Internal consensus execution has terminated with an error
diff --git a/node/src/chain/acceptor.rs b/node/src/chain/acceptor.rs
index 79b6fd6847..3585b66feb 100644
--- a/node/src/chain/acceptor.rs
+++ b/node/src/chain/acceptor.rs
@@ -355,20 +355,36 @@ impl<DB: database::DB, VM: vm::VMExecution, N: Network> Acceptor<N, DB, VM> {
             | Payload::Validation(_)
             | Payload::Ratification(_)
             | Payload::ValidationQuorum(_) => {
-                // Process consensus msg only if they are for the current round
-                // or at most 10 rounds in the future
                 let msg_round = msg.header.round;
-                if msg_round > tip_height
-                    && msg_round <= (tip_height + MAX_ROUND_DISTANCE)
-                {
-                    consensus_task.main_inbound.try_send(msg);
-                } else {
-                    warn!(
-                      event = "msg discarded",
-                      topic = ?msg.topic(),
-                      info = ?msg.header,
-                      ray_id = msg.ray_id()
-                    );
+
+                match msg_round {
+                    // Discard messages from the past
+                    r if r <= tip_height => {
+                        debug!(
+                          event = "Consensus msg discarded",
+                          reason = "past round",
+                          topic = ?msg.topic(),
+                          info = ?msg.header,
+                          ray_id = msg.ray_id()
+                        );
+                    }
+
+                    // Discard messages too far from the future
+                    r if r > tip_height + MAX_ROUND_DISTANCE => {
+                        warn!(
+                          event = "Consensus msg discarded",
+                          reason = "too far in the future",
+                          topic = ?msg.topic(),
+                          info = ?msg.header,
+                          ray_id = msg.ray_id()
+                        );
+                    }
+
+                    _ => {
+                        // Process consensus msg only if they are for the
+                        // current round or at most 10 rounds in the future
+                        consensus_task.main_inbound.try_send(msg);
+                    }
                 }
             }
 
diff --git a/node/src/chain/consensus.rs b/node/src/chain/consensus.rs
index e4e6eee572..b3212f3341 100644
--- a/node/src/chain/consensus.rs
+++ b/node/src/chain/consensus.rs
@@ -130,7 +130,7 @@ impl Task {
 
         let (all_num, eligible_num) = current.get_provisioners_info(ru.round);
 
-        info!(
+        debug!(
             event = "spawn consensus",
             id = self.task_id,
             round = ru.round,


Test patch: