From 0390e63761c76a514c9f070ff5211d0cc60a7c8e Mon Sep 17 00:00:00 2001 From: bennyhodl Date: Tue, 7 Jan 2025 10:09:12 -0500 Subject: [PATCH] Adding more logging --- Cargo.lock | 14 ++--- ddk-manager/Cargo.toml | 2 +- ddk-manager/src/chain_monitor.rs | 12 ++--- ddk-manager/src/contract/mod.rs | 13 +++++ ddk-manager/src/contract_updater.rs | 27 ++++++++++ ddk-manager/src/manager.rs | 59 +++++++++++++-------- ddk/src/chain/esplora.rs | 1 - ddk/src/ddk.rs | 5 +- ddk/src/transport/lightning/peer_manager.rs | 10 +++- ddk/tests/short_call.rs | 3 +- 10 files changed, 103 insertions(+), 43 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 97776df..fbdf234 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -976,12 +976,12 @@ dependencies = [ "futures", "hex-conservative 0.1.2", "lightning", - "log", "rand_chacha", "secp256k1-zkp", "serde", "serde_json", "tokio", + "tracing", ] [[package]] @@ -3778,9 +3778,9 @@ checksum = "8df9b6e13f2d32c91b9bd719c00d1958837bc7dec474d94952798cc8e69eeec3" [[package]] name = "tracing" -version = "0.1.40" +version = "0.1.41" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "c3523ab5a71916ccf420eebdf5521fcef02141234bbc0b8a49f2fdc4544364ef" +checksum = "784e0ac535deb450455cbfa28a6f0df145ea1bb7ae51b821cf5e7927fdcfbdd0" dependencies = [ "pin-project-lite", "tracing-attributes", @@ -3789,9 +3789,9 @@ dependencies = [ [[package]] name = "tracing-attributes" -version = "0.1.27" +version = "0.1.28" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "34704c8d6ebcbc939824180af020566b01a7c01f80641264eba0999f6c2b6be7" +checksum = "395ae124c09f9e6918a2310af6038fba074bcf474ac352496d5910dd59a2226d" dependencies = [ "proc-macro2", "quote", @@ -3800,9 +3800,9 @@ dependencies = [ [[package]] name = "tracing-core" -version = "0.1.32" +version = "0.1.33" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "c06d3da6113f116aaee68e4d601191614c9053067f9ab7f6edbcb161237daa54" +checksum = "e672c95779cf947c5311f83787af4fa8fffd12fb27e4993211a84bdfd9610f9c" dependencies = [ "once_cell", "valuable", diff --git a/ddk-manager/Cargo.toml b/ddk-manager/Cargo.toml index a49c604..a431c23 100644 --- a/ddk-manager/Cargo.toml +++ b/ddk-manager/Cargo.toml @@ -29,10 +29,10 @@ dlc-trie = { version = "0.7.1", features = ["use-serde"] } futures = "0.3.31" hex = { package = "hex-conservative", version = "0.1" } lightning = { version = "0.0.125", default-features = false, features = ["grind_signatures"] } -log = "0.4.14" rand_chacha = {version = "0.3.1", optional = true} secp256k1-zkp = {version = "0.11.0"} serde = {version = "1.0", optional = true} +tracing = "0.1.41" [dev-dependencies] ddk = { path = "../ddk"} diff --git a/ddk-manager/src/chain_monitor.rs b/ddk-manager/src/chain_monitor.rs index 5344da2..9aa2857 100644 --- a/ddk-manager/src/chain_monitor.rs +++ b/ddk-manager/src/chain_monitor.rs @@ -79,7 +79,7 @@ impl ChainMonitor { } pub(crate) fn add_tx(&mut self, txid: Txid, channel_info: ChannelInfo) { - log::debug!("Watching transaction {txid}: {channel_info:?}"); + tracing::debug!("Watching transaction {txid}: {channel_info:?}"); self.watched_tx.insert(txid, WatchState::new(channel_info)); // When we watch a buffer transaction we also want to watch @@ -103,13 +103,13 @@ impl ChainMonitor { } fn add_txo(&mut self, outpoint: OutPoint, channel_info: ChannelInfo) { - log::debug!("Watching transaction output {outpoint}: {channel_info:?}"); + tracing::debug!("Watching transaction output {outpoint}: {channel_info:?}"); self.watched_txo .insert(outpoint, WatchState::new(channel_info)); } pub(crate) fn cleanup_channel(&mut self, channel_id: ChannelId) { - log::debug!("Cleaning up data related to channel {channel_id:?}"); + tracing::debug!("Cleaning up data related to channel {channel_id:?}"); self.watched_tx .retain(|_, state| state.channel_id() != channel_id); @@ -119,7 +119,7 @@ impl ChainMonitor { } pub(crate) fn remove_tx(&mut self, txid: &Txid) { - log::debug!("Stopped watching transaction {txid}"); + tracing::debug!("Stopped watching transaction {txid}"); self.watched_tx.remove(txid); } @@ -188,7 +188,7 @@ impl WatchState { fn confirm(&mut self, transaction: Transaction) { match self { WatchState::Registered { ref channel_info } => { - log::info!( + tracing::info!( "Transaction {} confirmed: {channel_info:?}", transaction.compute_txid() ); @@ -202,7 +202,7 @@ impl WatchState { channel_info, transaction, } => { - log::error!( + tracing::error!( "Transaction {} already confirmed: {channel_info:?}", transaction.compute_txid() ); diff --git a/ddk-manager/src/contract/mod.rs b/ddk-manager/src/contract/mod.rs index 155cee0..f14d432 100644 --- a/ddk-manager/src/contract/mod.rs +++ b/ddk-manager/src/contract/mod.rs @@ -13,6 +13,7 @@ use secp256k1_zkp::PublicKey; #[cfg(feature = "use-serde")] use serde::{Deserialize, Serialize}; use signed_contract::SignedContract; +use std::fmt::Write; use self::utils::unordered_equal; @@ -86,6 +87,18 @@ impl Contract { } } + /// Get the string representation of the contract id. + pub fn get_id_string(&self) -> String { + let mut string_id = String::with_capacity(32 * 2 + 2); + string_id.push_str("0x"); + let id = self.get_id(); + for i in &id { + write!(string_id, "{:02x}", i).unwrap(); + } + + string_id + } + /// Returns the temporary contract id of a contract. pub fn get_temporary_id(&self) -> ContractId { match self { diff --git a/ddk-manager/src/contract_updater.rs b/ddk-manager/src/contract_updater.rs index c825881..cbacdce 100644 --- a/ddk-manager/src/contract_updater.rs +++ b/ddk-manager/src/contract_updater.rs @@ -13,6 +13,7 @@ use dlc_messages::{ use secp256k1_zkp::{ ecdsa::Signature, All, EcdsaAdaptorSignature, PublicKey, Secp256k1, SecretKey, Signing, }; +use std::time::Instant; use crate::{ contract::{ @@ -111,6 +112,7 @@ where ) .await?; + let now = Instant::now(); let dlc_transactions = dlc::create_dlc_transactions( &offered_contract.offer_params, &accept_params, @@ -121,6 +123,11 @@ where offered_contract.cet_locktime, offered_contract.fund_output_serial_id, )?; + tracing::info!( + "Creted {} CETs in {} milliseconds", + dlc_transactions.cets.len(), + now.elapsed().as_millis() + ); let fund_output_value = dlc_transactions.get_fund_output().value; @@ -273,6 +280,7 @@ where let total_collateral = offered_contract.total_collateral; + let now = Instant::now(); let dlc_transactions = dlc::create_dlc_transactions( &offered_contract.offer_params, &accept_params, @@ -283,9 +291,15 @@ where offered_contract.cet_locktime, offered_contract.fund_output_serial_id, )?; + tracing::info!( + "Created {} CETs in {} milliseconds.", + dlc_transactions.cets.len(), + now.elapsed().as_millis() + ); let fund_output_value = dlc_transactions.get_fund_output().value; let signer = signer_provider.derive_contract_signer(offered_contract.keys_id)?; + let (signed_contract, adaptor_sigs) = verify_accepted_and_sign_contract_internal( secp, offered_contract, @@ -301,6 +315,8 @@ where &dlc_transactions, None, )?; + let contract_id = signed_contract.accepted_contract.get_contract_id_string(); + tracing::info!(contract_id, "Signed and verified contract."); let signed_msg: SignDlc = signed_contract.get_sign_dlc(adaptor_sigs); @@ -308,6 +324,10 @@ where } fn populate_psbt(psbt: &mut Psbt, all_funding_inputs: &[&FundingInput]) -> Result<(), Error> { + tracing::info!( + funding_inputs = all_funding_inputs.len(), + "Populating PSBT." + ); // add witness utxo to fund_psbt for all inputs for (input_index, x) in all_funding_inputs.iter().enumerate() { let tx = Transaction::consensus_decode(&mut x.prev_tx.as_slice()).map_err(|_| { @@ -686,6 +706,11 @@ pub fn get_signed_cet( where S::Target: ContractSigner, { + let contract_id = contract.accepted_contract.get_contract_id_string(); + tracing::info!( + contract_id, + "Getting the signed CET for the Oracle Attestation." + ); let (range_info, sigs) = crate::utils::get_range_info_and_oracle_sigs(contract_info, adaptor_info, attestations)?; let mut cet = contract.accepted_contract.dlc_transactions.cets[range_info.cet_index].clone(); @@ -709,6 +734,7 @@ where let funding_sk = signer.get_secret_key()?; + tracing::info!(contract_id, "Getting signed CET."); dlc::sign_cet( secp, &mut cet, @@ -740,6 +766,7 @@ pub fn get_signed_refund( where S::Target: ContractSigner, { + tracing::info!("Getting signed refund transaction."); let accepted_contract = &contract.accepted_contract; let offered_contract = &accepted_contract.offered_contract; let funding_script_pubkey = &accepted_contract.dlc_transactions.funding_script_pubkey; diff --git a/ddk-manager/src/manager.rs b/ddk-manager/src/manager.rs index e73c6b3..c6373c8 100644 --- a/ddk-manager/src/manager.rs +++ b/ddk-manager/src/manager.rs @@ -39,7 +39,6 @@ use lightning::chain::chaininterface::FeeEstimator; use lightning::ln::chan_utils::{ build_commitment_secret, derive_private_key, derive_private_revocation_key, }; -use log::{error, warn}; use secp256k1_zkp::XOnlyPublicKey; use secp256k1_zkp::{ ecdsa::Signature, All, EcdsaAdaptorSignature, PublicKey, Secp256k1, SecretKey, @@ -141,7 +140,7 @@ macro_rules! check_for_timed_out_channels { let is_timed_out = timeout < $manager.time.unix_time_now(); if is_timed_out { match $manager.force_close_channel_internal(channel, true).await { - Err(e) => error!("Error force closing channel {}", e), + Err(e) => tracing::error!("Error force closing channel {}", e), _ => {} } } @@ -379,6 +378,7 @@ where /// Function to call to check the state of the currently executing DLCs and /// update them if possible. pub async fn periodic_check(&self, check_channels: bool) -> Result<(), Error> { + tracing::debug!("Periodic check."); self.check_signed_contracts().await?; self.check_confirmed_contracts().await?; self.check_preclosed_contracts().await?; @@ -500,7 +500,7 @@ where sign_message: SignDlc, e: Error, ) -> Result { - error!("Error in on_sign {}", e); + tracing::error!("Error in on_sign {}", e); self.store .update_contract(&Contract::FailedSign(FailedSignContract { accepted_contract, @@ -516,7 +516,7 @@ where accept_message: AcceptDlc, e: Error, ) -> Result { - error!("Error in on_accept {}", e); + tracing::error!("Error in on_accept {}", e); self.store .update_contract(&Contract::FailedAccept(FailedAcceptContract { offered_contract, @@ -538,8 +538,20 @@ where ) .await?; if confirmations >= NB_CONFIRMATIONS { + tracing::info!( + confirmations, + contract_id = contract.accepted_contract.get_contract_id_string(), + "Marking contract as confirmed." + ); self.store .update_contract(&Contract::Confirmed(contract.clone()))?; + } else { + tracing::info!( + confirmations, + required = NB_CONFIRMATIONS, + contract_id = contract.accepted_contract.get_contract_id_string(), + "Not enough confirmations to mark contract as confirmed." + ); } Ok(()) } @@ -547,7 +559,7 @@ where async fn check_signed_contracts(&self) -> Result<(), Error> { for c in self.store.get_signed_contracts()? { if let Err(e) = self.check_signed_contract(&c).await { - error!( + tracing::error!( "Error checking confirmed contract {}: {}", c.accepted_contract.get_contract_id_string(), e @@ -565,7 +577,7 @@ where continue; } if let Err(e) = self.check_confirmed_contract(&c).await { - error!( + tracing::error!( "Error checking confirmed contract {}: {}", c.accepted_contract.get_contract_id_string(), e @@ -598,7 +610,7 @@ where let oracle = match self.oracles.get(&announcement.oracle_public_key) { Some(oracle) => oracle, None => { - log::debug!( + tracing::debug!( "Oracle not found for key: {}", announcement.oracle_public_key ); @@ -613,7 +625,7 @@ where { Ok(attestation) => attestation, Err(e) => { - log::error!( + tracing::error!( "Attestation not found for event. id={} error={}", announcement.oracle_event.event_id, e.to_string() @@ -624,7 +636,7 @@ where // Validate the attestation if let Err(e) = attestation.validate(&self.secp, announcement) { - log::error!( + tracing::error!( "Oracle attestation is not valid. pubkey={} event_id={}, error={:?}", announcement.oracle_public_key, announcement.oracle_event.event_id, @@ -655,7 +667,7 @@ where let signer = self.signer_provider.derive_contract_signer(offer.keys_id)?; // === WARNING === - // This code could potentiall be problematic. When running refund tests, it would look for a CET + // This code could potentially be problematic. When running refund tests, it would look for a CET // but the CET would be invalid and refund would not pass. By only updating with a valid CET, // we then go to update. This way if it fails we can check for refund instead of bailing and getting locked // funds. @@ -680,7 +692,7 @@ where return Ok(()); } Err(e) => { - warn!( + tracing::warn!( "Failed to close contract {}: {}", contract.accepted_contract.get_contract_id_string(), e @@ -757,7 +769,7 @@ where Ok(closed_contract) } Err(e) => { - warn!( + tracing::warn!( "Failed to close contract {}: {e}", contract.accepted_contract.get_contract_id_string() ); @@ -774,7 +786,7 @@ where async fn check_preclosed_contracts(&self) -> Result<(), Error> { for c in self.store.get_preclosed_contracts()? { if let Err(e) = self.check_preclosed_contract(&c).await { - error!( + tracing::error!( "Error checking pre-closed contract {}: {}", c.signed_contract.accepted_contract.get_contract_id_string(), e @@ -830,6 +842,10 @@ where .await?; if confirmations < 1 { + tracing::info!( + txid = signed_cet.compute_txid().to_string(), + "Broadcasting signed CET." + ); // TODO(tibo): if this fails because another tx is already in // mempool or blockchain, we might have been cheated. There is // not much to be done apart from possibly extracting a fraud @@ -1368,7 +1384,7 @@ where .await? >= CET_NSEQUENCE { - log::info!( + tracing::info!( "Buffer transaction for contract {} has enough confirmations to spend from it", serialize_hex(&contract_id) ); @@ -2132,7 +2148,7 @@ where } } } else { - warn!( + tracing::warn!( "Couldn't find rejected dlc channel with id: {}", reject.channel_id.to_lower_hex_string() ); @@ -2148,12 +2164,12 @@ where for channel in established_closing_channels { if let Err(e) = self.try_finalize_closing_established_channel(channel).await { - error!("Error trying to close established channel: {}", e); + tracing::error!("Error trying to close established channel: {}", e); } } if let Err(e) = self.check_for_timed_out_channels().await { - error!("Error checking timed out channels {}", e); + tracing::error!("Error checking timed out channels {}", e); } self.check_for_watched_tx().await } @@ -2182,9 +2198,10 @@ where ) { Ok(c) => c, Err(e) => { - error!( + tracing::error!( "Could not retrieve channel {:?}: {}", - channel_info.channel_id, e + channel_info.channel_id, + e ); continue; } @@ -2425,7 +2442,7 @@ where } } _ => { - error!("Saw spending of buffer transaction without being in closing state"); + tracing::error!("Saw spending of buffer transaction without being in closing state"); Channel::Closed(ClosedChannel { counter_party: signed_channel.counter_party, temporary_channel_id: signed_channel.temporary_channel_id, @@ -2662,7 +2679,7 @@ where match future.await { Ok(result) => Ok(result), Err(e) => { - log::error!("Failed to get oracle announcements: {}", e); + tracing::error!("Failed to get oracle announcements: {}", e); Err(e) } } diff --git a/ddk/src/chain/esplora.rs b/ddk/src/chain/esplora.rs index 1e196d3..660d094 100644 --- a/ddk/src/chain/esplora.rs +++ b/ddk/src/chain/esplora.rs @@ -74,7 +74,6 @@ impl ddk_manager::Blockchain for EsploraClient { txid = transaction.compute_txid().to_string(), "Transaction already submitted", ); - println!("Transaction is already submitted: {:}", status.confirmed); if status.confirmed { return Ok(()); } diff --git a/ddk/src/ddk.rs b/ddk/src/ddk.rs index e95afd5..2572bb1 100644 --- a/ddk/src/ddk.rs +++ b/ddk/src/ddk.rs @@ -269,10 +269,7 @@ where let contract_pnl = &contracts .iter() .map(|contract| match contract { - Contract::Closed(c) => { - println!("Closed contract: {}", c.pnl); - 0_i64 - } + Contract::Closed(_) => 0_i64, Contract::PreClosed(p) => p .signed_contract .accepted_contract diff --git a/ddk/src/transport/lightning/peer_manager.rs b/ddk/src/transport/lightning/peer_manager.rs index 3338844..52074d5 100644 --- a/ddk/src/transport/lightning/peer_manager.rs +++ b/ddk/src/transport/lightning/peer_manager.rs @@ -7,7 +7,7 @@ use lightning::{ PeerManager as LdkPeerManager, }, sign::{KeysManager, NodeSigner}, - util::logger::{Logger, Record}, + util::logger::{Level, Logger, Record}, }; use lightning_net_tokio::{setup_inbound, SocketDescriptor}; use std::{ @@ -23,7 +23,13 @@ pub struct DlcDevKitLogger; /// TODO: make a logging struct for the crate. impl Logger for DlcDevKitLogger { fn log(&self, record: Record) { - tracing::info!("{}", record.args); + match record.level { + Level::Info => tracing::info!("{}", record.args), + Level::Warn => tracing::warn!("{}", record.args), + Level::Debug => tracing::debug!("{}", record.args), + Level::Error => tracing::error!("{}", record.args), + _ => tracing::trace!("{}", record.args), + } } } diff --git a/ddk/tests/short_call.rs b/ddk/tests/short_call.rs index b2ee256..b7da8b1 100644 --- a/ddk/tests/short_call.rs +++ b/ddk/tests/short_call.rs @@ -9,7 +9,8 @@ use std::time::{Duration, SystemTime, UNIX_EPOCH}; use test_util::{generate_blocks, test_ddk}; use tokio::time::sleep; -#[tokio::test] +// #[tokio::test] +#[test_log::test(tokio::test)] async fn short_call() { let (alice, bob, oracle) = test_ddk().await; let expiry = TimeDelta::seconds(15);