[testnet] Improve a few log messages: timeouts, validator addresses. (#4920) (#4924)

Backport of #4920.

## Motivation

Some of our logs are less useful than they could be:
* Many show a validator's public key instead of address.
* One prints the `Debug` format of a `RoundTimeout`, with the time as a
number of microseconds since the epoch.
* We mix structured logging and printing values inline in the log
message.

## Proposal

* Print the validator address.
* `impl Display for RoundTimeout`, and show the formatted date and time.
* Prefer structured logging.

## Test Plan

(Only minor logging changes.)

## Release Plan

- These changes should
    - be released in a new SDK, (not urgent)
    - be released in a validator hotfix. (not urgent)

## Links

- PR to main: #4920
- [reviewer
checklist](https://github.com/linera-io/linera-protocol/blob/main/CONTRIBUTING.md#reviewer-checklist)

Author: afck

linera-client/src/chain_listener.rs

@@ -512,14 +512,16 @@ impl<C: ClientContext + 'static> ChainListener<C> {
             }
             Err(error) => warn!(%error, "Failed to process inbox."),
             Ok((certs, None)) => info!(
-                "Done processing inbox of chain. {} blocks created on chain {chain_id}.",
-                certs.len()
+                %chain_id,
+                created_block_count = %certs.len(),
+                "done processing inbox",
             ),
             Ok((certs, Some(new_timeout))) => {
                 info!(
-                    "{} blocks created on chain {chain_id}. Will try processing the inbox later \
-                    based on the round timeout: {new_timeout:?}",
-                    certs.len(),
+                    %chain_id,
+                    created_block_count = %certs.len(),
+                    timeout = %new_timeout,
+                    "waiting for round timeout before continuing to process the inbox",
                 );
                 listening_client.timeout = new_timeout.timestamp;
             }

linera-core/src/client/mod.rs

@@ -300,9 +300,10 @@ impl<Env: Environment> Client<Env> {
                 .download_certificates_from(&remote_node, chain_id, target_next_block_height)
                 .await
             {
-                Err(err) => info!(
-                    "Failed to download certificates from validator {:?}: {err}",
-                    remote_node.public_key
+                Err(error) => info!(
+                    remote_node = remote_node.address(),
+                    %error,
+                    "failed to download certificates from validator",
                 ),
                 Ok(Some(new_info)) => info = new_info,
                 Ok(None) => {}
@@ -888,7 +889,7 @@ impl<Env: Environment> Client<Env> {
             offset += received_entries as u64;
             remote_log.extend(info.requested_received_log);
             trace!(
-                ?remote_node,
+                remote_node = remote_node.address(),
                 %received_entries,
                 "get_received_log_from_validator: received log batch",
             );
@@ -898,8 +899,8 @@ impl<Env: Environment> Client<Env> {
         }
 
         trace!(
-            ?remote_node,
-            num_entries = %remote_log.len(),
+            remote_node = remote_node.address(),
+            num_entries = remote_log.len(),
             "get_received_log_from_validator: returning downloaded log",
         );
 
@@ -1080,8 +1081,10 @@ impl<Env: Environment> Client<Env> {
         // If we are at the same height as the remote node, we also update our chain manager.
         if local_info.next_block_height != remote_info.next_block_height {
             debug!(
-                "Synced from validator {}; but remote height is {} and local height is {}",
-                remote_node.public_key, remote_info.next_block_height, local_info.next_block_height
+                remote_node = remote_node.address(),
+                remote_height = %remote_info.next_block_height,
+                local_height = %local_info.next_block_height,
+                "synced from validator, but remote height and local height are different",
             );
             return Ok(());
         };
@@ -1103,10 +1106,14 @@ impl<Env: Environment> Client<Env> {
                 }
                 LockingBlock::Regular(cert) => {
                     let hash = cert.hash();
-                    if let Err(err) = self.try_process_locking_block_from(remote_node, cert).await {
+                    if let Err(error) = self.try_process_locking_block_from(remote_node, cert).await
+                    {
                         debug!(
-                            "Skipping locked block {hash} from validator {} at height {}: {err}",
-                            remote_node.public_key, local_info.next_block_height,
+                            remote_node = remote_node.address(),
+                            %hash,
+                            height = %local_info.next_block_height,
+                            %error,
+                            "skipping locked block from validator",
                         );
                     }
                 }
@@ -1128,11 +1135,14 @@ impl<Env: Environment> Client<Env> {
                                 .await
                             {
                                 Ok(content) => content,
-                                Err(err) => {
+                                Err(error) => {
                                     info!(
-                                        "Skipping proposal from {owner} and validator {} at \
-                                        height {}; failed to download {blob_id}: {err}",
-                                        remote_node.public_key, local_info.next_block_height
+                                        remote_node = remote_node.address(),
+                                        height = %local_info.next_block_height,
+                                        proposer = %owner,
+                                        %blob_id,
+                                        %error,
+                                        "skipping proposal from validator; failed to download blob",
                                     );
                                     continue 'proposal_loop;
                                 }
@@ -1195,8 +1205,11 @@ impl<Env: Environment> Client<Env> {
                 }
 
                 debug!(
-                    "Skipping proposal from {owner} and validator {} at height {}: {err}",
-                    remote_node.public_key, local_info.next_block_height
+                    remote_node = remote_node.address(),
+                    proposer = %owner,
+                    height = %local_info.next_block_height,
+                    error = %err,
+                    "skipping proposal from validator",
                 );
             }
         }

linera-core/src/data_types.rs

@@ -2,7 +2,7 @@
 // Copyright (c) Zefchain Labs, Inc.
 // SPDX-License-Identifier: Apache-2.0
 
-use std::{collections::BTreeMap, ops::Not};
+use std::{collections::BTreeMap, fmt, ops::Not};
 
 use custom_debug_derive::Debug;
 use linera_base::{
@@ -354,12 +354,22 @@ pub struct RoundTimeout {
     pub next_block_height: BlockHeight,
 }
 
+impl fmt::Display for RoundTimeout {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        write!(
+            f,
+            "{} at height {} times out at {}",
+            self.current_round, self.next_block_height, self.timestamp
+        )
+    }
+}
+
 impl<T> ClientOutcome<T> {
     #[cfg(with_testing)]
     pub fn unwrap(self) -> T {
         match self {
             ClientOutcome::Committed(t) => t,
-            ClientOutcome::WaitForTimeout(timeout) => panic!("Unexpected timeout: {timeout:?}"),
+            ClientOutcome::WaitForTimeout(timeout) => panic!("unexpected timeout: {timeout}"),
         }
     }
 

linera-core/src/remote_node.rs

@@ -285,6 +285,11 @@ impl<N: ValidatorNode> RemoteNode<N> {
         }
         Ok(())
     }
+
+    /// Returns the validator's URL.
+    pub fn address(&self) -> String {
+        self.node.address()
+    }
 }
 
 impl<N: ValidatorNode> PartialEq for RemoteNode<N> {

linera-core/src/updater.rs

@@ -345,12 +345,12 @@ where
         height: BlockHeight,
         error: &NodeError,
     ) -> Result<(), ChainClientError> {
-        let validator = &self.remote_node.public_key;
+        let validator = &self.remote_node.address();
         match error {
             NodeError::WrongRound(validator_round) if *validator_round > round => {
                 tracing::debug!(
-                    ?validator, %chain_id, %validator_round, %round,
-                    "Validator is at a higher round; synchronizing.",
+                    validator, %chain_id, %validator_round, %round,
+                    "validator is at a higher round; synchronizing",
                 );
                 self.client
                     .synchronize_chain_state_from(&self.remote_node, chain_id)
@@ -361,20 +361,20 @@ where
                 found_block_height,
             } if expected_block_height > found_block_height => {
                 tracing::debug!(
-                    ?validator,
+                    validator,
                     %chain_id,
                     %expected_block_height,
                     %found_block_height,
-                    "Validator is at a higher height; synchronizing.",
+                    "validator is at a higher height; synchronizing",
                 );
                 self.client
                     .synchronize_chain_state_from(&self.remote_node, chain_id)
                     .await?;
             }
             NodeError::WrongRound(validator_round) if *validator_round < round => {
                 tracing::debug!(
-                    ?validator, %chain_id, %validator_round, %round,
-                    "Validator is at a lower round; sending chain info.",
+                    validator, %chain_id, %validator_round, %round,
+                    "validator is at a lower round; sending chain info",
                 );
                 self.send_chain_information(
                     chain_id,
@@ -438,8 +438,9 @@ where
                     // The proposal is for a different round, so we need to update the validator.
                     // TODO: this should probably be more specific as to which rounds are retried.
                     tracing::debug!(
-                        "Wrong round; sending chain {chain_id} to validator {}.",
-                        self.remote_node.public_key
+                        remote_node = self.remote_node.address(),
+                        %chain_id,
+                        "wrong round; sending chain to validator",
                     );
                     self.send_chain_information(
                         chain_id,
@@ -455,8 +456,9 @@ where
                     && found_block_height == proposal.content.block.height =>
                 {
                     tracing::debug!(
-                        "Wrong height; sending chain {chain_id} to validator {}.",
-                        self.remote_node.public_key
+                        remote_node = self.remote_node.address(),
+                        %chain_id,
+                        "wrong height; sending chain to validator",
                     );
                     // The proposal is for a later block height, so we need to update the validator.
                     self.send_chain_information(
@@ -476,8 +478,9 @@ where
                         .is_none_or(|h| *h < height) =>
                 {
                     tracing::debug!(
-                        "Missing cross-chain update; sending chain {origin} to validator {}.",
-                        self.remote_node.public_key
+                        remote_node = %self.remote_node.address(),
+                        chain_id = %origin,
+                        "Missing cross-chain update; sending chain to validator.",
                     );
                     sent_cross_chain_updates.insert(origin, height);
                     // Some received certificates may be missing for this validator
@@ -492,20 +495,18 @@ where
                 }
                 Err(NodeError::EventsNotFound(event_ids)) => {
                     let mut publisher_heights = BTreeMap::new();
-                    let new_chain_ids = event_ids
+                    let chain_ids = event_ids
                         .iter()
                         .map(|event_id| event_id.chain_id)
                         .filter(|chain_id| !publisher_chain_ids_sent.contains(chain_id))
                         .collect::<BTreeSet<_>>();
                     tracing::debug!(
-                        "Missing events; sending chains {new_chain_ids:?} to validator {}",
-                        self.remote_node.public_key
-                    );
-                    ensure!(
-                        !new_chain_ids.is_empty(),
-                        NodeError::EventsNotFound(event_ids)
+                        remote_node = self.remote_node.address(),
+                        ?chain_ids,
+                        "missing events; sending chains to validator",
                     );
-                    for chain_id in new_chain_ids {
+                    ensure!(!chain_ids.is_empty(), NodeError::EventsNotFound(event_ids));
+                    for chain_id in chain_ids {
                         let height = self
                             .client
                             .local_node
@@ -711,32 +712,32 @@ where
             .chain(manager.requested_signed_proposal)
         {
             if proposal.content.round == manager.current_round {
-                if let Err(err) = self.remote_node.handle_block_proposal(proposal).await {
-                    tracing::info!("Failed to send block proposal: {err}");
+                if let Err(error) = self.remote_node.handle_block_proposal(proposal).await {
+                    tracing::info!(%error, "failed to send block proposal");
                 } else {
                     return Ok(());
                 }
             }
         }
         if let Some(LockingBlock::Regular(validated)) = manager.requested_locking.map(|b| *b) {
             if validated.round == manager.current_round {
-                if let Err(err) = self
+                if let Err(error) = self
                     .remote_node
                     .handle_optimized_validated_certificate(
                         &validated,
                         CrossChainMessageDelivery::NonBlocking,
                     )
                     .await
                 {
-                    tracing::info!("Failed to send locking block: {err}");
+                    tracing::info!(%error, "failed to send locking block");
                 } else {
                     return Ok(());
                 }
             }
         }
         if let Some(cert) = manager.timeout {
             if cert.round >= remote_round {
-                tracing::debug!("Sending timeout for {}", cert.round);
+                tracing::debug!(round = %cert.round, "sending timeout");
                 self.remote_node.handle_timeout_certificate(*cert).await?;
             }
         }