Always log whole causality chain for errors.

This commit is contained in:
Philipp Hoenisch 2021-05-11 11:08:33 +10:00
parent c011e95062
commit 316f95c65b
No known key found for this signature in database
GPG Key ID: E5F8E74C672BC666
8 changed files with 40 additions and 47 deletions

View File

@ -157,7 +157,7 @@ async fn main() -> Result<()> {
tracing::debug!(%swap_id, %state, "Swap finished with state") tracing::debug!(%swap_id, %state, "Swap finished with state")
} }
Err(error) => { Err(error) => {
tracing::error!(%swap_id, %error, "Swap failed") tracing::error!(%swap_id, "Swap failed. Error {:#}", error)
} }
} }
}); });

View File

@ -155,13 +155,13 @@ impl Wallet {
let new_status = match client.lock().await.status_of_script(&tx) { let new_status = match client.lock().await.status_of_script(&tx) {
Ok(new_status) => new_status, Ok(new_status) => new_status,
Err(error) => { Err(error) => {
tracing::warn!(%txid, %error, "Failed to get status of script."); tracing::warn!(%txid, "Failed to get status of script. Error {:#}", error);
return; return;
} }
}; };
if Some(new_status) != last_status { 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); last_status = Some(new_status);
@ -201,7 +201,7 @@ impl Subscription {
let conf_target = self.finality_confirmations; let conf_target = self.finality_confirmations;
let txid = self.txid; 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; let mut seen_confirmations = 0;
@ -213,7 +213,7 @@ impl Subscription {
tracing::info!(%txid, tracing::info!(%txid,
seen_confirmations = %confirmations, seen_confirmations = %confirmations,
needed_confirmations = %conf_target, needed_confirmations = %conf_target,
"Waiting for Bitcoin transaction finality."); "Waiting for Bitcoin transaction finality");
seen_confirmations = confirmations; seen_confirmations = confirmations;
} }
@ -593,7 +593,7 @@ impl Client {
[] => Ok(ScriptStatus::Unseen), [] => Ok(ScriptStatus::Unseen),
[remaining @ .., last] => { [remaining @ .., last] => {
if !remaining.is_empty() { 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 { if last.height <= 0 {
@ -619,7 +619,7 @@ impl Client {
if let Some(new_block) = latest_block { if let Some(new_block) = latest_block {
tracing::debug!( tracing::debug!(
block_height = new_block.height, block_height = new_block.height,
"Got notification for new block." "Got notification for new block"
); );
self.latest_block = BlockHeight::try_from(new_block)?; self.latest_block = BlockHeight::try_from(new_block)?;
} }

View File

@ -43,16 +43,18 @@ pub fn connect() -> Result<PriceUpdates> {
} }
}, },
|error, next: Duration| { |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; .await;
match result { match result {
Err(e) => { Err(e) => {
tracing::warn!( tracing::warn!("Rate updates incurred an unrecoverable error: {:#}", e);
error = %e,
"Rate updates incurred an unrecoverable error.");
// in case the retries fail permanently, let the subscribers know // in case the retries fail permanently, let the subscribers know
price_update.send(Err(Error::PermanentFailure)) price_update.send(Err(Error::PermanentFailure))
@ -186,8 +188,7 @@ mod connection {
Err(_) => match serde_json::from_str::<wire::PriceUpdate>(&msg) { Err(_) => match serde_json::from_str::<wire::PriceUpdate>(&msg) {
Ok(ticker) => ticker, Ok(ticker) => ticker,
Err(error) => { 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); return Ok(None);
} }
}, },

View File

@ -157,13 +157,12 @@ impl Wallet {
Err(error) => { Err(error) => {
tracing::warn!( tracing::warn!(
address = %self.main_address, address = %self.main_address,
%error, "Transferring Monero back to default wallet failed. Error {:#}", error
"Transferring Monero back to default wallet failed",
); );
} }
}, },
Err(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) => { Err(error) => {
tracing::debug!( tracing::debug!(
%txid, %txid,
%error, "Failed to retrieve tx from blockchain. Error {:#}", error
"Failed to retrieve tx from blockchain"
); );
continue; // treating every error as transient and retrying continue; // treating every error as transient and retrying
// is obviously wrong but the jsonrpc client is // is obviously wrong but the jsonrpc client is

View File

@ -63,10 +63,8 @@ where
.await .await
.map_err(|e| io::Error::new(io::ErrorKind::InvalidData, e))?; .map_err(|e| io::Error::new(io::ErrorKind::InvalidData, e))?;
let mut de = serde_cbor::Deserializer::from_slice(&message); let mut de = serde_cbor::Deserializer::from_slice(&message);
let msg = Res::deserialize(&mut de).map_err(|error| { let msg = Res::deserialize(&mut de)
tracing::debug!(%error, "serde read_response error."); .map_err(|error| io::Error::new(io::ErrorKind::InvalidData, error))?;
io::Error::new(io::ErrorKind::InvalidData, error)
})?;
Ok(msg) Ok(msg)
} }
@ -97,10 +95,8 @@ where
where where
T: AsyncWrite + Unpin + Send, T: AsyncWrite + Unpin + Send,
{ {
let bytes = serde_cbor::to_vec(&res).map_err(|error| { let bytes = serde_cbor::to_vec(&res)
tracing::debug!(%error,"serde write_response error"); .map_err(|error| io::Error::new(io::ErrorKind::InvalidData, error))?;
io::Error::new(io::ErrorKind::InvalidData, error)
})?;
upgrade::write_one(io, &bytes).await?; upgrade::write_one(io, &bytes).await?;
Ok(()) Ok(())

View File

@ -61,8 +61,7 @@ impl Transport for TorTcpConfig {
Err(error) => { Err(error) => {
tracing::warn!( tracing::warn!(
address = %addr, address = %addr,
%error, "Address could not be formatted. Dialling via clear net. Error {:#}", error,
"Address could not be formatted. Dialling via clear net.",
); );
self.inner.dial(addr) self.inner.dial(addr)
} }

View File

@ -170,7 +170,7 @@ where
(redeem_address, punish_address) (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; continue;
} }
}; };
@ -183,7 +183,7 @@ where
(tx_redeem_fee, tx_punish_fee) (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; continue;
} }
}; };
@ -200,7 +200,7 @@ where
) { ) {
Ok(state) => state, Ok(state) => state,
Err(error) => { 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; continue;
} }
}; };
@ -236,7 +236,7 @@ where
let quote = match self.make_quote(self.min_buy, self.max_buy).await { let quote = match self.make_quote(self.min_buy, self.max_buy).await {
Ok(quote) => quote, Ok(quote) => quote,
Err(error) => { Err(error) => {
tracing::warn!(%peer, %error, "Failed to make quote."); tracing::warn!(%peer, "Failed to make quote. Error {:#}", error);
continue; continue;
} }
}; };
@ -265,7 +265,7 @@ where
tracing::warn!( tracing::warn!(
unknown_swap_id = %swap_id, unknown_swap_id = %swap_id,
from = %peer, from = %peer,
"Ignoring encrypted signature for unknown swap."); "Ignoring encrypted signature for unknown swap");
continue; continue;
} }
}; };
@ -275,7 +275,7 @@ where
%swap_id, %swap_id,
received_from = %peer, received_from = %peer,
expected_from = %swap_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; continue;
} }
@ -306,8 +306,7 @@ where
SwarmEvent::Behaviour(OutEvent::Failure {peer, error}) => { SwarmEvent::Behaviour(OutEvent::Failure {peer, error}) => {
tracing::error!( tracing::error!(
%peer, %peer,
%error, "Communication error. Error {:#}", error);
"Communication error");
} }
SwarmEvent::ConnectionEstablished { peer_id: peer, endpoint, .. } => { SwarmEvent::ConnectionEstablished { peer_id: peer, endpoint, .. } => {
tracing::debug!(%peer, address = %endpoint.get_remote_address(), "New connection established"); tracing::debug!(%peer, address = %endpoint.get_remote_address(), "New connection established");
@ -322,15 +321,15 @@ where
} }
} }
SwarmEvent::IncomingConnectionError { send_back_addr: address, error, .. } => { 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 => { SwarmEvent::ConnectionClosed { peer_id: peer, num_established, endpoint, cause } if num_established == 0 => {
match cause { match cause {
Some(error) => { 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 => { 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); self.inflight_transfer_proofs.insert(id, responder);
}, },
Some(Err(error)) => { 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 => { None => {
unreachable!("stream of transfer proof receivers must never terminate") unreachable!("stream of transfer proof receivers must never terminate")

View File

@ -212,8 +212,9 @@ where
}, },
Err(error) => { Err(error) => {
error!( error!(
%error, "Publishing the redeem transaction failed. Error {:#}",
"Publishing the redeem transaction failed"); error
);
tx_lock_status tx_lock_status
.wait_until_confirmed_with(state3.cancel_timelock) .wait_until_confirmed_with(state3.cancel_timelock)
.await?; .await?;
@ -227,8 +228,7 @@ where
}, },
Err(error) => { Err(error) => {
error!( error!(
%error, "Constructing the redeem transaction failed. Attempting to wait for cancellation now. Error {:#}", error);
"Constructing the redeem transaction failed. Attempting to wait for cancellation now");
tx_lock_status tx_lock_status
.wait_until_confirmed_with(state3.cancel_timelock) .wait_until_confirmed_with(state3.cancel_timelock)
.await?; .await?;
@ -331,8 +331,8 @@ where
Ok(_) => AliceState::BtcPunished, Ok(_) => AliceState::BtcPunished,
Err(error) => { Err(error) => {
warn!( warn!(
%error, "Falling back to refund because punish transaction failed. Error {:#}",
"Falling back to refund because punish transaction failed" error
); );
// Upon punish failure we assume that the refund tx was included but we // Upon punish failure we assume that the refund tx was included but we