Add logging (first tier) (#567)

* Add logging (first tier)

* Review fixes

crates/bitcoin-da/src/helpers/builders.rs

@@ -1,3 +1,4 @@
+use core::fmt;
 use core::result::Result::Ok;
 use core::str::FromStr;
 use std::fs::File;
@@ -21,6 +22,7 @@ use bitcoin::{
     Witness,
 };
 use brotli::{CompressorWriter, DecompressorWriter};
+use tracing::{instrument, trace, warn};
 
 use crate::helpers::{BODY_TAG, PUBLICKEY_TAG, RANDOM_TAG, ROLLUP_NAME_TAG, SIGNATURE_TAG};
 use crate::spec::utxo::UTXO;
@@ -140,6 +142,7 @@ fn choose_utxos(
     }
 }
 
+#[instrument(level = "trace", skip(utxos), err)]
 fn build_commit_transaction(
     prev_tx: Option<TxWithId>, // reuse outputs to add commit tx order
     utxos: Vec<UTXO>,
@@ -184,9 +187,16 @@ fn build_commit_transaction(
     } else {
         (None, utxos)
     };
+    let mut iteration = 0;
     let mut last_size = size;
 
     let tx = loop {
+        if iteration % 100 == 0 {
+            trace!(iteration, "Trying to find commitment size");
+            if iteration > 5000 {
+                warn!("Too many iterations");
+            }
+        }
         let fee = ((last_size as f64) * fee_rate).ceil() as u64;
 
         let input_total = output_value + fee;
@@ -247,6 +257,7 @@ fn build_commit_transaction(
         }
 
         last_size = size;
+        iteration += 1;
     };
 
     Ok(tx)
@@ -308,10 +319,20 @@ pub struct TxWithId {
     pub tx: Transaction,
 }
 
+impl fmt::Debug for TxWithId {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        f.debug_struct("TxWithId")
+            .field("id", &self.id)
+            .field("tx", &"...")
+            .finish()
+    }
+}
+
 // TODO: parametrize hardness
 // so tests are easier
 // Creates the inscription transactions (commit and reveal)
 #[allow(clippy::too_many_arguments)]
