Improve logging by adding details as fields instead of into the msg.

pull/474/head
Philipp Hoenisch 3 years ago
parent 1706b36800
commit c011e95062
No known key found for this signature in database
GPG Key ID: E5F8E74C672BC666

@ -105,8 +105,8 @@ pub struct ConfigNotInitialized {}
pub fn read_config(config_path: PathBuf) -> Result<Result<Config, ConfigNotInitialized>> {
if config_path.exists() {
info!(
"Using config file at default path: {}",
config_path.display()
path = %config_path.display(),
"Using config file at path",
);
} else {
return Ok(Err(ConfigNotInitialized {}));
@ -148,8 +148,8 @@ where
fs::write(&config_path, toml)?;
info!(
"Initial setup complete, config file created at {} ",
config_path.as_path().display()
path = %config_path.as_path().display(),
"Initial setup complete, config file created",
);
Ok(())
}

@ -21,7 +21,7 @@ pub fn init(level: LevelFilter) -> Result<()> {
builder.init();
}
tracing::info!("Initialized tracing with level: {}", level);
tracing::info!(%level, "Initialized tracing");
Ok(())
}

@ -35,7 +35,7 @@ use swap::protocol::alice::{redeem, run, EventLoop};
use swap::seed::Seed;
use swap::tor::AuthenticatedClient;
use swap::{asb, bitcoin, env, kraken, monero, tor};
use tracing::{info, warn};
use tracing::{debug, info, warn};
use tracing_subscriber::filter::LevelFilter;
#[macro_use]
@ -64,8 +64,8 @@ async fn main() -> Result<()> {
};
info!(
"Database and Seed will be stored in directory: {}",
config.data.dir.display()
db_folder = %config.data.dir.display(),
"Database and Seed will be stored in",
);
let db_path = config.data.dir.join("database");
@ -81,20 +81,21 @@ async fn main() -> Result<()> {
match opt.cmd {
Command::Start { resume_only } => {
let bitcoin_wallet = init_bitcoin_wallet(&config, &seed, env_config).await?;
let monero_wallet = init_monero_wallet(&config, env_config).await?;
let bitcoin_balance = bitcoin_wallet.balance().await?;
info!("Bitcoin balance: {}", bitcoin_balance);
info!(%bitcoin_balance, "Initialized Bitcoin wallet");
let monero_balance = monero_wallet.get_balance().await?;
if monero_balance == Amount::ZERO {
let deposit_address = monero_wallet.get_main_address();
let monero_address = monero_wallet.get_main_address();
warn!(
"The Monero balance is 0, make sure to deposit funds at: {}",
deposit_address
%monero_address,
"The Monero balance is 0, make sure to deposit funds",
)
} else {
info!("Monero balance: {}", monero_balance);
info!(%monero_balance, "Initialized Monero wallet");
}
let kraken_price_updates = kraken::connect()?;
@ -104,14 +105,14 @@ async fn main() -> Result<()> {
tor::Client::new(config.tor.socks5_port).with_control_port(config.tor.control_port);
let _ac = match tor_client.assert_tor_running().await {
Ok(_) => {
tracing::info!("Tor found. Setting up hidden service. ");
tracing::info!("Tor found. Setting up hidden service");
let ac =
register_tor_services(config.network.clone().listen, tor_client, &seed)
.await?;
Some(ac)
}
Err(_) => {
tracing::warn!("Tor not found. Running on clear net. ");
tracing::warn!("Tor not found. Running on clear net");
None
}
};
@ -153,17 +154,17 @@ async fn main() -> Result<()> {
let swap_id = swap.swap_id;
match run(swap, rate).await {
Ok(state) => {
tracing::debug!(%swap_id, "Swap finished with state {}", state)
tracing::debug!(%swap_id, %state, "Swap finished with state")
}
Err(e) => {
tracing::error!(%swap_id, "Swap failed with {:#}", e)
Err(error) => {
tracing::error!(%swap_id, %error, "Swap failed")
}
}
});
}
});
info!("Our peer id is {}", event_loop.peer_id());
info!(perr_id = %event_loop.peer_id(), "Our peer id");
event_loop.run().await;
}
@ -203,7 +204,10 @@ async fn main() -> Result<()> {
let bitcoin_balance = bitcoin_wallet.balance().await?;
let monero_balance = monero_wallet.get_balance().await?;
tracing::info!("Current balance: {}, {}", bitcoin_balance, monero_balance);
tracing::info!(
%bitcoin_balance,
%monero_balance,
"Current balance");
}
Command::ManualRecovery(ManualRecovery::Cancel {
cancel_params: RecoverCommandParams { swap_id, force },
@ -274,6 +278,7 @@ async fn init_bitcoin_wallet(
seed: &Seed,
env_config: swap::env::Config,
) -> Result<bitcoin::Wallet> {
debug!("Opening Bitcoin wallet");
let wallet_dir = config.data.dir.join("wallet");
let wallet = bitcoin::Wallet::new(
@ -295,6 +300,7 @@ async fn init_monero_wallet(
config: &Config,
env_config: swap::env::Config,
) -> Result<monero::Wallet> {
debug!("Opening Monero wallet");
let wallet = monero::Wallet::open_or_create(
config.monero.wallet_rpc_url.clone(),
DEFAULT_WALLET_NAME.to_string(),
@ -341,7 +347,8 @@ async fn register_tor_services(
.get_address_without_dot_onion();
hidden_services_details.iter().for_each(|(port, _)| {
tracing::info!("/onion3/{}:{}", onion_address, port);
let onion_address = format!("/onion3/{}:{}", onion_address, port);
tracing::info!(%onion_address);
});
Ok(ac)

@ -245,8 +245,7 @@ async fn main() -> Result<()> {
debug!("Cancel transaction successfully published with id {}", txid)
}
Err(bob::cancel::Error::CancelTimelockNotExpiredYet) => error!(
"The Cancel Transaction cannot be published yet, \
because the timelock has not expired. Please try again later."
"The Cancel Transaction cannot be published yet, because the timelock has not expired. Please try again later"
),
}
}

@ -102,7 +102,7 @@ impl Wallet {
format!("Failed to broadcast Bitcoin {} transaction {}", kind, txid)
})?;
tracing::info!(%txid, "Published Bitcoin {} transaction", kind);
tracing::info!(%txid, %kind, "Published Bitcoin transaction");
Ok((txid, subscription))
}
@ -154,15 +154,16 @@ impl Wallet {
let new_status = match client.lock().await.status_of_script(&tx) {
Ok(new_status) => new_status,
Err(e) => {
tracing::warn!(%txid, "Failed to get status of script: {:#}", e);
Err(error) => {
tracing::warn!(%txid, %error, "Failed to get status of script.");
return;
}
};
if Some(new_status) != last_status {
tracing::debug!(%txid, "Transaction is {}", new_status);
tracing::debug!(%txid, status = %new_status, "Transaction status.");
}
last_status = Some(new_status);
let all_receivers_gone = sender.send(new_status).is_err();
@ -200,7 +201,7 @@ impl Subscription {
let conf_target = self.finality_confirmations;
let txid = self.txid;
tracing::info!(%txid, "Waiting for {} confirmation{} of Bitcoin transaction", conf_target, if conf_target > 1 { "s" } else { "" });
tracing::info!(%txid, required_confirmation=%conf_target, "Waiting for Bitcoin transaction finality.");
let mut seen_confirmations = 0;
@ -209,15 +210,18 @@ impl Subscription {
let confirmations = inner.confirmations();
if confirmations > seen_confirmations {
tracing::info!(%txid, "Bitcoin tx has {} out of {} confirmation{}", confirmations, conf_target, if conf_target > 1 { "s" } else { "" });
tracing::info!(%txid,
seen_confirmations = %confirmations,
needed_confirmations = %conf_target,
"Waiting for Bitcoin transaction finality.");
seen_confirmations = confirmations;
}
inner.meets_target(conf_target)
},
_ => false
}
_ => false,
})
.await
.await
}
pub async fn wait_until_seen(&self) -> Result<()> {
@ -614,8 +618,8 @@ impl Client {
if let Some(new_block) = latest_block {
tracing::debug!(
"Got notification for new block at height {}",
new_block.height
block_height = new_block.height,
"Got notification for new block."
);
self.latest_block = BlockHeight::try_from(new_block)?;
}

@ -24,8 +24,8 @@ pub fn ensure_directory_exists(file: &Path) -> Result<(), std::io::Error> {
if let Some(path) = file.parent() {
if !path.exists() {
tracing::info!(
"Parent directory does not exist, creating recursively: {}",
file.display()
directory = %file.display(),
"Parent directory does not exist, creating recursively",
);
return std::fs::create_dir_all(path);
}

@ -50,7 +50,9 @@ pub fn connect() -> Result<PriceUpdates> {
match result {
Err(e) => {
tracing::warn!("Rate updates incurred an unrecoverable error: {:#}", e);
tracing::warn!(
error = %e,
"Rate updates incurred an unrecoverable error.");
// in case the retries fail permanently, let the subscribers know
price_update.send(Err(Error::PermanentFailure))
@ -183,8 +185,8 @@ mod connection {
// if the message is not an event, it is a ticker update or an unknown event
Err(_) => match serde_json::from_str::<wire::PriceUpdate>(&msg) {
Ok(ticker) => ticker,
Err(e) => {
tracing::warn!(%e, "Failed to deserialize message '{}' as ticker update", msg);
Err(error) => {
tracing::warn!(%error, %msg, "Failed to deserialize message as ticker update.");
return Ok(None);
}

@ -33,9 +33,9 @@ impl Wallet {
"Unable to create Monero wallet, please ensure that the monero-wallet-rpc is available",
)?;
tracing::debug!("Created Monero wallet {}", name);
tracing::debug!(monero_wallet_name = %name, "Created Monero wallet");
} else {
tracing::debug!("Opened Monero wallet {}", name);
tracing::debug!(monero_wallet_name = %name, "Opened Monero wallet");
}
Self::connect(client, name, env_config).await
@ -148,19 +148,22 @@ impl Wallet {
Ok(_) => match wallet.sweep_all(self.main_address.to_string()).await {
Ok(sweep_all) => {
for tx in sweep_all.tx_hash_list {
tracing::info!(%tx, "Monero transferred back to default wallet {}", self.main_address);
tracing::info!(
%tx,
monero_address = %self.main_address,
"Monero transferred back to default wallet");
}
}
Err(e) => {
Err(error) => {
tracing::warn!(
"Transferring Monero back to default wallet {} failed with {:#}",
self.main_address,
e
address = %self.main_address,
%error,
"Transferring Monero back to default wallet failed",
);
}
},
Err(e) => {
tracing::warn!("Refreshing the generated wallet failed with {:#}", e);
Err(error) => {
tracing::warn!(%error, "Refreshing the generated wallet failed");
}
}
@ -187,10 +190,10 @@ impl Wallet {
.await?;
tracing::debug!(
"sent transfer of {} to {} in {}",
amount,
public_spend_key,
res.tx_hash
%amount,
to = %public_spend_key,
tx_id = %res.tx_hash,
"Sent transfer"
);
Ok(TransferProof::new(
@ -211,7 +214,11 @@ impl Wallet {
let txid = transfer_proof.tx_hash();
tracing::info!(%txid, "Waiting for {} confirmation{} of Monero transaction", conf_target, if conf_target > 1 { "s" } else { "" });
tracing::info!(
%txid,
target_confirmations = %conf_target,
"Waiting for Monero transaction finality"
);
let address = Address::standard(self.network, public_spend_key, public_view_key.into());
@ -311,7 +318,11 @@ where
let tx = match fetch_tx(txid.clone()).await {
Ok(proof) => proof,
Err(error) => {
tracing::debug!(%txid, "Failed to retrieve tx from blockchain: {:#}", error);
tracing::debug!(
%txid,
%error,
"Failed to retrieve tx from blockchain"
);
continue; // treating every error as transient and retrying
// is obviously wrong but the jsonrpc client is
// too primitive to differentiate between all the
@ -330,7 +341,12 @@ where
if tx.confirmations > seen_confirmations {
seen_confirmations = tx.confirmations;
tracing::info!(%txid, "Monero lock tx has {} out of {} confirmations", tx.confirmations, conf_target);
tracing::info!(
%txid,
%seen_confirmations,
needed_confirmations = %conf_target,
"Received new confirmation for Monero lock tx"
);
}
}

@ -121,7 +121,10 @@ impl WalletRpc {
.local_addr()?
.port();
tracing::debug!("Starting monero-wallet-rpc on port {}", port);
tracing::debug!(
monero_wallet_rpc_port = %port,
"Starting monero-wallet-rpc on port"
);
let mut child = Command::new(self.exec_path())
.env("LANG", "en_AU.UTF-8")

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

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

@ -49,11 +49,11 @@ fn with_clear_net<B>(seed: &Seed, behaviour: B) -> Result<Swarm<B>>
where
B: NetworkBehaviour,
{
tracing::info!("All connections will go through clear net.");
tracing::info!("All connections will go through clear net");
let identity = seed.derive_libp2p_identity();
let transport = transport::build_clear_net(&identity)?;
let peer_id = identity.public().into_peer_id();
tracing::debug!("Our peer-id: {}", peer_id);
tracing::debug!(%peer_id, "Our peer-id");
let swarm = SwarmBuilder::new(transport, behaviour, peer_id)
.executor(Box::new(|f| {
@ -68,11 +68,11 @@ async fn with_tor<B>(seed: &Seed, behaviour: B, tor_socks5_port: u16) -> Result<
where
B: NetworkBehaviour,
{
tracing::info!("All connections will go through Tor socks5 proxy.");
tracing::info!("All connections will go through Tor socks5 proxy");
let identity = seed.derive_libp2p_identity();
let transport = transport::build_tor(&identity, tor_socks5_port)?;
let peer_id = identity.public().into_peer_id();
tracing::debug!("Our peer-id: {}", peer_id);
tracing::debug!(%peer_id, "Our peer-id");
let swarm = SwarmBuilder::new(transport, behaviour, peer_id)
.executor(Box::new(|f| {

@ -58,11 +58,11 @@ impl Transport for TorTcpConfig {
Ok(tor_address_string) => {
Ok(Box::pin(do_tor_dial(self.socks_port, tor_address_string)))
}
Err(e) => {
Err(error) => {
tracing::warn!(
"Address {} could not be formatted. Dialling via clear net. Details: {}",
addr,
e
address = %addr,
%error,
"Address could not be formatted. Dialling via clear net.",
);
self.inner.dial(addr)
}

@ -199,8 +199,8 @@ where
&mut OsRng
) {
Ok(state) => state,
Err(e) => {
tracing::warn!(%peer, "Failed to make State0 for execution setup: {:#}", e);
Err(error) => {
tracing::warn!(%peer, %error, "Failed to make State0 for execution setup.");
continue;
}
};
@ -235,8 +235,8 @@ where
let quote = match self.make_quote(self.min_buy, self.max_buy).await {
Ok(quote) => quote,
Err(e) => {
tracing::warn!(%peer, "Failed to make quote: {:#}", e);
Err(error) => {
tracing::warn!(%peer, %error, "Failed to make quote.");
continue;
}
};
@ -262,7 +262,10 @@ where
let swap_peer = match swap_peer {
Ok(swap_peer) => swap_peer,
Err(_) => {
tracing::warn!("Ignoring encrypted signature for unknown swap {} from {}", swap_id, peer);
tracing::warn!(
unknown_swap_id = %swap_id,
from = %peer,
"Ignoring encrypted signature for unknown swap.");
continue;
}
};
@ -270,9 +273,10 @@ where
if swap_peer != peer {
tracing::warn!(
%swap_id,
"Ignoring malicious encrypted signature from {}, expected to receive it from {}",
peer,
swap_peer);
received_from = %peer,
expected_from = %swap_peer,
"Ignoring malicious encrypted signature which was not expected from this peer.",
);
continue;
}
@ -300,7 +304,10 @@ where
}.boxed());
}
SwarmEvent::Behaviour(OutEvent::Failure {peer, error}) => {
tracing::error!(%peer, "Communication error: {:#}", error);
tracing::error!(
%peer,
%error,
"Communication error");
}
SwarmEvent::ConnectionEstablished { peer_id: peer, endpoint, .. } => {
tracing::debug!(%peer, address = %endpoint.get_remote_address(), "New connection established");
@ -315,20 +322,20 @@ where
}
}
SwarmEvent::IncomingConnectionError { send_back_addr: address, error, .. } => {
tracing::warn!(%address, "Failed to set up connection with peer: {}", error);
tracing::warn!(%address, %error, "Failed to set up connection with peer. ");
}
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(), "Lost connection: {}", error);
tracing::warn!(%peer, address = %endpoint.get_remote_address(), %error, "Lost connection.");
},
None => {
tracing::info!(%peer, address = %endpoint.get_remote_address(), "Successfully closed connection");
tracing::info!(%peer, address = %endpoint.get_remote_address(), "Successfully closed connection.");
}
}
}
SwarmEvent::NewListenAddr(addr) => {
tracing::info!("Listening on {}", addr);
SwarmEvent::NewListenAddr(address) => {
tracing::info!(%address, "Listening on");
}
_ => {}
}
@ -345,8 +352,8 @@ where
let id = self.swarm.behaviour_mut().transfer_proof.send_request(&peer, transfer_proof);
self.inflight_transfer_proofs.insert(id, responder);
},
Some(Err(e)) => {
tracing::debug!("A swap stopped without sending a transfer proof: {:#}", e);
Some(Err(error)) => {
tracing::debug!(%error, "A swap stopped without sending a transfer proof.");
}
None => {
unreachable!("stream of transfer proof receivers must never terminate")

@ -8,7 +8,7 @@ use crate::{bitcoin, database, monero};
use anyhow::{bail, Context, Result};
use tokio::select;
use tokio::time::timeout;
use tracing::{error, info};
use tracing::{error, info, warn};
use uuid::Uuid;
pub async fn run<LR>(swap: Swap, rate_service: LR) -> Result<AliceState>
@ -66,7 +66,7 @@ where
.latest_rate()
.map_or("NaN".to_string(), |rate| format!("{}", rate));
info!(%state, %rate, "Update");
info!(%state, %rate, "Advancing state");
Ok(match state {
AliceState::Started { state3 } => {
@ -78,10 +78,10 @@ where
.await
{
Err(_) => {
tracing::info!(
"TxLock lock did not get {} confirmations in {} minutes",
env_config.bitcoin_finality_confirmations,
env_config.bitcoin_lock_confirmed_timeout.as_secs_f64() / 60.0
info!(
confirmations_needed = %env_config.bitcoin_finality_confirmations,
minutes = %env_config.bitcoin_lock_confirmed_timeout.as_secs_f64() / 60.0,
"TxLock lock did not get enough confirmations in time",
);
AliceState::SafelyAborted
}
@ -183,7 +183,7 @@ where
}
}
enc_sig = event_loop_handle.recv_encrypted_signature() => {
tracing::info!("Received encrypted signature");
info!("Received encrypted signature");
AliceState::EncSigLearned {
monero_wallet_restore_blockheight,
@ -210,8 +210,10 @@ where
bail!("Waiting for Bitcoin transaction finality failed with {}! The redeem transaction was published, but it is not ensured that the transaction was included! You're screwed.", e)
}
},
Err(e) => {
error!("Publishing the redeem transaction failed with {}, attempting to wait for cancellation now. If you restart the application before the timelock is expired publishing the redeem transaction will be retried.", e);
Err(error) => {
error!(
%error,
"Publishing the redeem transaction failed");
tx_lock_status
.wait_until_confirmed_with(state3.cancel_timelock)
.await?;
@ -223,8 +225,10 @@ where
}
}
},
Err(e) => {
error!("Constructing the redeem transaction failed with {}, attempting to wait for cancellation now.", e);
Err(error) => {
error!(
%error,
"Constructing the redeem transaction failed. Attempting to wait for cancellation now");
tx_lock_status
.wait_until_confirmed_with(state3.cancel_timelock)
.await?;
@ -325,10 +329,10 @@ where
match punish {
Ok(_) => AliceState::BtcPunished,
Err(e) => {
tracing::warn!(
"Falling back to refund because punish transaction failed with {:#}",
e
Err(error) => {
warn!(
%error,
"Falling back to refund because punish transaction failed"
);
// Upon punish failure we assume that the refund tx was included but we

@ -134,7 +134,7 @@ impl EventLoop {
if swap_id != self.swap_id {
// TODO: Save unexpected transfer proofs in the database and check for messages in the database when handling swaps
tracing::warn!("Received unexpected transfer proof for swap {} while running swap {}. This transfer proof will be ignored.", swap_id, self.swap_id);
tracing::warn!("Received unexpected transfer proof for swap {} while running swap {}. This transfer proof will be ignored", swap_id, self.swap_id);
// When receiving a transfer proof that is unexpected we still have to acknowledge that it was received
let _ = self.swarm.behaviour_mut().transfer_proof.send_response(channel, ());

Loading…
Cancel
Save