From d1ffc26cce885bdf3d2fd40f9a057f5fdda741ea Mon Sep 17 00:00:00 2001 From: mojoX911 Date: Sun, 1 Aug 2021 18:02:00 +0530 Subject: [PATCH 1/3] Adds env_logger This adds an env_logger and sets it up in main. Its run within a std::sync::Once to ensure its only setup once even though main executes multiple times. Logger will throw error otherwise. Adds logging in the test. --- Cargo.toml | 1 + src/main.rs | 17 +++++++++++++++++ src/maker_protocol.rs | 32 ++++++++++++++++---------------- src/taker_protocol.rs | 26 +++++++++++++------------- 4 files changed, 47 insertions(+), 29 deletions(-) diff --git a/Cargo.toml b/Cargo.toml index 4a070873..652a7bcf 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -15,6 +15,7 @@ serde = { version = "1.0", features = ["derive"] } serde_json = "1.0" tokio = { version = "0.3", features = ["full"] } log = "^0.4" +env_logger = "0.7" futures = "0.3" rand = "0.7.3" itertools = "0.9.0" diff --git a/src/main.rs b/src/main.rs index 66944a24..95b8f658 100644 --- a/src/main.rs +++ b/src/main.rs @@ -6,6 +6,7 @@ use dirs::home_dir; use std::io; use std::iter::repeat; use std::path::PathBuf; +use std::sync::Once; use std::sync::{Arc, RwLock}; use bitcoin::hashes::hex::ToHex; @@ -340,7 +341,21 @@ enum Subcommand { CoinswapSend, } +static INIT: Once = Once::new(); + +/// Setup function that will only run once, even if called multiple times. +fn setup_logger() { + INIT.call_once(|| { + env_logger::builder() + .is_test(true) + .filter_module("teleport", log::LevelFilter::Trace) + .init(); + }); +} + fn main() -> Result<(), Box> { + setup_logger(); + let args = ArgsWithWalletFile::from_args(); match args.subcommand { @@ -429,6 +444,8 @@ mod test { // wallet name `teleport` loaded and have enough balance to execute transactions. #[tokio::test] async fn test_standard_coin_swap() { + setup_logger(); + let rpc = get_bitcoin_rpc().unwrap(); // unlock all utxos to avoid "insufficient fund" error diff --git a/src/maker_protocol.rs b/src/maker_protocol.rs index 3e304aa8..b888d048 100644 --- a/src/maker_protocol.rs +++ b/src/maker_protocol.rs @@ -49,8 +49,8 @@ enum ExpectedMessage { #[tokio::main] pub async fn start_maker(rpc: Arc, wallet: Arc>, port: u16) { match run(rpc, wallet, port).await { - Ok(_o) => println!("maker ended without error"), - Err(e) => println!("maker ended with err {:?}", e), + Ok(_o) => log::trace!("maker ended without error"), + Err(e) => log::trace!("maker ended with err {:?}", e), }; } @@ -64,7 +64,7 @@ struct ConnectionState { async fn run(rpc: Arc, wallet: Arc>, port: u16) -> Result<(), Error> { //TODO port number in config file let listener = TcpListener::bind((Ipv4Addr::LOCALHOST, port)).await?; - log::trace!(target: "maker", "listening on port {}", port); + log::trace!("listening on port {}", port); let (server_loop_comms_tx, mut server_loop_comms_rx) = mpsc::channel::(100); let mut accepting_clients = true; @@ -75,12 +75,12 @@ async fn run(rpc: Arc, wallet: Arc>, port: u16) -> Result //unwrap the option here because we'll never close the mscp so it will always work match client_err.as_ref().unwrap() { Error::Rpc(_e) => { - println!("lost connection with bitcoin node, temporarily shutting \ + log::trace!("lost connection with bitcoin node, temporarily shutting \ down server until connection reestablished"); accepting_clients = false; continue; }, - _ => println!("ending server"), + _ => log::trace!("ending server"), } break Err(client_err.unwrap()); }, @@ -88,17 +88,17 @@ async fn run(rpc: Arc, wallet: Arc>, port: u16) -> Result _ = sleep(Duration::from_secs(60)) => { let r = rpc.get_best_block_hash(); accepting_clients = r.is_ok(); - println!("timeout branch, accepting clients={}", accepting_clients); + log::trace!("timeout branch, accepting clients={}", accepting_clients); continue; }, }; if !accepting_clients { - println!("rejecting connection from {:?}", addr); + log::trace!("rejecting connection from {:?}", addr); continue; } - println!("accepted connection from {:?}", addr); + log::trace!("accepted connection from {:?}", addr); let client_rpc = Arc::clone(&rpc); let client_wallet = Arc::clone(&wallet); let server_loop_comms_tx = server_loop_comms_tx.clone(); @@ -123,7 +123,7 @@ async fn run(rpc: Arc, wallet: Arc>, port: u16) -> Result ) .await { - println!("io error sending first message: {:?}", e); + log::trace!("io error sending first message: {:?}", e); return; } @@ -131,12 +131,12 @@ async fn run(rpc: Arc, wallet: Arc>, port: u16) -> Result let mut line = String::new(); match reader.read_line(&mut line).await { Ok(n) if n == 0 => { - log::trace!(target: "maker", "reached EOF"); + log::trace!("reached EOF"); break; } Ok(_n) => (), Err(e) => { - println!("error reading from socket: {:?}", e); + log::trace!("error reading from socket: {:?}", e); break; } }; @@ -146,7 +146,7 @@ async fn run(rpc: Arc, wallet: Arc>, port: u16) -> Result .send(Error::Protocol("kill signal")) .await .unwrap(); - println!("Kill signal received, stopping maker...."); + log::trace!("Kill signal received, stopping maker...."); break; } @@ -161,14 +161,14 @@ async fn run(rpc: Arc, wallet: Arc>, port: u16) -> Result Ok(reply) => { if let Some(message) = reply { if let Err(e) = send_message(&mut socket_writer, &message).await { - println!("closing due to io error sending message: {:?}", e); + log::trace!("closing due to io error sending message: {:?}", e); break; } } //if reply is None then dont send anything to client } Err(err) => { - println!("error handling client request: {:?}", err); + log::trace!("error handling client request: {:?}", err); match err { Error::Network(_e) => (), Error::Protocol(_e) => (), @@ -425,7 +425,7 @@ fn handle_proof_of_funding( &funding_info.contract_redeemscript, ); let (coin_privkey, coin_other_pubkey, hashlock_privkey) = incoming_swapcoin_keys; - println!( + log::trace!( "adding incoming_swapcoin contract_tx = {:?} fo = {:?}", my_receivers_contract_tx.clone(), funding_output @@ -672,6 +672,6 @@ fn handle_private_key_handover( } } wallet_ref.update_swap_coins_list()?; - println!("successfully completed coinswap"); + log::trace!("successfully completed coinswap"); Ok(None) } diff --git a/src/taker_protocol.rs b/src/taker_protocol.rs index 8f4036d9..c464bec2 100644 --- a/src/taker_protocol.rs +++ b/src/taker_protocol.rs @@ -48,13 +48,13 @@ use crate::wallet_sync::{ pub async fn start_taker(rpc: &Client, wallet: &mut Wallet) { match run(rpc, wallet).await { Ok(_o) => (), - Err(e) => log::trace!(target: "taker", "err {:?}", e), + Err(e) => log::trace!("err {:?}", e), }; } async fn run(rpc: &Client, wallet: &mut Wallet) -> Result<(), Error> { let mut offers_addresses = sync_offerbook().await; - log::trace!(target: "taker", "offers_addresses = {:?}", offers_addresses); + log::trace!("offers_addresses = {:?}", offers_addresses); send_coinswap(rpc, wallet, &mut offers_addresses).await?; Ok(()) @@ -79,7 +79,7 @@ async fn send_coinswap( let first_maker = maker_offers_addresses.last().unwrap(); let last_maker = maker_offers_addresses.first().unwrap().clone(); - log::trace!(target: "taker", "coinswapping to first maker1 = {}", first_maker.address); + log::trace!("coinswapping to first maker1 = {}", first_maker.address); let ( first_maker_multisig_pubkeys, @@ -139,7 +139,7 @@ async fn send_coinswap( for maker_index in 0..maker_count { let maker = maker_offers_addresses.pop().unwrap(); - log::trace!(target: "taker", "coinswapping to maker = {:?}", maker.address); + log::trace!("coinswapping to maker = {:?}", maker.address); let maker_refund_locktime = REFUND_LOCKTIME + REFUND_LOCKTIME_STEP * (maker_count - maker_index - 1); let is_taker_next_peer = maker_index == maker_count - 1; @@ -396,7 +396,7 @@ async fn send_coinswap( } wallet.update_swap_coins_list().unwrap(); - println!("successfully completed coinswap"); + log::trace!("successfully completed coinswap"); Ok(()) } @@ -404,7 +404,7 @@ async fn send_message( socket_writer: &mut WriteHalf<'_>, message: TakerToMakerMessage, ) -> Result<(), Error> { - println!("=> {:?}", message); + log::trace!("=> {:?}", message); let mut result_bytes = serde_json::to_vec(&message).map_err(|e| io::Error::from(e))?; result_bytes.push(b'\n'); socket_writer.write_all(&result_bytes).await?; @@ -426,14 +426,14 @@ async fn read_message(reader: &mut BufReader>) -> Result return Err(Error::Protocol("json parsing error")), }; - log::trace!(target: "taker", "<= {:?}", message); + log::trace!("<= {:?}", message); Ok(message) } async fn handshake_maker( socket: &mut TcpStream, ) -> Result<(BufReader>, WriteHalf<'_>), Error> { - println!("connected to maker"); + log::trace!("connected to maker"); let (reader, mut socket_writer) = socket.split(); let mut socket_reader = BufReader::new(reader); @@ -513,7 +513,7 @@ async fn request_senders_contract_tx_signatures( hashvalue: Hash160, locktime: u16, ) -> Result, Error> { - println!( + log::trace!( "requesting senders contract tx sig from maker = {}", maker_address ); @@ -578,7 +578,7 @@ async fn request_receivers_contract_tx_signatures( incoming_swapcoins: &[S], receivers_contract_txes: &[Transaction], ) -> Result, Error> { - println!( + log::trace!( "requesting receivers contract tx sig from maker = {}", maker_address ); @@ -625,7 +625,7 @@ async fn wait_for_funding_tx_confirmation( rpc: &Client, funding_txids: &[Txid], ) -> Result<(Vec, Vec), Error> { - println!( + log::trace!( "waiting for funding transaction to confirm, txids={:?}", funding_txids ); @@ -645,7 +645,7 @@ async fn wait_for_funding_tx_confirmation( if gettx.info.confirmations >= 1 { txid_tx_map.insert(*txid, deserialize::(&gettx.hex).unwrap()); txid_blockhash_map.insert(*txid, gettx.info.blockhash.unwrap()); - log::trace!(target: "taker", "funding tx {} reached 1 confirmation(s)", txid); + log::trace!("funding tx {} reached 1 confirmation(s)", txid); } } if txid_tx_map.len() == funding_txids.len() { @@ -655,7 +655,7 @@ async fn wait_for_funding_tx_confirmation( #[cfg(test)] crate::test::generate_1_block(&get_bitcoin_rpc().unwrap()); } - log::trace!(target: "taker", "funding transactions confirmed"); + log::trace!("funding transactions confirmed"); let txes = funding_txids .iter() From 7920f1f2e9dfca04fd8699cd31012cd374c9f322 Mon Sep 17 00:00:00 2001 From: mojoX911 Date: Fri, 3 Sep 2021 23:03:41 +0530 Subject: [PATCH 2/3] Fixed Logging initialisation --- src/main.rs | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/src/main.rs b/src/main.rs index 95b8f658..7a190545 100644 --- a/src/main.rs +++ b/src/main.rs @@ -346,10 +346,12 @@ static INIT: Once = Once::new(); /// Setup function that will only run once, even if called multiple times. fn setup_logger() { INIT.call_once(|| { - env_logger::builder() - .is_test(true) - .filter_module("teleport", log::LevelFilter::Trace) - .init(); + env_logger::Builder::from_env( + env_logger::Env::default() + .default_filter_or("teleport=info") + .default_write_style_or("always"), + ) + .init(); }); } From 10ee94d9237c0d9ce3b66887687d3d681aa0cc33 Mon Sep 17 00:00:00 2001 From: mojoX911 Date: Fri, 3 Sep 2021 23:04:20 +0530 Subject: [PATCH 3/3] Add more logging informations - Logging framework is refactored to categorize loggings into `info`, `debug`, `warn` and `error`. - Default logging level is `info` - Generic Logging format: "===> [Peer Port] | " - Object details are hidden in `debug` level Objective of more extensive logging is to observe protocol communications in more readable mode. Can be helpful for new devs. --- src/maker_protocol.rs | 132 +++++++++++++++++++++++++++++++----------- src/taker_protocol.rs | 123 +++++++++++++++++++++++++++------------ 2 files changed, 182 insertions(+), 73 deletions(-) diff --git a/src/maker_protocol.rs b/src/maker_protocol.rs index b888d048..6c79c226 100644 --- a/src/maker_protocol.rs +++ b/src/maker_protocol.rs @@ -1,4 +1,4 @@ -use std::net::Ipv4Addr; +use std::net::{Ipv4Addr, SocketAddr}; use std::sync::{Arc, RwLock}; use std::time::Duration; @@ -49,8 +49,8 @@ enum ExpectedMessage { #[tokio::main] pub async fn start_maker(rpc: Arc, wallet: Arc>, port: u16) { match run(rpc, wallet, port).await { - Ok(_o) => log::trace!("maker ended without error"), - Err(e) => log::trace!("maker ended with err {:?}", e), + Ok(_o) => log::info!("maker ended without error"), + Err(e) => log::info!("maker ended with err {:?}", e), }; } @@ -64,7 +64,7 @@ struct ConnectionState { async fn run(rpc: Arc, wallet: Arc>, port: u16) -> Result<(), Error> { //TODO port number in config file let listener = TcpListener::bind((Ipv4Addr::LOCALHOST, port)).await?; - log::trace!("listening on port {}", port); + log::info!("Listening On Port {}", port); let (server_loop_comms_tx, mut server_loop_comms_rx) = mpsc::channel::(100); let mut accepting_clients = true; @@ -75,12 +75,12 @@ async fn run(rpc: Arc, wallet: Arc>, port: u16) -> Result //unwrap the option here because we'll never close the mscp so it will always work match client_err.as_ref().unwrap() { Error::Rpc(_e) => { - log::trace!("lost connection with bitcoin node, temporarily shutting \ + log::warn!("lost connection with bitcoin node, temporarily shutting \ down server until connection reestablished"); accepting_clients = false; continue; }, - _ => log::trace!("ending server"), + _ => log::error!("ending server"), } break Err(client_err.unwrap()); }, @@ -88,17 +88,17 @@ async fn run(rpc: Arc, wallet: Arc>, port: u16) -> Result _ = sleep(Duration::from_secs(60)) => { let r = rpc.get_best_block_hash(); accepting_clients = r.is_ok(); - log::trace!("timeout branch, accepting clients={}", accepting_clients); + log::info!("Timeout Branch, Accepting Clients @ {}", port); continue; }, }; if !accepting_clients { - log::trace!("rejecting connection from {:?}", addr); + log::warn!("Rejecting Connection From {:?}", addr); continue; } - log::trace!("accepted connection from {:?}", addr); + log::info!("<=== [{}] | Accepted Connection From", addr.port()); let client_rpc = Arc::clone(&rpc); let client_wallet = Arc::clone(&wallet); let server_loop_comms_tx = server_loop_comms_tx.clone(); @@ -123,7 +123,7 @@ async fn run(rpc: Arc, wallet: Arc>, port: u16) -> Result ) .await { - log::trace!("io error sending first message: {:?}", e); + log::error!("io error sending first message: {:?}", e); return; } @@ -131,12 +131,12 @@ async fn run(rpc: Arc, wallet: Arc>, port: u16) -> Result let mut line = String::new(); match reader.read_line(&mut line).await { Ok(n) if n == 0 => { - log::trace!("reached EOF"); + log::info!("Reached EOF"); break; } Ok(_n) => (), Err(e) => { - log::trace!("error reading from socket: {:?}", e); + log::error!("error reading from socket: {:?}", e); break; } }; @@ -146,7 +146,7 @@ async fn run(rpc: Arc, wallet: Arc>, port: u16) -> Result .send(Error::Protocol("kill signal")) .await .unwrap(); - log::trace!("Kill signal received, stopping maker...."); + log::info!("Kill signal received, stopping maker...."); break; } @@ -156,19 +156,20 @@ async fn run(rpc: Arc, wallet: Arc>, port: u16) -> Result &mut connection_state, Arc::clone(&client_rpc), Arc::clone(&client_wallet), + addr, ); match message_result { Ok(reply) => { if let Some(message) = reply { if let Err(e) = send_message(&mut socket_writer, &message).await { - log::trace!("closing due to io error sending message: {:?}", e); + log::error!("closing due to io error sending message: {:?}", e); break; } } //if reply is None then dont send anything to client } Err(err) => { - log::trace!("error handling client request: {:?}", err); + log::error!("error handling client request: {:?}", err); match err { Error::Network(_e) => (), Error::Protocol(_e) => (), @@ -202,16 +203,17 @@ fn handle_message( connection_state: &mut ConnectionState, rpc: Arc, wallet: Arc>, + from_addrs: SocketAddr, ) -> Result, Error> { let request: TakerToMakerMessage = match serde_json::from_str(&line) { Ok(r) => r, Err(_e) => return Err(Error::Protocol("message parsing error")), }; - log::trace!(target: "maker", "<== {:?}", request); let outgoing_message = match connection_state.allowed_message { ExpectedMessage::TakerHello => { if let TakerToMakerMessage::TakerHello(_) = request { + log::debug!("{:#?}", request); connection_state.allowed_message = ExpectedMessage::NewlyConnectedTaker; None } else { @@ -220,6 +222,8 @@ fn handle_message( } ExpectedMessage::NewlyConnectedTaker => match request { TakerToMakerMessage::GiveOffer(_) => { + log::info!("<=== [{}] | Recieved GiveOffer", from_addrs.port()); + log::info!("===> [{}] | Sending Offer Data", from_addrs.port()); let max_size = wallet.read().unwrap().get_offer_maxsize(rpc)?; let tweakable_point = wallet.read().unwrap().get_tweakable_keypair().1; connection_state.allowed_message = ExpectedMessage::SignSendersContractTx; @@ -232,18 +236,42 @@ fn handle_message( })) } TakerToMakerMessage::SignSendersContractTx(message) => { + log::info!( + "<=== [{}] | Recieved SignSendersContractTx ", + from_addrs.port() + ); + log::info!("===> [{}] | Sending SendersContractSig", from_addrs.port()); + log::debug!("{:#?}", message); connection_state.allowed_message = ExpectedMessage::ProofOfFunding; handle_sign_senders_contract_tx(wallet, message)? } TakerToMakerMessage::ProofOfFunding(proof) => { + log::info!("<=== [{}] | Recieved ProofOfFunding", from_addrs.port()); + log::info!( + "===> [{}] | Sending SignSendersAndReceiversContractTxes", + from_addrs.port() + ); + log::debug!("{:#?}", proof); connection_state.allowed_message = ExpectedMessage::SendersAndReceiversContractSigs; handle_proof_of_funding(connection_state, rpc, wallet, &proof)? } TakerToMakerMessage::SignReceiversContractTx(message) => { + log::info!( + "<=== [{}] | Recieved SignReceiversContractTx", + from_addrs.port() + ); + log::info!( + "===> [{}] | Sending ReceiversContractSig", + from_addrs.port() + ); + log::debug!("{:#?}", message); connection_state.allowed_message = ExpectedMessage::HashPreimage; handle_sign_receivers_contract_tx(wallet, message)? } TakerToMakerMessage::HashPreimage(message) => { + log::info!("<=== [{}] | Recieved HashPreimage", from_addrs.port()); + log::info!("===> [{}] | Sending Private Keys", from_addrs.port()); + log::debug!("{:#?}", message); connection_state.allowed_message = ExpectedMessage::PrivateKeyHandover; handle_hash_preimage(wallet, message)? } @@ -253,6 +281,12 @@ fn handle_message( }, ExpectedMessage::SignSendersContractTx => { if let TakerToMakerMessage::SignSendersContractTx(message) = request { + log::info!( + "<=== [{}] | Recieved SignSendersContractTx ", + from_addrs.port() + ); + log::info!("===> [{}] | Sending SendersContractSig", from_addrs.port()); + log::debug!("{:#?}", message); connection_state.allowed_message = ExpectedMessage::ProofOfFunding; handle_sign_senders_contract_tx(wallet, message)? } else { @@ -263,6 +297,12 @@ fn handle_message( } ExpectedMessage::ProofOfFunding => { if let TakerToMakerMessage::ProofOfFunding(proof) = request { + log::info!("<=== [{}] | Recieved ProofOfFunding", from_addrs.port()); + log::info!( + "===> [{}] | Sending SignSendersAndReceiversContractTxes", + from_addrs.port() + ); + log::debug!("{:#?}", proof); connection_state.allowed_message = ExpectedMessage::SendersAndReceiversContractSigs; handle_proof_of_funding(connection_state, rpc, wallet, &proof)? } else { @@ -271,6 +311,12 @@ fn handle_message( } ExpectedMessage::SendersAndReceiversContractSigs => { if let TakerToMakerMessage::SendersAndReceiversContractSigs(message) = request { + log::info!( + "<=== [{}] | Recieved SendersAndReceiversContractSigs", + from_addrs.port() + ); + // Nothing to send. Maker now creates and broadcasts his funding Txs + log::debug!("{:#?}", message); connection_state.allowed_message = ExpectedMessage::SignReceiversContractTx; handle_senders_and_receivers_contract_sigs(connection_state, rpc, wallet, message)? } else { @@ -281,6 +327,15 @@ fn handle_message( } ExpectedMessage::SignReceiversContractTx => { if let TakerToMakerMessage::SignReceiversContractTx(message) = request { + log::info!( + "<=== [{}] | Recieved SignReceiversContractTx", + from_addrs.port() + ); + log::info!( + "===> [{}] | Sending ReceiversContractSig", + from_addrs.port() + ); + log::debug!("{:#?}", message); connection_state.allowed_message = ExpectedMessage::HashPreimage; handle_sign_receivers_contract_tx(wallet, message)? } else { @@ -289,6 +344,9 @@ fn handle_message( } ExpectedMessage::HashPreimage => { if let TakerToMakerMessage::HashPreimage(message) = request { + log::info!("<=== [{}] | Recieved HashPreimage", from_addrs.port()); + log::info!("===> [{}] | Sending Private Keys", from_addrs.port()); + log::debug!("{:#?}", message); connection_state.allowed_message = ExpectedMessage::PrivateKeyHandover; handle_hash_preimage(wallet, message)? } else { @@ -297,6 +355,9 @@ fn handle_message( } ExpectedMessage::PrivateKeyHandover => { if let TakerToMakerMessage::PrivateKeyHandover(message) = request { + log::info!("<=== [{}] | Recieved Private Keys", from_addrs.port()); + // Nothing to send. Succesfully completed swap + log::debug!("{:#?}", message); handle_private_key_handover(wallet, message)? } else { return Err(Error::Protocol("expected privatekey handover")); @@ -304,9 +365,11 @@ fn handle_message( } }; - log::trace!(target: "maker", "==> {:?}", outgoing_message); match outgoing_message { - Some(result) => Ok(Some(result)), + Some(result) => { + log::debug!("{:#?}", result); + Ok(Some(result)) + } None => Ok(None), } } @@ -354,9 +417,10 @@ fn handle_proof_of_funding( for funding_info in &proof.confirmed_funding_txes { //check that the claimed multisig redeemscript is in the transaction - log::trace!(target: "maker", - "tx = {:?}\nms_rs = {:x}", - funding_info.funding_tx, funding_info.multisig_redeemscript + log::debug!( + "Proof of Funding: \ntx = {:#?}\nMultisig_Reedimscript = {:x}", + funding_info.funding_tx, + funding_info.multisig_redeemscript ); let (funding_output_index, funding_output) = match find_funding_output( &funding_info.funding_tx, @@ -397,7 +461,7 @@ fn handle_proof_of_funding( } } - log::trace!(target: "maker", "proof of funding valid, creating own funding txes"); + log::debug!("proof of funding valid, creating own funding txes"); connection_state.incoming_swapcoins = Some(Vec::::new()); for (funding_info, &funding_output_index, &funding_output, &incoming_swapcoin_keys) in izip!( @@ -425,8 +489,8 @@ fn handle_proof_of_funding( &funding_info.contract_redeemscript, ); let (coin_privkey, coin_other_pubkey, hashlock_privkey) = incoming_swapcoin_keys; - log::trace!( - "adding incoming_swapcoin contract_tx = {:?} fo = {:?}", + log::debug!( + "Adding incoming_swapcoin contract_tx = {:?} fo = {:?}", my_receivers_contract_tx.clone(), funding_output ); @@ -447,7 +511,7 @@ fn handle_proof_of_funding( //set up the next coinswap address in the route let coinswap_fees = 10000; //TODO calculate them properly let incoming_amount = funding_outputs.iter().map(|o| o.value).sum::(); - log::trace!(target: "maker", "incoming amount = {}", incoming_amount); + log::debug!("incoming amount = {}", incoming_amount); let amount = incoming_amount - coinswap_fees; let (my_funding_txes, outgoing_swapcoins, timelock_pubkeys) = @@ -468,13 +532,14 @@ fn handle_proof_of_funding( proof.next_locktime, )?; - log::trace!(target: "maker", "my_funding_txes = {:?}", my_funding_txes); + log::debug!("My Funding Transactions = {:#?}", my_funding_txes); connection_state.pending_funding_txes = Some(my_funding_txes); connection_state.outgoing_swapcoins = Some(outgoing_swapcoins); - log::trace!(target: "maker", - "incoming_swapcoins = {:?}\noutgoing_swapcoins = {:?}", - connection_state.incoming_swapcoins, connection_state.outgoing_swapcoins, + log::debug!( + "Incoming_swapcoins = {:#?}\nOutgoing_swapcoins = {:#?}", + connection_state.incoming_swapcoins, + connection_state.outgoing_swapcoins, ); Ok(Some( MakerToTakerMessage::SignSendersAndReceiversContractTxes( @@ -562,13 +627,10 @@ fn handle_senders_and_receivers_contract_sigs( //TODO add coin to watchtowers for my_funding_tx in connection_state.pending_funding_txes.as_ref().unwrap() { - log::trace!(target: "maker", - "broadcasting tx = {}", - bitcoin::consensus::encode::serialize_hex(my_funding_tx) - ); + log::debug!("Broadcasting My Funding Tx : {:#?}", my_funding_tx); let txid = rpc.send_raw_transaction(my_funding_tx)?; assert_eq!(txid, my_funding_tx.txid()); - log::trace!(target: "maker", "broadcasted my funding tx, txid={}", txid); + log::info!("Broadcasted My Funding Tx: {}", txid); } //set these to None which might be helpful in picking up logic errors later @@ -672,6 +734,6 @@ fn handle_private_key_handover( } } wallet_ref.update_swap_coins_list()?; - log::trace!("successfully completed coinswap"); + log::info!("Successfully Completed Coinswap"); Ok(None) } diff --git a/src/taker_protocol.rs b/src/taker_protocol.rs index c464bec2..83838839 100644 --- a/src/taker_protocol.rs +++ b/src/taker_protocol.rs @@ -48,13 +48,14 @@ use crate::wallet_sync::{ pub async fn start_taker(rpc: &Client, wallet: &mut Wallet) { match run(rpc, wallet).await { Ok(_o) => (), - Err(e) => log::trace!("err {:?}", e), + Err(e) => log::error!("err {:?}", e), }; } async fn run(rpc: &Client, wallet: &mut Wallet) -> Result<(), Error> { let mut offers_addresses = sync_offerbook().await; - log::trace!("offers_addresses = {:?}", offers_addresses); + log::info!("<=== Got Offers"); + log::debug!("Offers : {:#?}", offers_addresses); send_coinswap(rpc, wallet, &mut offers_addresses).await?; Ok(()) @@ -79,7 +80,8 @@ async fn send_coinswap( let first_maker = maker_offers_addresses.last().unwrap(); let last_maker = maker_offers_addresses.first().unwrap().clone(); - log::trace!("coinswapping to first maker1 = {}", first_maker.address); + let first_maker_port = first_maker.address.split(":").collect::>()[1]; + let last_maker_port = last_maker.address.split(":").collect::>()[1]; let ( first_maker_multisig_pubkeys, @@ -99,6 +101,14 @@ async fn send_coinswap( ) .unwrap(); + log::debug!("My Funding Tx: {:#?}", my_funding_txes); + log::debug!("Outgoing SwapCoins: {:#?}", outgoing_swapcoins); + log::debug!("My Timelock Keys: {:#?}", my_timelock_pubkeys); + + log::info!( + "===> [{}] | Sending SignSendersContractTx", + first_maker_port + ); let first_maker_senders_contract_sigs = request_senders_contract_tx_signatures( &first_maker.address, &outgoing_swapcoins, @@ -121,8 +131,11 @@ async fn send_coinswap( for my_funding_tx in my_funding_txes.iter() { let txid = rpc.send_raw_transaction(my_funding_tx)?; + log::info!("Broadcasting My Funding Tx: {}", txid); assert_eq!(txid, my_funding_tx.txid()); } + + log::info!("Waiting for funding Tx to confirm"); let (mut funding_txes, mut funding_tx_merkleproofs) = wait_for_funding_tx_confirmation( rpc, &my_funding_txes @@ -139,7 +152,7 @@ async fn send_coinswap( for maker_index in 0..maker_count { let maker = maker_offers_addresses.pop().unwrap(); - log::trace!("coinswapping to maker = {:?}", maker.address); + let current_maker_port = maker.address.split(":").collect::>()[1]; let maker_refund_locktime = REFUND_LOCKTIME + REFUND_LOCKTIME_STEP * (maker_count - maker_index - 1); let is_taker_next_peer = maker_index == maker_count - 1; @@ -172,6 +185,8 @@ async fn send_coinswap( let mut socket = TcpStream::connect(maker.address.clone()).await?; let (mut socket_reader, mut socket_writer) = handshake_maker(&mut socket).await?; + log::info!("===> [{}] | Sending ProofOfFunding", current_maker_port); + let (maker_sign_sender_and_receiver_contracts, next_swap_contract_redeemscripts) = send_proof_of_funding_and_get_contract_txes( &mut socket_reader, @@ -191,25 +206,46 @@ async fn send_coinswap( .await?; let receivers_sigs = if is_taker_previous_peer { + log::info!("Taker is previous peer. Signing Receivers Contract Txs",); sign_receivers_contract_txes( &maker_sign_sender_and_receiver_contracts.receivers_contract_txes, &outgoing_swapcoins, )? } else { assert!(previous_maker.is_some()); + let previous_maker_addr = previous_maker.unwrap().address; + let prev_maker_port = previous_maker_addr.split(":").collect::>()[1]; + log::info!( + "===> [{}] | {} is previous peer. Sending SignReceiversContractTx", + prev_maker_port, + prev_maker_port + ); request_receivers_contract_tx_signatures( - &previous_maker.unwrap().address, + &previous_maker_addr, watchonly_swapcoins.last().unwrap(), &maker_sign_sender_and_receiver_contracts.receivers_contract_txes, ) .await? }; + let senders_sigs = if is_taker_next_peer { + log::info!("Taker is next peer. Signing Sender's Contract Txs",); sign_senders_contract_txes( &next_peer_multisig_keys_or_nonces, &maker_sign_sender_and_receiver_contracts, )? } else { + let next_maker_port = maker_offers_addresses + .last() + .unwrap() + .address + .split(":") + .collect::>()[1]; + log::info!( + "===> [{}] | {} is next peer. Sending SignSendersContractTx", + next_maker_port, + next_maker_port + ); let next_swapcoins = create_watch_only_swap_coins( rpc, wallet, @@ -234,6 +270,12 @@ async fn send_coinswap( watchonly_swapcoins.push(next_swapcoins); sigs }; + + log::info!( + "===> [{}] | Sending SendersAndReceiversContractSigs", + current_maker_port + ); + send_message( &mut socket_writer, TakerToMakerMessage::SendersAndReceiversContractSigs(SendersAndReceiversContractSigs { @@ -244,6 +286,7 @@ async fn send_coinswap( .await?; active_maker_addresses.push(maker.address.clone()); + log::info!("Waiting for funding transaction confirmations",); let (next_funding_txes, next_funding_tx_merkleproofs) = wait_for_funding_tx_confirmation( rpc, &maker_sign_sender_and_receiver_contracts @@ -276,6 +319,11 @@ async fn send_coinswap( this_maker_hashlock_privkeys = next_peer_hashlock_keys_or_nonces; previous_maker = Some(maker); } + + log::info!( + "===> [{}] | Sending SignReceiversContractTx", + last_maker_port + ); let last_receiver_contract_sig = request_receivers_contract_tx_signatures( &last_maker.address, &incoming_swapcoins, @@ -297,19 +345,18 @@ async fn send_coinswap( wallet.update_swap_coins_list().unwrap(); let mut outgoing_privkeys: Option> = None; - log::trace!(target: "taker", - "handing over hashvalue and privkeys to = {:?}", - active_maker_addresses - ); for (index, maker_address) in active_maker_addresses.iter().enumerate() { let is_taker_previous_peer = index == 0; let is_taker_next_peer = (index as u16) == maker_count - 1; + let port = maker_address.split(":").collect::>()[1]; + let senders_multisig_redeemscripts = if is_taker_previous_peer { get_multisig_redeemscripts_from_swapcoins(&outgoing_swapcoins) } else { get_multisig_redeemscripts_from_swapcoins(&watchonly_swapcoins[index - 1]) }; + let receivers_multisig_redeemscripts = if is_taker_next_peer { get_multisig_redeemscripts_from_swapcoins(&incoming_swapcoins) } else { @@ -319,6 +366,7 @@ async fn send_coinswap( let mut socket = TcpStream::connect(maker_address).await?; let (mut socket_reader, mut socket_writer) = handshake_maker(&mut socket).await?; + log::info!("===> [{}] | Sending HashPreimage", port); let maker_private_key_handover = send_hash_preimage_and_get_private_keys( &mut socket_reader, &mut socket_writer, @@ -356,6 +404,7 @@ async fn send_coinswap( ret }?; + log::info!("===> [{}] | Sending PrivateKeyHandover", port); send_message( &mut socket_writer, TakerToMakerMessage::PrivateKeyHandover(PrivateKeyHandover { @@ -365,12 +414,8 @@ async fn send_coinswap( .await?; } - log::trace!(target: "taker", - "my outgoing txes = {:#?}", - my_funding_txes.iter().map(|t| t.txid()).collect::>() - ); for (index, watchonly_swapcoin) in watchonly_swapcoins.iter().enumerate() { - log::trace!(target: "taker", + log::debug!( "maker[{}] funding txes = {:#?}", index, watchonly_swapcoin @@ -379,7 +424,7 @@ async fn send_coinswap( .collect::>() ); } - log::trace!(target: "taker", + log::debug!( "my incoming txes = {:#?}", incoming_swapcoins .iter() @@ -396,7 +441,7 @@ async fn send_coinswap( } wallet.update_swap_coins_list().unwrap(); - log::trace!("successfully completed coinswap"); + log::info!("Successfully Completed Coinswap"); Ok(()) } @@ -404,7 +449,7 @@ async fn send_message( socket_writer: &mut WriteHalf<'_>, message: TakerToMakerMessage, ) -> Result<(), Error> { - log::trace!("=> {:?}", message); + log::debug!("==> {:#?}", message); let mut result_bytes = serde_json::to_vec(&message).map_err(|e| io::Error::from(e))?; result_bytes.push(b'\n'); socket_writer.write_all(&result_bytes).await?; @@ -426,15 +471,13 @@ async fn read_message(reader: &mut BufReader>) -> Result return Err(Error::Protocol("json parsing error")), }; - log::trace!("<= {:?}", message); + log::debug!("<== {:#?}", message); Ok(message) } async fn handshake_maker( socket: &mut TcpStream, ) -> Result<(BufReader>, WriteHalf<'_>), Error> { - log::trace!("connected to maker"); - let (reader, mut socket_writer) = socket.split(); let mut socket_reader = BufReader::new(reader); @@ -453,10 +496,8 @@ async fn handshake_maker( } else { return Err(Error::Protocol("expected method makerhello")); }; - log::trace!(target: "taker", - "protocol version min/max = {}/{}", - makerhello.protocol_version_min, makerhello.protocol_version_max - ); + log::debug!("{:#?}", makerhello); + Ok((socket_reader, socket_writer)) } @@ -513,10 +554,6 @@ async fn request_senders_contract_tx_signatures( hashvalue: Hash160, locktime: u16, ) -> Result, Error> { - log::trace!( - "requesting senders contract tx sig from maker = {}", - maker_address - ); let mut socket = TcpStream::connect(maker_address).await?; let (mut socket_reader, mut socket_writer) = handshake_maker(&mut socket).await?; send_message( @@ -570,6 +607,8 @@ async fn request_senders_contract_tx_signatures( //TODO now go back to the start and try with another maker, in a loop } + let port = maker_address.split(":").collect::>()[1]; + log::info!("<=== [{}] | Received SendersContractSig", port); Ok(maker_senders_contract_sig.sigs) } @@ -578,10 +617,6 @@ async fn request_receivers_contract_tx_signatures( incoming_swapcoins: &[S], receivers_contract_txes: &[Transaction], ) -> Result, Error> { - log::trace!( - "requesting receivers contract tx sig from maker = {}", - maker_address - ); let mut socket = TcpStream::connect(maker_address).await?; let (mut socket_reader, mut socket_writer) = handshake_maker(&mut socket).await?; send_message( @@ -618,6 +653,9 @@ async fn request_receivers_contract_tx_signatures( { return Err(Error::Protocol("invalid signature from maker")); } + + let port = maker_address.split(":").collect::>()[1]; + log::info!("<=== [{}] | Received ReceiversContractSig", port); Ok(maker_receiver_contract_sig.sigs) } @@ -625,10 +663,6 @@ async fn wait_for_funding_tx_confirmation( rpc: &Client, funding_txids: &[Txid], ) -> Result<(Vec, Vec), Error> { - log::trace!( - "waiting for funding transaction to confirm, txids={:?}", - funding_txids - ); let mut txid_tx_map = HashMap::::new(); let mut txid_blockhash_map = HashMap::::new(); loop { @@ -645,7 +679,7 @@ async fn wait_for_funding_tx_confirmation( if gettx.info.confirmations >= 1 { txid_tx_map.insert(*txid, deserialize::(&gettx.hex).unwrap()); txid_blockhash_map.insert(*txid, gettx.info.blockhash.unwrap()); - log::trace!("funding tx {} reached 1 confirmation(s)", txid); + log::debug!("funding tx {} reached 1 confirmation(s)", txid); } } if txid_tx_map.len() == funding_txids.len() { @@ -655,7 +689,8 @@ async fn wait_for_funding_tx_confirmation( #[cfg(test)] crate::test::generate_1_block(&get_bitcoin_rpc().unwrap()); } - log::trace!("funding transactions confirmed"); + + log::info!("Funding Transaction confirmed"); let txes = funding_txids .iter() @@ -820,6 +855,13 @@ async fn send_proof_of_funding_and_get_contract_txes( }) .collect::>(); + let peer_addr = socket_writer.as_ref().peer_addr().unwrap().to_string(); + let peer_port = peer_addr.split(":").collect::>()[1]; + + log::info!( + "<=== [{}] | Recieved SignSendersAndReceiversContractTxes", + peer_port + ); Ok(( maker_sign_sender_and_receiver_contracts, next_swap_contract_redeemscripts, @@ -1031,5 +1073,10 @@ async fn send_hash_preimage_and_get_private_keys( { return Err(Error::Protocol("wrong number of private keys from maker")); } + + let peer_addr = socket_writer.as_ref().peer_addr().unwrap().to_string(); + let peer_port = peer_addr.split(":").collect::>()[1]; + + log::info!("<=== [{}] | Received PrivateKeyHandover", peer_port); Ok(maker_private_key_handover) }