+#[instrument(level = "trace", skip_all, err)]
 pub fn create_inscription_transactions(
     rollup_name: &str,
     body: Vec<u8>,
@@ -358,6 +379,12 @@ pub fn create_inscription_transactions(
     // Start loop to find a 'nonce' i.e. random number that makes the reveal tx hash starting with zeros given length
     let mut nonce: i64 = 0;
     loop {
+        if nonce % 100 == 0 {
+            trace!(nonce, "Trying to find commit & reveal nonce");
+            if nonce > 1000 {
+                warn!("Too many iterations");
+            }
+        }
         let utxos = utxos.clone();
         let recipient = recipient.clone();
         // ownerships are moved to the loop

crates/bitcoin-da/src/rpc.rs

@@ -1,4 +1,4 @@
-use core::fmt::Display;
+use core::fmt::{Debug, Display};
 use core::str::FromStr;
 
 use bitcoin::block::{Header, Version};
@@ -9,6 +9,7 @@ use reqwest::header::HeaderMap;
 use serde::{Deserialize, Serialize};
 use serde_json::value::RawValue;
 use serde_json::{json, to_value};
+use tracing::{instrument, warn};
 
 use crate::helpers::parsers::parse_hex_transaction;
 use crate::spec::block::BitcoinBlock;
@@ -44,6 +45,7 @@ pub struct BitcoinNode {
     client: reqwest::Client,
 }
 impl BitcoinNode {
+    #[instrument(level = "trace", ret)]
     pub fn new(url: String, username: String, password: String) -> Self {
         let mut headers = HeaderMap::new();
         headers.insert(
@@ -69,6 +71,7 @@ impl BitcoinNode {
         Self { url, client }
     }
 
+    #[instrument(level = "trace", skip_all, err)]
     async fn call_inner<T: serde::de::DeserializeOwned>(
         &self,
         method: &str,
@@ -89,14 +92,16 @@ impl BitcoinNode {
         let response = response.json::<Response<T>>().await?;
 
         if let Some(error) = response.error {
+            warn!(error=?error, "RPC returned error");
             return Ok(Err(error));
         }
 
         Ok(Ok(response.result.unwrap()))
     }
 
     // TODO: add max retries
-    async fn call<T: serde::de::DeserializeOwned>(
+    #[instrument(level = "trace", skip(self), err, ret)]
+    async fn call<T: Debug + serde::de::DeserializeOwned>(
         &self,
         method: &str,
         params: Vec<serde_json::Value>,
@@ -112,7 +117,7 @@ impl BitcoinNode {
                     // sometimes requests to bitcoind are dropped without a reason
                     // TODO: maybe remove is_request() check?
                     if error.is_connect() || error.is_timeout() || error.is_request() {
-                        tracing::warn!(error=?error, attempt=attempt, "Failed to send a call to bitcoind");
+                        warn!(error=?error, attempt=attempt, "Failed to send a call to bitcoind");
                         attempt += 1;
                         tokio::time::sleep(tokio::time::Duration::from_millis(500)).await;
                         continue; // retry
@@ -221,6 +226,7 @@ impl BitcoinNode {
     }
 
     // estimate_smart_fee estimates the fee to confirm a transaction in the next block
+    #[instrument(level = "trace", skip(self), err, ret)]
     pub async fn estimate_smart_fee(&self) -> Result<f64, anyhow::Error> {
         let result = self
             .call::<Box<RawValue>>("estimatesmartfee", vec![to_value(1)?])

crates/bitcoin-da/src/service.rs

@@ -1,3 +1,6 @@
+// fix clippy for tracing::instrument
+#![allow(clippy::blocks_in_conditions)]
+
 use core::result::Result::Ok;
 use core::str::FromStr;
 use core::time::Duration;
@@ -16,7 +19,7 @@ use tokio::sync::mpsc::{unbounded_channel, UnboundedSender};
 use tokio::sync::oneshot::{
     channel as oneshot_channel, Receiver as OneshotReceiver, Sender as OneshotSender,
 };
-use tracing::info;
+use tracing::{error, info, instrument, trace};
 
 use crate::helpers::builders::{
     compress_blob, create_inscription_transactions, decompress_blob, sign_blob_with_private_key,
@@ -104,8 +107,11 @@ impl BitcoinService {
                 // TODO find last tx by utxo chain
                 let mut prev_tx = None;
 
+                trace!("BitcoinDA queue is initialized. Waiting for the first request...");
+
                 // We execute commit and reveal txs one by one to chain them
                 while let Some(request) = rx.recv().await {
+                    trace!("A new request is received");
                     let fee_sat_per_vbyte = match this.get_fee_rate().await {
                         Ok(rate) => rate,
                         Err(e) => {
@@ -123,14 +129,18 @@ impl BitcoinService {
                     {
                         Ok(tx) => {
                             let tx_id = TxidWrapper(tx.id);
+                            info!(%tx.id, "Send tx to BitcoinDA");
                             prev_tx = Some(tx);
                             let _ = request.notify.send(Ok(tx_id));
                         }
                         Err(e) => {
+                            error!(?e, "Failed to send transaction to DA layer");
                             let _ = request.notify.send(Err(e));
                         }
                     }
                 }
+
+                error!("BitcoinDA queue stopped");
             });
         });
 
@@ -187,6 +197,7 @@ impl BitcoinService {
         }
     }
 
+    #[instrument(level = "trace", skip_all, ret)]
     async fn get_utxos(&self) -> Result<Vec<UTXO>, anyhow::Error> {
         let utxos = self.client.get_utxos().await?;
         if utxos.is_empty() {
@@ -204,6 +215,7 @@ impl BitcoinService {
         Ok(utxos)
     }
 
+    #[instrument(level = "trace", fields(prev_tx), ret, err)]
     pub async fn send_transaction_with_fee_rate(
         &self,
         prev_tx: Option<TxWithId>,
@@ -276,6 +288,7 @@ impl BitcoinService {
         Ok(reveal_tx)
     }
 
+    #[instrument(level = "trace", skip_all, ret)]
     pub async fn get_fee_rate(&self) -> Result<f64, anyhow::Error> {
         if self.network == bitcoin::Network::Regtest {
             // sometimes local mempool is empty, node cannot estimate
@@ -310,6 +323,7 @@ impl DaService for BitcoinService {
 
     // Make an RPC call to the node to get the block at the given height
     // If no such block exists, block until one does.
+    #[instrument(level = "trace", skip(self), err)]
     async fn get_block_at(&self, height: u64) -> Result<Self::FilteredBlock, Self::Error> {
         info!("Getting block at height {}", height);
 
@@ -344,6 +358,7 @@ impl DaService for BitcoinService {
     }
 
     // Fetch the [`DaSpec::BlockHeader`] of the last finalized block.
+    #[instrument(level = "trace", skip(self), err)]
     async fn get_last_finalized_block_header(
         &self,
     ) -> Result<<Self::Spec as DaSpec>::BlockHeader, Self::Error> {
@@ -364,6 +379,7 @@ impl DaService for BitcoinService {
     }
 
     // Fetch the head block of DA.
+    #[instrument(level = "trace", skip(self), err)]
     async fn get_head_block_header(
         &self,
     ) -> Result<<Self::Spec as DaSpec>::BlockHeader, Self::Error> {
@@ -375,6 +391,7 @@ impl DaService for BitcoinService {
     }
 
     // Extract the blob transactions relevant to a particular rollup from a block.
+    #[instrument(level = "trace", skip_all)]
     fn extract_relevant_blobs(
         &self,
         block: &Self::FilteredBlock,
@@ -418,6 +435,7 @@ impl DaService for BitcoinService {
         txs
     }
 
+    #[instrument(level = "trace", skip_all)]
     async fn get_extraction_proof(
         &self,
         block: &Self::FilteredBlock,
@@ -483,13 +501,15 @@ impl DaService for BitcoinService {
         (txs, inclusion_proof, completeness_proof)
     }
 
+    #[instrument(level = "trace", skip_all)]
     async fn send_transaction(
         &self,
         _blob: &[u8],
     ) -> Result<<Self as DaService>::TransactionId, Self::Error> {
         unimplemented!("Use send_tx_no_wait instead")
     }
 
+    #[instrument(level = "trace", skip_all)]
     async fn send_tx_no_wait(
         &self,
         blob: Vec<u8>,
@@ -513,14 +533,16 @@ impl DaService for BitcoinService {
         unimplemented!();
     }
 
+    #[instrument(level = "trace", skip(self))]
     async fn get_fee_rate(&self) -> Result<u128, Self::Error> {
         // This already returns ceil, so the conversion should work
-        let res = self.client.estimate_smart_fee().await.unwrap() as u128;
+        let res = self.client.estimate_smart_fee().await? as u128;
         // multiply with 10^10/4 = 25*10^8 = 2_500_000_000
         let multiplied_fee = res.saturating_mul(2_500_000_000);
         Ok(multiplied_fee)
     }
 
+    #[instrument(level = "trace", skip(self))]
     async fn get_block_by_hash(&self, hash: [u8; 32]) -> Result<Self::FilteredBlock, Self::Error> {
         info!("Getting block with hash {:?}", hash);
 

crates/ethereum-rpc/src/lib.rs

@@ -28,7 +28,7 @@ use serde_json::json;
 use sov_modules_api::utils::to_jsonrpsee_error_object;
 use sov_modules_api::WorkingSet;
 use sov_rollup_interface::services::da::DaService;
-use tracing::info;
+use tracing::{info, instrument};
 
 const MAX_TRACE_BLOCK: u32 = 1000;
 
@@ -127,6 +127,7 @@ impl<C: sov_modules_api::Context, Da: DaService> Ethereum<C, Da> {
 }
 
 impl<C: sov_modules_api::Context, Da: DaService> Ethereum<C, Da> {
+    #[instrument(level = "trace", skip_all)]
     async fn max_fee_per_gas(&self, working_set: &mut WorkingSet<C>) -> (U256, U256) {
         let suggested_tip = self
             .gas_price_oracle
@@ -610,7 +611,7 @@ fn register_rpc_methods<C: sov_modules_api::Context, Da: DaService>(
             // else; calls the debug_trace_transaction_block function in evm
             // that function traces the entire block, returns all the traces to here
             // then we put them into cache and return the trace of the requested transaction
-            info!("eth module: debug_traceTransaction");
+            info!(params = ?parameters, "eth module: debug_traceTransaction");
 
             let mut params = parameters.sequence();
 
@@ -716,7 +717,7 @@ fn register_rpc_methods<C: sov_modules_api::Context, Da: DaService>(
         rpc.register_async_method::<Result<H256, ErrorObjectOwned>, _, _>(
             "eth_sendRawTransaction",
             |parameters, ethereum| async move {
-                info!("Full Node: eth_sendRawTransaction");
+                info!(params = ?parameters, "Full Node: eth_sendRawTransaction");
                 // send this directly to the sequencer
                 let data: Bytes = parameters.one()?;
                 // sequencer client should send it

crates/evm/src/call.rs

@@ -5,6 +5,7 @@ use reth_primitives::TransactionSignedEcRecovered;
 use revm::primitives::{CfgEnv, CfgEnvWithHandlerCfg, EVMError, SpecId};
 use sov_modules_api::prelude::*;
 use sov_modules_api::{CallResponse, WorkingSet};
+use tracing::{error, instrument};
 
 use crate::evm::db::EvmDb;
 use crate::evm::executor::{self};
@@ -30,6 +31,7 @@ pub struct CallMessage {
 
 impl<C: sov_modules_api::Context> Evm<C> {
     /// Executes system events for the current block and push tx to pending_transactions.
+    #[instrument(level = "debug", skip_all, ret)]
     pub(crate) fn execute_system_events(
         &self,
         system_events: Vec<SystemEvent>,
@@ -53,13 +55,13 @@ impl<C: sov_modules_api::Context> Evm<C> {
             .get(&BitcoinLightClient::address(), working_set)
             .is_some();
         if !l1_block_hash_exists {
-            tracing::error!("System contract not found: BitcoinLightClient");
+            error!("System contract not found: BitcoinLightClient");
             return;
         }
 
         let bridge_contract_exists = self.accounts.get(&Bridge::address(), working_set).is_some();
         if !bridge_contract_exists {
-            tracing::error!("System contract not found: Bridge");
+            error!("System contract not found: Bridge");
             return;
         }
 
@@ -125,6 +127,7 @@ impl<C: sov_modules_api::Context> Evm<C> {
     }
 
     /// Executes a call message.
+    #[instrument(level = "debug", skip_all, ret, err)]
     pub(crate) fn execute_call(
         &self,
         txs: Vec<RlpEvmTransaction>,
@@ -217,7 +220,7 @@ impl<C: sov_modules_api::Context> Evm<C> {
                 // Adopted from https://github.com/paradigmxyz/reth/blob/main/crates/payload/basic/src/lib.rs#L884
                 Err(err) => match err {
                     EVMError::Transaction(_) => {
-                        tracing::error!("evm: Transaction error: {:?}", err);
+                        error!("evm: Transaction error: {:?}", err);
                         // This is a transactional error, so we can skip it without doing anything.
                         continue;
                     }
@@ -230,11 +233,11 @@ impl<C: sov_modules_api::Context> Evm<C> {
                                 .push(&evm_tx_recovered.hash(), &mut working_set.accessory_state());
                         }
                         // This is a custom error - we need to log it but no need to shutdown the system as of now.
-                        tracing::error!("evm: Custom error: {:?}", msg);
+                        error!("evm: Custom error: {:?}", msg);
                         continue;
                     }
                     err => {
-                        tracing::error!("evm: Transaction error: {:?}", err);
+                        error!("evm: Transaction error: {:?}", err);
                         // This is a fatal error, so we need to return it.
                         return Err(err.into());
                     }