From 316f95c65ba0c67e13dbf607d56890d54227ddfd Mon Sep 17 00:00:00 2001 From: Philipp Hoenisch Date: Tue, 11 May 2021 11:08:33 +1000 Subject: [PATCH] Always log whole causality chain for errors. --- swap/src/bin/asb.rs | 2 +- swap/src/bitcoin/wallet.rs | 12 ++++++------ swap/src/kraken.rs | 15 ++++++++------- swap/src/monero/wallet.rs | 8 +++----- swap/src/network/cbor_request_response.rs | 12 ++++-------- swap/src/network/tor_transport.rs | 3 +-- swap/src/protocol/alice/event_loop.rs | 23 +++++++++++------------ swap/src/protocol/alice/swap.rs | 12 ++++++------ 8 files changed, 40 insertions(+), 47 deletions(-) diff --git a/swap/src/bin/asb.rs b/swap/src/bin/asb.rs index f1e5d90f..7a671802 100644 --- a/swap/src/bin/asb.rs +++ b/swap/src/bin/asb.rs @@ -157,7 +157,7 @@ async fn main() -> Result<()> { tracing::debug!(%swap_id, %state, "Swap finished with state") } Err(error) => { - tracing::error!(%swap_id, %error, "Swap failed") + tracing::error!(%swap_id, "Swap failed. Error {:#}", error) } } }); diff --git a/swap/src/bitcoin/wallet.rs b/swap/src/bitcoin/wallet.rs index 3f2c4152..8bf9db7c 100644 --- a/swap/src/bitcoin/wallet.rs +++ b/swap/src/bitcoin/wallet.rs @@ -155,13 +155,13 @@ impl Wallet { let new_status = match client.lock().await.status_of_script(&tx) { Ok(new_status) => new_status, Err(error) => { - tracing::warn!(%txid, %error, "Failed to get status of script."); + tracing::warn!(%txid, "Failed to get status of script. Error {:#}", error); return; } }; if Some(new_status) != last_status { - tracing::debug!(%txid, status = %new_status, "Transaction status."); + tracing::debug!(%txid, status = %new_status, "Transaction status"); } last_status = Some(new_status); @@ -201,7 +201,7 @@ impl Subscription { let conf_target = self.finality_confirmations; let txid = self.txid; - tracing::info!(%txid, required_confirmation=%conf_target, "Waiting for Bitcoin transaction finality."); + tracing::info!(%txid, required_confirmation=%conf_target, "Waiting for Bitcoin transaction finality"); let mut seen_confirmations = 0; @@ -213,7 +213,7 @@ impl Subscription { tracing::info!(%txid, seen_confirmations = %confirmations, needed_confirmations = %conf_target, - "Waiting for Bitcoin transaction finality."); + "Waiting for Bitcoin transaction finality"); seen_confirmations = confirmations; } @@ -593,7 +593,7 @@ impl Client { [] => Ok(ScriptStatus::Unseen), [remaining @ .., last] => { if !remaining.is_empty() { - tracing::warn!("Found more than a single history entry for script. This is highly unexpected and those history entries will be ignored.") + tracing::warn!("Found more than a single history entry for script. This is highly unexpected and those history entries will be ignored") } if last.height <= 0 { @@ -619,7 +619,7 @@ impl Client { if let Some(new_block) = latest_block { tracing::debug!( block_height = new_block.height, - "Got notification for new block." + "Got notification for new block" ); self.latest_block = BlockHeight::try_from(new_block)?; } diff --git a/swap/src/kraken.rs b/swap/src/kraken.rs index 8e42386b..001696ff 100644 --- a/swap/src/kraken.rs +++ b/swap/src/kraken.rs @@ -43,16 +43,18 @@ pub fn connect() -> Result { } }, |error, next: Duration| { - tracing::info!(%error, "Kraken websocket connection failed, retrying in {}ms", next.as_millis()); - } + tracing::info!( + "Kraken websocket connection failed, retrying in {}ms. Error {:#}", + next.as_millis(), + error + ); + }, ) .await; match result { Err(e) => { - tracing::warn!( - error = %e, - "Rate updates incurred an unrecoverable error."); + tracing::warn!("Rate updates incurred an unrecoverable error: {:#}", e); // in case the retries fail permanently, let the subscribers know price_update.send(Err(Error::PermanentFailure)) @@ -186,8 +188,7 @@ mod connection { Err(_) => match serde_json::from_str::(&msg) { Ok(ticker) => ticker, Err(error) => { - tracing::warn!(%error, %msg, "Failed to deserialize message as ticker update."); - + tracing::warn!(%msg, "Failed to deserialize message as ticker update. Error {:#}", error); return Ok(None); } }, diff --git a/swap/src/monero/wallet.rs b/swap/src/monero/wallet.rs index 87b3df1d..4732a632 100644 --- a/swap/src/monero/wallet.rs +++ b/swap/src/monero/wallet.rs @@ -157,13 +157,12 @@ impl Wallet { Err(error) => { tracing::warn!( address = %self.main_address, - %error, - "Transferring Monero back to default wallet failed", + "Transferring Monero back to default wallet failed. Error {:#}", error ); } }, Err(error) => { - tracing::warn!(%error, "Refreshing the generated wallet failed"); + tracing::warn!("Refreshing the generated wallet failed. Error {:#}", error); } } @@ -320,8 +319,7 @@ where Err(error) => { tracing::debug!( %txid, - %error, - "Failed to retrieve tx from blockchain" + "Failed to retrieve tx from blockchain. Error {:#}", error ); continue; // treating every error as transient and retrying // is obviously wrong but the jsonrpc client is diff --git a/swap/src/network/cbor_request_response.rs b/swap/src/network/cbor_request_response.rs index 3101d07c..abec6e07 100644 --- a/swap/src/network/cbor_request_response.rs +++ b/swap/src/network/cbor_request_response.rs @@ -63,10 +63,8 @@ where .await .map_err(|e| io::Error::new(io::ErrorKind::InvalidData, e))?; let mut de = serde_cbor::Deserializer::from_slice(&message); - let msg = Res::deserialize(&mut de).map_err(|error| { - tracing::debug!(%error, "serde read_response error."); - io::Error::new(io::ErrorKind::InvalidData, error) - })?; + let msg = Res::deserialize(&mut de) + .map_err(|error| io::Error::new(io::ErrorKind::InvalidData, error))?; Ok(msg) } @@ -97,10 +95,8 @@ where where T: AsyncWrite + Unpin + Send, { - let bytes = serde_cbor::to_vec(&res).map_err(|error| { - tracing::debug!(%error,"serde write_response error"); - io::Error::new(io::ErrorKind::InvalidData, error) - })?; + let bytes = serde_cbor::to_vec(&res) + .map_err(|error| io::Error::new(io::ErrorKind::InvalidData, error))?; upgrade::write_one(io, &bytes).await?; Ok(()) diff --git a/swap/src/network/tor_transport.rs b/swap/src/network/tor_transport.rs index 03e865e0..772470af 100644 --- a/swap/src/network/tor_transport.rs +++ b/swap/src/network/tor_transport.rs @@ -61,8 +61,7 @@ impl Transport for TorTcpConfig { Err(error) => { tracing::warn!( address = %addr, - %error, - "Address could not be formatted. Dialling via clear net.", + "Address could not be formatted. Dialling via clear net. Error {:#}", error, ); self.inner.dial(addr) } diff --git a/swap/src/protocol/alice/event_loop.rs b/swap/src/protocol/alice/event_loop.rs index de5e3f17..ae26d1f1 100644 --- a/swap/src/protocol/alice/event_loop.rs +++ b/swap/src/protocol/alice/event_loop.rs @@ -170,7 +170,7 @@ where (redeem_address, punish_address) } _ => { - tracing::error!(%peer, "Failed to get new address during execution setup."); + tracing::error!(%peer, "Failed to get new address during execution setup"); continue; } }; @@ -183,7 +183,7 @@ where (tx_redeem_fee, tx_punish_fee) } _ => { - tracing::error!(%peer, "Failed to calculate transaction fees during execution setup."); + tracing::error!(%peer, "Failed to calculate transaction fees during execution setup"); continue; } }; @@ -200,7 +200,7 @@ where ) { Ok(state) => state, Err(error) => { - tracing::warn!(%peer, %error, "Failed to make State0 for execution setup."); + tracing::warn!(%peer, "Failed to make State0 for execution setup. Error {:#}", error); continue; } }; @@ -236,7 +236,7 @@ where let quote = match self.make_quote(self.min_buy, self.max_buy).await { Ok(quote) => quote, Err(error) => { - tracing::warn!(%peer, %error, "Failed to make quote."); + tracing::warn!(%peer, "Failed to make quote. Error {:#}", error); continue; } }; @@ -265,7 +265,7 @@ where tracing::warn!( unknown_swap_id = %swap_id, from = %peer, - "Ignoring encrypted signature for unknown swap."); + "Ignoring encrypted signature for unknown swap"); continue; } }; @@ -275,7 +275,7 @@ where %swap_id, received_from = %peer, expected_from = %swap_peer, - "Ignoring malicious encrypted signature which was not expected from this peer.", + "Ignoring malicious encrypted signature which was not expected from this peer", ); continue; } @@ -306,8 +306,7 @@ where SwarmEvent::Behaviour(OutEvent::Failure {peer, error}) => { tracing::error!( %peer, - %error, - "Communication error"); + "Communication error. Error {:#}", error); } SwarmEvent::ConnectionEstablished { peer_id: peer, endpoint, .. } => { tracing::debug!(%peer, address = %endpoint.get_remote_address(), "New connection established"); @@ -322,15 +321,15 @@ where } } SwarmEvent::IncomingConnectionError { send_back_addr: address, error, .. } => { - tracing::warn!(%address, %error, "Failed to set up connection with peer. "); + tracing::warn!(%address, "Failed to set up connection with peer. Error {:#}", error); } SwarmEvent::ConnectionClosed { peer_id: peer, num_established, endpoint, cause } if num_established == 0 => { match cause { Some(error) => { - tracing::warn!(%peer, address = %endpoint.get_remote_address(), %error, "Lost connection."); + tracing::warn!(%peer, address = %endpoint.get_remote_address(), "Lost connection. Error {:#}", error); }, None => { - tracing::info!(%peer, address = %endpoint.get_remote_address(), "Successfully closed connection."); + tracing::info!(%peer, address = %endpoint.get_remote_address(), "Successfully closed connection"); } } } @@ -353,7 +352,7 @@ where self.inflight_transfer_proofs.insert(id, responder); }, Some(Err(error)) => { - tracing::debug!(%error, "A swap stopped without sending a transfer proof."); + tracing::debug!("A swap stopped without sending a transfer proof. Error {:#}", error); } None => { unreachable!("stream of transfer proof receivers must never terminate") diff --git a/swap/src/protocol/alice/swap.rs b/swap/src/protocol/alice/swap.rs index 22351519..28290a21 100644 --- a/swap/src/protocol/alice/swap.rs +++ b/swap/src/protocol/alice/swap.rs @@ -212,8 +212,9 @@ where }, Err(error) => { error!( - %error, - "Publishing the redeem transaction failed"); + "Publishing the redeem transaction failed. Error {:#}", + error + ); tx_lock_status .wait_until_confirmed_with(state3.cancel_timelock) .await?; @@ -227,8 +228,7 @@ where }, Err(error) => { error!( - %error, - "Constructing the redeem transaction failed. Attempting to wait for cancellation now"); + "Constructing the redeem transaction failed. Attempting to wait for cancellation now. Error {:#}", error); tx_lock_status .wait_until_confirmed_with(state3.cancel_timelock) .await?; @@ -331,8 +331,8 @@ where Ok(_) => AliceState::BtcPunished, Err(error) => { warn!( - %error, - "Falling back to refund because punish transaction failed" + "Falling back to refund because punish transaction failed. Error {:#}", + error ); // Upon punish failure we assume that the refund tx was included but we