Improve agent logging

rust/agents/relayer/Cargo.toml

@@ -9,15 +9,15 @@ coingecko = { git = "https://github.com/hyperlane-xyz/coingecko-rs", tag = "2022
 config = "~0.13.3"
 serde = {version = "1.0", features = ["derive"]}
 serde_json = { version = "1.0", default-features = false }
-ethers = { git = "https://github.com/hyperlane-xyz/ethers-rs", tag = "2023-01-10-04" }
-ethers-contract = { git = "https://github.com/hyperlane-xyz/ethers-rs", tag = "2023-01-10-04", features=["legacy"] }
+ethers = { git = "https://github.com/hyperlane-xyz/ethers-rs", tag = "2023-02-10-01" }
+ethers-contract = { git = "https://github.com/hyperlane-xyz/ethers-rs", tag = "2023-02-10-01", features=["legacy"] }
 thiserror = "1.0"
 async-trait = { version = "0.1", default-features = false }
 futures-util = "0.3"
 eyre = "0.6"
 reqwest = { version = "0", features = ["json"]}
 strum = "0.24"
-tracing = "0.1"
+tracing = { version = "0.1", features = ["release_max_level_debug"] }
 tracing-futures = "0.2"
 tracing-subscriber = "0.3"
 

rust/agents/relayer/src/msg/gas_payment/policies/meets_estimated_cost.rs

@@ -7,6 +7,7 @@ use async_trait::async_trait;
 use coingecko::CoinGeckoClient;
 use eyre::{eyre, Result};
 use tokio::{sync::RwLock, time::timeout};
+use tracing::{debug, info};
 
 use hyperlane_core::{HyperlaneMessage, KnownHyperlaneDomain, TxCostEstimate, U256};
 
@@ -200,16 +201,25 @@ impl GasPaymentPolicy for GasPaymentPolicyMeetsEstimatedCost {
             .await?;
 
         let meets_requirement = *current_payment >= origin_token_tx_cost;
-        tracing::info!(
-            message_id=?message.id(),
-            message_nonce=?message.nonce,
-            tx_cost_estimate=?tx_cost_estimate,
-            destination_token_tx_cost=?destination_token_tx_cost,
-            origin_token_tx_cost=?origin_token_tx_cost,
-            current_payment=?current_payment,
-            meets_requirement=?meets_requirement,
-            "Evaluated whether message gas payment meets estimated cost",
-        );
+        if !meets_requirement {
+            info!(
+                %message,
+                ?tx_cost_estimate,
+                ?destination_token_tx_cost,
+                ?origin_token_tx_cost,
+                ?current_payment,
+                "Message gas payment does not meet estimated cost",
+            );
+        } else {
+            debug!(
+                %message,
+                ?tx_cost_estimate,
+                ?destination_token_tx_cost,
+                ?origin_token_tx_cost,
+                ?current_payment,
+                "Message gas payment meets estimated cost",
+            );
+        }
 
         Ok(meets_requirement)
     }

rust/agents/relayer/src/msg/gelato_submitter/sponsored_call_op.rs

@@ -9,7 +9,7 @@ use tokio::{
     sync::mpsc::UnboundedSender,
     time::{sleep, timeout},
 };
-use tracing::instrument;
+use tracing::{error, info, instrument, warn};
 
 use gelato::{
     sponsored_call::{SponsoredCallApiCall, SponsoredCallApiCallResult, SponsoredCallArgs},
@@ -66,27 +66,22 @@ impl SponsoredCallOp {
         Self(args)
     }
 
-    #[instrument(skip(self), fields(msg_id=format!("{:x}", self.message.message.id()), msg_nonce=self.message.message.nonce))]
+    #[instrument(skip(self), fields(message=?self.message.message))]
     pub async fn run(&mut self) {
         loop {
             match self.tick().await {
                 Ok(true) => {
                     // If the message was processed, send it over the channel and
                     // stop running.
-                    if let Err(err) = self.send_message_processed() {
-                        tracing::error!(
-                            err=?err,
+                    if let Err(error) = self.send_message_processed() {
+                        error!(
+                            ?error,
                             "Unable to send processed message, receiver is closed or dropped.",
                         );
                     }
                     return;
                 }
-                Err(err) => {
-                    tracing::warn!(
-                        err=?err,
-                        "Error occurred in sponsored_call_op tick",
-                    );
-                }
+                Err(error) => warn!(?error, "Error occurred in sponsored_call_op tick"),
                 _ => {}
             }
 
@@ -102,68 +97,67 @@ impl SponsoredCallOp {
         if let Ok(true) = self.message_delivered().await {
             return Ok(true);
         }
-        if let Some(metadata) = self
+        let Some(metadata) = self
             .metadata_builder
             .fetch_metadata(&self.message.message, self.mailbox.clone())
             .await?
-        {
-            // Estimate transaction costs for the process call. If there are issues, it's
-            // likely that gas estimation has failed because the message is
-            // reverting. This is defined behavior, so we just log the error and
-            // move onto the next tick.
-            let tx_cost_estimate = match self
-                .mailbox
-                .process_estimate_costs(&self.message.message, &metadata)
-                .await
-            {
-                Ok(tx_cost_estimate) => tx_cost_estimate,
-                Err(err) => {
-                    tracing::info!(error=?err, "Error estimating process costs");
-                    return Ok(false);
-                }
-            };
-
-            // If the gas payment requirement hasn't been met, sleep briefly and wait for
-            // the next tick.
-            let (meets_gas_requirement, gas_payment) = self
-                .gas_payment_enforcer
-                .message_meets_gas_payment_requirement(&self.message.message, &tx_cost_estimate)
-                .await?;
+        else {
+            return Ok(false)
+        };
 
-            if !meets_gas_requirement {
-                tracing::info!(gas_payment=?gas_payment, "Gas payment requirement not met yet");
+        // Estimate transaction costs for the process call. If there are issues, it's
+        // likely that gas estimation has failed because the message is
+        // reverting. This is defined behavior, so we just log the error and
+        // move onto the next tick.
+        let tx_cost_estimate = match self
+            .mailbox
+            .process_estimate_costs(&self.message.message, &metadata)
+            .await
+        {
+            Ok(tx_cost_estimate) => tx_cost_estimate,
+            Err(error) => {
+                info!(?error, "Error estimating process costs");
                 return Ok(false);
             }
+        };
 
-            // Send the sponsored call.
-            let sponsored_call_result = self.send_sponsored_call_api_call(&metadata).await?;
-            tracing::info!(
-                msg=?self.message,
-                task_id=sponsored_call_result.task_id,
-                "Sent sponsored call",
-            );
+        // If the gas payment requirement hasn't been met, sleep briefly and wait for
+        // the next tick.
+        let (meets_gas_requirement, gas_payment) = self
+            .gas_payment_enforcer
+            .message_meets_gas_payment_requirement(&self.message.message, &tx_cost_estimate)
+            .await?;
 
-            // Wait for a terminal state, timing out according to the retry_submit_interval.
-            match timeout(
-                self.opts.retry_submit_interval,
-                self.poll_for_terminal_state(sponsored_call_result.task_id.clone()),
-            )
-            .await
-            {
-                Ok(result) => {
-                    // Bubble up any error that may have occurred in `poll_for_terminal_state`.
-                    result
-                }
-                // If a timeout occurred, don't bubble up an error, instead just log
-                // and set ourselves up for the next tick.
-                Err(err) => {
-                    tracing::info!(err=?err, "Sponsored call timed out, reattempting");
-                    Ok(false)
-                }
+        if !meets_gas_requirement {
+            info!(?gas_payment, "Gas payment requirement not met yet");
+            return Ok(false);
+        }
+
+        // Send the sponsored call.
+        let sponsored_call_result = self.send_sponsored_call_api_call(&metadata).await?;
+        info!(
+            msg=?self.message,
+            task_id=sponsored_call_result.task_id,
+            "Sent sponsored call",
+        );
+
+        // Wait for a terminal state, timing out according to the retry_submit_interval.
+        match timeout(
+            self.opts.retry_submit_interval,
+            self.poll_for_terminal_state(sponsored_call_result.task_id.clone()),
+        )
+        .await
+        {
+            Ok(result) => {
+                // Bubble up any error that may have occurred in `poll_for_terminal_state`.
+                result
+            }
+            // If a timeout occurred, don't bubble up an error, instead just log
+            // and set ourselves up for the next tick.
+            Err(error) => {
+                info!(?error, "Sponsored call timed out, reattempting");
+                Ok(false)
             }
-        } else {
-            tracing::info!("Unable to fetch metadata for message");
-            Ok(false)
         }
     }
 
@@ -192,7 +186,7 @@ impl SponsoredCallOp {
             let task_status_result = task_status_api_call.run().await?;
             let task_state = task_status_result.task_state();
 
-            tracing::info!(
+            info!(
                 task_id=task_id,
                 task_state=?task_state,
                 task_status_result=?task_status_result,