app: more logs for mining, wallet updates, net (#16)

* app: more logs for mining + wallet updates

* node: include source error in Error::SendNewTipReady

* node: more networking logs

* net+node: more logs

* multi: add context to MailboxItem::AcceptConnection about remote address

* net: add remote_address to Error::Connection

* logging: make level for file log configurable

* net: tune logs

* multi: more BMM logs

* cli: make RPC timeout configurable

* cli: turn RPC request timeout into Option<u64>

* net: remove invalid peers at startup

* app: remove confusing error conversion functions

* node: delete unused function

* main: update bad param name

* app: remove inspect_err

Author: torkelrogstad

app/app.rs

@@ -46,6 +46,7 @@ pub enum Error {
 }
 
 fn update_wallet(node: &Node, wallet: &Wallet) -> Result<(), Error> {
+    tracing::trace!("starting wallet update");
     let addresses = wallet.get_addresses()?;
     let utxos = node.get_utxos_by_addresses(&addresses)?;
     let outpoints: Vec<_> = wallet.get_utxos()?.into_keys().collect();
@@ -56,6 +57,8 @@ fn update_wallet(node: &Node, wallet: &Wallet) -> Result<(), Error> {
         .collect();
     wallet.put_utxos(&utxos)?;
     wallet.spend_utxos(&spent)?;
+
+    tracing::debug!("finished wallet update");
     Ok(())
 }
 
@@ -355,34 +358,35 @@ impl App {
             .attempt_bmm(bribe.to_sat(), 0, header, body)
             .await?;
 
-        // miner_write.generate().await?;
         tracing::debug!(%bmm_txid, "mine: confirming BMM...");
         if let Some((main_hash, header, body)) =
             miner_write.confirm_bmm().await?
         {
             tracing::debug!(
-                "mine: confirmed BMM, submitting block {}",
-                header.hash()
+                %main_hash, side_hash = %header.hash(), "mine: confirmed BMM, submitting block",
             );
             match self.node.submit_block(main_hash, &header, &body).await? {
                 true => {
                     tracing::debug!(
-                        "mine: BMM accepted as new tip: {}",
-                        main_hash
+                         %main_hash, "mine: BMM accepted as new tip",
                     );
                 }
                 false => {
                     tracing::warn!(
-                        "mine: BMM not accepted as new tip: {}",
-                        main_hash
+                        %main_hash, "mine: BMM not accepted as new tip",
                     );
                 }
             }
         }
 
         drop(miner_write);
         let () = self.update()?;
-        self.node.regenerate_proof(&mut self.transaction.write())?;
+
+        self.node
+            .regenerate_proof(&mut self.transaction.write())
+            .inspect_err(|err| {
+                tracing::error!("mine: unable to regenerate proof: {err:#}");
+            })?;
         Ok(())
     }
 

app/cli.rs

@@ -109,6 +109,11 @@ pub(super) struct Cli {
     /// If set to the empty string, logging to file will be disabled.
     #[arg(long)]
     log_dir: Option<PathBuf>,
+
+    /// Log level for logs that get written to file
+    #[arg(default_value_t = tracing::Level::WARN, long)]
+    log_level_file: tracing::Level,
+
     /// Log level
     #[arg(default_value_t = tracing::Level::DEBUG, long)]
     log_level: tracing::Level,
@@ -135,6 +140,7 @@ pub struct Config {
     /// If None, logging to file should be disabled.
     pub log_dir: Option<PathBuf>,
     pub log_level: tracing::Level,
+    pub log_level_file: tracing::Level, // Level for logs that get written to file
     pub mainchain_grpc_address: url::Url,
     pub mnemonic_seed_phrase_path: Option<PathBuf>,
     pub net_addr: SocketAddr,
@@ -164,6 +170,7 @@ impl Cli {
             headless: self.headless,
             log_dir,
             log_level: self.log_level,
+            log_level_file: self.log_level_file,
             mainchain_grpc_address: self.mainchain_grpc_address,
             mnemonic_seed_phrase_path: self.mnemonic_seed_phrase_path,
             net_addr: self.net_addr,

app/gui/console_logs.rs

@@ -72,6 +72,7 @@ impl ConsoleLogs {
         };
         let cli = thunder_app_cli_lib::Cli {
             rpc_addr: self.rpc_addr,
+            timeout: None,
             command,
         };
         app.runtime.spawn({

app/main.rs

@@ -56,21 +56,21 @@ type RollingLoggerGuard = tracing_appender::non_blocking::WorkerGuard;
 /// to keep the file logger alive.
 fn rolling_logger<S>(
     log_dir: &Path,
+    log_level: tracing::Level,
 ) -> anyhow::Result<(impl Layer<S>, RollingLoggerGuard)>
 where
     S: tracing::Subscriber
         + for<'s> tracing_subscriber::registry::LookupSpan<'s>,
 {
-    const DEFAULT_LEVEL: tracing::Level = tracing::Level::WARN;
     const LOG_FILE_SUFFIX: &str = "log";
     let rolling_log_appender = tracing_appender::rolling::Builder::new()
         .rotation(tracing_appender::rolling::Rotation::DAILY)
         .filename_suffix(LOG_FILE_SUFFIX)
         .build(log_dir)?;
     let (non_blocking_rolling_log_writer, rolling_log_guard) =
         tracing_appender::non_blocking(rolling_log_appender);
-    let level_filter =
-        tracing_filter::Targets::new().with_default(DEFAULT_LEVEL);
+    let level_filter = tracing_filter::Targets::new().with_default(log_level);
+
     let rolling_log_layer = tracing_subscriber::fmt::layer()
         .compact()
         .with_ansi(false)
@@ -85,6 +85,7 @@ where
 fn set_tracing_subscriber(
     log_dir: Option<&Path>,
     log_level: tracing::Level,
+    log_level_file: tracing::Level,
 ) -> anyhow::Result<(LineBuffer, Option<RollingLoggerGuard>)> {
     let targets_filter = {
         let default_directives_str = targets_directive_str([
@@ -114,7 +115,7 @@ fn set_tracing_subscriber(
     let (rolling_log_layer, rolling_log_guard) = match log_dir {
         None => (None, None),
         Some(log_dir) => {
-            let (layer, guard) = rolling_logger(log_dir)?;
+            let (layer, guard) = rolling_logger(log_dir, log_level_file)?;
             (Some(layer), Some(guard))
         }
     };
@@ -136,18 +137,25 @@ fn set_tracing_subscriber(
 fn main() -> anyhow::Result<()> {
     let cli = cli::Cli::parse();
     let config = cli.get_config()?;
-    let (line_buffer, _rolling_log_guard) =
-        set_tracing_subscriber(config.log_dir.as_deref(), config.log_level)?;
-    let app: Result<app::App, app::Error> =
-        app::App::new(&config).inspect(|app| {
+    let (line_buffer, _rolling_log_guard) = set_tracing_subscriber(
+        config.log_dir.as_deref(),
+        config.log_level,
+        config.log_level_file,
+    )?;
+    let app: Result<app::App, app::Error> = app::App::new(&config)
+        .inspect(|app| {
             // spawn rpc server
             app.runtime.spawn({
                 let app = app.clone();
                 async move {
                     rpc_server::run_server(app, config.rpc_addr).await.unwrap()
                 }
             });
+        })
+        .inspect_err(|err| {
+            tracing::error!("application error: {:?}", err);
         });
+
     if config.headless {
         tracing::info!("Running in headless mode");
         drop(line_buffer);

app/rpc_server.rs

@@ -7,13 +7,12 @@ use jsonrpsee::{
     types::ErrorObject,
 };
 use thunder::{
-    node,
     types::{Address, PointedOutput, Txid, WithdrawalBundle},
-    wallet::{self, Balance},
+    wallet::Balance,
 };
 use thunder_app_rpc_api::RpcServer;
 
-use crate::app::{self, App};
+use crate::app::App;
 
 pub struct RpcServerImpl {
     app: App,
@@ -30,25 +29,10 @@ where
     let error = anyhow::Error::from(error);
     custom_err_msg(format!("{error:#}"))
 }
-
-fn convert_app_err(err: app::Error) -> ErrorObject<'static> {
-    let err = anyhow::anyhow!(err);
-    tracing::error!("{err:#}");
-    custom_err(err)
-}
-
-fn convert_node_err(err: node::Error) -> ErrorObject<'static> {
-    custom_err(err)
-}
-
-fn convert_wallet_err(err: wallet::Error) -> ErrorObject<'static> {
-    custom_err(err)
-}
-
 #[async_trait]
 impl RpcServer for RpcServerImpl {
     async fn balance(&self) -> RpcResult<Balance> {
-        self.app.wallet.get_balance().map_err(convert_wallet_err)
+        self.app.wallet.get_balance().map_err(custom_err)
     }
 
     async fn create_deposit(
@@ -64,14 +48,14 @@ impl RpcServer for RpcServerImpl {
                 bitcoin::Amount::from_sat(value_sats),
                 bitcoin::Amount::from_sat(fee_sats),
             )
-            .map_err(convert_app_err)
+            .map_err(custom_err)
         })
         .await
         .unwrap()
     }
 
     async fn connect_peer(&self, addr: SocketAddr) -> RpcResult<()> {
-        self.app.node.connect_peer(addr).map_err(convert_node_err)
+        self.app.node.connect_peer(addr).map_err(custom_err)
     }
 
     async fn format_deposit_address(
@@ -118,25 +102,18 @@ impl RpcServer for RpcServerImpl {
     }
 
     async fn get_new_address(&self) -> RpcResult<Address> {
-        self.app
-            .wallet
-            .get_new_address()
-            .map_err(convert_wallet_err)
+        self.app.wallet.get_new_address().map_err(custom_err)
     }
 
     async fn get_wallet_addresses(&self) -> RpcResult<Vec<Address>> {
-        let addrs = self
-            .app
-            .wallet
-            .get_addresses()
-            .map_err(convert_wallet_err)?;
+        let addrs = self.app.wallet.get_addresses().map_err(custom_err)?;
         let mut res: Vec<_> = addrs.into_iter().collect();
         res.sort_by_key(|addr| addr.as_base58());
         Ok(res)
     }
 
     async fn get_wallet_utxos(&self) -> RpcResult<Vec<PointedOutput>> {
-        let utxos = self.app.wallet.get_utxos().map_err(convert_wallet_err)?;
+        let utxos = self.app.wallet.get_utxos().map_err(custom_err)?;
         let utxos = utxos
             .into_iter()
             .map(|(outpoint, output)| PointedOutput { outpoint, output })
@@ -145,8 +122,7 @@ impl RpcServer for RpcServerImpl {
     }
 
     async fn getblockcount(&self) -> RpcResult<u32> {
-        let height =
-            self.app.node.try_get_height().map_err(convert_node_err)?;
+        let height = self.app.node.try_get_height().map_err(custom_err)?;
         let block_count = height.map_or(0, |height| height + 1);
         Ok(block_count)
     }
@@ -158,7 +134,7 @@ impl RpcServer for RpcServerImpl {
             .app
             .node
             .get_latest_failed_withdrawal_bundle_height()
-            .map_err(convert_node_err)?;
+            .map_err(custom_err)?;
         Ok(height)
     }
 
@@ -168,7 +144,7 @@ impl RpcServer for RpcServerImpl {
     }
 
     async fn list_utxos(&self) -> RpcResult<Vec<PointedOutput>> {
-        let utxos = self.app.node.get_all_utxos().map_err(convert_node_err)?;
+        let utxos = self.app.node.get_all_utxos().map_err(custom_err)?;
         let res = utxos
             .into_iter()
             .map(|(outpoint, output)| PointedOutput { outpoint, output })
@@ -178,10 +154,14 @@ impl RpcServer for RpcServerImpl {
 
     async fn mine(&self, fee: Option<u64>) -> RpcResult<()> {
         let fee = fee.map(bitcoin::Amount::from_sat);
-        self.app.local_pool.spawn_pinned({
-            let app = self.app.clone();
-            move || async move { app.mine(fee).await.map_err(convert_app_err) }
-        }).await.unwrap()
+        self.app
+            .local_pool
+            .spawn_pinned({
+                let app = self.app.clone();
+                move || async move { app.mine(fee).await.map_err(custom_err) }
+            })
+            .await
+            .unwrap()
     }
 
     async fn pending_withdrawal_bundle(
@@ -190,7 +170,7 @@ impl RpcServer for RpcServerImpl {
         self.app
             .node
             .get_pending_withdrawal_bundle()
-            .map_err(convert_node_err)
+            .map_err(custom_err)
     }
 
     async fn openapi_schema(&self) -> RpcResult<utoipa::openapi::OpenApi> {
@@ -199,10 +179,7 @@ impl RpcServer for RpcServerImpl {
     }
 
     async fn remove_from_mempool(&self, txid: Txid) -> RpcResult<()> {
-        self.app
-            .node
-            .remove_from_mempool(txid)
-            .map_err(convert_node_err)
+        self.app.node.remove_from_mempool(txid).map_err(custom_err)
     }
 
     async fn set_seed_from_mnemonic(&self, mnemonic: String) -> RpcResult<()> {
@@ -213,18 +190,12 @@ impl RpcServer for RpcServerImpl {
         let seed_bytes: [u8; 64] = seed.as_bytes().try_into().map_err(
             |err: <[u8; 64] as TryFrom<&[u8]>>::Error| custom_err(err),
         )?;
-        self.app
-            .wallet
-            .set_seed(&seed_bytes)
-            .map_err(convert_wallet_err)
+        self.app.wallet.set_seed(&seed_bytes).map_err(custom_err)
     }
 
     async fn sidechain_wealth_sats(&self) -> RpcResult<u64> {
-        let sidechain_wealth = self
-            .app
-            .node
-            .get_sidechain_wealth()
-            .map_err(convert_node_err)?;
+        let sidechain_wealth =
+            self.app.node.get_sidechain_wealth().map_err(custom_err)?;
         Ok(sidechain_wealth.to_sat())
     }
 
@@ -238,11 +209,8 @@ impl RpcServer for RpcServerImpl {
         value_sats: u64,
         fee_sats: u64,
     ) -> RpcResult<Txid> {
-        let accumulator = self
-            .app
-            .node
-            .get_tip_accumulator()
-            .map_err(convert_node_err)?;
+        let accumulator =
+            self.app.node.get_tip_accumulator().map_err(custom_err)?;
         let tx = self
             .app
             .wallet
@@ -252,9 +220,9 @@ impl RpcServer for RpcServerImpl {
                 Amount::from_sat(value_sats),
                 Amount::from_sat(fee_sats),
             )
-            .map_err(convert_wallet_err)?;
+            .map_err(custom_err)?;
         let txid = tx.txid();
-        self.app.sign_and_send(tx).map_err(convert_app_err)?;
+        self.app.sign_and_send(tx).map_err(custom_err)?;
         Ok(txid)
     }
 
@@ -265,11 +233,8 @@ impl RpcServer for RpcServerImpl {
         fee_sats: u64,
         mainchain_fee_sats: u64,
     ) -> RpcResult<Txid> {
-        let accumulator = self
-            .app
-            .node
-            .get_tip_accumulator()
-            .map_err(convert_node_err)?;
+        let accumulator =
+            self.app.node.get_tip_accumulator().map_err(custom_err)?;
         let tx = self
             .app
             .wallet
@@ -280,9 +245,9 @@ impl RpcServer for RpcServerImpl {
                 Amount::from_sat(mainchain_fee_sats),
                 Amount::from_sat(fee_sats),
             )
-            .map_err(convert_wallet_err)?;
+            .map_err(custom_err)?;
         let txid = tx.txid();
-        self.app.sign_and_send(tx).map_err(convert_app_err)?;
+        self.app.sign_and_send(tx).map_err(custom_err)?;
         Ok(txid)
     }
 }