diff --git a/.env.sample b/.env.sample new file mode 100644 index 00000000..e132b642 --- /dev/null +++ b/.env.sample @@ -0,0 +1,13 @@ +POSTGRES_USER=dlcdevkit +POSTGRES_PASS=dlcdevkit + +POSTGRES_HOST=localhost:5432 +POSTGRES_DB=ddk +DATABASE_URL=postgres://dlcdevkit:dlcdevkit@localhost:5432/ddk + +ESPLORA_HOST=http://localhost:30000 + +BITCOIND_USER=dlcdevkit +BITCOIND_PASS=dlcdevkit +BITCOIND_HOST=http://localhost:18443 +RPC_WALLET=ddk \ No newline at end of file diff --git a/.github/workflows/rust.yml b/.github/workflows/rust.yml index 5dc8e890..b6546a62 100644 --- a/.github/workflows/rust.yml +++ b/.github/workflows/rust.yml @@ -5,6 +5,14 @@ on: pull_request: env: CARGO_TERM_COLOR: always + POSTGRES_USER: dlcdevkit + POSTGRES_PASS: dlcdevkit + DATABASE_URL: postgresql://dlcdevkit:dlcdevkit@localhost:5432/postgres + BITCOIND_HOST: http://localhost:18443 + BITCOIND_USER: dlcdevkit + BITCOIND_PASS: dlcdevkit + ESPLORA_HOST: http://localhost:30000 + RPC_WALLET: ddk jobs: clippy: @@ -51,11 +59,6 @@ jobs: unit-tests: name: unit tests runs-on: ubuntu-latest - env: - DATABASE_URL: postgresql://dlcdevkit:dlcdevkit@localhost:5433/postgres - BITCOIND_HOST: http://localhost:18443 - ESPLORA_HOST: http://localhost:30000 - steps: - name: Install Protoc run: sudo apt-get update && sudo apt-get install -y protobuf-compiler diff --git a/.gitignore b/.gitignore index dfc5e33d..50f59a1f 100644 --- a/.gitignore +++ b/.gitignore @@ -8,4 +8,9 @@ /ddk/.env .env -/releases \ No newline at end of file +/releases + +logs + +**/*/CLAUDE.md +/.claude \ No newline at end of file diff --git a/Cargo.lock b/Cargo.lock index cb43c34a..09d6b461 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -955,6 +955,7 @@ dependencies = [ "ddk-messages", "ddk-payouts", "ddk-trie", + "dotenv", "hex", "hmac", "kormir", @@ -1128,6 +1129,12 @@ version = "0.6.8" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ec4f825369fc7134da70ca4040fddc8e03b80a46d249ae38d9c1c39b7b4476bf" +[[package]] +name = "dotenv" +version = "0.15.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "77c90badedccf4105eca100756a0b1289e191f6fcbdadd3cee1d2f614f97da8f" + [[package]] name = "dotenvy" version = "0.15.7" diff --git a/ddk-manager/src/chain_monitor.rs b/ddk-manager/src/chain_monitor.rs index eb6be8c7..1fecb0cb 100644 --- a/ddk-manager/src/chain_monitor.rs +++ b/ddk-manager/src/chain_monitor.rs @@ -79,7 +79,6 @@ impl ChainMonitor { } pub(crate) fn add_tx(&mut self, txid: Txid, channel_info: ChannelInfo) { - 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,14 +102,11 @@ impl ChainMonitor { } fn add_txo(&mut self, outpoint: OutPoint, channel_info: ChannelInfo) { - 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) { - tracing::debug!("Cleaning up data related to channel {channel_id:?}"); - self.watched_tx .retain(|_, state| state.channel_id() != channel_id); @@ -119,7 +115,6 @@ impl ChainMonitor { } pub(crate) fn remove_tx(&mut self, txid: &Txid) { - tracing::debug!("Stopped watching transaction {txid}"); self.watched_tx.remove(txid); } @@ -188,25 +183,15 @@ impl WatchState { fn confirm(&mut self, transaction: Transaction) { match self { WatchState::Registered { ref channel_info } => { - tracing::info!( - "Transaction {} confirmed: {channel_info:?}", - transaction.compute_txid() - ); - *self = WatchState::Confirmed { channel_info: *channel_info, transaction, } } WatchState::Confirmed { - channel_info, - transaction, - } => { - tracing::error!( - "Transaction {} already confirmed: {channel_info:?}", - transaction.compute_txid() - ); - } + channel_info: _, + transaction: _, + } => {} } } diff --git a/ddk-manager/src/channel_updater.rs b/ddk-manager/src/channel_updater.rs index dee80da3..62a8b298 100644 --- a/ddk-manager/src/channel_updater.rs +++ b/ddk-manager/src/channel_updater.rs @@ -40,8 +40,9 @@ use ddk_messages::{ oracle_msgs::{OracleAnnouncement, OracleAttestation}, FundingSignatures, }; -use lightning::ln::chan_utils::{ - build_commitment_secret, derive_private_key, CounterpartyCommitmentSecrets, +use lightning::{ + ln::chan_utils::{build_commitment_secret, derive_private_key, CounterpartyCommitmentSecrets}, + util::logger::Logger, }; use secp256k1_zkp::{All, EcdsaAdaptorSignature, PublicKey, Secp256k1, SecretKey, Signing}; @@ -283,7 +284,13 @@ where /// to a [`SignedChannel`] and [`SignedContract`], returning them as well as the /// [`SignChannel`] to be sent to the counter party. #[allow(clippy::too_many_arguments)] -pub async fn verify_and_sign_accepted_channel( +pub async fn verify_and_sign_accepted_channel< + W: Deref, + SP: Deref, + X: ContractSigner, + S: Deref, + L: Deref, +>( secp: &Secp256k1, offered_channel: &OfferedChannel, offered_contract: &OfferedContract, @@ -293,11 +300,13 @@ pub async fn verify_and_sign_accepted_channel, + logger: &L, ) -> Result<(SignedChannel, SignedContract, SignChannel), Error> where W::Target: Wallet, SP::Target: ContractSignerProvider, S::Target: Storage, + L::Target: Logger, { let (tx_input_infos, input_amount) = crate::conversion_utils::get_tx_input_infos(&accept_channel.funding_inputs)?; @@ -385,6 +394,7 @@ where Some(channel_id), storage, signer_provider, + logger, ) .await?; @@ -467,7 +477,7 @@ where /// given [`AcceptedChannel`] and [`AcceptedContract`], transforming them /// to a [`SignedChannel`] and [`SignedContract`], and returning them. #[allow(clippy::too_many_arguments)] -pub async fn verify_signed_channel( +pub async fn verify_signed_channel( secp: &Secp256k1, accepted_channel: &AcceptedChannel, accepted_contract: &AcceptedContract, @@ -476,11 +486,13 @@ pub async fn verify_signed_channel, storage: &S, signer_provider: &SP, + logger: &L, ) -> Result<(SignedChannel, SignedContract, Transaction), Error> where W::Target: Wallet, SP::Target: ContractSignerProvider, S::Target: Storage, + L::Target: Logger, { let own_publish_pk = accepted_channel .accept_base_points @@ -514,6 +526,7 @@ where Some(accepted_channel.channel_id), storage, signer_provider, + logger, ) .await?; @@ -1374,6 +1387,7 @@ pub async fn verify_renew_accept_and_confirm< X: ContractSigner, T: Deref, S: Deref, + L: Deref, >( secp: &Secp256k1, renew_accept: &RenewAccept, @@ -1385,12 +1399,14 @@ pub async fn verify_renew_accept_and_confirm< signer_provider: &SP, time: &T, storage: &S, + logger: &L, ) -> Result<(SignedContract, RenewConfirm), Error> where W::Target: Wallet, SP::Target: ContractSignerProvider, T::Target: Time, S::Target: Storage, + L::Target: Logger, { let own_base_secret_key = signer_provider.get_secret_key_for_pubkey(&signed_channel.own_points.own_basepoint)?; @@ -1457,6 +1473,7 @@ where Some(signed_channel.channel_id), storage, signer_provider, + logger, ) .await?; @@ -1505,6 +1522,7 @@ pub(crate) async fn verify_renew_confirm_and_finalize< W: Deref, SP: Deref, X: ContractSigner, + L: Deref, >( secp: &Secp256k1, signed_channel: &mut SignedChannel, @@ -1516,12 +1534,14 @@ pub(crate) async fn verify_renew_confirm_and_finalize< signer: &SP, chain_monitor: &Mutex, storage: &S, + logger: &L, ) -> Result<(SignedContract, RenewFinalize), Error> where T::Target: Time, SP::Target: ContractSignerProvider, W::Target: Wallet, S::Target: Storage, + L::Target: Logger, { let ( &offer_per_update_point, @@ -1575,6 +1595,7 @@ where Some(signed_channel.channel_id), storage, signer, + logger, ) .await?; diff --git a/ddk-manager/src/contract_updater.rs b/ddk-manager/src/contract_updater.rs index 06d35b93..1b2b680a 100644 --- a/ddk-manager/src/contract_updater.rs +++ b/ddk-manager/src/contract_updater.rs @@ -2,6 +2,7 @@ use std::ops::Deref; +use bitcoin::hex::DisplayHex; use bitcoin::psbt::Psbt; use bitcoin::Amount; use bitcoin::{consensus::Decodable, Script, Transaction, Witness}; @@ -12,10 +13,11 @@ use ddk_messages::{ AcceptDlc, FundingSignature, FundingSignatures, OfferDlc, SignDlc, WitnessElement, }; use ddk_messages::{CloseDlc, FundingInput}; +use lightning::util::logger::Logger; +use lightning::{log_debug, log_info}; use secp256k1_zkp::{ ecdsa::Signature, All, EcdsaAdaptorSignature, PublicKey, Secp256k1, SecretKey, Signing, }; -use std::time::Instant; use crate::dlc_input::{get_dlc_inputs_from_funding_inputs, get_signature_for_dlc_input}; use crate::Storage; @@ -40,6 +42,7 @@ pub async fn offer_contract< X: ContractSigner, SP: Deref, C: Signing, + L: Deref, >( secp: &Secp256k1, contract_input: &ContractInput, @@ -51,12 +54,14 @@ pub async fn offer_contract< blockchain: &B, time: &T, signer_provider: &SP, + logger: &L, ) -> Result<(OfferedContract, OfferDlc), Error> where W::Target: Wallet, B::Target: Blockchain, T::Target: Time, SP::Target: ContractSignerProvider, + L::Target: Logger, { contract_input.validate()?; @@ -76,6 +81,19 @@ where ) .await?; + log_debug!( + logger, + "Created offer contract with offer party params. temp_id={} counter_party={} fund_pubkey={} change_spk={} payout_spk={} dlc_inputs={} input_amount={} collateral={}", + id.to_lower_hex_string(), + counter_party.to_string(), + party_params.fund_pubkey.to_string(), + party_params.change_script_pubkey.to_string(), + party_params.payout_script_pubkey.to_string(), + !party_params.dlc_inputs.is_empty(), + party_params.input_amount.to_sat(), + party_params.collateral.to_sat(), + ); + let offered_contract = OfferedContract::new( id, contract_input, @@ -95,17 +113,19 @@ where /// Creates an [`AcceptedContract`] and produces /// the accepting party's cet adaptor signatures. -pub async fn accept_contract( +pub async fn accept_contract( secp: &Secp256k1, offered_contract: &OfferedContract, wallet: &W, signer_provider: &SP, blockchain: &B, + logger: &L, ) -> Result<(AcceptedContract, AcceptDlc), Error> where W::Target: Wallet, B::Target: Blockchain, SP::Target: ContractSignerProvider, + L::Target: Logger, { let total_collateral = offered_contract.total_collateral; @@ -123,7 +143,19 @@ where ) .await?; - let now = Instant::now(); + log_debug!( + logger, + "Created accept party params. temp_id={} counter_party={} fund_pubkey={} change_spk={} payout_spk={} dlc_inputs={} input_amount={} collateral={}", + offered_contract.id.to_lower_hex_string(), + offered_contract.counter_party.to_string(), + accept_params.fund_pubkey.to_string(), + accept_params.change_script_pubkey.to_string(), + accept_params.payout_script_pubkey.to_string(), + !accept_params.dlc_inputs.is_empty(), + accept_params.input_amount.to_sat(), + accept_params.collateral.to_sat(), + ); + let dlc_transactions = ddk_dlc::create_dlc_transactions( &offered_contract.offer_params, &accept_params, @@ -134,10 +166,16 @@ 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() + + log_info!( + logger, + "Created DLC transactions. temp_id={} fund_txid={} funding_spk={} fund_output_value={} refund_txid={} num_cets={}", + offered_contract.id.to_lower_hex_string(), + dlc_transactions.fund.compute_txid().to_string(), + dlc_transactions.funding_script_pubkey.to_string(), + dlc_transactions.get_fund_output().value.to_sat(), + dlc_transactions.refund.compute_txid().to_string(), + dlc_transactions.cets.len() ); let fund_output_value = dlc_transactions.get_fund_output().value; @@ -153,6 +191,13 @@ where &dlc_transactions, )?; + log_info!( + logger, + "Created accept contract. temp_id={} contract_id={}", + offered_contract.id.to_lower_hex_string(), + accepted_contract.get_contract_id().to_lower_hex_string() + ); + let accept_msg: AcceptDlc = accepted_contract.get_accept_contract_msg(&adaptor_sigs); Ok((accepted_contract, accept_msg)) @@ -260,18 +305,26 @@ pub(crate) fn accept_contract_internal( /// Verifies the information of the accepting party [`Accept` message](dlc_messages::AcceptDlc), /// creates a [`SignedContract`], and generates the offering party CET adaptor signatures. -pub async fn verify_accepted_and_sign_contract( +pub async fn verify_accepted_and_sign_contract< + W: Deref, + X: ContractSigner, + SP: Deref, + S: Deref, + L: Deref, +>( secp: &Secp256k1, offered_contract: &OfferedContract, accept_msg: &AcceptDlc, wallet: &W, signer_provider: &SP, storage: &S, + logger: &L, ) -> Result<(SignedContract, SignDlc), Error> where W::Target: Wallet, SP::Target: ContractSignerProvider, S::Target: Storage, + L::Target: Logger, { let (tx_input_infos, input_amount) = get_tx_input_infos(&accept_msg.funding_inputs)?; let dlc_inputs = get_dlc_inputs_from_funding_inputs(&accept_msg.funding_inputs); @@ -288,6 +341,19 @@ where collateral: accept_msg.accept_collateral, }; + log_debug!( + logger, + "Retrieved the party params for the accepting party. temp_id={} counter_party={} fund_pubkey={} change_spk={} payout_spk={} dlc_inputs={} input_amount={} collateral={}", + offered_contract.id.to_lower_hex_string(), + offered_contract.counter_party.to_string(), + accept_params.fund_pubkey.to_string(), + accept_params.change_script_pubkey.to_string(), + accept_params.payout_script_pubkey.to_string(), + !accept_params.dlc_inputs.is_empty(), + accept_params.input_amount.to_sat(), + accept_params.collateral.to_sat(), + ); + let cet_adaptor_signatures = accept_msg .cet_adaptor_signatures .ecdsa_adaptor_signatures @@ -297,6 +363,11 @@ where let total_collateral = offered_contract.total_collateral; let dlc_transactions = if !dlc_inputs.is_empty() { + log_debug!( + logger, + "Creating spliced DLC transactions. num_dlc_inputs={}", + dlc_inputs.len() + ); ddk_dlc::create_spliced_dlc_transactions( &offered_contract.offer_params, &accept_params, @@ -320,6 +391,17 @@ where )? }; + log_info!( + logger, + "Created DLC transactions. temp_id={} fund_txid={} funding_spk={} fund_output_value={} refund_txid={} num_cets={}", + offered_contract.id.to_lower_hex_string(), + dlc_transactions.fund.compute_txid().to_string(), + dlc_transactions.funding_script_pubkey.to_string(), + dlc_transactions.get_fund_output().value.to_sat(), + dlc_transactions.refund.compute_txid().to_string(), + dlc_transactions.cets.len() + ); + let fund_output_value = dlc_transactions.get_fund_output().value; let signer = signer_provider.derive_contract_signer(offered_contract.keys_id)?; @@ -340,10 +422,19 @@ where None, storage, signer_provider, + logger, ) .await?; + let contract_id = signed_contract.accepted_contract.get_contract_id_string(); - tracing::info!(contract_id, "Signed and verified contract."); + + log_info!( + logger, + "Signed and verified accept message. tmp_id={} contract_id={} num_adaptor_sigs={}", + offered_contract.id.to_lower_hex_string(), + contract_id, + adaptor_sigs.len() + ); let signed_msg: SignDlc = signed_contract.get_sign_dlc(adaptor_sigs); @@ -351,10 +442,6 @@ 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(|_| { @@ -380,6 +467,7 @@ pub(crate) async fn verify_accepted_and_sign_contract_internal< X: ContractSigner, S: Deref, SP: Deref, + L: Deref, >( secp: &Secp256k1, offered_contract: &OfferedContract, @@ -396,11 +484,13 @@ pub(crate) async fn verify_accepted_and_sign_contract_internal< channel_id: Option, storage: &S, signer_provider: &SP, + logger: &L, ) -> Result<(SignedContract, Vec), Error> where W::Target: Wallet, S::Target: Storage, SP::Target: ContractSignerProvider, + L::Target: Logger, { let DlcTransactions { fund, @@ -427,6 +517,13 @@ where &counter_adaptor_pk, )?; + log_debug!( + logger, + "Verified refund signature. temp_id={} refund_txid={}", + offered_contract.id.to_lower_hex_string(), + refund.compute_txid().to_string(), + ); + let (adaptor_info, mut adaptor_index) = offered_contract.contract_info[0] .verify_and_get_adaptor_info( secp, @@ -503,6 +600,11 @@ where // sort by serial id all_funding_inputs.sort_by_key(|x| x.input_serial_id); + log_info!( + logger, + "Populating PSBT for signing funding inputs. num_funding_inputs={}", + all_funding_inputs.len(), + ); populate_psbt(&mut fund_psbt, &all_funding_inputs)?; let mut witnesses: Vec = Vec::new(); @@ -523,6 +625,15 @@ where // The funding pubkeys for both the offer and accepting party are deterministically derived from // the ContractSignerProvider. Becuase of this, we do not need to prompt the consumer for the signature. if let Some(dlc_input) = &funding_input.dlc_input { + log_debug!( + logger, + "Signing DLC input. temp_id={} splice_contract_id={} local_fund_pubkey={} remote_fund_pubkey={} input_index={}", + offered_contract.id.to_lower_hex_string(), + dlc_input.contract_id.to_lower_hex_string(), + dlc_input.local_fund_pubkey.to_string(), + dlc_input.remote_fund_pubkey.to_string(), + input_index, + ); let dlc_input_signature = get_signature_for_dlc_input( secp, funding_input, @@ -552,6 +663,13 @@ where witnesses.push(witness); } + log_debug!( + logger, + "Signed funding inputs. temp_id={} num_signatures={}", + offered_contract.id.to_lower_hex_string(), + witnesses.len() + ); + let funding_signatures: Vec = witnesses .into_iter() .map(|witness| { @@ -606,18 +724,20 @@ where /// Verifies the information from the offer party [`Sign` message](dlc_messages::SignDlc), /// creates the accepting party's [`SignedContract`] and returns it along with the /// signed fund transaction. -pub async fn verify_signed_contract( +pub async fn verify_signed_contract( secp: &Secp256k1, accepted_contract: &AcceptedContract, sign_msg: &SignDlc, wallet: &W, storage: &S, signer_provider: &SP, + logger: &L, ) -> Result<(SignedContract, Transaction), Error> where W::Target: Wallet, S::Target: Storage, SP::Target: ContractSignerProvider, + L::Target: Logger, { let cet_adaptor_signatures: Vec<_> = (&sign_msg.cet_adaptor_signatures).into(); verify_signed_contract_internal( @@ -633,6 +753,7 @@ where None, storage, signer_provider, + logger, ) .await } @@ -643,6 +764,7 @@ pub(crate) async fn verify_signed_contract_internal< SP: Deref, S: Deref, X: ContractSigner, + L: Deref, >( secp: &Secp256k1, accepted_contract: &AcceptedContract, @@ -656,11 +778,13 @@ pub(crate) async fn verify_signed_contract_internal< channel_id: Option, storage: &S, signer_provider: &SP, + logger: &L, ) -> Result<(SignedContract, Transaction), Error> where W::Target: Wallet, S::Target: Storage, SP::Target: ContractSignerProvider, + L::Target: Logger, { let offered_contract = &accepted_contract.offered_contract; let input_script_pubkey = input_script_pubkey @@ -678,6 +802,16 @@ where &counter_adaptor_pk, )?; + log_debug!( + logger, + "Verified refund signature. contract_id={} refund_txid={}", + accepted_contract.get_contract_id_string(), + accepted_contract + .dlc_transactions + .refund + .compute_txid() + .to_string(), + ); let mut adaptor_sig_start = 0; for (adaptor_info, contract_info) in accepted_contract @@ -697,6 +831,13 @@ where )?; } + log_debug!( + logger, + "Verified adaptor signatures. contract_id={} num_adaptor_infos={}", + accepted_contract.get_contract_id_string(), + accepted_contract.adaptor_infos.len(), + ); + let fund_tx = &accepted_contract.dlc_transactions.fund; let mut fund_psbt = Psbt::from_unsigned_tx(fund_tx.clone()) .map_err(|_| Error::InvalidState("Tried to create PSBT from signed tx".to_string()))?; @@ -710,6 +851,12 @@ where // sort by serial id all_funding_inputs.sort_by_key(|x| x.input_serial_id); + log_debug!( + logger, + "Populating PSBT for signing funding inputs. contract_id={} num_funding_inputs={}", + accepted_contract.get_contract_id_string(), + all_funding_inputs.len(), + ); populate_psbt(&mut fund_psbt, &all_funding_inputs)?; for (funding_input, funding_signatures) in offered_contract @@ -731,6 +878,14 @@ where // from the offer party is their half of the DLC input and we can build the valid redeem script. if let Some(dlc_input) = &funding_input.dlc_input { let dlc_input_info: DlcInputInfo = funding_input.into(); + log_debug!( + logger, + "Verifying DLC input signature. contract_id={} input_index={} remote_fund_pubkey={} local_fund_pubkey={}", + accepted_contract.get_contract_id_string(), + input_index, + dlc_input.remote_fund_pubkey.to_string(), + dlc_input.local_fund_pubkey.to_string(), + ); // Verify the signature from the offer party is valid for the DLC input. ddk_dlc::dlc_input::verify_dlc_funding_input_signature( @@ -742,6 +897,12 @@ where &dlc_input.local_fund_pubkey, )?; + log_debug!( + logger, + "Signing DLC input. contract_id={} input_index={}", + accepted_contract.get_contract_id_string(), + input_index, + ); // Get the signature for the DLC input from the accepting party. let my_dlc_input_signature = get_signature_for_dlc_input( secp, @@ -763,6 +924,13 @@ where &dlc_input.local_fund_pubkey, ); + log_debug!( + logger, + "Completed the signatures for the DLC input. contract_id={} input_index={}", + accepted_contract.get_contract_id_string(), + input_index, + ); + fund_psbt.inputs[input_index].final_script_witness = Some(completed_witness); } else { fund_psbt.inputs[input_index].final_script_witness = Some(Witness::from_slice( @@ -786,6 +954,12 @@ where )) })?; + log_debug!( + logger, + "Signing funding input. contract_id={} input_index={}", + accepted_contract.get_contract_id_string(), + input_index, + ); wallet.sign_psbt_input(&mut fund_psbt, input_index).await?; } @@ -803,21 +977,29 @@ where } /// Signs and return the CET that can be used to close the given contract. -pub fn get_signed_cet( +pub fn get_signed_cet( secp: &Secp256k1, contract: &SignedContract, contract_info: &ContractInfo, adaptor_info: &AdaptorInfo, attestations: &[(usize, OracleAttestation)], signer: S, + logger: &L, ) -> Result where S::Target: ContractSigner, + L::Target: Logger, { let contract_id = contract.accepted_contract.get_contract_id_string(); - tracing::info!( + log_info!( + logger, + "Getting the signed CET for the Oracle Attestation. contract_id={} outcomes={:?} event_id={}", contract_id, - "Getting the signed CET for the Oracle Attestation." + attestations + .iter() + .map(|(_, a)| &a.outcomes) + .collect::>(), + attestations.first().unwrap().1.event_id, ); let (range_info, sigs) = crate::utils::get_range_info_and_oracle_sigs(contract_info, adaptor_info, attestations)?; @@ -842,7 +1024,6 @@ where let funding_sk = signer.get_secret_key()?; - tracing::info!(contract_id, "Getting signed CET."); ddk_dlc::sign_cet( secp, &mut cet, @@ -865,15 +1046,21 @@ where } /// Signs and return the refund transaction to refund the contract. -pub fn get_signed_refund( +pub fn get_signed_refund( secp: &Secp256k1, contract: &SignedContract, signer: S, + logger: &L, ) -> Result where S::Target: ContractSigner, + L::Target: Logger, { - tracing::info!("Getting signed refund transaction."); + log_info!( + logger, + "Getting signed refund transaction. contract_id={}", + contract.accepted_contract.get_contract_id_string() + ); let accepted_contract = &contract.accepted_contract; let offered_contract = &accepted_contract.offered_contract; let funding_script_pubkey = &accepted_contract.dlc_transactions.funding_script_pubkey; @@ -906,14 +1093,16 @@ where } /// Creates a cooperative close transaction and signs it with the local party's key. -pub fn create_cooperative_close( +pub fn create_cooperative_close( secp: &Secp256k1, signed_contract: &SignedContract, counter_payout: Amount, signer_provider: &SP, + logger: &L, ) -> Result<(CloseDlc, Transaction), Error> where SP::Target: ContractSignerProvider, + L::Target: Logger, { let accepted_contract = &signed_contract.accepted_contract; let offered_contract = &accepted_contract.offered_contract; @@ -940,6 +1129,15 @@ where &[], // TODO: Add additional inputs parameter to prevent free option problem ); + log_debug!( + logger, + "Created cooperative close transaction. contract_id={} close_txid={} offer_payout={} counter_payout={}", + accepted_contract.get_contract_id_string(), + close_tx.compute_txid().to_string(), + offer_payout, + counter_payout, + ); + // Get our private key and sign the transaction let signer = signer_provider.derive_contract_signer(offered_contract.keys_id)?; let fund_private_key = signer.get_secret_key()?; @@ -969,14 +1167,16 @@ where } /// Verifies and completes a cooperative close transaction using the counter party's signature. -pub fn complete_cooperative_close( +pub fn complete_cooperative_close( secp: &Secp256k1, signed_contract: &SignedContract, close_message: &CloseDlc, signer_provider: &SP, + logger: &L, ) -> Result where SP::Target: ContractSignerProvider, + L::Target: Logger, { let accepted_contract = &signed_contract.accepted_contract; let offered_contract = &accepted_contract.offered_contract; @@ -997,6 +1197,15 @@ where &[], // No additional inputs for contract cooperative close verification ); + log_debug!( + logger, + "Recreated close transaction for cooperative close verification. contract_id={} close_txid={} offer_payout={} counter_payout={}", + accepted_contract.get_contract_id_string(), + close_tx.compute_txid().to_string(), + offer_payout, + close_message.accept_payout, + ); + // Get our private key let signer = signer_provider.derive_contract_signer(offered_contract.keys_id)?; let fund_private_key = signer.get_secret_key()?; diff --git a/ddk-manager/src/manager.rs b/ddk-manager/src/manager.rs index d44a37fe..286c993d 100644 --- a/ddk-manager/src/manager.rs +++ b/ddk-manager/src/manager.rs @@ -39,6 +39,8 @@ use lightning::chain::chaininterface::FeeEstimator; use lightning::ln::chan_utils::{ build_commitment_secret, derive_private_key, derive_private_revocation_key, }; +use lightning::util::logger::Logger; +use lightning::{log_debug, log_error, log_info, log_trace, log_warn}; use secp256k1_zkp::XOnlyPublicKey; use secp256k1_zkp::{ ecdsa::Signature, All, EcdsaAdaptorSignature, PublicKey, Secp256k1, SecretKey, @@ -76,6 +78,7 @@ pub struct Manager< T: Deref, F: Deref, X: ContractSigner, + L: Deref, > where W::Target: Wallet, SP::Target: ContractSignerProvider, @@ -84,6 +87,7 @@ pub struct Manager< O::Target: Oracle, T::Target: Time, F::Target: FeeEstimator, + L::Target: Logger, { oracles: HashMap, wallet: W, @@ -94,6 +98,7 @@ pub struct Manager< chain_monitor: Mutex, time: T, fee_estimator: F, + logger: L, } macro_rules! get_contract_in_state { @@ -143,7 +148,9 @@ 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) => tracing::error!("Error force closing channel {}", e), + Err(e) => { + log_error!($manager.logger, "Error force closing channel. error={}", e) + } _ => {} } } @@ -152,8 +159,17 @@ macro_rules! check_for_timed_out_channels { }; } -impl - Manager>, B, S, O, T, F, X> +impl< + W: Deref, + SP: Deref, + B: Deref, + S: Deref, + O: Deref, + T: Deref, + F: Deref, + X: ContractSigner, + L: Deref, + > Manager>, B, S, O, T, F, X, L> where W::Target: Wallet, SP::Target: ContractSignerProvider, @@ -162,8 +178,11 @@ where O::Target: Oracle, T::Target: Time, F::Target: FeeEstimator, + L::Target: Logger, { /// Create a new Manager struct. + #[allow(clippy::too_many_arguments)] + #[tracing::instrument(skip_all)] pub async fn new( wallet: W, signer_provider: SP, @@ -172,6 +191,7 @@ where oracles: HashMap, time: T, fee_estimator: F, + logger: L, ) -> Result { let init_height = blockchain.get_blockchain_height().await?; let chain_monitor = Mutex::new( @@ -183,6 +203,8 @@ where let signer_provider = Arc::new(CachedContractSignerProvider::new(signer_provider)); + log_info!(logger, "Manager initialized"); + Ok(Manager { secp: secp256k1_zkp::Secp256k1::new(), wallet, @@ -193,6 +215,7 @@ where time, fee_estimator, chain_monitor, + logger, }) } @@ -202,6 +225,7 @@ where } /// Function called to pass a DlcMessage to the Manager. + #[tracing::instrument(skip_all)] pub async fn on_dlc_message( &self, msg: &DlcMessage, @@ -209,66 +233,100 @@ where ) -> Result, Error> { match msg { DlcMessage::Offer(o) => { + log_debug!(self.logger, "Received offer message"); self.on_offer_message(o, counter_party).await?; Ok(None) } - DlcMessage::Accept(a) => Ok(Some(self.on_accept_message(a, &counter_party).await?)), + DlcMessage::Accept(a) => { + log_debug!(self.logger, "Received accept message"); + Ok(Some(self.on_accept_message(a, &counter_party).await?)) + } DlcMessage::Sign(s) => { + log_debug!(self.logger, "Received sign message"); self.on_sign_message(s, &counter_party).await?; Ok(None) } DlcMessage::Close(c) => { + log_debug!(self.logger, "Received close message"); self.on_close_message(c, &counter_party).await?; Ok(None) } DlcMessage::OfferChannel(o) => { + log_debug!(self.logger, "Received offer channel message"); self.on_offer_channel(o, counter_party).await?; Ok(None) } - DlcMessage::AcceptChannel(a) => Ok(Some(DlcMessage::SignChannel( - self.on_accept_channel(a, &counter_party).await?, - ))), + DlcMessage::AcceptChannel(a) => { + log_debug!(self.logger, "Received accept channel message"); + Ok(Some(DlcMessage::SignChannel( + self.on_accept_channel(a, &counter_party).await?, + ))) + } DlcMessage::SignChannel(s) => { + log_debug!(self.logger, "Received sign channel message"); self.on_sign_channel(s, &counter_party).await?; Ok(None) } - DlcMessage::SettleOffer(s) => match self.on_settle_offer(s, &counter_party).await? { - Some(msg) => Ok(Some(DlcMessage::Reject(msg))), - None => Ok(None), - }, - DlcMessage::SettleAccept(s) => Ok(Some(DlcMessage::SettleConfirm( - self.on_settle_accept(s, &counter_party).await?, - ))), - DlcMessage::SettleConfirm(s) => Ok(Some(DlcMessage::SettleFinalize( - self.on_settle_confirm(s, &counter_party).await?, - ))), + DlcMessage::SettleOffer(s) => { + log_debug!(self.logger, "Received settle offer message"); + match self.on_settle_offer(s, &counter_party).await? { + Some(msg) => Ok(Some(DlcMessage::Reject(msg))), + None => Ok(None), + } + } + DlcMessage::SettleAccept(s) => { + log_debug!(self.logger, "Received settle accept message"); + Ok(Some(DlcMessage::SettleConfirm( + self.on_settle_accept(s, &counter_party).await?, + ))) + } + DlcMessage::SettleConfirm(s) => { + log_debug!(self.logger, "Received settle confirm message"); + Ok(Some(DlcMessage::SettleFinalize( + self.on_settle_confirm(s, &counter_party).await?, + ))) + } DlcMessage::SettleFinalize(s) => { + log_debug!(self.logger, "Received settle finalize message"); self.on_settle_finalize(s, &counter_party).await?; Ok(None) } - DlcMessage::RenewOffer(r) => match self.on_renew_offer(r, &counter_party).await? { - Some(msg) => Ok(Some(DlcMessage::Reject(msg))), - None => Ok(None), - }, - DlcMessage::RenewAccept(r) => Ok(Some(DlcMessage::RenewConfirm( - self.on_renew_accept(r, &counter_party).await?, - ))), - DlcMessage::RenewConfirm(r) => Ok(Some(DlcMessage::RenewFinalize( - self.on_renew_confirm(r, &counter_party).await?, - ))), + DlcMessage::RenewOffer(r) => { + log_debug!(self.logger, "Received renew offer message"); + match self.on_renew_offer(r, &counter_party).await? { + Some(msg) => Ok(Some(DlcMessage::Reject(msg))), + None => Ok(None), + } + } + DlcMessage::RenewAccept(r) => { + log_debug!(self.logger, "Received renew accept message"); + Ok(Some(DlcMessage::RenewConfirm( + self.on_renew_accept(r, &counter_party).await?, + ))) + } + DlcMessage::RenewConfirm(r) => { + log_debug!(self.logger, "Received renew confirm message"); + Ok(Some(DlcMessage::RenewFinalize( + self.on_renew_confirm(r, &counter_party).await?, + ))) + } DlcMessage::RenewFinalize(r) => { + log_debug!(self.logger, "Received renew finalize message"); let revoke = self.on_renew_finalize(r, &counter_party).await?; Ok(Some(DlcMessage::RenewRevoke(revoke))) } DlcMessage::RenewRevoke(r) => { + log_debug!(self.logger, "Received renew revoke message"); self.on_renew_revoke(r, &counter_party).await?; Ok(None) } DlcMessage::CollaborativeCloseOffer(c) => { + log_debug!(self.logger, "Received collaborative close offer message"); self.on_collaborative_close_offer(c, &counter_party).await?; Ok(None) } DlcMessage::Reject(r) => { + log_debug!(self.logger, "Received reject message"); self.on_reject(r, &counter_party).await?; Ok(None) } @@ -276,6 +334,7 @@ where } /// Create a new spliced offer + #[tracing::instrument(skip_all)] pub async fn send_splice_offer( &self, contract_input: &ContractInput, @@ -295,6 +354,7 @@ where /// Creates a new offer DLC using an existing DLC as an input. /// The new DLC MUST use a Confirmed contract as an input. + #[tracing::instrument(skip_all)] pub async fn send_splice_offer_with_announcements( &self, contract_input: &ContractInput, @@ -318,6 +378,7 @@ where &self.blockchain, &self.time, &self.signer_provider, + &self.logger, ) .await?; @@ -332,6 +393,7 @@ where /// and an OfferDlc message returned. /// /// This function will fetch the oracle announcements from the oracle. + #[tracing::instrument(skip_all)] pub async fn send_offer( &self, contract_input: &ContractInput, @@ -349,6 +411,7 @@ where /// /// This function allows to pass the oracle announcements directly instead of /// fetching them from the oracle. + #[tracing::instrument(skip_all)] pub async fn send_offer_with_announcements( &self, contract_input: &ContractInput, @@ -366,6 +429,7 @@ where &self.blockchain, &self.time, &self.signer_provider, + &self.logger, ) .await?; @@ -377,6 +441,7 @@ where } /// Function to call to accept a DLC for which an offer was received. + #[tracing::instrument(skip_all)] pub async fn accept_contract_offer( &self, contract_id: &ContractId, @@ -392,6 +457,7 @@ where &self.wallet, &self.signer_provider, &self.blockchain, + &self.logger, ) .await?; @@ -406,6 +472,13 @@ where .update_contract(&Contract::Accepted(accepted_contract)) .await?; + log_info!( + self.logger, + "Accepted and stored the contract. temp_id={} contract_id={}", + offered_contract.id.to_lower_hex_string(), + contract_id.to_lower_hex_string(), + ); + Ok((contract_id, counter_party, accept_msg)) } @@ -414,6 +487,7 @@ where /// /// Consumers **MUST** call this periodically in order to /// determine when pending transactions reach confirmation. + #[tracing::instrument(skip_all)] pub async fn periodic_chain_monitor(&self) -> Result<(), Error> { let cur_height = self.blockchain.get_blockchain_height().await?; let last_height = self.chain_monitor.lock().await.last_height; @@ -440,8 +514,8 @@ where /// Function to call to check the state of the currently executing DLCs and /// update them if possible. + #[tracing::instrument(skip_all, level = "debug")] pub async fn periodic_check(&self, check_channels: bool) -> Result<(), Error> { - tracing::debug!("Periodic check."); let signed_contracts = self.check_for_spliced_contract().await?; self.check_signed_contracts(&signed_contracts).await?; self.check_confirmed_contracts().await?; @@ -455,6 +529,7 @@ where } /// Function to call to offer a DLC. + #[tracing::instrument(skip_all)] pub async fn on_offer_message( &self, offered_message: &OfferDlc, @@ -475,11 +550,16 @@ where } self.store.create_contract(&contract).await?; - + log_info!( + self.logger, + "Created and stored the offered contract. temp_id={}", + contract.id.to_lower_hex_string(), + ); Ok(()) } /// Function to call to close a DLC. + #[tracing::instrument(skip_all)] pub async fn on_close_message( &self, close_msg: &CloseDlc, @@ -500,6 +580,7 @@ where &signed_contract, close_msg, &self.signer_provider, + &self.logger, )?; // Message is valid - the application layer should call accept_cooperative_close() @@ -508,6 +589,7 @@ where } /// Function to call to accept a DLC for which an offer was received. + #[tracing::instrument(skip_all)] pub async fn on_accept_message( &self, accept_msg: &AcceptDlc, @@ -527,17 +609,33 @@ where &self.wallet, &self.signer_provider, &self.store, + &self.logger, ) .await { Ok(contract) => contract, Err(e) => { + log_error!( + self.logger, + "Error in on_accept_message. tmp_contract_id={} error={}", + offered_contract.id.to_lower_hex_string(), + e.to_string() + ); return self .accept_fail_on_error(offered_contract, accept_msg.clone(), e) - .await + .await; } }; + log_info!( + self.logger, + "Verified the accept message and signed the contract. temp_id={} contract_id={}", + offered_contract.id.to_lower_hex_string(), + signed_contract.accepted_contract.get_contract_id_string(), + ); + + let contract_id = signed_contract.accepted_contract.get_contract_id_string(); + self.wallet.import_address(&Address::p2wsh( &signed_contract .accepted_contract @@ -550,10 +648,18 @@ where .update_contract(&Contract::Signed(signed_contract)) .await?; + log_info!( + self.logger, + "Accepted and signed the contract. temp_id={} contract_id={}", + offered_contract.id.to_lower_hex_string(), + contract_id, + ); + Ok(DlcMessage::Sign(signed_msg)) } /// Function to call to sign a DLC for which an accept was received. + #[tracing::instrument(skip_all)] pub async fn on_sign_message( &self, sign_message: &SignDlc, @@ -568,14 +674,21 @@ where &self.wallet, &self.store, &self.signer_provider, + &self.logger, ) .await { Ok(contract) => contract, Err(e) => { + log_error!( + self.logger, + "Error in on_sign_message. contract_id={} error={}", + accepted_contract.get_contract_id_string(), + e.to_string() + ); return self .sign_fail_on_error(accepted_contract, sign_message.clone(), e) - .await + .await; } }; @@ -601,7 +714,6 @@ where else { return Ok(()); }; - let preclosed_contract = get_contract_in_state!( self, &dlc_input.dlc_input.as_ref().unwrap().contract_id, @@ -619,6 +731,11 @@ where .clone(), }; + log_debug!(self.logger, + "Contract contains a DLC input. Marking the previous contract as pre-closed. dlc_input_contract_id={}", + preclosed_contract.signed_contract.accepted_contract.get_contract_id_string() + ); + self.store .update_contract(&Contract::PreClosed(preclosed_contract.clone())) .await?; @@ -627,6 +744,7 @@ where Ok(()) } + #[tracing::instrument(skip_all, level = "debug")] async fn get_oracle_announcements( &self, oracle_inputs: &OracleInput, @@ -650,7 +768,12 @@ where sign_message: SignDlc, e: Error, ) -> Result { - tracing::error!("Error in on_sign {}", e); + log_error!( + self.logger, + "Error in on_sign_message marking contract as failed sign. contract_id={} error={}", + accepted_contract.get_contract_id_string(), + e.to_string() + ); self.store .update_contract(&Contract::FailedSign(FailedSignContract { accepted_contract, @@ -667,7 +790,12 @@ where accept_message: AcceptDlc, e: Error, ) -> Result { - tracing::error!("Error in on_accept {}", e); + log_error!( + self.logger, + "Error in on_accept_message marking contract as failed accept. contract_id={} error={}", + offered_contract.id.to_lower_hex_string(), + e.to_string() + ); self.store .update_contract(&Contract::FailedAccept(FailedAcceptContract { offered_contract, @@ -678,6 +806,7 @@ where Err(e) } + #[tracing::instrument(skip_all, level = "debug")] async fn check_signed_contract(&self, contract: &SignedContract) -> Result<(), Error> { let confirmations = self .blockchain @@ -690,35 +819,38 @@ where ) .await?; if confirmations >= NB_CONFIRMATIONS { - tracing::info!( + log_info!( + self.logger, + "Marking signed contract as confirmed. confirmations={} contract_id={}", confirmations, - contract_id = contract.accepted_contract.get_contract_id_string(), - "Marking contract as confirmed." + contract.accepted_contract.get_contract_id_string(), ); self.store .update_contract(&Contract::Confirmed(contract.clone())) .await?; } else { - tracing::info!( + log_debug!(self.logger, + "Not enough confirmations to mark contract as confirmed. confirmations={} required={} contract_id={}", confirmations, - required = NB_CONFIRMATIONS, - contract_id = contract.accepted_contract.get_contract_id_string(), - "Not enough confirmations to mark contract as confirmed." + NB_CONFIRMATIONS, + contract.accepted_contract.get_contract_id_string(), ); } Ok(()) } + #[tracing::instrument(skip_all, level = "debug")] async fn check_signed_contracts( &self, signed_contracts: &[SignedContract], ) -> Result<(), Error> { for c in signed_contracts { if let Err(e) = self.check_signed_contract(c).await { - tracing::error!( - "Error checking confirmed contract {}: {}", + log_error!( + self.logger, + "Error checking signed contract. contract_id={} error={}", c.accepted_contract.get_contract_id_string(), - e + e.to_string() ) } } @@ -726,6 +858,7 @@ where Ok(()) } + #[tracing::instrument(skip_all, level = "debug")] async fn check_for_spliced_contract(&self) -> Result, Error> { let contracts = self.get_store().get_signed_contracts().await?; for contract in &contracts { @@ -749,9 +882,18 @@ where None as Option ) { Ok(c) => Ok(c), - Err(Error::InvalidState(_)) => continue, + Err(Error::InvalidState(e)) => { + log_trace!(self.logger, + "The previouse contract referenced in a splice transaction is in an unexpected state. contract_id={} error={}", + contract_id.to_lower_hex_string(), e.to_string(), + ); + continue; + } Err(e) => { - tracing::debug!("The previouse contract referenced in a splice transaction failed to retrieve. error={}", e.to_string()); + log_debug!(self.logger, + "The previouse contract referenced in a splice transaction failed to retrieve. contract_id={} error={}", + contract_id.to_lower_hex_string(), e.to_string(), + ); Err(e) } }?; @@ -762,6 +904,11 @@ where signed_cet: contract.accepted_contract.dlc_transactions.fund.clone(), }; + log_debug!(self.logger, + "The previous contract that was spliced is now closed because the splice contract is confirmed. contract_id={}", + contract_id.to_lower_hex_string(), + ); + self.store .update_contract(&Contract::PreClosed(preclosed_contract.clone())) .await?; @@ -769,6 +916,7 @@ where Ok(contracts) } + #[tracing::instrument(skip_all, level = "debug")] async fn check_confirmed_contracts(&self) -> Result<(), Error> { for c in self.store.get_confirmed_contracts().await? { // Confirmed contracts from channel are processed in channel specific methods. @@ -776,10 +924,11 @@ where continue; } if let Err(e) = self.check_confirmed_contract(&c).await { - tracing::error!( - "Error checking confirmed contract {}: {}", + log_error!( + self.logger, + "Error checking confirmed contract. contract_id={} error={}", c.accepted_contract.get_contract_id_string(), - e + e.to_string() ) } } @@ -787,6 +936,7 @@ where Ok(()) } + #[tracing::instrument(skip_all, level = "debug")] async fn get_closable_contract_info<'a>( &'a self, contract: &'a SignedContract, @@ -794,7 +944,11 @@ where let contract_infos = &contract.accepted_contract.offered_contract.contract_info; let adaptor_infos = &contract.accepted_contract.adaptor_infos; for (contract_info, adaptor_info) in contract_infos.iter().zip(adaptor_infos.iter()) { - tracing::info!("Checking contract for oracle maturation."); + log_debug!( + self.logger, + "Checking contract for oracle maturation. contract_id={}", + contract.accepted_contract.get_contract_id_string() + ); let matured: Vec<_> = contract_info .oracle_announcements .iter() @@ -806,14 +960,20 @@ where if matured.len() >= contract_info.threshold { let attestations = stream::iter(matured.iter()) .map(|(i, announcement)| async move { - tracing::info!("Oracle announcement is matured check for attestation. even_id={}", announcement.oracle_event.event_id); + log_debug!(self.logger, + "Oracle announcement for contract is matured. Getting attestations. contract_id={} event_id={}", + contract.accepted_contract.get_contract_id_string(), + announcement.oracle_event.event_id + ); // First try to get the oracle let oracle = match self.oracles.get(&announcement.oracle_public_key) { Some(oracle) => oracle, None => { - tracing::debug!( - "Oracle not found for key: {}", - announcement.oracle_public_key + log_debug!(self.logger, + "Oracle not found. pubkey={}. contract_id={} event_id={}", + announcement.oracle_public_key, + contract.accepted_contract.get_contract_id_string(), + announcement.oracle_event.event_id ); return None; } @@ -825,8 +985,9 @@ where { Ok(attestation) => attestation, Err(e) => { - tracing::error!( - "Attestation not found for event. id={} error={}", + log_error!(self.logger, + "Attestation not found for event. pubkey={} event_id={} error={}", + announcement.oracle_public_key, announcement.oracle_event.event_id, e.to_string() ); @@ -835,15 +996,20 @@ where }; // Validate the attestation if let Err(e) = attestation.validate(&self.secp, announcement) { - tracing::error!( - "Oracle attestation is not valid. pubkey={} event_id={}, error={:?}", + log_error!(self.logger, + "Oracle attestation is not valid. pubkey={} event_id={}, error={}", announcement.oracle_public_key, announcement.oracle_event.event_id, - e + e.to_string() ); return None; } - tracing::info!("Oracle attestation is valid. event_id={}", announcement.oracle_event.event_id); + log_info!(self.logger, + "Retrieved a valid attestation. pubkey={} event_id={} outcomes={:?}", + announcement.oracle_public_key, + announcement.oracle_event.event_id, + attestation.outcomes + ); Some((*i, attestation)) }) .collect::>() @@ -852,6 +1018,11 @@ where .collect::>() .await; if attestations.len() >= contract_info.threshold { + log_info!(self.logger, + "Found enough attestations to close contract. contract_id={} attestations={}", + contract.accepted_contract.get_contract_id_string(), + attestations.len() + ); return Some((contract_info, adaptor_info, attestations)); } } @@ -859,13 +1030,21 @@ where None } + #[tracing::instrument(skip_all, level = "debug")] async fn check_confirmed_contract(&self, contract: &SignedContract) -> Result<(), Error> { - tracing::info!( - "Checking confirmed contract {}", + log_debug!( + self.logger, + "Checking confirmed contract. contract_id={}", contract.accepted_contract.get_contract_id_string() ); let closable_contract_info = self.get_closable_contract_info(contract).await; if let Some((contract_info, adaptor_info, attestations)) = closable_contract_info { + log_debug!( + self.logger, + "Found closable contract info. contract_id={} attestations={}", + contract.accepted_contract.get_contract_id_string(), + attestations.len() + ); let offer = &contract.accepted_contract.offered_contract; let signer = self.signer_provider.derive_contract_signer(offer.keys_id)?; @@ -881,7 +1060,13 @@ where adaptor_info, &attestations, &signer, + &self.logger, ) { + log_info!( + self.logger, + "Found valid CET. Closing contract. contract_id={}", + contract.accepted_contract.get_contract_id_string() + ); match self .close_contract( contract, @@ -891,14 +1076,20 @@ where .await { Ok(closed_contract) => { + log_info!( + self.logger, + "Updated contract to closed. contract_id={}", + contract.accepted_contract.get_contract_id_string() + ); self.store.update_contract(&closed_contract).await?; return Ok(()); } Err(e) => { - tracing::warn!( - "Failed to close contract {}: {}", + log_warn!( + self.logger, + "Failed to close contract. contract_id={} error={}", contract.accepted_contract.get_contract_id_string(), - e + e.to_string() ); return Err(e); } @@ -917,8 +1108,21 @@ where .get_transaction_confirmations(&pending_close_tx.compute_txid()) .await?; + log_debug!( + self.logger, + "Checking pending close transaction. close_txid={} contract_id={} confirmations={}", + pending_close_tx.compute_txid().to_string(), + contract.accepted_contract.get_contract_id_string(), + confirmations + ); + if confirmations >= NB_CONFIRMATIONS { // Found a fully confirmed pending close - move directly to Closed + log_info!(self.logger, + "Pending close transaction is fully confirmed. Moving to closed. close_txid={} contract_id={}", + pending_close_tx.compute_txid().to_string(), + contract.accepted_contract.get_contract_id_string() + ); let pnl = contract.accepted_contract.compute_pnl(pending_close_tx); let closed_contract = ClosedContract { attestations: None, // Cooperative close has no attestations @@ -940,6 +1144,11 @@ where break; // Only one close can be confirmed } else if confirmations >= 1 { // Found a confirmed but not fully confirmed pending close - move to PreClosed + log_debug!(self.logger, + "Found a confirmed but not fully confirmed pending close. Moving to preclosed. close_txid={} contract_id={}", + pending_close_tx.compute_txid().to_string(), + contract.accepted_contract.get_contract_id_string() + ); let preclosed_contract = PreClosedContract { signed_contract: contract.clone(), attestations: None, // Cooperative close has no attestations @@ -959,11 +1168,21 @@ where } /// Manually close a contract with the oracle attestations. + #[tracing::instrument(skip_all, level = "debug")] pub async fn close_confirmed_contract( &self, contract_id: &ContractId, attestations: Vec<(usize, OracleAttestation)>, ) -> Result { + log_info!( + self.logger, + "Attempting to close confirmed contract manually. contract_id={} outcomes={:?}", + contract_id.to_lower_hex_string(), + attestations + .iter() + .map(|(_, a)| a.outcomes.clone()) + .collect::>() + ); let contract = get_contract_in_state!(self, contract_id, Confirmed, None::)?; let contract_infos = &contract.accepted_contract.offered_contract.contract_info; let adaptor_infos = &contract.accepted_contract.adaptor_infos; @@ -983,6 +1202,11 @@ where { let offer = &contract.accepted_contract.offered_contract; let signer = self.signer_provider.derive_contract_signer(offer.keys_id)?; + log_debug!( + self.logger, + "Getting signed CET. contract_id={}", + contract.accepted_contract.get_contract_id_string() + ); let cet = crate::contract_updater::get_signed_cet( &self.secp, &contract, @@ -990,6 +1214,7 @@ where adaptor_info, &attestations, &signer, + &self.logger, )?; // Check that the lock time has passed @@ -1015,13 +1240,20 @@ where .await { Ok(closed_contract) => { + log_info!( + self.logger, + "Closed contract manually. contract_id={}", + contract.accepted_contract.get_contract_id_string() + ); self.store.update_contract(&closed_contract).await?; Ok(closed_contract) } Err(e) => { - tracing::warn!( - "Failed to close contract {}: {e}", - contract.accepted_contract.get_contract_id_string() + log_error!( + self.logger, + "Failed to close contract. contract_id={} error={}", + contract.accepted_contract.get_contract_id_string(), + e.to_string() ); Err(e) } @@ -1033,11 +1265,13 @@ where } } + #[tracing::instrument(skip_all, level = "debug")] async fn check_preclosed_contracts(&self) -> Result<(), Error> { for c in self.store.get_preclosed_contracts().await? { if let Err(e) = self.check_preclosed_contract(&c).await { - tracing::error!( - "Error checking pre-closed contract {}: {}", + log_error!( + self.logger, + "Error checking pre-closed contract. contract_id={} error={}", c.signed_contract.accepted_contract.get_contract_id_string(), e ) @@ -1047,13 +1281,29 @@ where Ok(()) } + #[tracing::instrument(skip_all, level = "debug")] async fn check_preclosed_contract(&self, contract: &PreClosedContract) -> Result<(), Error> { let broadcasted_txid = contract.signed_cet.compute_txid(); let confirmations = self .blockchain .get_transaction_confirmations(&broadcasted_txid) .await?; + log_debug!( + self.logger, + "Checking pre-closed contract. broadcasted_txid={} contract_id={} confirmations={}", + broadcasted_txid.to_string(), + contract + .signed_contract + .accepted_contract + .get_contract_id_string(), + confirmations + ); if confirmations >= NB_CONFIRMATIONS { + log_debug!(self.logger, + "Pre-closed contract is fully confirmed. Moving to closed. broadcasted_txid={} contract_id={}", + broadcasted_txid.to_string(), + contract.signed_contract.accepted_contract.get_contract_id_string() + ); let pnl = contract .signed_contract .accepted_contract @@ -1089,6 +1339,7 @@ where Ok(()) } + #[tracing::instrument(skip_all, level = "debug")] async fn close_contract( &self, contract: &SignedContract, @@ -1101,9 +1352,11 @@ where .await?; if confirmations < 1 { - tracing::info!( - txid = signed_cet.compute_txid().to_string(), - "Broadcasting signed CET." + log_info!( + self.logger, + "Broadcasting signed CET. txid={} contract_id={}", + signed_cet.compute_txid().to_string(), + contract.accepted_contract.get_contract_id_string() ); // TODO(tibo): if this fails because another tx is already in // mempool or blockchain, we might have been cheated. There is @@ -1119,6 +1372,11 @@ where return Ok(Contract::PreClosed(preclosed_contract)); } else if confirmations < NB_CONFIRMATIONS { + log_debug!(self.logger, + "Found a confirmed but not fully confirmed pending close. Moving to preclosed. txid={} contract_id={}", + signed_cet.compute_txid().to_string(), + contract.accepted_contract.get_contract_id_string() + ); let preclosed_contract = PreClosedContract { signed_contract: contract.clone(), attestations: Some(attestations), @@ -1146,6 +1404,7 @@ where } // TODO: Make this public to refund + #[tracing::instrument(skip_all, level = "debug")] async fn check_refund(&self, contract: &SignedContract) -> Result<(), Error> { // TODO(tibo): should check for confirmation of refund before updating state if contract @@ -1156,6 +1415,11 @@ where .to_consensus_u32() as u64 <= self.time.unix_time_now() { + log_debug!(self.logger, + "Refund locktime has passed. Attempting to broadcast refund. refund_txid={} contract_id={}", + contract.accepted_contract.dlc_transactions.refund.compute_txid().to_string(), + contract.accepted_contract.get_contract_id_string() + ); let accepted_contract = &contract.accepted_contract; let refund = accepted_contract.dlc_transactions.refund.clone(); let confirmations = self @@ -1163,10 +1427,19 @@ where .get_transaction_confirmations(&refund.compute_txid()) .await?; if confirmations == 0 { + log_debug!(self.logger, + "Refund transaction has not been broadcast yet. Sending transaction txid={} contract_id={}", + refund.compute_txid().to_string(), + contract.accepted_contract.get_contract_id_string() + ); let offer = &contract.accepted_contract.offered_contract; let signer = self.signer_provider.derive_contract_signer(offer.keys_id)?; - let refund = - crate::contract_updater::get_signed_refund(&self.secp, contract, &signer)?; + let refund = crate::contract_updater::get_signed_refund( + &self.secp, + contract, + &signer, + &self.logger, + )?; self.blockchain.send_transaction(&refund).await?; } @@ -1180,6 +1453,7 @@ where /// Function to call when we detect that a contract was closed by our counter party. /// This will update the state of the contract and return the [`Contract`] object. + #[tracing::instrument(skip_all, level = "debug")] pub async fn on_counterparty_close( &mut self, contract: &SignedContract, @@ -1194,6 +1468,12 @@ where .dlc_transactions .get_fund_outpoint() }) { + log_error!( + self.logger, + "Closing tx does not spend the funding tx. txid={} contract_id={}", + closing_tx.compute_txid().to_string(), + contract.accepted_contract.get_contract_id_string() + ); return Err(Error::InvalidParameters( "Closing tx does not spend the funding tx".to_string(), )); @@ -1207,18 +1487,35 @@ where .compute_txid() == closing_tx.compute_txid() { + log_debug!( + self.logger, + "Closing tx is the refund tx. Moving to refunded. txid={} contract_id={}", + closing_tx.compute_txid().to_string(), + contract.accepted_contract.get_contract_id_string() + ); let refunded = Contract::Refunded(contract.clone()); self.store.update_contract(&refunded).await?; return Ok(refunded); } let contract = if confirmations < NB_CONFIRMATIONS { + log_info!(self.logger, + "Closing transaction is not fully confirmed. Moving to preclosed. txid={} contract_id={}", + closing_tx.compute_txid().to_string(), + contract.accepted_contract.get_contract_id_string() + ); Contract::PreClosed(PreClosedContract { signed_contract: contract.clone(), attestations: None, // todo in some cases we can get the attestations from the closing tx signed_cet: closing_tx, }) } else { + log_info!( + self.logger, + "Closing transaction is fully confirmed. Moving to closed. txid={} contract_id={}", + closing_tx.compute_txid().to_string(), + contract.accepted_contract.get_contract_id_string() + ); Contract::Closed(ClosedContract { attestations: None, // todo in some cases we can get the attestations from the closing tx pnl: contract.accepted_contract.compute_pnl(&closing_tx), @@ -1242,6 +1539,7 @@ where /// Initiates a cooperative close of a contract by creating and signing a closing transaction. /// Returns a CloseDlc message to be sent to the counter party. /// The contract remains in Confirmed state until the close transaction is broadcast. + #[tracing::instrument(skip_all, level = "debug")] pub async fn cooperative_close_contract( &self, contract_id: &ContractId, @@ -1255,6 +1553,7 @@ where &signed_contract, counter_payout, &self.signer_provider, + &self.logger, )?; // Create updated contract with pending close transaction @@ -1263,6 +1562,12 @@ where updated_dlc_transactions .pending_close_txs .push(close_tx.clone()); + log_debug!( + self.logger, + "Created updated contract with pending close transaction. close_txid={} contract_id={}", + close_tx.compute_txid().to_string(), + contract_id.to_lower_hex_string() + ); let updated_accepted_contract = AcceptedContract { dlc_transactions: updated_dlc_transactions, @@ -1289,6 +1594,7 @@ where /// Accepts a cooperative close request by completing the close transaction /// and broadcasting it to the network. + #[tracing::instrument(skip_all, level = "debug")] pub async fn accept_cooperative_close( &self, contract_id: &ContractId, @@ -1302,8 +1608,15 @@ where &signed_contract, close_message, &self.signer_provider, + &self.logger, )?; + log_debug!( + self.logger, + "Completed cooperative close. close_txid={} contract_id={}", + close_tx.compute_txid().to_string(), + contract_id.to_lower_hex_string() + ); // Broadcast the closing transaction self.blockchain.send_transaction(&close_tx).await?; @@ -1322,8 +1635,17 @@ where } } -impl - Manager>, B, S, O, T, F, X> +impl< + W: Deref, + SP: Deref, + B: Deref, + S: Deref, + O: Deref, + T: Deref, + F: Deref, + X: ContractSigner, + L: Deref, + > Manager>, B, S, O, T, F, X, L> where W::Target: Wallet, SP::Target: ContractSignerProvider, @@ -1332,6 +1654,7 @@ where O::Target: Oracle, T::Target: Time, F::Target: FeeEstimator, + L::Target: Logger, { /// Create a new channel offer and return the [`dlc_messages::channel::OfferChannel`] /// message to be sent to the `counter_party`. @@ -1763,7 +2086,8 @@ where .await? >= CET_NSEQUENCE { - tracing::info!( + log_info!( + self.logger, "Buffer transaction for contract {} has enough confirmations to spend from it", serialize_hex(&contract_id) ); @@ -1880,6 +2204,7 @@ where &self.signer_provider, &self.store, &self.chain_monitor, + &self.logger, ) .await; @@ -1961,6 +2286,7 @@ where &self.chain_monitor, &self.store, &self.signer_provider, + &self.logger, ) .await; @@ -2233,6 +2559,7 @@ where &self.signer_provider, &self.time, &self.store, + &self.logger, ) .await?; @@ -2321,6 +2648,7 @@ where &self.signer_provider, &self.chain_monitor, &self.store, + &self.logger, ) .await?; @@ -2563,7 +2891,8 @@ where } } } else { - tracing::warn!( + log_warn!( + self.logger, "Couldn't find rejected dlc channel with id: {}", reject.channel_id.to_lower_hex_string() ); @@ -2580,12 +2909,16 @@ where for channel in established_closing_channels { if let Err(e) = self.try_finalize_closing_established_channel(channel).await { - tracing::error!("Error trying to close established channel: {}", e); + log_error!( + self.logger, + "Error trying to close established channel: {}", + e + ); } } if let Err(e) = self.check_for_timed_out_channels().await { - tracing::error!("Error checking timed out channels {}", e); + log_error!(self.logger, "Error checking timed out channels {}", e); } self.check_for_watched_tx().await } @@ -2614,7 +2947,8 @@ where ) { Ok(c) => c, Err(e) => { - tracing::error!( + log_error!( + self.logger, "Could not retrieve channel {:?}: {}", channel_info.channel_id, e @@ -2862,7 +3196,7 @@ where } } _ => { - tracing::error!("Saw spending of buffer transaction without being in closing state"); + log_error!(self.logger, "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, @@ -3114,7 +3448,7 @@ where match future.await { Ok(result) => Ok(result), Err(e) => { - tracing::error!("Failed to get oracle announcements: {}", e); + log_error!(self.logger, "Failed to get oracle announcements: {}", e); Err(e) } } diff --git a/ddk-manager/tests/contract_updater.rs b/ddk-manager/tests/contract_updater.rs index 8a154b5b..18e7728d 100644 --- a/ddk-manager/tests/contract_updater.rs +++ b/ddk-manager/tests/contract_updater.rs @@ -2,17 +2,18 @@ #[allow(dead_code)] mod test_utils; -use std::rc::Rc; use std::sync::Arc; use bitcoin::Network; use ddk::chain::EsploraClient; +use ddk::logger::Logger; use ddk_manager::contract::offered_contract::OfferedContract; use secp256k1_zkp::rand::Fill; use secp256k1_zkp::PublicKey; #[tokio::test] async fn accept_contract_test() { + let logger = Arc::new(Logger::disabled("test_contract_updater".to_string())); let offer_dlc = serde_json::from_str(include_str!("../test_inputs/offer_contract.json")).unwrap(); let dummy_pubkey: PublicKey = @@ -25,10 +26,11 @@ async fn accept_contract_test() { .unwrap(); let offered_contract = OfferedContract::try_from_offer_dlc(&offer_dlc, dummy_pubkey, keys_id).unwrap(); - let blockchain = - Rc::new(EsploraClient::new("http://localhost:30000", Network::Regtest).unwrap()); + let blockchain = Arc::new( + EsploraClient::new("http://localhost:30000", Network::Regtest, logger.clone()).unwrap(), + ); - let stuff = test_utils::create_and_fund_wallet().await; + let stuff = test_utils::create_and_fund_wallet(logger.clone(), blockchain.clone()).await; let wallet = Arc::new(stuff.0); wallet.sync().await.unwrap(); @@ -38,6 +40,7 @@ async fn accept_contract_test() { &wallet, &wallet, &blockchain, + &logger, ) .await .expect("Not to fail"); diff --git a/ddk-manager/tests/manager_execution_tests.rs b/ddk-manager/tests/manager_execution_tests.rs index 2ad27763..7754abc9 100644 --- a/ddk-manager/tests/manager_execution_tests.rs +++ b/ddk-manager/tests/manager_execution_tests.rs @@ -4,6 +4,7 @@ mod test_utils; use bitcoin::Amount; use ddk::chain::EsploraClient; +use ddk::logger::Logger; use ddk_manager::payout_curve::PayoutFunctionPiece; use test_utils::*; @@ -726,12 +727,19 @@ async fn get_attestations(test_params: &TestParams) -> Vec<(usize, OracleAttesta async fn manager_execution_test(test_params: TestParams, path: TestPath, manual_close: bool) { env_logger::try_init().ok(); + let esplora_host = std::env::var("ESPLORA_HOST").expect("ESPLORA_HOST must be set"); + let logger = Arc::new(Logger::disabled("test_manager_execution".to_string())); + let electrs = Arc::new( + EsploraClient::new(&esplora_host, bitcoin::Network::Regtest, logger.clone()).unwrap(), + ); + let (alice_send, mut bob_receive) = channel::>(100); let (bob_send, mut alice_receive) = channel::>(100); let (sync_send, mut sync_receive) = channel::<()>(100); let alice_sync_send = sync_send.clone(); let bob_sync_send = sync_send; - let (bob_wallet, bob_storage, alice_wallet, alice_storage, sink_rpc) = init_clients().await; + let (bob_wallet, bob_storage, alice_wallet, alice_storage, sink_rpc) = + init_clients(logger.clone(), electrs.clone()).await; let alice_wallet = Arc::new(alice_wallet); let bob_wallet = Arc::new(bob_wallet); let sink = Arc::new(sink_rpc); @@ -755,9 +763,6 @@ async fn manager_execution_test(test_params: TestParams, path: TestPath, manual_ test_utils::set_time(initial_time); - let electrs = - Arc::new(EsploraClient::new("http://localhost:30000", bitcoin::Network::Regtest).unwrap()); - test_utils::generate_blocks(6, electrs.clone(), sink.clone()).await; refresh_wallet(&alice_wallet, TOTAL_COLLATERAL.to_sat()).await; @@ -772,6 +777,7 @@ async fn manager_execution_test(test_params: TestParams, path: TestPath, manual_ alice_oracles, Arc::clone(&mock_time), Arc::clone(&electrs), + logger.clone(), ) .await .unwrap(), @@ -789,6 +795,7 @@ async fn manager_execution_test(test_params: TestParams, path: TestPath, manual_ bob_oracles, Arc::clone(&mock_time), Arc::clone(&electrs), + logger.clone(), ) .await .unwrap(), diff --git a/ddk-manager/tests/manager_tests.rs b/ddk-manager/tests/manager_tests.rs index ebd184a2..89f22226 100644 --- a/ddk-manager/tests/manager_tests.rs +++ b/ddk-manager/tests/manager_tests.rs @@ -3,10 +3,10 @@ mod test_utils; use bitcoin::Network; -use ddk::chain::EsploraClient; use ddk::oracle::memory::MemoryOracle; use ddk::storage::memory::MemoryStorage; use ddk::wallet::DlcDevKitWallet; +use ddk::{chain::EsploraClient, logger::Logger}; use ddk_manager::{manager::Manager, CachedContractSignerProvider, Oracle, SimpleSigner}; use ddk_messages::Message; use secp256k1_zkp::{rand::Fill, PublicKey, XOnlyPublicKey}; @@ -22,11 +22,13 @@ type TestManager = Manager< Arc, Arc, SimpleSigner, + Arc, >; -async fn get_manager() -> TestManager { - let blockchain = - Arc::new(EsploraClient::new("http://localhost:30000", Network::Regtest).unwrap()); +async fn get_manager(logger: Arc) -> TestManager { + let blockchain = Arc::new( + EsploraClient::new("http://localhost:30000", Network::Regtest, logger.clone()).unwrap(), + ); let store = Arc::new(MemoryStorage::new()); let mut seed = [0u8; 64]; seed.try_fill(&mut bitcoin::key::rand::thread_rng()) @@ -34,10 +36,11 @@ async fn get_manager() -> TestManager { let wallet = Arc::new( DlcDevKitWallet::new( &seed, - "http://localhost:30000", + blockchain.clone(), Network::Regtest, store.clone(), None, + logger.clone(), ) .await .unwrap(), @@ -60,6 +63,7 @@ async fn get_manager() -> TestManager { oracles, time, blockchain, + logger, ) .await .unwrap() @@ -73,11 +77,12 @@ fn pubkey() -> PublicKey { #[tokio::test] async fn reject_offer_with_existing_contract_id() { + let logger = Arc::new(Logger::disabled("test_manager".to_string())); let offer_message = Message::Offer( serde_json::from_str(include_str!("../test_inputs/offer_contract.json")).unwrap(), ); - let manager = get_manager().await; + let manager = get_manager(logger).await; manager .on_dlc_message(&offer_message, pubkey()) @@ -92,11 +97,12 @@ async fn reject_offer_with_existing_contract_id() { #[tokio::test] async fn reject_channel_offer_with_existing_channel_id() { + let logger = Arc::new(Logger::disabled("test_manager".to_string())); let offer_message = Message::OfferChannel( serde_json::from_str(include_str!("../test_inputs/offer_channel.json")).unwrap(), ); - let manager = get_manager().await; + let manager = get_manager(logger).await; manager .on_dlc_message(&offer_message, pubkey()) diff --git a/ddk-manager/tests/test_utils.rs b/ddk-manager/tests/test_utils.rs index ce8a1446..7094b588 100644 --- a/ddk-manager/tests/test_utils.rs +++ b/ddk-manager/tests/test_utils.rs @@ -6,7 +6,7 @@ use bitcoin::{ }; use bitcoincore_rpc::{Auth, Client, RpcApi}; use bitcoincore_rpc_json::AddressType; -use ddk::{chain::EsploraClient, wallet::DlcDevKitWallet}; +use ddk::{chain::EsploraClient, logger::Logger, wallet::DlcDevKitWallet}; use ddk::{oracle::memory::MemoryOracle, storage::memory::MemoryStorage}; use ddk_dlc::{EnumerationPayout, Payout}; use ddk_manager::payout_curve::{ @@ -799,13 +799,17 @@ pub async fn refresh_wallet(wallet: &DlcDevKitWallet, expected_funds: u64) { } pub fn rpc_client() -> Client { - let auth = Auth::UserPass("ddk".to_string(), "ddk".to_string()); + let user = std::env::var("BITCOIND_USER").expect("BITCOIND_USER must be set"); + let pass = std::env::var("BITCOIND_PASS").expect("BITCOIND_PASS must be set"); let host = std::env::var("BITCOIND_HOST").unwrap_or_else(|_| "http://localhost:18443".to_owned()); - Client::new(&host, auth).unwrap() + Client::new(&host, Auth::UserPass(user, pass)).unwrap() } -pub async fn init_clients() -> ( +pub async fn init_clients( + logger: Arc, + esplora: Arc, +) -> ( DlcDevKitWallet, Arc, DlcDevKitWallet, @@ -815,8 +819,8 @@ pub async fn init_clients() -> ( let sink_rpc = rpc_client(); tokio::time::sleep(std::time::Duration::from_millis(100)).await; - let offer_rpc = create_and_fund_wallet().await; - let accept_rpc = create_and_fund_wallet().await; + let offer_rpc = create_and_fund_wallet(logger.clone(), esplora.clone()).await; + let accept_rpc = create_and_fund_wallet(logger.clone(), esplora.clone()).await; let sink_address = sink_rpc .get_new_address(None, Some(AddressType::Bech32)) @@ -834,7 +838,10 @@ pub async fn init_clients() -> ( ) } -pub async fn create_and_fund_wallet() -> (DlcDevKitWallet, Arc) { +pub async fn create_and_fund_wallet( + logger: Arc, + esplora: Arc, +) -> (DlcDevKitWallet, Arc) { let sink_rpc = rpc_client(); let sink_address = sink_rpc .get_new_address(None, None) @@ -846,10 +853,11 @@ pub async fn create_and_fund_wallet() -> (DlcDevKitWallet, Arc) { let memory_storage = Arc::new(MemoryStorage::new()); let wallet = DlcDevKitWallet::new( &seed, - "http://localhost:30000", + esplora, Network::Regtest, memory_storage.clone(), None, + logger.clone(), ) .await .unwrap(); diff --git a/ddk-node/Cargo.toml b/ddk-node/Cargo.toml index 49da7562..7573a14c 100644 --- a/ddk-node/Cargo.toml +++ b/ddk-node/Cargo.toml @@ -27,7 +27,7 @@ serde_json = "1.0.125" tokio = { version = "1.38.0", features = ["full"] } tonic = "0.10.2" tracing = "0.1.40" -tracing-subscriber = "0.3.18" +tracing-subscriber = { version = "0.3.18", features = ["env-filter"] } reqwest = { version = "0.12.12", features = ["json"] } chrono = "0.4.39" diff --git a/ddk-node/src/bin/node.rs b/ddk-node/src/bin/node.rs index 47e0af4e..90565961 100644 --- a/ddk-node/src/bin/node.rs +++ b/ddk-node/src/bin/node.rs @@ -3,16 +3,35 @@ use ddk_node::opts::NodeOpts; use ddk_node::DdkNode; use std::str::FromStr; use tracing::level_filters::LevelFilter; +use tracing_subscriber::EnvFilter; #[tokio::main] async fn main() -> anyhow::Result<()> { let opts = NodeOpts::parse(); + let base_level = LevelFilter::from_str(&opts.log).unwrap_or(LevelFilter::INFO); + + // Build the filter string based on the base level + let filter_string = match base_level { + LevelFilter::TRACE => "trace", + LevelFilter::DEBUG => { + "debug,hyper_util=info,sqlx=info,nostr_relay_pool=info,hyper=info,h2=info" + } + LevelFilter::INFO => "info", + LevelFilter::WARN => "warn", + LevelFilter::ERROR => "error", + LevelFilter::OFF => "off", + }; + + // Parse the filter string, with fallback to the base level + let filter = EnvFilter::from_str(filter_string).unwrap_or(EnvFilter::from_default_env()); - let level = LevelFilter::from_str(&opts.log).unwrap_or(LevelFilter::INFO); let subscriber = tracing_subscriber::fmt() .with_line_number(true) - .with_max_level(level) + .with_file(false) + // .with_target(false) + .with_env_filter(filter) .finish(); + tracing::subscriber::set_global_default(subscriber).unwrap(); DdkNode::serve(opts).await?; diff --git a/ddk-node/src/command.rs b/ddk-node/src/command.rs index a1aef819..303bd75b 100644 --- a/ddk-node/src/command.rs +++ b/ddk-node/src/command.rs @@ -1,3 +1,5 @@ +use std::sync::Arc; + use crate::cli_opts::{CliCommand, OracleCommand, WalletCommand}; // use crate::convert::*; use crate::ddkrpc::ddk_rpc_client::DdkRpcClient; @@ -11,6 +13,7 @@ use anyhow::anyhow; use bitcoin::{Amount, Transaction}; use chrono::TimeDelta; use ddk::json::*; +use ddk::logger::{LogLevel, Logger}; use ddk::oracle::kormir::KormirOracleClient; use ddk::util; use ddk::wallet::LocalOutput; @@ -228,8 +231,12 @@ async fn generate_contract_input() -> anyhow::Result { }, ], }); + let logger = Arc::new(Logger::console( + "generate_contract_input".to_string(), + LogLevel::Info, + )); - let kormir = KormirOracleClient::new("https://kormir.dlcdevkit.com", None).await?; + let kormir = KormirOracleClient::new("https://kormir.dlcdevkit.com", None, logger).await?; let expiry = (chrono::Utc::now() .checked_add_signed(TimeDelta::minutes(15)) diff --git a/ddk-node/src/lib.rs b/ddk-node/src/lib.rs index 345a21df..296af0df 100644 --- a/ddk-node/src/lib.rs +++ b/ddk-node/src/lib.rs @@ -7,6 +7,7 @@ mod seed; use bitcoin::secp256k1::PublicKey; use bitcoin::{Address, Amount, FeeRate, Network}; use ddk::builder::{Builder, SeedConfig}; +use ddk::logger::{LogLevel, Logger}; use ddk::oracle::kormir::KormirOracleClient; use ddk::storage::postgres::PostgresStore; use ddk::transport::nostr::NostrDlc; @@ -52,6 +53,10 @@ impl DdkNode { } pub async fn serve(opts: NodeOpts) -> anyhow::Result<()> { + let logger = Arc::new(Logger::console( + "console_logger".to_string(), + LogLevel::Info, + )); let storage_path = match opts.storage_dir { Some(storage) => storage, None => homedir::my_home() @@ -65,14 +70,23 @@ impl DdkNode { let seed_bytes = crate::seed::xprv_from_path(storage_path.clone())?; - tracing::info!("Starting DDK node."); - let transport = - Arc::new(NostrDlc::new(&seed_bytes, "wss://nostr.dlcdevkit.com", network).await?); + let transport = Arc::new( + NostrDlc::new( + &seed_bytes, + "wss://nostr.dlcdevkit.com", + network, + logger.clone(), + ) + .await?, + ); - let storage = Arc::new(PostgresStore::new(&opts.postgres_url, true, opts.name).await?); + let storage = Arc::new( + PostgresStore::new(&opts.postgres_url, true, logger.clone(), opts.name).await?, + ); // let oracle = Arc::new(P2PDOracleClient::new(&oracle_host).await?); - let oracle = Arc::new(KormirOracleClient::new(&opts.oracle_host, None).await?); + let oracle = + Arc::new(KormirOracleClient::new(&opts.oracle_host, None, logger.clone()).await?); let mut builder = Builder::new(); builder.set_seed_bytes(SeedConfig::Bytes(seed_bytes))?; @@ -81,6 +95,7 @@ impl DdkNode { builder.set_transport(transport.clone()); builder.set_storage(storage.clone()); builder.set_oracle(oracle.clone()); + builder.set_logger(logger.clone()); let ddk: Ddk = builder.finish().await?; diff --git a/ddk/Cargo.toml b/ddk/Cargo.toml index 61dece42..aedc42fe 100644 --- a/ddk/Cargo.toml +++ b/ddk/Cargo.toml @@ -68,9 +68,10 @@ bip39 = "2.2.0" test-log = { version = "0.2.16", features = ["trace"] } ddk-payouts = { path = "../payouts/" } bitcoincore-rpc = "0.19.0" +dotenv = "0.15.0" [[example]] -name = "lighnting" +name = "lightning" path = "examples/lightning.rs" required-features = ["lightning", "kormir", "sled"] diff --git a/ddk/examples/lightning.rs b/ddk/examples/lightning.rs index 9bb6095c..2aa8e10f 100644 --- a/ddk/examples/lightning.rs +++ b/ddk/examples/lightning.rs @@ -1,4 +1,5 @@ use ddk::builder::{Builder, SeedConfig}; +use ddk::logger::{LogLevel, Logger}; use ddk::oracle::kormir::KormirOracleClient; use ddk::storage::sled::SledStorage; use ddk::transport::lightning::LightningTransport; @@ -9,15 +10,23 @@ type ApplicationDdk = ddk::DlcDevKit Result<(), ddk::error::Error> { - let transport = Arc::new(LightningTransport::new(&[0u8; 32], 1776)?); - let storage = Arc::new(SledStorage::new(current_dir().unwrap().to_str().unwrap()).unwrap()); - let oracle_client = Arc::new(KormirOracleClient::new("host", None).await?); + let logger = Arc::new(Logger::console( + "lightning_example".to_string(), + LogLevel::Info, + )); + let transport = Arc::new(LightningTransport::new(&[0u8; 32], 1776, logger.clone())?); + let storage = Arc::new( + SledStorage::new(current_dir().unwrap().to_str().unwrap(), logger.clone()).unwrap(), + ); + let oracle_client = + Arc::new(KormirOracleClient::new("http://localhost:8080", None, logger.clone()).await?); let mut builder = Builder::new(); builder.set_seed_bytes(SeedConfig::Random)?; builder.set_transport(transport.clone()); builder.set_storage(storage.clone()); builder.set_oracle(oracle_client.clone()); + builder.set_logger(logger.clone()); let ddk: ApplicationDdk = builder.finish().await?; diff --git a/ddk/examples/nostr.rs b/ddk/examples/nostr.rs index 88031b80..d0d28b65 100644 --- a/ddk/examples/nostr.rs +++ b/ddk/examples/nostr.rs @@ -1,6 +1,7 @@ use bitcoin::key::rand::Fill; use bitcoin::Network; use ddk::builder::{Builder, SeedConfig}; +use ddk::logger::{LogLevel, Logger}; use ddk::oracle::memory::MemoryOracle; use ddk::storage::memory::MemoryStorage; use ddk::transport::nostr::NostrDlc; @@ -14,9 +15,17 @@ async fn main() -> Result<(), ddk::error::Error> { seed_bytes .try_fill(&mut bitcoin::key::rand::thread_rng()) .unwrap(); + let logger = Arc::new(Logger::console("nostr_example".to_string(), LogLevel::Info)); - let transport = - Arc::new(NostrDlc::new(&seed_bytes, "wss://nostr.dlcdevkit.com", Network::Regtest).await?); + let transport = Arc::new( + NostrDlc::new( + &seed_bytes, + "wss://nostr.dlcdevkit.com", + Network::Regtest, + logger.clone(), + ) + .await?, + ); let storage = Arc::new(MemoryStorage::new()); let oracle_client = Arc::new(MemoryOracle::default()); @@ -25,6 +34,7 @@ async fn main() -> Result<(), ddk::error::Error> { builder.set_transport(transport.clone()); builder.set_storage(storage.clone()); builder.set_oracle(oracle_client.clone()); + builder.set_logger(logger.clone()); let ddk: NostrDdk = builder.finish().await?; diff --git a/ddk/examples/postgres.rs b/ddk/examples/postgres.rs index b3f9f24b..a219c06b 100644 --- a/ddk/examples/postgres.rs +++ b/ddk/examples/postgres.rs @@ -1,5 +1,6 @@ use bitcoin::key::rand::Fill; use ddk::builder::{Builder, SeedConfig}; +use ddk::logger::{LogLevel, Logger}; use ddk::oracle::kormir::KormirOracleClient; use ddk::storage::postgres::PostgresStore; use ddk::transport::lightning::LightningTransport; @@ -9,17 +10,23 @@ type ApplicationDdk = ddk::DlcDevKit Result<(), ddk::error::Error> { - let transport = Arc::new(LightningTransport::new(&[0u8; 32], 1776)?); + let logger = Arc::new(Logger::console( + "console_logger".to_string(), + LogLevel::Info, + )); + let transport = Arc::new(LightningTransport::new(&[0u8; 32], 1776, logger.clone())?); let storage = Arc::new( PostgresStore::new( &std::env::var("DATABASE_URL").expect("DATABASE_URL must be set"), false, + logger.clone(), "test".to_string(), ) .await?, ); - let oracle_client = - Arc::new(KormirOracleClient::new("https://kormir.dlcdevkit.com", None).await?); + let oracle_client = Arc::new( + KormirOracleClient::new("https://kormir.dlcdevkit.com", None, logger.clone()).await?, + ); let mut seed_bytes = [0u8; 64]; seed_bytes @@ -31,6 +38,7 @@ async fn main() -> Result<(), ddk::error::Error> { builder.set_transport(transport.clone()); builder.set_storage(storage.clone()); builder.set_oracle(oracle_client.clone()); + builder.set_logger(logger.clone()); let ddk: ApplicationDdk = builder.finish().await?; diff --git a/ddk/src/builder.rs b/ddk/src/builder.rs index 83f83960..ded893e5 100644 --- a/ddk/src/builder.rs +++ b/ddk/src/builder.rs @@ -1,3 +1,4 @@ +use crate::logger::{log_error, log_info, WriteLog}; use bip39::{Language, Mnemonic}; use bitcoin::key::rand::Fill; use bitcoin::Network; @@ -9,12 +10,14 @@ use std::sync::{Arc, RwLock}; use crate::chain::EsploraClient; use crate::ddk::{DlcDevKit, DlcManagerMessage}; use crate::error::{BuilderError, Error}; +use crate::logger::{LogLevel, Logger}; use crate::wallet::address::AddressGenerator; use crate::wallet::DlcDevKitWallet; use crate::{Oracle, Storage, Transport}; const DEFAULT_ESPLORA_HOST: &str = "https://mutinynet.com/api"; const DEFAULT_NETWORK: Network = Network::Signet; +const DEFAULT_LOG_LEVEL: LogLevel = LogLevel::Info; /// Configuration for the seed bytes for the wallet. #[derive(Debug, Clone)] @@ -38,6 +41,7 @@ pub struct Builder { esplora_host: String, network: Network, seed_bytes: [u8; 64], + logger: Option>, } /// Defaults when creating a DDK application @@ -56,6 +60,7 @@ impl Default for Builder { esplora_host: DEFAULT_ESPLORA_HOST.to_string(), network: DEFAULT_NETWORK, seed_bytes: [0u8; 64], + logger: None, } } } @@ -137,14 +142,29 @@ impl Builder { Ok(self) } + /// Set the logger for the DDK instance. + pub fn set_logger(&mut self, logger: Arc) -> &mut Self { + self.logger = Some(logger); + self + } + + /// Setup the logger based on the provided logger or use default console logging + fn setup_logger(&self, name: &str) -> Result, Error> { + match &self.logger { + Some(logger) => Ok(logger.clone()), + None => { + // Default to console logging with Info level + Ok(Arc::new(Logger::console( + name.to_string(), + DEFAULT_LOG_LEVEL, + ))) + } + } + } + /// Builds the `DlcDevKit` instance. Fails if any components are missing. + #[tracing::instrument(name = "builder", skip(self))] pub async fn finish(&self) -> Result, Error> { - tracing::info!( - network = self.network.to_string(), - esplora = self.esplora_host, - "Building DDK." - ); - let transport = self .transport .as_ref() @@ -160,19 +180,28 @@ impl Builder { .as_ref() .map_or_else(|| Err(BuilderError::NoOracle), |o| Ok(o.clone()))?; - let _ = self + let name = self .name .clone() .unwrap_or_else(|| uuid::Uuid::new_v4().to_string()); + let logger = self.setup_logger(&name)?; + + let esplora_client = Arc::new(EsploraClient::new( + &self.esplora_host, + self.network, + logger.clone(), + )?); + let wallet = match &self.contract_address_generator { Some(w) => { let wallet = DlcDevKitWallet::new( &self.seed_bytes, - &self.esplora_host, + esplora_client.clone(), self.network, storage.clone(), Some(w.clone()), + logger.clone(), ) .await?; Arc::new(wallet) @@ -180,10 +209,11 @@ impl Builder { None => Arc::new( DlcDevKitWallet::new( &self.seed_bytes, - &self.esplora_host, + esplora_client.clone(), self.network, storage.clone(), None, + logger.clone(), ) .await?, ), @@ -192,8 +222,6 @@ impl Builder { let mut oracles = HashMap::new(); oracles.insert(oracle.get_public_key(), oracle.clone()); - let esplora_client = Arc::new(EsploraClient::new(&self.esplora_host, self.network)?); - let (sender, mut receiver) = tokio::sync::mpsc::channel(100); let (stop_signal_sender, stop_signal) = tokio::sync::watch::channel(false); @@ -206,11 +234,13 @@ impl Builder { oracles, Arc::new(SystemTimeProvider {}), wallet.clone(), + logger.clone(), ) .await?, ); let manager_clone = manager.clone(); + let logger_clone = logger.clone(); tokio::spawn(async move { while let Some(msg) = receiver.recv().await { match msg { @@ -229,7 +259,7 @@ impl Builder { .await; let _ = responder.send(offer).map_err(|e| { - tracing::error!("Error sending offer: {:?}", e); + log_error!(logger_clone.clone(), "Error sending offer: {:?}", e); }); } DlcManagerMessage::AcceptDlc { @@ -239,7 +269,7 @@ impl Builder { let accept_dlc = manager_clone.accept_contract_offer(&contract).await; let _ = responder.send(accept_dlc).map_err(|e| { - tracing::error!("Error sending accept DLC: {:?}", e); + log_error!(logger_clone.clone(), "Error sending accept DLC: {:?}", e); }); } DlcManagerMessage::PeriodicCheck => { @@ -249,6 +279,16 @@ impl Builder { } }); + log_info!( + logger.clone(), + "DDK runtime created. name={}, esplora={}, network={}, transport={}, oracle={}", + name, + self.esplora_host, + self.network, + transport.name(), + oracle.get_public_key() + ); + Ok(DlcDevKit { runtime: Arc::new(RwLock::new(None)), wallet, @@ -260,6 +300,7 @@ impl Builder { network: self.network, stop_signal, stop_signal_sender, + logger, }) } } diff --git a/ddk/src/chain/esplora.rs b/ddk/src/chain/esplora.rs index 9da890ff..f83d1e90 100644 --- a/ddk/src/chain/esplora.rs +++ b/ddk/src/chain/esplora.rs @@ -1,6 +1,9 @@ +use std::sync::Arc; use std::time::Duration; use crate::error::{esplora_err_to_manager_err, Error}; +use crate::logger::Logger; +use crate::logger::{log_error, log_info, log_warn, WriteLog}; use bdk_esplora::esplora_client::Error as EsploraError; use bdk_esplora::esplora_client::{AsyncClient, BlockingClient, Builder}; use bitcoin::Network; @@ -18,10 +21,15 @@ pub struct EsploraClient { pub blocking_client: BlockingClient, pub async_client: AsyncClient, network: Network, + logger: Arc, } impl EsploraClient { - pub fn new(esplora_host: &str, network: Network) -> Result { + pub fn new( + esplora_host: &str, + network: Network, + logger: Arc, + ) -> Result { let builder = Builder::new(esplora_host).timeout(Duration::from_secs(5).as_secs()); let blocking_client = builder.clone().build_blocking(); let async_client = builder.build_async()?; @@ -29,6 +37,7 @@ impl EsploraClient { blocking_client, async_client, network, + logger, }) } } @@ -42,7 +51,11 @@ impl ddk_manager::Blockchain for EsploraClient { } async fn get_transaction(&self, tx_id: &Txid) -> Result { - tracing::info!(txid = tx_id.to_string(), "Querying for transaction."); + log_info!( + self.logger, + "Querying for transaction. txid={}", + tx_id.to_string() + ); let txn = self .async_client .get_tx(tx_id) @@ -61,11 +74,12 @@ impl ddk_manager::Blockchain for EsploraClient { &self, transaction: &bitcoin::Transaction, ) -> Result<(), ManagerError> { - tracing::info!( - txid = transaction.compute_txid().to_string(), - num_inputs = transaction.input.len(), - num_outputs = transaction.output.len(), - "Broadcasting transaction." + log_info!( + self.logger, + "Broadcasting transaction. txid={}, num_inputs={}, num_outputs={}", + transaction.compute_txid().to_string(), + transaction.input.len(), + transaction.output.len() ); if let Ok(status) = self @@ -73,9 +87,10 @@ impl ddk_manager::Blockchain for EsploraClient { .get_tx_status(&transaction.compute_txid()) .await { - tracing::warn!( - txid = transaction.compute_txid().to_string(), - "Transaction already submitted", + log_warn!( + self.logger, + "Transaction already submitted. txid={}", + transaction.compute_txid().to_string() ); if status.confirmed { return Ok(()); @@ -83,10 +98,11 @@ impl ddk_manager::Blockchain for EsploraClient { }; if let Err(e) = self.async_client.broadcast(transaction).await { - tracing::error!( - error =? e, - "Could not broadcast transaction {}", - transaction.compute_txid() + log_error!( + self.logger, + "Could not broadcast transaction. txid={} error={:?}", + transaction.compute_txid().to_string(), + e.to_string() ); return Err(esplora_err_to_manager_err(e)); @@ -95,8 +111,8 @@ impl ddk_manager::Blockchain for EsploraClient { Ok(()) } + #[tracing::instrument(skip(self))] async fn get_block_at_height(&self, height: u64) -> Result { - tracing::info!(height, "Getting block at height."); let block_hash = self .async_client .get_block_hash(height as u32) @@ -118,6 +134,7 @@ impl ddk_manager::Blockchain for EsploraClient { } } + #[tracing::instrument(skip(self))] async fn get_blockchain_height(&self) -> Result { Ok(self .async_client @@ -126,14 +143,11 @@ impl ddk_manager::Blockchain for EsploraClient { .map_err(esplora_err_to_manager_err)? as u64) } + #[tracing::instrument(skip(self), fields(txid = tx_id.to_string()))] async fn get_transaction_confirmations( &self, tx_id: &bitcoin::Txid, ) -> Result { - tracing::info!( - txid = tx_id.to_string(), - "Getting transaction confirmations." - ); let txn = self .async_client .get_tx_status(tx_id) diff --git a/ddk/src/ddk.rs b/ddk/src/ddk.rs index 24bf0048..c22054a2 100644 --- a/ddk/src/ddk.rs +++ b/ddk/src/ddk.rs @@ -27,8 +27,11 @@ use crate::chain::EsploraClient; use crate::error::Error; +use crate::logger::Logger; +use crate::logger::{log_error, log_info, log_warn, WriteLog}; use crate::wallet::DlcDevKitWallet; use crate::{Oracle, Storage, Transport}; +use bitcoin::hex::DisplayHex; use bitcoin::secp256k1::PublicKey; use bitcoin::{Amount, Network, SignedAmount}; use ddk_manager::contract::Contract; @@ -63,6 +66,7 @@ pub type DlcDevKitDlcManager = ddk_manager::manager::Manager< Arc, Arc, SimpleSigner, + Arc, >; type Result = std::result::Result; @@ -143,6 +147,8 @@ pub struct DlcDevKit { pub stop_signal: watch::Receiver, /// Sender for stop signal pub stop_signal_sender: watch::Sender, + /// Logger instance for structured logging + pub logger: Arc, } impl DlcDevKit @@ -204,26 +210,33 @@ where let transport_clone = self.transport.clone(); let manager_clone = self.manager.clone(); let stop_signal = self.stop_signal.clone(); + let logger_clone = self.logger.clone(); runtime.spawn(async move { if let Err(e) = transport_clone.start(stop_signal, manager_clone).await { - tracing::error!(error = e.to_string(), "Error in transport listeners."); + log_error!( + logger_clone, + "Error in transport listeners. error={}", + e.to_string() + ); } }); // Spawn wallet sync thread (60-second interval) let wallet_clone = self.wallet.clone(); + let logger_clone = self.logger.clone(); runtime.spawn(async move { let mut timer = tokio::time::interval(Duration::from_secs(60)); loop { timer.tick().await; if let Err(e) = wallet_clone.sync().await { - tracing::warn!(error=?e, "Did not sync wallet."); + log_warn!(logger_clone, "Did not sync wallet. error={}", e.to_string()); }; } }); // Spawn contract monitor thread (30-second interval) let processor = self.sender.clone(); + let logger_clone = self.logger.clone(); runtime.spawn(async move { let mut timer = tokio::time::interval(Duration::from_secs(30)); loop { @@ -232,7 +245,11 @@ where .send(DlcManagerMessage::PeriodicCheck) .await .map_err(|e| { - tracing::error!("Error sending periodic check: {}", e); + log_error!( + logger_clone, + "Error sending periodic check: error={}", + e.to_string() + ); }); } }); @@ -247,7 +264,7 @@ where /// - Background tasks are terminated /// - Resources are properly cleaned up pub fn stop(&self) -> Result<()> { - tracing::warn!("Shutting down DDK runtime and listeners."); + log_warn!(self.logger, "Shutting down DDK runtime and listeners."); self.stop_signal_sender .send(true) .map_err(|e| Error::ActorSendError(e.to_string()))?; @@ -271,6 +288,7 @@ where /// 1. Creates a DLC offer message /// 2. Sends it through the transport layer /// 3. Returns the created offer for further processing + #[tracing::instrument(skip(self, contract_input))] pub async fn send_dlc_offer( &self, contract_input: &ContractInput, @@ -278,6 +296,12 @@ where oracle_announcements: Vec, ) -> Result { let (responder, receiver) = oneshot::channel(); + let event_ids = &oracle_announcements + .iter() + .map(|announcement| announcement.oracle_event.event_id.as_str()) + .collect::>() + .join(","); + self.sender .send(DlcManagerMessage::OfferDlc { contract_input: contract_input.to_owned(), @@ -293,14 +317,15 @@ where let offer = offer?; - let contract_id = hex::encode(offer.temporary_contract_id); self.transport .send_message(counter_party, Message::Offer(offer.clone())) .await; - tracing::info!( - counterparty = counter_party.to_string(), - contract_id, - "Sent DLC offer to counterparty." + + log_info!( + self.logger, + "Sent DLC offer to counterparty. counterparty={} event_ids={}", + counter_party.to_string(), + event_ids, ); Ok(offer) @@ -313,6 +338,7 @@ where /// 2. Creates acceptance message /// 3. Sends it to the counterparty /// 4. Returns the acceptance details + #[tracing::instrument(skip(self))] pub async fn accept_dlc_offer( &self, contract: [u8; 32], @@ -338,10 +364,12 @@ where let contract_id = hex::encode(contract_id); let counter_party = public_key.to_string(); - tracing::info!( - counter_party, + log_info!( + self.logger, + "Accepted and sent accept DLC contract. counter_party={}, contract_id={} temp_contract_id={}", + counter_party.to_string(), contract_id, - "Accepted and sent accept DLC contract." + contract.to_lower_hex_string() ); Ok((contract_id, counter_party, accept_dlc)) @@ -352,6 +380,7 @@ where /// - Unconfirmed changes /// - Funds locked in contracts /// - Total profit/loss from closed contracts + #[tracing::instrument(skip(self))] pub async fn balance(&self) -> Result { let wallet_balance = self.wallet.get_balance().await?; let contracts = self.storage.get_contracts().await?; diff --git a/ddk/src/error.rs b/ddk/src/error.rs index 04248d97..50259154 100644 --- a/ddk/src/error.rs +++ b/ddk/src/error.rs @@ -36,6 +36,8 @@ pub enum Error { Manager(#[from] DlcManagerError), #[error("BuilderError: {0}")] Builder(#[from] BuilderError), + #[error("LoggerError: {0}")] + Logger(#[from] LoggerError), #[error("EsploraError: {0}")] Esplora(#[from] bdk_esplora::esplora_client::Error), #[error("Generic error: {0}")] @@ -126,6 +128,21 @@ pub enum NostrError { Generic(String), } +/// Errors related to logging operations in DDK. +/// Handles failures in: +/// - Logger initialization +/// - File creation and writing +/// - Log formatting +#[derive(Error, Debug)] +pub enum LoggerError { + #[error("Logger initialization: {0}")] + Init(String), + #[error("File I/O error: {0}")] + Io(#[from] std::io::Error), + #[error("Tracing setup error: {0}")] + TracingSetup(String), +} + /// Errors that can occur during the DlcDevKit builder process. /// These errors indicate missing required components when constructing /// a new DlcDevKit instance. @@ -139,6 +156,8 @@ pub enum BuilderError { NoOracle, #[error("Failed to generate random seed.")] SeedGenerationFailed, + #[error("Logger setup failed.")] + LoggerSetupFailed, } /// Errors related to Bitcoin wallet operations. diff --git a/ddk/src/lib.rs b/ddk/src/lib.rs index a5302a32..11528af0 100644 --- a/ddk/src/lib.rs +++ b/ddk/src/lib.rs @@ -11,6 +11,8 @@ mod ddk; pub mod error; /// JSON structs pub mod json; +/// Logging infrastructure +pub mod logger; /// Nostr related functions. #[cfg(feature = "nostr")] pub mod nostr; @@ -120,7 +122,7 @@ pub trait Transport: Send + Sync + 'static { /// - Sled storage (persistent, embedded) /// - In-memory storage (temporary, testing) #[async_trait] -pub trait Storage: ddk_manager::Storage + Send + Sync + 'static { +pub trait Storage: ddk_manager::Storage + Send + Sync + std::fmt::Debug + 'static { /// Initializes the BDK wallet storage and returns initial state. /// /// This method is called during startup to: diff --git a/ddk/src/logger/console.rs b/ddk/src/logger/console.rs new file mode 100644 index 00000000..c7d14f40 --- /dev/null +++ b/ddk/src/logger/console.rs @@ -0,0 +1,45 @@ +use super::{LogLevel, LogRecord, LogWriter}; +use std::io::Write; + +/// Console log writer that writes logs to stdout/stderr +pub struct ConsoleLogWriter { + max_level: LogLevel, +} + +impl ConsoleLogWriter { + pub fn new(max_level: LogLevel) -> Self { + Self { max_level } + } + + fn format_log_record(&self, record: &LogRecord) -> String { + let timestamp = record.timestamp.format("%H:%M:%S%.3f"); + let location = match (&record.module_path, record.line) { + (Some(module), Some(line)) => format!(" [{module}:{line}]"), + (Some(module), None) => format!(" [{module}]"), + _ => String::new(), + }; + + format!( + "{} {}{} {}", + timestamp, record.level, location, record.message + ) + } +} + +impl LogWriter for ConsoleLogWriter { + fn write_log(&self, record: &LogRecord) { + if record.level >= self.max_level { + let formatted = self.format_log_record(record); + match record.level { + LogLevel::Error => eprintln!("{formatted}"), + _ => println!("{formatted}"), + } + } + } + + fn flush(&self) { + use std::io::{stderr, stdout}; + let _ = stdout().flush(); + let _ = stderr().flush(); + } +} diff --git a/ddk/src/logger/file.rs b/ddk/src/logger/file.rs new file mode 100644 index 00000000..888ac14f --- /dev/null +++ b/ddk/src/logger/file.rs @@ -0,0 +1,60 @@ +use super::{LogLevel, LogRecord, LogWriter}; +use std::fs::{File, OpenOptions}; +use std::io::{BufWriter, Write}; +use std::path::Path; +use std::sync::{Arc, Mutex}; + +/// File-based log writer that writes logs to a file with timestamps +pub struct FileLogWriter { + writer: Arc>>, + max_level: LogLevel, +} + +impl FileLogWriter { + pub fn new(file_path: &Path, max_level: LogLevel) -> Result { + // Create parent directory if it doesn't exist + if let Some(parent) = file_path.parent() { + std::fs::create_dir_all(parent)?; + } + + let file = OpenOptions::new() + .create(true) + .append(true) + .open(file_path)?; + + let writer = Arc::new(Mutex::new(BufWriter::new(file))); + + Ok(Self { writer, max_level }) + } + + fn format_log_record(&self, record: &LogRecord) -> String { + let timestamp = record.timestamp.format("%Y-%m-%d %H:%M:%S%.3f"); + let location = match (&record.module_path, record.line) { + (Some(module), Some(line)) => format!(" [{module}:{line}]"), + (Some(module), None) => format!(" [{module}]"), + _ => String::new(), + }; + + format!( + "{} {}{} {}\n", + timestamp, record.level, location, record.message + ) + } +} + +impl LogWriter for FileLogWriter { + fn write_log(&self, record: &LogRecord) { + if record.level >= self.max_level { + if let Ok(mut writer) = self.writer.lock() { + let formatted = self.format_log_record(record); + let _ = writer.write_all(formatted.as_bytes()); + } + } + } + + fn flush(&self) { + if let Ok(mut writer) = self.writer.lock() { + let _ = writer.flush(); + } + } +} diff --git a/ddk/src/logger/mod.rs b/ddk/src/logger/mod.rs new file mode 100644 index 00000000..a6ff84b3 --- /dev/null +++ b/ddk/src/logger/mod.rs @@ -0,0 +1,556 @@ +mod console; +mod file; +mod multi; +mod tracing; + +use ::tracing::Level; +use chrono::{DateTime, Utc}; +use lightning::util::logger::Level as LdkLevel; +use lightning::util::logger::Record as LdkRecord; +pub use lightning::{ + log_bytes, log_debug, log_error, log_info, log_trace, log_warn, + util::logger::Logger as WriteLog, +}; +use std::collections::HashMap; +use std::path::Path; +use std::sync::Arc; + +/// Log levels supported by DDK logging system +#[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord)] +pub enum LogLevel { + Trace, + Debug, + Info, + Warn, + Error, +} + +impl From for LogLevel { + fn from(s: String) -> Self { + match s.as_str() { + "info" => LogLevel::Info, + "debug" => LogLevel::Debug, + "trace" => LogLevel::Trace, + "warn" => LogLevel::Warn, + "error" => LogLevel::Error, + _ => LogLevel::Info, + } + } +} + +/// Structured log record containing all log information +#[derive(Debug, Clone)] +pub struct LogRecord { + pub timestamp: DateTime, + pub level: LogLevel, + pub target: String, + pub module_path: Option, + pub file: Option, + pub line: Option, + pub message: String, + pub fields: HashMap, +} + +/// Trait for custom log writers that can be plugged into the logging system +pub trait LogWriter: Send + Sync + 'static { + /// Write a log record to the output destination + fn write_log(&self, record: &LogRecord); + + /// Flush any buffered log data + fn flush(&self); +} + +/// Central logger that coordinates all logging activities +pub struct Logger { + writer: Arc, + name: String, +} + +impl lightning::util::logger::Logger for Logger { + fn log(&self, record: LdkRecord) { + let ddk_record: LogRecord = record.into(); + self.writer.write_log(&ddk_record); + } +} + +impl Logger { + pub fn new(name: String, writer: Arc) -> Self { + Self { name, writer } + } + + /// Create a logger that outputs to the console + pub fn console(name: String, max_level: LogLevel) -> Self { + let writer = Arc::new(console::ConsoleLogWriter::new(max_level)); + Self::new(name, writer) + } + + /// Create a logger that outputs to a file + pub fn file( + name: String, + file_path: &Path, + max_level: LogLevel, + ) -> Result { + let writer = Arc::new(file::FileLogWriter::new(file_path, max_level)?); + Ok(Self::new(name, writer)) + } + + /// Create a logger that integrates with tracing + pub fn tracing(name: String, max_level: LogLevel) -> Self { + let writer = Arc::new(tracing::TracingLogWriter::new(max_level)); + Self::new(name, writer) + } + + /// Create a logger that discards all log messages (no-op) + pub fn disabled(name: String) -> Self { + struct NoOpWriter; + impl LogWriter for NoOpWriter { + fn write_log(&self, _record: &LogRecord) {} + fn flush(&self) {} + } + let writer = Arc::new(NoOpWriter); + Self::new(name, writer) + } + + pub fn write_record(&self, record: LogRecord) { + self.writer.write_log(&record); + } + + pub fn trace(&self, target: &str, message: &str) { + let record = LogRecord::new( + LogLevel::Trace, + target.to_string(), + message.to_string(), + None, + None, + None, + ); + self.write_record(record); + } + + pub fn debug(&self, target: &str, message: &str) { + let record = LogRecord::new( + LogLevel::Debug, + target.to_string(), + message.to_string(), + None, + None, + None, + ); + self.write_record(record); + } + + pub fn info(&self, target: &str, message: &str) { + let record = LogRecord::new( + LogLevel::Info, + target.to_string(), + message.to_string(), + None, + None, + None, + ); + self.write_record(record); + } + + pub fn warn(&self, target: &str, message: &str) { + let record = LogRecord::new( + LogLevel::Warn, + target.to_string(), + message.to_string(), + None, + None, + None, + ); + self.write_record(record); + } + + pub fn error(&self, target: &str, message: &str) { + let record = LogRecord::new( + LogLevel::Error, + target.to_string(), + message.to_string(), + None, + None, + None, + ); + self.write_record(record); + } + + pub fn flush(&self) { + self.writer.flush(); + } + + pub fn name(&self) -> &str { + &self.name + } +} + +impl From for Level { + fn from(level: LogLevel) -> Self { + match level { + LogLevel::Trace => Level::TRACE, + LogLevel::Debug => Level::DEBUG, + LogLevel::Info => Level::INFO, + LogLevel::Warn => Level::WARN, + LogLevel::Error => Level::ERROR, + } + } +} + +impl std::fmt::Display for LogLevel { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + match self { + LogLevel::Trace => write!(f, "TRACE"), + LogLevel::Debug => write!(f, "DEBUG"), + LogLevel::Info => write!(f, "INFO "), + LogLevel::Warn => write!(f, "WARN "), + LogLevel::Error => write!(f, "ERROR"), + } + } +} + +impl std::fmt::Debug for Logger { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + f.debug_struct("Logger") + .field("name", &self.name) + .field("writer", &"") + .finish() + } +} + +impl LogRecord { + pub fn new( + level: LogLevel, + target: String, + message: String, + module_path: Option, + file: Option, + line: Option, + ) -> Self { + Self { + timestamp: Utc::now(), + level, + target, + module_path, + file, + line, + message, + fields: HashMap::new(), + } + } + + pub fn add_field(&mut self, key: String, value: String) { + self.fields.insert(key, value); + } +} + +// Convert LDK Level to DDK LogLevel +impl From for LogLevel { + fn from(ldk_level: LdkLevel) -> Self { + match ldk_level { + LdkLevel::Gossip => LogLevel::Trace, + LdkLevel::Trace => LogLevel::Trace, + LdkLevel::Debug => LogLevel::Debug, + LdkLevel::Info => LogLevel::Info, + LdkLevel::Warn => LogLevel::Warn, + LdkLevel::Error => LogLevel::Error, + } + } +} + +// Convert LDK Record to DDK LogRecord +impl<'a> From> for LogRecord { + fn from(record: LdkRecord<'a>) -> Self { + Self { + timestamp: chrono::Utc::now(), + level: record.level.into(), + target: record.module_path.to_string(), + module_path: Some(record.module_path.to_string()), + file: None, // LDK Record doesn't include file info + line: Some(record.line), + message: record.args.to_string(), + fields: HashMap::new(), + } + } +} + +#[cfg(test)] +mod tests { + use super::*; + use std::collections::VecDeque; + use std::sync::Mutex; + use std::thread; + use std::time::Duration; + + /// Test utility logger that captures logs in memory for verification + pub struct TestLogWriter { + logs: Arc>>, + max_level: LogLevel, + max_logs: usize, + } + + impl TestLogWriter { + pub fn new(max_level: LogLevel) -> Self { + Self { + logs: Arc::new(Mutex::new(VecDeque::new())), + max_level, + max_logs: 1000, // Default maximum number of logs to keep in memory + } + } + + pub fn with_capacity(max_level: LogLevel, max_logs: usize) -> Self { + Self { + logs: Arc::new(Mutex::new(VecDeque::new())), + max_level, + max_logs, + } + } + + /// Retrieve all captured logs + pub fn get_logs(&self) -> Vec { + self.logs.lock().unwrap().clone().into() + } + + /// Get logs at a specific level + pub fn get_logs_at_level(&self, level: LogLevel) -> Vec { + self.logs + .lock() + .unwrap() + .iter() + .filter(|log| log.level == level) + .cloned() + .collect() + } + + /// Get logs containing specific text + pub fn get_logs_containing(&self, text: &str) -> Vec { + self.logs + .lock() + .unwrap() + .iter() + .filter(|log| log.message.contains(text)) + .cloned() + .collect() + } + + /// Check if any log contains specific text + pub fn has_log_containing(&self, text: &str) -> bool { + self.logs + .lock() + .unwrap() + .iter() + .any(|log| log.message.contains(text)) + } + + /// Get logs from a specific target + pub fn get_logs_from_target(&self, target: &str) -> Vec { + self.logs + .lock() + .unwrap() + .iter() + .filter(|log| log.target == target) + .cloned() + .collect() + } + } + + impl LogWriter for TestLogWriter { + fn write_log(&self, record: &LogRecord) { + if record.level >= self.max_level { + let mut logs = self.logs.lock().unwrap(); + + // Keep only the most recent logs if we exceed capacity + if logs.len() >= self.max_logs { + logs.pop_front(); + } + + logs.push_back(record.clone()); + } + } + + fn flush(&self) { + // No-op for in-memory storage + } + } + + /// Convenience function to create a test logger with TestLogWriter + pub fn create_test_logger( + name: &str, + max_level: LogLevel, + ) -> (Arc, Arc) { + let writer = Arc::new(TestLogWriter::new(max_level)); + let logger = Arc::new(Logger::new(name.to_string(), writer.clone())); + (logger, writer) + } + + #[test] + fn test_test_log_writer_basic() { + let writer = TestLogWriter::new(LogLevel::Debug); + let record = LogRecord::new( + LogLevel::Info, + "test".to_string(), + "test message".to_string(), + Some("test::module".to_string()), + Some("test.rs".to_string()), + Some(42), + ); + + writer.write_log(&record); + + let logs = writer.get_logs(); + assert_eq!(logs.len(), 1); + assert_eq!(logs[0].message, "test message"); + assert_eq!(logs[0].level, LogLevel::Info); + } + + #[test] + fn test_log_level_filtering() { + let writer = TestLogWriter::new(LogLevel::Warn); + + // This should be filtered out + let debug_record = LogRecord::new( + LogLevel::Debug, + "test".to_string(), + "debug message".to_string(), + None, + None, + None, + ); + + // This should be included + let error_record = LogRecord::new( + LogLevel::Error, + "test".to_string(), + "error message".to_string(), + None, + None, + None, + ); + + writer.write_log(&debug_record); + writer.write_log(&error_record); + + let logs = writer.get_logs(); + assert_eq!(logs.len(), 1); + assert_eq!(logs[0].message, "error message"); + } + + #[test] + fn test_capacity_limit() { + let writer = TestLogWriter::with_capacity(LogLevel::Debug, 3); + + for i in 0..5 { + let record = LogRecord::new( + LogLevel::Info, + "test".to_string(), + format!("message {}", i), + None, + None, + None, + ); + writer.write_log(&record); + } + + let logs = writer.get_logs(); + assert_eq!(logs.len(), 3); + // Should keep the most recent logs + assert_eq!(logs[0].message, "message 2"); + assert_eq!(logs[1].message, "message 3"); + assert_eq!(logs[2].message, "message 4"); + } + + #[test] + fn test_log_search_functionality() { + let writer = TestLogWriter::new(LogLevel::Debug); + + let records = vec![ + LogRecord::new( + LogLevel::Info, + "ddk::wallet".to_string(), + "wallet synchronized".to_string(), + None, + None, + None, + ), + LogRecord::new( + LogLevel::Error, + "ddk::transport".to_string(), + "connection failed".to_string(), + None, + None, + None, + ), + LogRecord::new( + LogLevel::Warn, + "ddk::wallet".to_string(), + "low balance warning".to_string(), + None, + None, + None, + ), + ]; + + for record in &records { + writer.write_log(record); + } + + // Test filtering by level + let error_logs = writer.get_logs_at_level(LogLevel::Error); + assert_eq!(error_logs.len(), 1); + assert!(error_logs[0].message.contains("connection failed")); + + // Test filtering by text content + let wallet_logs = writer.get_logs_containing("wallet"); + assert_eq!(wallet_logs.len(), 1); + + // Test filtering by target + let wallet_target_logs = writer.get_logs_from_target("ddk::wallet"); + assert_eq!(wallet_target_logs.len(), 2); + + // Test existence check + assert!(writer.has_log_containing("synchronized")); + assert!(!writer.has_log_containing("nonexistent")); + } + + #[test] + fn test_create_test_logger() { + let (logger, writer) = create_test_logger("test_logger", LogLevel::Debug); + + logger.info("ddk::test", "test message"); + + let logs = writer.get_logs(); + assert_eq!(logs.len(), 1); + assert_eq!(logs[0].message, "test message"); + assert_eq!(logs[0].target, "ddk::test"); + assert_eq!(logger.name(), "test_logger"); + } + + #[test] + fn test_thread_safety() { + let writer = Arc::new(TestLogWriter::new(LogLevel::Debug)); + let mut handles = vec![]; + + for i in 0..10 { + let writer_clone = writer.clone(); + let handle = thread::spawn(move || { + let record = LogRecord::new( + LogLevel::Info, + "test".to_string(), + format!("message from thread {}", i), + None, + None, + None, + ); + writer_clone.write_log(&record); + thread::sleep(Duration::from_millis(10)); + }); + handles.push(handle); + } + + for handle in handles { + handle.join().unwrap(); + } + + let logs = writer.get_logs(); + assert_eq!(logs.len(), 10); + } +} diff --git a/ddk/src/logger/multi.rs b/ddk/src/logger/multi.rs new file mode 100644 index 00000000..2cf542bf --- /dev/null +++ b/ddk/src/logger/multi.rs @@ -0,0 +1,34 @@ +#![allow(dead_code)] +use super::{LogRecord, LogWriter}; +use std::sync::Arc; + +/// Multi-writer that can send logs to multiple destinations +pub struct MultiLogWriter { + writers: Vec>, +} + +impl MultiLogWriter { + pub fn new() -> Self { + Self { + writers: Vec::new(), + } + } + + pub fn add_writer(&mut self, writer: Arc) { + self.writers.push(writer); + } +} + +impl LogWriter for MultiLogWriter { + fn write_log(&self, record: &LogRecord) { + for writer in &self.writers { + writer.write_log(record); + } + } + + fn flush(&self) { + for writer in &self.writers { + writer.flush(); + } + } +} diff --git a/ddk/src/logger/tracing.rs b/ddk/src/logger/tracing.rs new file mode 100644 index 00000000..3627bf1f --- /dev/null +++ b/ddk/src/logger/tracing.rs @@ -0,0 +1,78 @@ +use super::{LogLevel, LogRecord, LogWriter}; + +/// Tracing-compatible log writer that bridges to the standard Rust `log` crate +pub struct TracingLogWriter { + max_level: LogLevel, +} + +impl TracingLogWriter { + pub fn new(max_level: LogLevel) -> Self { + Self { max_level } + } +} + +impl LogWriter for TracingLogWriter { + fn write_log(&self, record: &LogRecord) { + if record.level >= self.max_level { + let module_path = record.module_path.as_deref().unwrap_or(&record.target); + // Use tracing macros with module information as fields + match record.level { + LogLevel::Trace => tracing::trace!( + message = record.message, + module = module_path, + timestamp = record.timestamp.to_utc().timestamp_millis(), + ), + LogLevel::Debug => tracing::debug!( + message = record.message, + module = module_path, + timestamp = record.timestamp.to_utc().timestamp_millis(), + ), + LogLevel::Info => tracing::info!( + message = record.message, + module = module_path, + timestamp = record.timestamp.to_utc().timestamp_millis(), + ), + LogLevel::Warn => tracing::warn!( + message = %record.message, + module = module_path, + timestamp = record.timestamp.to_utc().timestamp_millis(), + ), + LogLevel::Error => tracing::error!( + message = record.message, + module = module_path, + timestamp = record.timestamp.to_utc().timestamp_millis(), + ), + }; + }; + } + + fn flush(&self) { + // Tracing handles flushing internally + } +} + +// Initializes the global tracing subscriber with DDK logger integration +// pub fn init_tracing_subscriber(config: TracingConfig) -> Result<(), Box> { +// let filter = EnvFilter::try_from_default_env().or_else(|_| { +// let level_filter = match config.max_level { +// LogLevel::Trace => "trace", +// LogLevel::Debug => "debug", +// LogLevel::Info => "info", +// LogLevel::Warn => "warn", +// LogLevel::Error => "error", +// }; +// EnvFilter::try_new(level_filter) +// })?; + +// let subscriber = tracing_subscriber::Registry::default().with(filter).with( +// fmt::layer() +// .with_target(true) +// .with_thread_ids(false) +// .with_thread_names(false) +// .with_file(true) +// .with_line_number(true), +// ); + +// tracing::subscriber::set_global_default(subscriber)?; +// Ok(()) +// } diff --git a/ddk/src/nostr/messages.rs b/ddk/src/nostr/messages.rs index ef473e30..47f04ed4 100644 --- a/ddk/src/nostr/messages.rs +++ b/ddk/src/nostr/messages.rs @@ -13,7 +13,6 @@ use crate::error::NostrError; use crate::nostr::nostr_to_bitcoin_pubkey; use crate::nostr::{DLC_MESSAGE_KIND, ORACLE_ANNOUNCMENT_KIND, ORACLE_ATTESTATION_KIND}; -use crate::util::ser::message_variant_name; use ddk_dlc::secp256k1_zkp::PublicKey as SecpPublicKey; use ddk_messages::message_handler::read_dlc_message; use ddk_messages::{Message, WireMessage}; @@ -107,12 +106,6 @@ pub fn parse_dlc_msg_event(event: &Event, secret_key: &SecretKey) -> Result(host: &str, path: &str) -> Result where @@ -58,6 +62,7 @@ pub struct KormirOracleClient { client: reqwest::Client, host: String, hmac_secret: Option>, + logger: Arc, } #[derive(Debug, Clone, Deserialize)] @@ -69,16 +74,18 @@ impl KormirOracleClient { pub async fn new( host: &str, hmac_secret: Option>, + logger: Arc, ) -> Result { let pubkey: XOnlyPublicKey = get::(host, "pubkey") .await .map_err(|_| OracleError::Init("Could not get pubkey from Kormir.".to_string()))? .pubkey; let client = reqwest::Client::new(); - tracing::info!( + log_info!( + logger, + "Connected to Kormir client. host={} pubkey={}", host, - pubkey = pubkey.to_string(), - "Connected to Kormir client." + pubkey.to_string() ); Ok(KormirOracleClient { @@ -86,6 +93,7 @@ impl KormirOracleClient { client, host: host.to_string(), hmac_secret, + logger, }) } @@ -95,7 +103,11 @@ impl KormirOracleClient { /// if announcement has been signed, and nostr information. pub async fn list_events(&self) -> Result, OracleError> { get(&self.host, "list-events").await.map_err(|e| { - tracing::error!(error = e.to_string(), "Error getting all kormir events."); + log_error!( + self.logger, + "Error getting all kormir events. error={}", + e.to_string() + ); OracleError::Announcement("Could not list events from Kormir.".to_string()) }) } @@ -128,7 +140,11 @@ impl KormirOracleClient { .json::() .await?; - tracing::info!(event_id, "Created Kormir oracle event."); + log_info!( + self.logger, + "Created Kormir oracle event. event_id={}", + event_id + ); Ok(announcement) } @@ -139,7 +155,12 @@ impl KormirOracleClient { event_id: String, outcome: String, ) -> Result { - tracing::info!("Signing event. event_id={} outcome={}", event_id, outcome); + log_info!( + self.logger, + "Signing event. event_id={} outcome={}", + event_id, + outcome + ); let event = SignEnumEvent { event_id: event_id.clone(), @@ -158,7 +179,12 @@ impl KormirOracleClient { .json::() .await?; - tracing::info!(event_id, outcome, "Signed Kormir oracle event."); + log_info!( + self.logger, + "Signed Kormir oracle event. event_id={} outcome={}", + event_id, + outcome + ); Ok(attestation) } @@ -199,7 +225,11 @@ impl KormirOracleClient { .json::() .await?; - tracing::info!(event_id, "Created Kormir oracle event."); + log_info!( + self.logger, + "Created Kormir oracle event. event_id={}", + event_id + ); Ok(announcement) } @@ -210,7 +240,12 @@ impl KormirOracleClient { event_id: String, outcome: i64, ) -> Result { - tracing::info!("Signing event. event_id={} outcome={}", event_id, outcome); + log_info!( + self.logger, + "Signing event. event_id={} outcome={}", + event_id, + outcome + ); let event = SignNumericEvent { event_id: event_id.clone(), @@ -229,7 +264,12 @@ impl KormirOracleClient { .json::() .await?; - tracing::info!(event_id, outcome, "Signed Kormir oracle event."); + log_info!( + self.logger, + "Signed Kormir oracle event. event_id={} outcome={}", + event_id, + outcome + ); Ok(attestation) } @@ -267,36 +307,50 @@ impl ddk_manager::Oracle for KormirOracleClient { self.pubkey } + #[tracing::instrument(skip(self))] async fn get_attestation( &self, event_id: &str, ) -> Result { - tracing::info!(event_id, "Getting attestation to close contract."); let attestation = get::(&self.host, &format!("attestation/{event_id}")) .await .map_err(|e| { - tracing::error!(error=?e, "Could not get attestation."); + log_error!(self.logger, "Could not get attestation. error={:?}", e); ddk_manager::error::Error::OracleError(format!("Could not get attestation: {e}")) })?; - tracing::info!(event_id, attestation =? attestation, "Kormir attestation."); + log_info!( + self.logger, + "Kormir attestation. event_id={} attestation={:?}", + event_id, + attestation + ); Ok(attestation) } + #[tracing::instrument(skip(self))] async fn get_announcement( &self, event_id: &str, ) -> Result { - tracing::info!(event_id, "Getting oracle announcement."); let announcement = get::(&self.host, &format!("announcement/{event_id}")) .await .map_err(|e| { - tracing::error!(error =? e, "Could not get announcement."); + log_error!( + self.logger, + "Could not get announcement. error={}", + e.to_string() + ); ddk_manager::error::Error::OracleError(format!( "Could not get announcement: {e}" )) })?; - tracing::info!(event_id, announcement=?announcement, "Kormir announcement."); + log_info!( + self.logger, + "Kormir announcement. event_id={} announcement={:?}", + event_id, + announcement + ); Ok(announcement) } } @@ -314,9 +368,13 @@ mod tests { use super::*; async fn create_kormir() -> KormirOracleClient { - KormirOracleClient::new("https://kormir.dlcdevkit.com", None) - .await - .unwrap() + KormirOracleClient::new( + "https://kormir.dlcdevkit.com", + None, + Arc::new(Logger::disabled("kormir".to_string())), + ) + .await + .unwrap() } #[tokio::test] diff --git a/ddk/src/oracle/nostr.rs b/ddk/src/oracle/nostr.rs index 096912ee..b6e8643d 100644 --- a/ddk/src/oracle/nostr.rs +++ b/ddk/src/oracle/nostr.rs @@ -1,7 +1,10 @@ use std::str::FromStr; +use std::sync::Arc; use std::time::Duration; use crate::error::OracleError; +use crate::logger::Logger; +use crate::logger::{log_debug, log_error, log_info, log_warn, WriteLog}; use bitcoin::XOnlyPublicKey; use ddk_manager::error::Error as ManagerError; use ddk_messages::oracle_msgs::{OracleAnnouncement, OracleAttestation}; @@ -40,6 +43,8 @@ pub struct NostrOracle { xonly_oracle_pubkey: XOnlyPublicKey, /// Nostr public key for message verification and routing nostr_oracle_pubkey: NostrPublicKey, + /// [`ddk::logger::Logger`] instance for logging + logger: Arc, } impl NostrOracle { @@ -55,6 +60,7 @@ impl NostrOracle { /// * `relays` - List of Nostr relay URLs to connect to /// * `since` - Optional timestamp to filter events from (defaults to now if None) /// * `nostr_oracle_pubkey` - The oracle's Nostr public key for message verification + /// * `logger` - [`ddk::logger::Logger`] instance for logging /// /// # Returns /// * `Ok(NostrOracle)` - Successfully initialized oracle @@ -63,6 +69,7 @@ impl NostrOracle { relays: Vec, since: Option, nostr_oracle_pubkey: NostrPublicKey, + logger: Arc, ) -> Result { let xonly_oracle_pubkey = XOnlyPublicKey::from_slice(nostr_oracle_pubkey.as_bytes()) .map_err(|_| { @@ -77,7 +84,7 @@ impl NostrOracle { if let Ok(url) = relay.try_into_url() { client.add_relay(url).await.unwrap(); } else { - tracing::error!("Invalid relay URL."); + log_error!(logger, "Invalid relay URL."); } } @@ -98,6 +105,7 @@ impl NostrOracle { db, xonly_oracle_pubkey, nostr_oracle_pubkey, + logger, }) } @@ -127,26 +135,28 @@ impl NostrOracle { &self, mut stop_signal: watch::Receiver, ) -> JoinHandle> { - tracing::info!( - pubkey = self.nostr_oracle_pubkey.to_string(), - "Starting Nostr Oracle listener." + log_info!( + self.logger, + "Starting Nostr Oracle listener. pubkey={}", + self.nostr_oracle_pubkey.to_string() ); let nostr_client = self.client.clone(); let db = self.db.clone(); + let logger = self.logger.clone(); tokio::spawn(async move { - tracing::info!("Listening for Oracle messages."); + log_info!(logger, "Listening for Oracle messages."); let mut notifications = nostr_client.notifications(); loop { tokio::select! { _ = stop_signal.changed() => { if *stop_signal.borrow() { - tracing::warn!("Stopping nostr oracle subscription."); + log_warn!(logger, "Stopping nostr oracle subscription."); nostr_client.disconnect().await; break; } }, Ok(notification) = notifications.recv() => { - tracing::info!("Received notification {:?}", notification); + log_info!(logger, "Received notification {:?}", notification); match notification { RelayPoolNotification::Event { relay_url: _, @@ -157,13 +167,13 @@ impl NostrOracle { match event.kind { Kind::Custom(88) => { if let Ok(announcement) = decode_base64::(&event.content) { - tracing::info!("Received announcement event: {}", announcement.oracle_event.event_id); + log_info!(logger, "Received announcement event: {}", announcement.oracle_event.event_id); let _ = db.save_event(&event).await; } } Kind::Custom(89) => { if let Ok(attestation) = decode_base64::(&event.content) { - tracing::info!("Received attestation event: {}", attestation.event_id); + log_info!(logger, "Received attestation event: {}", attestation.event_id); let _ =db.save_event(&event).await; } } @@ -192,13 +202,17 @@ impl ddk_manager::Oracle for NostrOracle { self.xonly_oracle_pubkey } + #[tracing::instrument(skip(self))] async fn get_announcement(&self, event_id: &str) -> Result { - tracing::info!("Getting announcement for event id: {}", event_id); let event_id = EventId::from_str(event_id) .map_err(|_| ManagerError::OracleError(format!("Invalid event id: {}", event_id)))?; if let Ok(event) = self.db.event_by_id(&event_id).await { - tracing::info!("Event found in db: {:?}", event); + log_debug!( + self.logger, + "Event found in nostr database. event_id={}", + event_id + ); if let Some(event) = event { return Ok(decode_base64::(&event.content).unwrap()); } @@ -226,6 +240,7 @@ impl ddk_manager::Oracle for NostrOracle { )) } + #[tracing::instrument(skip(self))] async fn get_attestation(&self, event_id: &str) -> Result { let event_id = EventId::from_str(event_id) .map_err(|_| ManagerError::OracleError(format!("Invalid event id: {}", event_id)))?; diff --git a/ddk/src/storage/postgres/mod.rs b/ddk/src/storage/postgres/mod.rs index 69befe3b..1c6cdb1e 100644 --- a/ddk/src/storage/postgres/mod.rs +++ b/ddk/src/storage/postgres/mod.rs @@ -1,5 +1,7 @@ use super::sqlx::{ContractData, ContractMetadata, SqlxError}; use crate::error::{StorageError, WalletError}; +use crate::logger::Logger; +use crate::logger::{log_info, WriteLog}; use crate::Storage; use crate::{ error::to_storage_error, @@ -33,19 +35,20 @@ use sqlx::postgres::PgRow; use sqlx::{FromRow, Pool, Postgres, Row, Transaction}; use std::str::FromStr; use std::sync::Arc; -use tracing::info; /// Manages a pool of database connections. #[derive(Debug)] pub struct PostgresStore { pub(crate) pool: Pool, wallet_name: String, + logger: Arc, } impl PostgresStore { pub async fn new( url: &str, migrations: bool, + logger: Arc, wallet_name: String, ) -> Result { let pool = PoolOptions::::new() @@ -53,15 +56,20 @@ impl PostgresStore { .connect(url) .await .map_err(|e| StorageError::Sqlx(e.into()))?; + // TODO: inline migrations if migrations { - tracing::info!("Migrating postgres"); + log_info!(logger, "Migrating postgres"); sqlx::migrate!("src/storage/postgres/migrations") .run(&pool) .await .map_err(|e| StorageError::Sqlx(e.into()))?; } - Ok(Self { pool, wallet_name }) + Ok(Self { + pool, + logger, + wallet_name, + }) } pub async fn get_contract_metadata( @@ -119,8 +127,13 @@ impl PostgresStore { Ok(rows) } - #[tracing::instrument] + #[tracing::instrument(skip(self))] pub(crate) async fn read(&self) -> Result { + log_info!( + self.logger, + "Reading changeset from postgres. wallet_name={}", + self.wallet_name + ); let mut tx = self .pool .begin() @@ -150,15 +163,12 @@ impl PostgresStore { Ok(changeset) } - #[tracing::instrument] pub(crate) async fn changeset_from_row( tx: &mut Transaction<'_, Postgres>, changeset: &mut ChangeSet, row: PgRow, wallet_name: &str, ) -> Result<(), StorageError> { - tracing::info!("changeset from row"); - let network: String = row.get("network"); let internal_last_revealed: Option = row.get("internal_last_revealed"); let external_last_revealed: Option = row.get("external_last_revealed"); @@ -194,12 +204,19 @@ impl PostgresStore { Ok(()) } - #[tracing::instrument] + #[tracing::instrument(skip(self, changeset))] pub(crate) async fn write(&self, changeset: &ChangeSet) -> Result<(), StorageError> { - tracing::info!("changeset write"); if changeset.is_empty() { return Ok(()); } + log_info!( + self.logger, + "Writing changeset to postgres. num_blocks={}, num_txs={}, num_txouts={}, num_anchors={}", + changeset.local_chain.blocks.len(), + changeset.tx_graph.txs.len(), + changeset.tx_graph.txouts.len(), + changeset.tx_graph.anchors.len(), + ); let wallet_name = &self.wallet_name; let mut tx = self @@ -253,15 +270,17 @@ impl PostgresStore { #[async_trait::async_trait] impl Storage for PostgresStore { async fn initialize_bdk(&self) -> Result { - tracing::info!("initialize store"); + log_info!( + self.logger, + "Initializing storage for the BDK wallet. name={}", + self.wallet_name + ); self.read() .await .map_err(|_| WalletError::StorageError("Did not initialize bdk storage".to_string())) } async fn persist_bdk(&self, changeset: &ChangeSet) -> Result<(), WalletError> { - tracing::info!("persist store"); - self.write(changeset) .await .map_err(|_| WalletError::StorageError("Did not persist bdk storage".to_string())) @@ -270,6 +289,7 @@ impl Storage for PostgresStore { #[async_trait::async_trait] impl ManagerStorage for PostgresStore { + #[tracing::instrument(skip(self))] async fn get_contract( &self, id: &ddk_manager::ContractId, @@ -288,6 +308,7 @@ impl ManagerStorage for PostgresStore { } } + #[tracing::instrument(skip(self))] async fn get_contracts(&self) -> Result, ddk_manager::error::Error> { let contracts = sqlx::query_as::("SELECT * FROM contract_data") .fetch_all(&self.pool) @@ -355,9 +376,16 @@ impl ManagerStorage for PostgresStore { tx.commit().await.map_err(to_storage_error)?; + log_info!( + self.logger, + "Stored offered contract. id={}", + hex::encode(contract.id) + ); + Ok(()) } + #[tracing::instrument(skip(self))] async fn delete_contract( &self, id: &ddk_manager::ContractId, @@ -382,7 +410,11 @@ impl ManagerStorage for PostgresStore { } async fn update_contract(&self, contract: &Contract) -> Result<(), ddk_manager::error::Error> { - tracing::info!("Updating contract: {}", hex::encode(contract.get_id())); + log_info!( + self.logger, + "Updating contract. id={}", + hex::encode(contract.get_id()) + ); let prefix = ContractPrefix::get_prefix(contract); let contract_id = hex::encode(contract.get_id()); let (offer_collateral, accept_collateral, total_collateral) = contract.get_collateral(); @@ -393,8 +425,9 @@ impl ManagerStorage for PostgresStore { // Step 1: Remove by temp_id if Accepted or Signed match contract { a @ Contract::Accepted(_) | a @ Contract::Signed(_) => { - tracing::info!( - "Deleting contract by temp_id: {:?}", + log_info!( + self.logger, + "Deleting contract by temp_id. tmp_id={}", hex::encode(a.get_temporary_id()) ); let temp_id = hex::encode(a.get_temporary_id()); @@ -519,6 +552,7 @@ impl ManagerStorage for PostgresStore { Ok(()) } + #[tracing::instrument(skip(self))] async fn get_signed_contracts(&self) -> Result, ddk_manager::error::Error> { let contracts = sqlx::query_as::("SELECT * FROM contract_data WHERE state = 3") @@ -538,6 +572,7 @@ impl ManagerStorage for PostgresStore { Ok(signed) } + #[tracing::instrument(skip(self))] async fn get_contract_offers(&self) -> Result, ddk_manager::error::Error> { let contracts = sqlx::query_as::( "SELECT cd.id, cd.state, cd.contract_data, cd.is_compressed @@ -561,6 +596,7 @@ impl ManagerStorage for PostgresStore { Ok(offers) } + #[tracing::instrument(skip(self))] async fn get_confirmed_contracts( &self, ) -> Result, ddk_manager::error::Error> { @@ -582,6 +618,7 @@ impl ManagerStorage for PostgresStore { Ok(signed) } + #[tracing::instrument(skip(self))] async fn get_preclosed_contracts( &self, ) -> Result, ddk_manager::error::Error> { @@ -603,6 +640,7 @@ impl ManagerStorage for PostgresStore { Ok(preclosed) } + #[tracing::instrument(skip(self))] async fn upsert_channel( &self, _channel: ddk_manager::channel::Channel, @@ -611,6 +649,7 @@ impl ManagerStorage for PostgresStore { unimplemented!("Channels not supported.") } + #[tracing::instrument(skip(self))] async fn delete_channel( &self, _channel_id: &ddk_manager::ChannelId, @@ -618,6 +657,7 @@ impl ManagerStorage for PostgresStore { unimplemented!("Channels not supported.") } + #[tracing::instrument(skip(self, _channel_state))] async fn get_signed_channels( &self, _channel_state: Option, @@ -626,6 +666,7 @@ impl ManagerStorage for PostgresStore { unimplemented!("Channels not supported.") } + #[tracing::instrument(skip(self))] async fn get_channel( &self, _channel_id: &ddk_manager::ChannelId, @@ -633,6 +674,7 @@ impl ManagerStorage for PostgresStore { unimplemented!("Channels not supported.") } + #[tracing::instrument(skip(self))] async fn get_offered_channels( &self, ) -> Result, ddk_manager::error::Error> @@ -640,6 +682,7 @@ impl ManagerStorage for PostgresStore { unimplemented!("Channels not supported.") } + #[tracing::instrument(skip(self))] async fn persist_chain_monitor( &self, _monitor: &ddk_manager::chain_monitor::ChainMonitor, @@ -647,6 +690,7 @@ impl ManagerStorage for PostgresStore { unimplemented!("Chain monitor not supported.") } + #[tracing::instrument(skip(self))] async fn get_chain_monitor( &self, ) -> Result, ddk_manager::error::Error> { @@ -655,14 +699,13 @@ impl ManagerStorage for PostgresStore { } /// Insert keychain descriptors. -#[tracing::instrument] +#[tracing::instrument(skip_all)] async fn insert_descriptor( tx: &mut Transaction<'_, Postgres>, wallet_name: &str, descriptor: &ExtendedDescriptor, keychain: KeychainKind, ) -> Result<(), SqlxError> { - info!("insert descriptor"); let descriptor_str = descriptor.to_string(); let descriptor_id = descriptor.descriptor_id().to_byte_array(); @@ -685,13 +728,12 @@ async fn insert_descriptor( } /// Insert network. -#[tracing::instrument] +#[tracing::instrument(skip(tx))] async fn insert_network( tx: &mut Transaction<'_, Postgres>, wallet_name: &str, network: Network, ) -> Result<(), SqlxError> { - info!("insert network"); sqlx::query("INSERT INTO network (wallet_name, name) VALUES ($1, $2)") .bind(wallet_name) .bind(network.to_string()) @@ -702,15 +744,13 @@ async fn insert_network( } /// Update keychain last revealed -#[tracing::instrument] +#[tracing::instrument(skip(tx))] async fn update_last_revealed( tx: &mut Transaction<'_, Postgres>, wallet_name: &str, descriptor_id: DescriptorId, last_revealed: u32, ) -> Result<(), SqlxError> { - info!("update last revealed"); - sqlx::query( "UPDATE keychain SET last_revealed = $1 WHERE wallet_name = $2 AND descriptor_id = $3", ) @@ -724,12 +764,11 @@ async fn update_last_revealed( } /// Select transactions, txouts, and anchors. -#[tracing::instrument] +#[tracing::instrument(skip(db_tx))] async fn tx_graph_changeset_from_postgres( db_tx: &mut Transaction<'_, Postgres>, wallet_name: &str, ) -> Result, SqlxError> { - info!("tx graph changeset from postgres"); let mut changeset = tx_graph::ChangeSet::default(); // Fetch transactions @@ -799,13 +838,12 @@ async fn tx_graph_changeset_from_postgres( } /// Insert transactions, txouts, and anchors. -#[tracing::instrument] +#[tracing::instrument(skip(db_tx, changeset))] async fn tx_graph_changeset_persist_to_postgres( db_tx: &mut Transaction<'_, Postgres>, wallet_name: &str, changeset: &tx_graph::ChangeSet, ) -> Result<(), SqlxError> { - info!("tx graph changeset from postgres"); for tx in &changeset.txs { sqlx::query( "INSERT INTO tx (wallet_name, txid, whole_tx) VALUES ($1, $2, $3) @@ -860,12 +898,11 @@ async fn tx_graph_changeset_persist_to_postgres( } /// Select blocks. -#[tracing::instrument] +#[tracing::instrument(skip(db_tx))] async fn local_chain_changeset_from_postgres( db_tx: &mut Transaction<'_, Postgres>, wallet_name: &str, ) -> Result { - info!("local chain changeset from postgres"); let mut changeset = local_chain::ChangeSet::default(); let rows = sqlx::query("SELECT hash, height FROM block WHERE wallet_name = $1") @@ -884,13 +921,12 @@ async fn local_chain_changeset_from_postgres( } /// Insert blocks. -#[tracing::instrument] +#[tracing::instrument(skip(db_tx, changeset))] async fn local_chain_changeset_persist_to_postgres( db_tx: &mut Transaction<'_, Postgres>, wallet_name: &str, changeset: &local_chain::ChangeSet, ) -> Result<(), SqlxError> { - info!("local chain changeset to postgres"); for (&height, &hash) in &changeset.blocks { match hash { Some(hash) => { @@ -918,10 +954,10 @@ async fn local_chain_changeset_persist_to_postgres( } /// Collects information on all the wallets in the database and dumps it to stdout. -#[tracing::instrument] +#[tracing::instrument(skip(db))] #[allow(dead_code)] -async fn easy_backup(db: Pool) -> Result<(), SqlxError> { - info!("Starting easy backup"); +async fn easy_backup(db: Pool, logger: Arc) -> Result<(), SqlxError> { + log_info!(logger, "Starting backup of the wallet database"); let statement = "SELECT * FROM keychain"; @@ -932,7 +968,7 @@ async fn easy_backup(db: Pool) -> Result<(), SqlxError> { let json_array = json!(results); println!("{}", serde_json::to_string_pretty(&json_array)?); - info!("Easy backup completed successfully"); + log_info!(logger, "Wallet database backup completed successfully."); Ok(()) } @@ -950,13 +986,19 @@ struct KeychainEntry { #[cfg(test)] mod tests { use super::*; - use crate::util::ser::deserialize_contract; + use crate::{logger::LogLevel, util::ser::deserialize_contract}; use ddk_manager::Storage; async fn seed_db() -> PostgresStore { + let database_url = std::env::var("DATABASE_URL").expect("DATABASE_URL must be set"); + println!("database_url: {database_url}"); let store = PostgresStore::new( - &std::env::var("DATABASE_URL").unwrap(), + &database_url, true, + Arc::new(Logger::console( + "console_logger".to_string(), + LogLevel::Info, + )), "test".to_string(), ) .await @@ -1010,6 +1052,7 @@ mod tests { #[tokio::test] async fn postgres() { + dotenv::dotenv().ok(); let db = seed_db().await; let confirmed_rows = db.get_contract_metadata(None).await.unwrap(); diff --git a/ddk/src/storage/sled/contract.rs b/ddk/src/storage/sled/contract.rs index 3dea81ff..43d647ce 100644 --- a/ddk/src/storage/sled/contract.rs +++ b/ddk/src/storage/sled/contract.rs @@ -1,4 +1,5 @@ use super::{SledStorage, CHAIN_MONITOR_KEY, CHAIN_MONITOR_TREE}; +use crate::logger::{log_error, log_info, WriteLog}; use crate::util::ser::{ deserialize_contract, serialize_contract, ChannelPrefix, ContractPrefix, SignedChannelPrefix, }; @@ -63,7 +64,7 @@ impl Storage for SledStorage { } async fn update_contract(&self, contract: &Contract) -> Result<(), Error> { - tracing::info!("Updating contract. {:?}", contract); + log_info!(self.logger, "Updating contract. {:?}", contract); let serialized = serialize_contract(contract)?; self.contract_tree()? .transaction::<_, _, UnabortableTransactionError>(|db| { @@ -78,7 +79,7 @@ impl Storage for SledStorage { Ok(()) }) .map_err(|e| { - tracing::error!("Could not update contract: {:?}", e); + log_error!(self.logger, "Could not update contract. error={}", e); to_storage_error(e) })?; Ok(()) @@ -313,14 +314,17 @@ fn deserialize_channel(buff: &sled::IVec) -> Result { #[cfg(test)] mod tests { use super::*; + use crate::logger::Logger; + use std::sync::Arc; macro_rules! sled_test { ($name: ident, $body: expr) => { #[tokio::test] async fn $name() { let path = format!("{}{}", "tests/data/dlc_storagedb/", std::stringify!($name)); + let logger = Arc::new(Logger::disabled("sled_test".to_string())); { - let storage = SledStorage::new(&path).expect("Error opening sled DB"); + let storage = SledStorage::new(&path, logger).expect("Error opening sled DB"); #[allow(clippy::redundant_closure_call)] $body(storage).await; } diff --git a/ddk/src/storage/sled/mod.rs b/ddk/src/storage/sled/mod.rs index 6e6185bf..7831975f 100644 --- a/ddk/src/storage/sled/mod.rs +++ b/ddk/src/storage/sled/mod.rs @@ -5,8 +5,11 @@ mod contract; mod wallet; -use crate::error::WalletError; +use std::sync::Arc; + +use crate::logger::{log_info, WriteLog}; use crate::Storage; +use crate::{error::WalletError, logger::Logger}; use bdk_chain::Merge; use bdk_wallet::ChangeSet; use ddk_manager::contract::ser::Serializable; @@ -27,13 +30,15 @@ const CHANGESET_KEY: &str = "changeset"; #[derive(Debug, Clone)] pub struct SledStorage { db: Db, + logger: Arc, } impl SledStorage { /// Creates a new instance of a SledStorage. - pub fn new(path: &str) -> Result { + pub fn new(path: &str, logger: Arc) -> Result { Ok(SledStorage { db: sled::open(path)?, + logger, }) } @@ -112,7 +117,7 @@ impl Storage for SledStorage { } async fn initialize_bdk(&self) -> Result { - tracing::info!("Initializing wallet persistance."); + log_info!(self.logger, "Initializing sled wallet persistance."); let changeset = match self .wallet_tree() .map_err(sled_to_wallet_error)? diff --git a/ddk/src/transport/lightning/mod.rs b/ddk/src/transport/lightning/mod.rs index 877498d3..584b8970 100644 --- a/ddk/src/transport/lightning/mod.rs +++ b/ddk/src/transport/lightning/mod.rs @@ -1,3 +1,4 @@ +use crate::logger::{log_info, log_warn, WriteLog}; use crate::{error::TransportError, DlcDevKitDlcManager, Oracle, Storage, Transport}; use async_trait::async_trait; use bitcoin::secp256k1::PublicKey; @@ -20,15 +21,20 @@ impl Transport for LightningTransport { /// Sends a message to a peer. async fn send_message(&self, counterparty: PublicKey, message: ddk_messages::Message) { - tracing::info!(message=?message, "Sending message to {}", counterparty.to_string()); + log_info!( + self.logger, + "Sending message to counter_party={}", + counterparty.to_string() + ); if self.peer_manager.peer_by_node_id(&counterparty).is_some() { self.message_handler.send_message(counterparty, message); self.peer_manager.process_events(); } else { - tracing::warn!( - pubkey = counterparty.to_string(), - "Not connected to counterparty. Message not sent" - ) + log_warn!( + self.logger, + "Not connected to counterparty. Message not sent. counter_party={}", + counterparty.to_string() + ); } } diff --git a/ddk/src/transport/lightning/peer_manager.rs b/ddk/src/transport/lightning/peer_manager.rs index 8e819fe0..c724fc04 100644 --- a/ddk/src/transport/lightning/peer_manager.rs +++ b/ddk/src/transport/lightning/peer_manager.rs @@ -5,8 +5,9 @@ use lightning::{ ErroringMessageHandler, IgnoringMessageHandler, MessageHandler, PeerManager as LdkPeerManager, }, + log_error, log_info, log_warn, sign::{KeysManager, NodeSigner}, - util::logger::{Level, Logger, Record}, + util::logger::Logger as LightningLogger, }; use lightning_net_tokio::{setup_inbound, SocketDescriptor}; use std::{ @@ -15,22 +16,7 @@ use std::{ }; use tokio::{net::TcpListener, sync::watch, task::JoinHandle, time::interval}; -use crate::{ddk::DlcDevKitDlcManager, error::TransportError, Oracle, Storage}; - -pub struct DlcDevKitLogger; - -/// TODO: make a logging struct for the crate. -impl Logger for DlcDevKitLogger { - fn log(&self, record: Record) { - 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), - } - } -} +use crate::{ddk::DlcDevKitDlcManager, error::TransportError, logger::Logger, Oracle, Storage}; /// Peer manager that only recognizes DLC messages. pub type LnPeerManager = LdkPeerManager< @@ -38,7 +24,7 @@ pub type LnPeerManager = LdkPeerManager< Arc, Arc, Arc, - Arc, + Arc, Arc, Arc, >; @@ -60,12 +46,15 @@ pub struct LightningTransport { pub node_id: PublicKey, /// Listening port for the TCP connection. pub listening_port: u16, + /// [`crate::logger::Logger`] instance. + pub logger: Arc, } impl LightningTransport { pub fn new( seed_bytes: &[u8; 32], listening_port: u16, + logger: Arc, ) -> Result { let time = SystemTime::now() .duration_since(SystemTime::UNIX_EPOCH) @@ -93,12 +82,13 @@ impl LightningTransport { message_handler, time.as_secs() as u32, &ephmeral_data, - Arc::new(DlcDevKitLogger {}), + logger.clone(), Arc::new(key_signer), )), message_handler: dlc_message_handler, node_id, listening_port, + logger, }) } @@ -109,20 +99,23 @@ impl LightningTransport { let listening_port = self.listening_port; let mut listen_stop = stop_signal.clone(); let peer_manager = Arc::clone(&self.peer_manager); + let logger = Arc::clone(&self.logger); tokio::spawn(async move { let listener = TcpListener::bind(format!("0.0.0.0:{}", listening_port)) .await .map_err(|e| TransportError::Listen(e.to_string()))?; - tracing::info!( - addr =? listener.local_addr().unwrap(), - "Starting lightning peer manager listener." + log_info!( + logger, + "Starting lightning peer manager listener. address={}", + listener.local_addr().unwrap() ); + let logger_clone = logger.clone(); loop { tokio::select! { _ = listen_stop.changed() => { if *listen_stop.borrow() { - tracing::warn!("Stop signal for lightning connection manager."); + log_warn!(logger_clone, "Stop signal for lightning connection manager."); break; } }, @@ -130,16 +123,14 @@ impl LightningTransport { match accept_result { Ok((tcp_stream, socket)) => { let peer_mgr = Arc::clone(&peer_manager); + let logger_clone = logger_clone.clone(); tokio::spawn(async move { - tracing::info!( - connection = socket.to_string(), - "Received connection." - ); + log_info!(logger_clone, "Received connection. connection={}", socket.to_string()); setup_inbound(peer_mgr, tcp_stream.into_std().unwrap()).await; }); } Err(e) => { - tracing::error!("Error accepting connection: {}", e); + log_error!(logger_clone, "Error accepting connection. error={}", e); } } } @@ -158,47 +149,42 @@ impl LightningTransport { let message_manager = Arc::clone(&manager); let peer_manager = Arc::clone(&self.peer_manager); let message_handler = Arc::clone(&self.message_handler); + let logger = Arc::clone(&self.logger); tokio::spawn(async move { let mut message_interval = interval(Duration::from_secs(20)); + let logger_clone = logger.clone(); loop { tokio::select! { _ = message_stop.changed() => { if *message_stop.borrow() { - tracing::warn!("Stop signal for lightning message processor."); + log_warn!(logger_clone, "Stop signal for lightning message processor."); break; } }, _ = message_interval.tick() => { if message_handler.has_pending_messages() { - tracing::info!("There are pending messages to be sent."); + log_info!(logger_clone, "There are pending messages to be sent."); peer_manager.process_events(); } let messages = message_handler.get_and_clear_received_messages(); for (counter_party, message) in messages { - tracing::info!( - counter_party = counter_party.to_string(), - "Processing DLC message" - ); + log_info!(logger_clone, "Processing DLC message. counter_party={}", counter_party.to_string()); match message_manager.on_dlc_message(&message, counter_party).await { Ok(Some(message)) => { if peer_manager.peer_by_node_id(&counter_party).is_some() { - tracing::info!(message=?message, "Sending message to {}", counter_party.to_string()); + log_info!(logger_clone, "Sending message to counter_party={}", counter_party.to_string()); message_handler.send_message(counter_party, message); peer_manager.process_events(); } else { - tracing::warn!( - pubkey = counter_party.to_string(), - "Not connected to counterparty. Message not sent" + log_warn!(logger_clone, + "Not connected to counterparty. Message not sent. counter_party={}", counter_party.to_string() ) } } Ok(None) => (), Err(e) => { - tracing::error!( - error=e.to_string(), - counterparty=counter_party.to_string(), - message=?message, - "Could not process dlc message." + log_error!(logger_clone, + "Could not process dlc message. message={:?} counterparty={} error={}", message, counter_party.to_string(), e.to_string() ); } } @@ -238,6 +224,7 @@ mod tests { #[tokio::test] async fn send_offer_test() { + let logger = Arc::new(Logger::disabled("test_lightning_transport".to_string())); let mut seed_bytes = [0u8; 32]; seed_bytes .try_fill(&mut bitcoin::key::rand::thread_rng()) @@ -247,8 +234,8 @@ mod tests { .try_fill(&mut bitcoin::key::rand::thread_rng()) .unwrap(); - let alice = LightningTransport::new(&seed_bytes, 1776).unwrap(); - let bob = LightningTransport::new(&bob_seed_bytes, 1777).unwrap(); + let alice = LightningTransport::new(&seed_bytes, 1776, logger.clone()).unwrap(); + let bob = LightningTransport::new(&bob_seed_bytes, 1777, logger.clone()).unwrap(); let (sender, receiver) = watch::channel(false); alice.listen(receiver.clone()); diff --git a/ddk/src/transport/memory.rs b/ddk/src/transport/memory.rs index e2fe2b44..857296af 100644 --- a/ddk/src/transport/memory.rs +++ b/ddk/src/transport/memory.rs @@ -1,11 +1,13 @@ -use crate::{ddk::DlcDevKitDlcManager, error::TransportError, Oracle, Storage, Transport}; +use crate::logger::{log_error, log_info, WriteLog}; +use crate::{ + ddk::DlcDevKitDlcManager, error::TransportError, logger::Logger, Oracle, Storage, Transport, +}; use bitcoin::{ key::{self, Keypair}, secp256k1::{All, PublicKey, Secp256k1}, }; -use std::{collections::HashMap, sync::Arc, time::Duration}; -// use crossbeam::channel::{unbounded, Receiver, Sender}; use ddk_messages::Message; +use std::{collections::HashMap, sync::Arc, time::Duration}; use tokio::sync::mpsc::{channel, Receiver, Sender}; use tokio::sync::watch; use tokio::sync::Mutex; @@ -16,10 +18,11 @@ pub struct MemoryTransport { pub sender: Sender<(Message, PublicKey)>, pub counterparty_transport: CounterPartyTransport, pub keypair: Keypair, + pub logger: Arc, } impl MemoryTransport { - pub fn new(secp: &Secp256k1) -> Self { + pub fn new(secp: &Secp256k1, logger: Arc) -> Self { let (sender, receiver) = channel(100); let keypair = Keypair::new(secp, &mut key::rand::thread_rng()); Self { @@ -27,6 +30,7 @@ impl MemoryTransport { sender, counterparty_transport: Arc::new(Mutex::new(HashMap::new())), keypair, + logger, } } @@ -60,7 +64,7 @@ impl Transport for MemoryTransport { .await .expect("could not send message to counterparty") } else { - tracing::error!("No counterparty connected.") + log_error!(self.logger, "No counterparty connected."); } } @@ -85,12 +89,13 @@ impl Transport for MemoryTransport { if let Some(reply) = s { self.send_message(msg.1, reply).await; } else { - tracing::info!("Handled on_dlc_message."); + log_info!(self.logger, "Handled on_dlc_message."); } } - Err(e) => tracing::error!( - error = e.to_string(), - "In memory transport error on dlc message." + Err(e) => log_error!( + self.logger, + "In memory transport error on dlc message. error={}", + e.to_string() ), } } diff --git a/ddk/src/transport/nostr/mod.rs b/ddk/src/transport/nostr/mod.rs index e21f9f1d..c3961882 100644 --- a/ddk/src/transport/nostr/mod.rs +++ b/ddk/src/transport/nostr/mod.rs @@ -1,5 +1,6 @@ mod relay_handler; +use crate::logger::{log_error, log_info, WriteLog}; pub use relay_handler::NostrDlc; use tokio::sync::watch; @@ -38,24 +39,38 @@ impl Transport for NostrDlc { /// Send a message to a specific counterparty. async fn send_message(&self, counterparty: BitcoinPublicKey, message: Message) { let nostr_counterparty = nostr::bitcoin_to_nostr_pubkey(&counterparty); - tracing::info!( - bitcoin_pk = counterparty.to_string(), - nostr_pk = nostr_counterparty.to_string(), - "Sending nostr message." + log_info!( + self.logger, + "Sending nostr message. bitcoin_pk={} nostr_pk={}", + counterparty.to_string(), + nostr_counterparty.to_string() ); let event = nostr::messages::create_dlc_msg_event(nostr_counterparty, None, message, &self.keys) .unwrap(); match self.client.send_event(&event).await { - Err(e) => tracing::error!(error = e.to_string(), "Failed to send nostr event."), - Ok(e) => tracing::info!(event_id = e.val.to_string(), "Sent DLC message event."), + Ok(e) => log_info!( + self.logger, + "Sent DLC message event. event_id={}", + e.val.to_string() + ), + Err(e) => log_error!( + self.logger, + "Failed to send nostr event. error={}", + e.to_string() + ), } } /// Connect to a relay. async fn connect_outbound(&self, _pubkey: BitcoinPublicKey, host: &str) { match self.client.add_relay(host).await { - Ok(_) => tracing::info!(host, "Added relay."), - Err(e) => tracing::error!(host, error = e.to_string(), "Could not add relay."), + Ok(_) => log_info!(self.logger, "Added relay. host={}", host), + Err(e) => log_error!( + self.logger, + "Could not add relay. host={} error={}", + host, + e.to_string() + ), } } } diff --git a/ddk/src/transport/nostr/relay_handler.rs b/ddk/src/transport/nostr/relay_handler.rs index 95d57a61..5949cd67 100644 --- a/ddk/src/transport/nostr/relay_handler.rs +++ b/ddk/src/transport/nostr/relay_handler.rs @@ -1,6 +1,8 @@ use std::sync::Arc; use crate::error::TransportError; +use crate::logger::Logger; +use crate::logger::{log_error, log_info, log_warn, WriteLog}; use crate::nostr::messages::{create_dlc_msg_event, handle_dlc_msg_event}; use crate::DlcDevKitDlcManager; use crate::{nostr, Transport}; @@ -16,15 +18,17 @@ pub struct NostrDlc { pub keys: Keys, pub relay_url: Url, pub client: Client, + pub logger: Arc, } impl NostrDlc { + #[tracing::instrument(skip(seed_bytes, logger))] pub async fn new( seed_bytes: &[u8; 64], relay_host: &str, network: Network, + logger: Arc, ) -> Result { - tracing::info!("Creating Nostr Dlc handler."); let secp = Secp256k1::new(); let seed = Xpriv::new_master(network, seed_bytes) .map_err(|e| TransportError::Init(e.to_string()))?; @@ -44,6 +48,7 @@ impl NostrDlc { keys, relay_url, client, + logger, }) } @@ -52,13 +57,15 @@ impl NostrDlc { mut stop_signal: watch::Receiver, manager: Arc>, ) -> JoinHandle> { - tracing::info!( - pubkey = self.keys.public_key().to_string(), - transport_public_key = self.public_key().to_string(), - "Starting Nostr DLC listener." + log_info!( + self.logger, + "Starting Nostr DLC listener. pubkey={} transport_public_key={}", + self.keys.public_key().to_string(), + self.public_key().to_string() ); let nostr_client = self.client.clone(); let keys = self.keys.clone(); + let logger = self.logger.clone(); tokio::spawn(async move { let since = Timestamp::now(); let msg_subscription = @@ -67,16 +74,18 @@ impl NostrDlc { .subscribe(msg_subscription, None) .await .map_err(|e| TransportError::Listen(e.to_string()))?; - tracing::info!( - "Listening for messages on {}", + log_info!( + logger, + "Listening for messages over nostr. pubkey={}", keys.public_key().to_string() ); let mut notifications = nostr_client.notifications(); loop { + let logger_clone = logger.clone(); tokio::select! { _ = stop_signal.changed() => { if *stop_signal.borrow() { - tracing::warn!("Stopping nostr dlc message subscription."); + log_warn!(logger_clone, "Stopping nostr dlc message subscription."); nostr_client.disconnect().await; break; } @@ -92,11 +101,11 @@ impl NostrDlc { keys.secret_key(), ) { Ok(msg) => { - tracing::info!(pubkey=msg.0.to_string(), "Received DLC nostr message."); + log_info!(logger_clone, "Received DLC nostr message. pubkey={}", msg.0.to_string()); (msg.0, msg.1, msg.2) }, - Err(_) => { - tracing::error!("Could not parse event {}", event.id); + Err(e) => { + log_error!(logger_clone, "Could not parse event {}. error={}", event.id, e.to_string()); continue; } }; diff --git a/ddk/src/wallet/command.rs b/ddk/src/wallet/command.rs index cb2aeb72..5544c931 100644 --- a/ddk/src/wallet/command.rs +++ b/ddk/src/wallet/command.rs @@ -1,26 +1,41 @@ -use crate::chain::EsploraClient; +use super::WalletStorage; use crate::error::WalletError; +use crate::logger::{log_debug, WriteLog}; +use crate::{chain::EsploraClient, logger::Logger}; use bdk_chain::spk_client::FullScanRequest; use bdk_esplora::EsploraAsyncExt; use bdk_wallet::{KeychainKind, PersistedWallet, Update}; use std::collections::BTreeMap; - -use super::WalletStorage; +use std::sync::Arc; type Result = std::result::Result; +#[tracing::instrument(skip_all)] pub async fn sync( wallet: &mut PersistedWallet, blockchain: &EsploraClient, storage: &mut WalletStorage, + logger: Arc, ) -> Result<()> { + let block_height = blockchain + .async_client + .get_height() + .await + .map_err(|e| WalletError::Esplora(e.to_string()))?; let prev_tip = wallet.latest_checkpoint(); - tracing::debug!( - height = prev_tip.height(), - "Syncing wallet with latest known height." + + if prev_tip.height() == block_height { + return Ok(()); + } + + log_debug!( + logger, + "Syncing wallet with latest known height. height={} wallet_height={}", + block_height, + prev_tip.height() ); let sync_result = if prev_tip.height() == 0 { - tracing::info!("Performing a full chain scan."); + log_debug!(logger, "Performing a full chain scan."); let spks = wallet .all_unbounded_spk_iters() .get(&KeychainKind::External) diff --git a/ddk/src/wallet/mod.rs b/ddk/src/wallet/mod.rs index 5da1174a..77118886 100644 --- a/ddk/src/wallet/mod.rs +++ b/ddk/src/wallet/mod.rs @@ -25,6 +25,8 @@ pub mod address; mod command; use crate::error::{wallet_err_to_manager_err, WalletError}; +use crate::logger::Logger; +use crate::logger::{log_error, log_info, WriteLog}; use crate::wallet::address::AddressGenerator; use crate::{chain::EsploraClient, Storage}; use bdk_chain::Balance; @@ -86,7 +88,7 @@ const MIN_CHANGE_SIZE: u64 = 25_000; /// # Thread Safety /// The wrapper uses Arc to ensure the storage can be safely shared across threads /// and provides the necessary interior mutability for BDK operations. -#[derive(Clone)] +#[derive(Clone, Debug)] pub struct WalletStorage(Arc); impl AsyncWalletPersister for WalletStorage { @@ -112,7 +114,6 @@ impl AsyncWalletPersister for WalletStorage { where Self: 'a, { - tracing::info!("persist store"); Box::pin(persister.0.persist_bdk(changeset)) } } @@ -199,6 +200,8 @@ pub struct DlcDevKitWallet { dlc_path: DerivationPath, /// Function to generate external addresses address_generator: Option>, + /// Logger + logger: Arc, } const MIN_FEERATE: u32 = 253; @@ -228,12 +231,14 @@ impl DlcDevKitWallet { /// - Maintains wallet state /// - Handles all BDK operations /// - Manages blockchain synchronization + #[tracing::instrument(name = "wallet", skip_all)] pub async fn new( seed_bytes: &[u8; 64], - esplora_url: &str, + blockchain: Arc, network: Network, storage: Arc, address_generator: Option>, + logger: Arc, ) -> Result { let secp = Secp256k1::new(); @@ -267,40 +272,54 @@ impl DlcDevKitWallet { let dlc_path = DerivationPath::from_str("m/420'/0'/0'")?; - let blockchain = Arc::new( - EsploraClient::new(esplora_url, network) - .map_err(|e| WalletError::Esplora(e.to_string()))?, - ); - let (sender, mut receiver) = channel(100); + let logger_clone = logger.clone(); tokio::spawn(async move { while let Some(command) = receiver.recv().await { match command { WalletCommand::Sync(sender) => { - let sync = command::sync(&mut wallet, &blockchain, &mut storage).await; + let sync = command::sync( + &mut wallet, + &blockchain, + &mut storage, + logger_clone.clone(), + ) + .await; let _ = sender.send(sync).map_err(|e| { - tracing::error!("Error sending sync command: {:?}", e); + log_error!(logger_clone, "Error sending sync command. error={:?}", e); }); } WalletCommand::Balance(sender) => { let balance = wallet.balance(); let _ = sender.send(balance).map_err(|e| { - tracing::error!("Error sending balance command: {:?}", e); + log_error!( + logger_clone, + "Error sending balance command. error={:?}", + e + ); }); } WalletCommand::NewExternalAddress(sender) => { let address = wallet.next_unused_address(KeychainKind::External); let _ = wallet.persist_async(&mut storage).await; let _ = sender.send(Ok(address)).map_err(|e| { - tracing::error!("Error sending new external address command: {:?}", e); + log_error!( + logger_clone, + "Error sending new external address command. error={:?}", + e + ); }); } WalletCommand::NewChangeAddress(sender) => { let address = wallet.next_unused_address(KeychainKind::Internal); let _ = wallet.persist_async(&mut storage).await; let _ = sender.send(Ok(address)).map_err(|e| { - tracing::error!("Error sending new change address command: {:?}", e); + log_error!( + logger_clone, + "Error sending new change address command. error={:?}", + e + ); }); } WalletCommand::SendToAddress(address, amount, fee_rate, sender) => { @@ -313,8 +332,9 @@ impl DlcDevKitWallet { Ok(psbt) => psbt, Err(e) => { let _ = sender.send(Err(WalletError::TxnBuilder(e))).map_err(|e| { - tracing::error!( - "Error sending send to address command: {:?}", + log_error!( + logger_clone, + "Error sending send to address command. error={:?}", e ); }); @@ -323,7 +343,11 @@ impl DlcDevKitWallet { }; if let Err(e) = wallet.sign(&mut psbt, SignOptions::default()) { let _ = sender.send(Err(WalletError::Signing(e))).map_err(|e| { - tracing::error!("Error sending send to address command: {:?}", e); + log_error!( + logger_clone, + "Error sending send to address command. error={:?}", + e + ); }); continue; } @@ -331,8 +355,9 @@ impl DlcDevKitWallet { Ok(tx) => tx, Err(_) => { let _ = sender.send(Err(WalletError::ExtractTx)).map_err(|e| { - tracing::error!( - "Error sending send to address command: {:?}", + log_error!( + logger_clone, + "Error sending send to address command. error={:?}", e ); }); @@ -344,15 +369,20 @@ impl DlcDevKitWallet { let _ = sender .send(Err(WalletError::Esplora(e.to_string()))) .map_err(|e| { - tracing::error!( - "Error sending send to address command: {:?}", + log_error!( + logger_clone, + "Error sending send to address command. error={:?}", e ); }); continue; } let _ = sender.send(Ok(txid)).map_err(|e| { - tracing::error!("Error sending send to address command: {:?}", e); + log_error!( + logger_clone, + "Error sending send to address command. error={:?}", + e + ); }); } WalletCommand::SendAll(address, fee_rate, sender) => { @@ -364,14 +394,22 @@ impl DlcDevKitWallet { Ok(psbt) => psbt, Err(e) => { let _ = sender.send(Err(WalletError::TxnBuilder(e))).map_err(|e| { - tracing::error!("Error sending send all command: {:?}", e); + log_error!( + logger_clone, + "Error sending send all command. error={:?}", + e + ); }); continue; } }; if let Err(e) = wallet.sign(&mut psbt, SignOptions::default()) { let _ = sender.send(Err(WalletError::Signing(e))).map_err(|e| { - tracing::error!("Error sending send all command: {:?}", e); + log_error!( + logger_clone, + "Error sending send all command. error={:?}", + e + ); }); continue; } @@ -379,7 +417,11 @@ impl DlcDevKitWallet { Ok(tx) => tx, Err(_) => { let _ = sender.send(Err(WalletError::ExtractTx)).map_err(|e| { - tracing::error!("Error sending send all command: {:?}", e); + log_error!( + logger_clone, + "Error sending send all command. error={:?}", + e + ); }); continue; } @@ -389,12 +431,20 @@ impl DlcDevKitWallet { let _ = sender .send(Err(WalletError::Esplora(e.to_string()))) .map_err(|e| { - tracing::error!("Error sending send all command: {:?}", e); + log_error!( + logger_clone, + "Error sending send all command. error={:?}", + e + ); }); continue; } let _ = sender.send(Ok(txid)).map_err(|e| { - tracing::error!("Error sending send all command: {:?}", e); + log_error!( + logger_clone, + "Error sending send all command. error={:?}", + e + ); }); } WalletCommand::GetTransactions(sender) => { @@ -403,19 +453,31 @@ impl DlcDevKitWallet { .map(|t| t.tx_node.tx) .collect::>>(); let _ = sender.send(Ok(txs)).map_err(|e| { - tracing::error!("Error sending get transactions command: {:?}", e); + log_error!( + logger_clone, + "Error sending get transactions command. error={:?}", + e + ); }); } WalletCommand::ListUtxos(sender) => { let utxos = wallet.list_unspent().map(|utxo| utxo.to_owned()).collect(); let _ = sender.send(Ok(utxos)).map_err(|e| { - tracing::error!("Error sending list utxos command: {:?}", e); + log_error!( + logger_clone, + "Error sending list utxos command. error={:?}", + e + ); }); } WalletCommand::NextDerivationIndex(sender) => { let index = wallet.next_derivation_index(KeychainKind::External); let _ = sender.send(Ok(index)).map_err(|e| { - tracing::error!("Error sending next derivation index command: {:?}", e); + log_error!( + logger_clone, + "Error sending next derivation index command. error={:?}", + e + ); }); } WalletCommand::SignPsbtInput(mut psbt, input_index, sender) => { @@ -425,21 +487,26 @@ impl DlcDevKitWallet { }; let mut signed_psbt = psbt.clone(); if let Err(e) = wallet.sign(&mut signed_psbt, sign_opts) { - tracing::error!("Could not sign PSBT: {:?}", e); + log_error!(logger_clone, "Could not sign PSBT. error={:?}", e); let _ = sender .send(Err(ManagerError::WalletError( WalletError::Signing(e).into(), ))) .map_err(|e| { - tracing::error!( - "Error sending sign psbt input command: {:?}", + log_error!( + logger_clone, + "Error sending sign psbt input command. error={:?}", e ); }); } else { psbt.inputs[input_index] = signed_psbt.inputs[input_index].clone(); let _ = sender.send(Ok(psbt)).map_err(|e| { - tracing::error!("Error sending sign psbt input command: {:?}", e); + log_error!( + logger_clone, + "Error sending sign psbt input command. error={:?}", + e + ); }); } } @@ -455,11 +522,13 @@ impl DlcDevKitWallet { fingerprint, dlc_path, address_generator, + logger, }) } /// Synchronizes the wallet with the blockchain. /// This updates the wallet's UTXO set and transaction history. + #[tracing::instrument(skip(self))] pub async fn sync(&self) -> Result<()> { let (tx, rx) = oneshot::channel(); self.sender.send(WalletCommand::Sync(tx)).await?; @@ -468,12 +537,13 @@ impl DlcDevKitWallet { /// Returns the wallet's master public key. /// Used for identification and key derivation. + #[tracing::instrument(skip(self))] pub fn get_pubkey(&self) -> PublicKey { - tracing::info!("Getting wallet public key."); PublicKey::from_secret_key(&self.secp, &self.xprv.private_key) } /// Retrieves the current wallet balance including confirmed and unconfirmed amounts. + #[tracing::instrument(skip(self))] pub async fn get_balance(&self) -> Result { let (tx, rx) = oneshot::channel(); self.sender.send(WalletCommand::Balance(tx)).await?; @@ -485,6 +555,7 @@ impl DlcDevKitWallet { /// /// WARNING: If you want your custom address generator call /// [`address::AddressGenerator::custom_external_address`] instead. + #[tracing::instrument(skip(self))] pub async fn new_external_address(&self) -> Result { let (tx, rx) = oneshot::channel(); self.sender @@ -498,6 +569,7 @@ impl DlcDevKitWallet { /// /// WARNING: If you want your custom address generator call /// [`address::AddressGenerator::custom_change_address`] instead. + #[tracing::instrument(skip(self))] pub async fn new_change_address(&self) -> Result { let (tx, rx) = oneshot::channel(); self.sender @@ -515,6 +587,7 @@ impl DlcDevKitWallet { /// /// # Returns /// Transaction ID of the sent transaction + #[tracing::instrument(skip(self))] pub async fn send_to_address( &self, address: Address, @@ -536,6 +609,7 @@ impl DlcDevKitWallet { /// /// # Returns /// Transaction ID of the sent transaction + #[tracing::instrument(skip(self))] pub async fn send_all(&self, address: Address, fee_rate: FeeRate) -> Result { let (tx, rx) = oneshot::channel(); self.sender @@ -545,6 +619,7 @@ impl DlcDevKitWallet { } /// Retrieves all transactions known to the wallet. + #[tracing::instrument(skip(self))] pub async fn get_transactions(&self) -> Result>> { let (tx, rx) = oneshot::channel(); self.sender.send(WalletCommand::GetTransactions(tx)).await?; @@ -552,6 +627,7 @@ impl DlcDevKitWallet { } /// Lists all unspent transaction outputs (UTXOs) in the wallet. + #[tracing::instrument(skip(self))] pub async fn list_utxos(&self) -> Result> { let (tx, rx) = oneshot::channel(); self.sender.send(WalletCommand::ListUtxos(tx)).await?; @@ -566,17 +642,12 @@ impl DlcDevKitWallet { /// # Arguments /// * `psbt` - The PSBT to sign /// * `input_index` - Index of the input to sign + #[tracing::instrument(skip(self))] async fn sign_psbt_input( &self, psbt: &mut bitcoin::psbt::Psbt, input_index: usize, ) -> std::result::Result<(), ManagerError> { - tracing::info!( - input_index, - inputs = psbt.inputs.len(), - outputs = psbt.outputs.len(), - "Signing psbt input for dlc manager." - ); let (tx, rx) = oneshot::channel(); self.sender .send(WalletCommand::SignPsbtInput(psbt.clone(), input_index, tx)) @@ -644,6 +715,7 @@ impl DlcDevKitWallet { SecretKey::from_slice(hardened_hash.as_ref()).map_err(|_| WalletError::InvalidSecretKey) } + #[tracing::instrument(skip(self, key_id))] fn derive_secret_key_from_key_id(&self, key_id: [u8; 32]) -> Result { let derivation_path = self.get_hierarchical_derivation_path(key_id)?; @@ -667,6 +739,7 @@ impl DlcDevKitWallet { impl FeeEstimator for DlcDevKitWallet { /// Returns the estimated fee rate in satoshis per 1000 weight units. /// Used by the DLC manager to estimate fees for funding transactions. + #[tracing::instrument(skip(self))] fn get_est_sat_per_1000_weight(&self, confirmation_target: ConfirmationTarget) -> u32 { let fees = fee_estimator(); fees.get(&confirmation_target) @@ -692,6 +765,7 @@ impl ddk_manager::ContractSignerProvider for DlcDevKitWallet { /// /// # Returns /// A 32-byte key ID for the contract + #[tracing::instrument(skip(self))] fn derive_signer_key_id(&self, _is_offer_party: bool, temp_id: [u8; 32]) -> [u8; 32] { let mut key_id_input = Vec::new(); @@ -713,6 +787,7 @@ impl ddk_manager::ContractSignerProvider for DlcDevKitWallet { /// /// # Returns /// A SimpleSigner configured for the contract + #[tracing::instrument(skip(self, key_id))] fn derive_contract_signer( &self, key_id: [u8; 32], @@ -760,9 +835,10 @@ impl ddk_manager::Wallet for DlcDevKitWallet { .await .map_err(wallet_err_to_manager_err)?; - tracing::info!( - address = address.address.to_string(), - "Revealed new address for contract." + log_info!( + self.logger.clone(), + "Revealed new address for contract. address={}", + address.address.to_string() ); Ok(address.address) } @@ -783,9 +859,10 @@ impl ddk_manager::Wallet for DlcDevKitWallet { .await .map_err(wallet_err_to_manager_err)?; - tracing::info!( - address = address.address.to_string(), - "Revealed new change address for contract." + log_info!( + self.logger.clone(), + "Revealed new change address for contract. address={}", + address.address.to_string() ); Ok(address.address) } @@ -797,12 +874,6 @@ impl ddk_manager::Wallet for DlcDevKitWallet { psbt: &mut bitcoin::psbt::Psbt, input_index: usize, ) -> std::result::Result<(), ManagerError> { - tracing::info!( - input_index, - inputs = psbt.inputs.len(), - outputs = psbt.outputs.len(), - "Signing psbt input for dlc manager." - ); self.sign_psbt_input(psbt, input_index).await } @@ -834,6 +905,7 @@ impl ddk_manager::Wallet for DlcDevKitWallet { /// /// # Returns /// A vector of UTXOs that can cover the required amount plus fees + #[tracing::instrument(skip(self))] async fn get_utxos_for_amount( &self, amount: Amount, @@ -932,6 +1004,8 @@ impl Debug for DlcDevKitWallet { mod tests { use std::{collections::HashSet, str::FromStr, sync::Arc, time::Duration}; + use crate::chain::EsploraClient; + use crate::logger::{LogLevel, Logger}; use crate::storage::memory::MemoryStorage; use bitcoin::{ address::NetworkChecked, @@ -946,22 +1020,36 @@ mod tests { use super::DlcDevKitWallet; async fn create_wallet() -> DlcDevKitWallet { - let esplora = std::env::var("ESPLORA_HOST").unwrap_or("http://localhost:30000".to_string()); + let esplora = std::env::var("ESPLORA_HOST").expect("ESPLORA_HOST must be set"); let storage = Arc::new(MemoryStorage::new()); + let logger = Arc::new(Logger::console( + "console_logger".to_string(), + LogLevel::Info, + )); + let esplora = + Arc::new(EsploraClient::new(&esplora, Network::Regtest, logger.clone()).unwrap()); let mut entropy = [0u8; 64]; entropy .try_fill(&mut bitcoin::key::rand::thread_rng()) .unwrap(); - DlcDevKitWallet::new(&entropy, &esplora, Network::Regtest, storage.clone(), None) - .await - .unwrap() + DlcDevKitWallet::new( + &entropy, + esplora, + Network::Regtest, + storage.clone(), + None, + logger.clone(), + ) + .await + .unwrap() } fn generate_blocks(num: u64) { - tracing::warn!("Generating {} blocks.", num); let bitcoind = std::env::var("BITCOIND_HOST").unwrap_or("http://localhost:18443".to_string()); - let auth = bitcoincore_rpc::Auth::UserPass("ddk".to_string(), "ddk".to_string()); + let user = std::env::var("BITCOIND_USER").expect("BITCOIND_USER must be set"); + let pass = std::env::var("BITCOIND_PASS").expect("BITCOIND_PASS must be set"); + let auth = bitcoincore_rpc::Auth::UserPass(user, pass); let client = bitcoincore_rpc::Client::new(&bitcoind, auth).unwrap(); let previous_height = client.get_block_count().unwrap(); @@ -977,7 +1065,9 @@ mod tests { fn fund_address(address: &Address) { let bitcoind = std::env::var("BITCOIND_HOST").unwrap_or("http://localhost:18443".to_string()); - let auth = bitcoincore_rpc::Auth::UserPass("ddk".to_string(), "ddk".to_string()); + let user = std::env::var("BITCOIND_USER").expect("BITCOIND_USER must be set"); + let pass = std::env::var("BITCOIND_PASS").expect("BITCOIND_PASS must be set"); + let auth = bitcoincore_rpc::Auth::UserPass(user, pass); let client = bitcoincore_rpc::Client::new(&bitcoind, auth).unwrap(); client .send_to_address( @@ -1487,6 +1577,14 @@ mod tests { .unwrap() .assume_checked(); + let logger = Arc::new(Logger::console( + "console_logger".to_string(), + LogLevel::Info, + )); + let esplora_host = std::env::var("ESPLORA_HOST").expect("ESPLORA_HOST must be set"); + let esplora = + Arc::new(EsploraClient::new(&esplora_host, Network::Regtest, logger.clone()).unwrap()); + let mut seed = [0u8; 64]; seed.try_fill(&mut bitcoin::key::rand::thread_rng()) .unwrap(); @@ -1494,10 +1592,11 @@ mod tests { let memory_storage = Arc::new(MemoryStorage::new()); let wallet = DlcDevKitWallet::new( &seed, - "http://localhost:30000", + esplora, Network::Regtest, memory_storage.clone(), Some(Arc::new(DummyAddressGenerator)), + logger.clone(), ) .await .unwrap(); diff --git a/ddk/tests/balance.rs b/ddk/tests/balance.rs index ecd492a1..5d285258 100644 --- a/ddk/tests/balance.rs +++ b/ddk/tests/balance.rs @@ -5,14 +5,18 @@ use std::sync::Arc; use bitcoin::key::Secp256k1; use bitcoin::Amount; use bitcoincore_rpc::RpcApi; +use ddk::logger::{LogLevel, Logger}; use ddk::oracle::memory::MemoryOracle; use ddk::util::ser::deserialize_contract; use ddk_manager::contract::Contract; use ddk_manager::Storage; use test_util::generate_blocks; +use crate::test_util::get_bitcoind_client; + #[tokio::test] async fn contract_balance() { + dotenv::dotenv().ok(); let contract_bytes = include_bytes!("../../testconfig/contract_binaries/PreClosed"); let contract = deserialize_contract(&contract_bytes.to_vec()).unwrap(); let preclosed = match contract { @@ -21,7 +25,8 @@ async fn contract_balance() { }; let secp = Secp256k1::new(); let oracle = Arc::new(MemoryOracle::default()); - let bob = test_util::TestSuite::new(&secp, "balance", oracle).await; + let logger = Arc::new(Logger::console("balance-test".to_string(), LogLevel::Info)); + let bob = test_util::TestSuite::new(&secp, "balance", oracle, logger).await; bob.ddk .storage @@ -31,8 +36,7 @@ async fn contract_balance() { let address = bob.ddk.wallet.new_external_address().await.unwrap().address; - let auth = bitcoincore_rpc::Auth::UserPass("ddk".to_string(), "ddk".to_string()); - let client = bitcoincore_rpc::Client::new("http://127.0.0.1:18443", auth).unwrap(); + let client = get_bitcoind_client(); client .send_to_address( &address, diff --git a/ddk/tests/enumeration.rs b/ddk/tests/enumeration.rs index 0e95d131..dfb45428 100644 --- a/ddk/tests/enumeration.rs +++ b/ddk/tests/enumeration.rs @@ -1,13 +1,19 @@ mod test_util; use bitcoin::Amount; use chrono::{Local, TimeDelta}; -use ddk::util::ser::serialize_contract; -use ddk::Transport; +use ddk::{ + logger::{LogLevel, Logger}, + util::ser::serialize_contract, + Transport, +}; use ddk_dlc::EnumerationPayout; use ddk_manager::contract::Contract; use ddk_manager::Storage; use ddk_messages::Message; -use std::time::{Duration, SystemTime, UNIX_EPOCH}; +use std::{ + sync::Arc, + time::{Duration, SystemTime, UNIX_EPOCH}, +}; use test_util::{generate_blocks, test_ddk}; use tokio::time::sleep; @@ -41,7 +47,10 @@ macro_rules! assert_contract_state_and_serialize { #[test_log::test(tokio::test)] #[ignore] async fn enumeration_contract() { - let (alice, bob, oracle) = test_ddk().await; + dotenv::dotenv().ok(); + let logger_one = Arc::new(Logger::tracing("alice".to_string(), LogLevel::Info)); + let logger_two = Arc::new(Logger::disabled("bob".to_string())); + let (alice, bob, oracle) = test_ddk(logger_two, logger_one).await; let expiry = TimeDelta::seconds(15); let timestamp: u32 = Local::now() .checked_add_signed(expiry) @@ -198,7 +207,6 @@ async fn enumeration_contract() { .await; while time < announcement.oracle_event.event_maturity_epoch || time < locktime { - tracing::warn!("Waiting for time to expire for oracle event and locktime."); let checked_time = SystemTime::now() .duration_since(UNIX_EPOCH) .unwrap() diff --git a/ddk/tests/nostr.rs b/ddk/tests/nostr.rs index b9380df3..fe806e92 100644 --- a/ddk/tests/nostr.rs +++ b/ddk/tests/nostr.rs @@ -7,6 +7,7 @@ mod nostr_test { use bitcoin::{key::rand::Fill, Network}; use chrono::{Local, TimeDelta}; use ddk::builder::SeedConfig; + use ddk::logger::{LogLevel, Logger}; use ddk::oracle::memory::MemoryOracle; use ddk::storage::memory::MemoryStorage; use ddk::transport::nostr::NostrDlc; @@ -17,16 +18,25 @@ mod nostr_test { type NostrDlcDevKit = DlcDevKit; - async fn nostr_ddk(name: &str, oracle: Arc) -> NostrDlcDevKit { + async fn nostr_ddk( + name: &str, + oracle: Arc, + logger: Arc, + ) -> NostrDlcDevKit { let mut seed = [0u8; 64]; seed.try_fill(&mut bitcoin::key::rand::thread_rng()) .unwrap(); let esplora_host = "http://127.0.0.1:30000".to_string(); let transport = Arc::new( - NostrDlc::new(&seed, "ws://127.0.0.1:8081", Network::Regtest) - .await - .unwrap(), + NostrDlc::new( + &seed, + "ws://127.0.0.1:8081", + Network::Regtest, + logger.clone(), + ) + .await + .unwrap(), ); let storage = Arc::new(MemoryStorage::new()); @@ -39,6 +49,7 @@ mod nostr_test { .set_oracle(oracle) .set_transport(transport) .set_storage(storage) + .set_logger(logger) .finish() .await .unwrap(); @@ -50,8 +61,9 @@ mod nostr_test { #[test_log::test(tokio::test)] async fn nostr_contract() { let oracle = Arc::new(MemoryOracle::default()); - let alice = nostr_ddk("alice-nostr", oracle.clone()).await; - let bob = nostr_ddk("bob-nostr", oracle.clone()).await; + let logger = Arc::new(Logger::console("nostr-test".to_string(), LogLevel::Info)); + let alice = nostr_ddk("alice-nostr", oracle.clone(), logger.clone()).await; + let bob = nostr_ddk("bob-nostr", oracle.clone(), logger.clone()).await; let alice_address = alice.wallet.new_external_address().await.unwrap().address; let bob_address = bob.wallet.new_external_address().await.unwrap().address; diff --git a/ddk/tests/short_call.rs b/ddk/tests/short_call.rs index c25ed052..4da7f8ea 100644 --- a/ddk/tests/short_call.rs +++ b/ddk/tests/short_call.rs @@ -2,11 +2,17 @@ mod test_util; use bitcoin::Amount; use chrono::{Local, TimeDelta}; -use ddk::Transport; +use ddk::{ + logger::{LogLevel, Logger}, + Transport, +}; use ddk_manager::{contract::Contract, Storage}; use ddk_messages::Message; use ddk_payouts::options::{Direction, OptionType}; -use std::time::{Duration, SystemTime, UNIX_EPOCH}; +use std::{ + sync::Arc, + time::{Duration, SystemTime, UNIX_EPOCH}, +}; use test_util::{generate_blocks, test_ddk}; use tokio::time::sleep; @@ -14,7 +20,10 @@ use tokio::time::sleep; #[test_log::test(tokio::test)] #[ignore] async fn short_call() { - let (alice, bob, oracle) = test_ddk().await; + dotenv::dotenv().ok(); + let logger_one = Arc::new(Logger::tracing("alice".to_string(), LogLevel::Info)); + let logger_two = Arc::new(Logger::disabled("bob".to_string())); + let (alice, bob, oracle) = test_ddk(logger_one, logger_two).await; let expiry = TimeDelta::seconds(15); let timestamp: u32 = Local::now() .checked_add_signed(expiry) @@ -138,7 +147,6 @@ async fn short_call() { assert!(attestation.is_ok()); while time < announcement.clone().oracle_event.event_maturity_epoch || time < locktime { - tracing::warn!("Waiting for time to expire for oracle event and locktime."); let checked_time = SystemTime::now() .duration_since(UNIX_EPOCH) .unwrap() diff --git a/ddk/tests/test_util.rs b/ddk/tests/test_util.rs index 78416768..187669db 100644 --- a/ddk/tests/test_util.rs +++ b/ddk/tests/test_util.rs @@ -6,6 +6,7 @@ use bitcoin::{ secp256k1::All, Address, Amount, Network, }; +use ddk::logger::{log_info, Logger, WriteLog}; use ddk_manager::{ContractId, Storage}; use std::{ fs::File, @@ -16,7 +17,7 @@ use std::{ time::Duration, }; -use bitcoincore_rpc::RpcApi; +use bitcoincore_rpc::{Client, RpcApi}; use ddk::{ builder::{Builder, SeedConfig}, oracle::memory::MemoryOracle, @@ -27,12 +28,15 @@ use ddk::{ type TestDlcDevKit = DlcDevKit; -pub async fn test_ddk() -> (TestSuite, TestSuite, Arc) { +pub async fn test_ddk( + logger_one: Arc, + logger_two: Arc, +) -> (TestSuite, TestSuite, Arc) { let secp = Secp256k1::new(); let oracle = Arc::new(MemoryOracle::default()); - let test = TestSuite::new(&secp, "send_offer", oracle.clone()).await; - let test_two = TestSuite::new(&secp, "sender_offer_two", oracle.clone()).await; + let test = TestSuite::new(&secp, "send_offer", oracle.clone(), logger_one).await; + let test_two = TestSuite::new(&secp, "sender_offer_two", oracle.clone(), logger_two).await; let node_one_address = test .ddk @@ -57,12 +61,19 @@ pub async fn test_ddk() -> (TestSuite, TestSuite, Arc) { (test, test_two, oracle) } +pub fn get_bitcoind_client() -> Client { + let bitcoind_user = std::env::var("BITCOIND_USER").expect("BITCOIND_USER must be set"); + let bitcoind_pass = std::env::var("BITCOIND_PASS").expect("BITCOIND_PASS must be set"); + let bitcoind_host = std::env::var("BITCOIND_HOST").expect("BITCOIND_HOST must be set"); + let auth = bitcoincore_rpc::Auth::UserPass(bitcoind_user, bitcoind_pass); + bitcoincore_rpc::Client::new(&bitcoind_host, auth).unwrap() +} + pub fn fund_addresses( node_one_address: &Address, node_two_address: &Address, ) { - let auth = bitcoincore_rpc::Auth::UserPass("ddk".to_string(), "ddk".to_string()); - let client = bitcoincore_rpc::Client::new("http://127.0.0.1:18443", auth).unwrap(); + let client = get_bitcoind_client(); client .send_to_address( node_one_address, @@ -91,9 +102,7 @@ pub fn fund_addresses( } pub fn generate_blocks(num: u64) { - tracing::warn!("Generating {} blocks.", num); - let auth = bitcoincore_rpc::Auth::UserPass("ddk".to_string(), "ddk".to_string()); - let client = bitcoincore_rpc::Client::new("http://127.0.0.1:18443", auth).unwrap(); + let client = get_bitcoind_client(); let previous_height = client.get_block_count().unwrap(); let address = client.get_new_address(None, None).unwrap().assume_checked(); @@ -110,27 +119,32 @@ pub struct TestSuite { } impl TestSuite { - pub async fn new(secp: &Secp256k1, name: &str, oracle: Arc) -> TestSuite { + pub async fn new( + secp: &Secp256k1, + name: &str, + oracle: Arc, + logger: Arc, + ) -> TestSuite { let mut seed = [0u8; 64]; seed.try_fill(&mut bitcoin::key::rand::thread_rng()) .unwrap(); - let esplora_host = "http://127.0.0.1:30000".to_string(); + let esplora_host = std::env::var("ESPLORA_HOST").expect("ESPLORA_HOST must be set"); - let transport = Arc::new(MemoryTransport::new(secp)); + let transport = Arc::new(MemoryTransport::new(secp, logger.clone())); let storage = Arc::new(MemoryStorage::new()); - let ddk: TestDlcDevKit = Builder::new() - .set_network(Network::Regtest) - .set_seed_bytes(SeedConfig::Bytes(seed)) - .unwrap() - .set_esplora_host(esplora_host) - .set_name(name) - .set_oracle(oracle) - .set_transport(transport) - .set_storage(storage) - .finish() - .await - .unwrap(); + let mut builder = Builder::new(); + builder.set_network(Network::Regtest); + builder.set_seed_bytes(SeedConfig::Bytes(seed)).unwrap(); + builder.set_esplora_host(esplora_host); + builder.set_name(name); + builder.set_oracle(oracle); + builder.set_transport(transport); + builder.set_storage(storage); + builder.set_logger(logger); + + let ddk: TestDlcDevKit = builder.finish().await.unwrap(); + log_info!(ddk.logger.clone(), "DDK created for {}", name); TestSuite { ddk } } diff --git a/docker-compose.yaml b/docker-compose.yaml index 64b1b420..a597cba7 100644 --- a/docker-compose.yaml +++ b/docker-compose.yaml @@ -5,8 +5,8 @@ services: container_name: bitcoin command: | -regtest=1 - -rpcuser=ddk - -rpcpassword=ddk + -rpcuser=$BITCOIND_USER + -rpcpassword=$BITCOIND_PASS -rpcallowip=0.0.0.0/0 -rpcbind=0.0.0.0 -server=1 @@ -37,7 +37,7 @@ services: - --daemon-rpc-addr - bitcoin:18443 - --cookie - - ddk:ddk + - $BITCOIND_USER:$BITCOIND_PASS - --http-addr - 0.0.0.0:30000 - --electrum-rpc-addr @@ -61,10 +61,11 @@ services: container_name: postgres hostname: postgres environment: - - POSTGRES_PASSWORD=dlcdevkit - - POSTGRES_USER=dlcdevkit + - POSTGRES_PASSWORD=$POSTGRES_PASS + - POSTGRES_USER=$POSTGRES_USER + ports: - - "5433:5432" + - "5432:5432" volumes: - postgres-data:/postgres nostr-relay: diff --git a/ddk/docs/Contract Key Derivation.md b/docs/contract-key-derivation.md similarity index 99% rename from ddk/docs/Contract Key Derivation.md rename to docs/contract-key-derivation.md index 434345e0..5780c7f6 100644 --- a/ddk/docs/Contract Key Derivation.md +++ b/docs/contract-key-derivation.md @@ -182,10 +182,6 @@ fn derive_contract_signer( let secret_key = self .derive_secret_key_from_key_id(key_id) .map_err(|e| ManagerError::WalletError(Box::new(e)))?; - tracing::debug!( - key_id = hex::encode(key_id), - "Derived secret key for contract." - ); Ok(SimpleSigner::new(secret_key)) } ``` diff --git a/docs/logging-strategy.md b/docs/logging-strategy.md new file mode 100644 index 00000000..eaf55c25 --- /dev/null +++ b/docs/logging-strategy.md @@ -0,0 +1,93 @@ +# `dlcdevkit` Logging Strategy + +## Overview + +`dlcdevkit` implements a structured logging approach using Rust's `tracing` crate and Lightning's `Logger` trait to provide comprehensive visibility into contract operations, channel management, and system events. + +## Key Components + +### Logger Integration +- All major operations accept a `Logger` parameter (`L: Deref` where `L::Target: Logger`) +- Uses Lightning's logging macros (`log_debug!`, `log_info!`) for consistent formatting +- Provides structured logging with contextual information for debugging and monitoring + +### Logging Levels + +**Debug Level (`log_debug!`)**: +- Contract party parameter details (fund pubkey, change/payout scripts, input amounts, collateral) +- DLC transaction creation details (funding script, output values, CET counts) +- Input signing operations and verification steps +- Channel cleanup and monitoring operations + +**Info Level (`log_info!`)**: +- High-level contract lifecycle events (offer created, contract accepted, signed) +- Major transaction milestones (funding signed, CET execution, refund operations) +- Performance metrics (DLC transaction creation timing) + +## Contract Lifecycle Logging + +### Contract Creation +- **Offer Contract**: Logs party parameters, temporary ID, counterparty details +- **Accept Contract**: Logs acceptance parameters, DLC transaction creation metrics +- **Sign Contract**: Logs verification steps, signature counts, final contract IDs + +### Transaction Operations +- **Funding Transactions**: Input population, signature verification, witness creation +- **CET Operations**: Oracle attestation processing, outcome verification +- **Refund Operations**: Refund transaction signing and verification +- **Cooperative Close**: Transaction creation and signature verification + +### Channel Management +- **Chain Monitoring**: Transaction and output watching (debug logging removed for noise reduction) +- **Channel Updates**: Contract renewal operations and finalization steps + +## Structured Data Logging + +Each log entry includes relevant contextual information: +- **Contract IDs**: Both temporary IDs and final contract IDs for traceability +- **Transaction Details**: TXIDs, script pubkeys, output values +- **Cryptographic Data**: Public keys, signature counts, input/output counts +- **Network Data**: Counterparty information, channel IDs + +## Performance Monitoring + +- **DLC Creation Timing**: Measures CET generation performance +- **Input Processing**: Tracks funding input counts and processing +- **Signature Operations**: Monitors adaptor signature verification and creation + +## Configuration + +The logging system is configurable through: +- Environment variables for log levels +- Runtime logger configuration via the `Logger` trait implementation +- Integration with external logging frameworks through the Lightning Logger interface + +## Usage Examples + +```rust +// Contract offer with logging +let (offered_contract, offer_msg) = offer_contract( + secp, + &contract_input, + // ... other parameters + &logger, // Logger instance +).await?; + +// This will log: +// DEBUG: Created offer contract with offer party params. temp_id=abc123... +``` + +## Benefits + +1. **Debugging**: Detailed trace of contract operations for troubleshooting +2. **Monitoring**: Performance metrics and operational insights +3. **Audit Trail**: Complete record of contract lifecycle events +4. **Integration**: Compatible with external logging and monitoring systems +5. **Structured Data**: Machine-readable log formats for automated processing + +## Implementation Notes + +- Logging overhead is minimal due to efficient `tracing` implementation +- Debug logs can be disabled in production for performance +- Hex encoding used for cryptographic data display +- Consistent formatting across all components for log aggregation \ No newline at end of file diff --git a/justfile b/justfile index 4b9c3904..712b8b02 100644 --- a/justfile +++ b/justfile @@ -1,14 +1,21 @@ +set dotenv-load +set dotenv-path := ".env" + + deps: - docker compose up -d bc *args: - - docker exec bitcoin bitcoin-cli --rpcport=18443 --rpcuser=ddk --rpcpassword=ddk -rpcwallet=ddk {{args}} + - docker exec bitcoin bitcoin-cli --rpcport=18443 --rpcuser=$BITCOIND_USER --rpcpassword=$BITCOIND_PASS -rpcwallet=$RPC_WALLET {{args}} + +echo: + - echo $DATABASE_URL node-one: - - cargo run --bin ddk-node -- --network regtest --esplora http://127.0.0.1:30000 --name node-one --postgres-url postgres://dlcdevkit:dlcdevkit@localhost:5433/ddk_one + - cargo run --bin ddk-node -- --network regtest --esplora $ESPLORA_HOST --name node-one --postgres-url postgres://$POSTGRES_USER:$POSTGRES_PASS@$POSTGRES_HOST/ddk_one --log debug node-two: - - cargo run --bin ddk-node -- --network regtest --esplora http://127.0.0.1:30000 --port 1777 --grpc 0.0.0.0:3031 --storage-dir ~/.ddk/node-two --name node-two --postgres-url postgres://dlcdevkit:dlcdevkit@localhost:5433/ddk_two + - cargo run --bin ddk-node -- --network regtest --esplora $ESPLORA_HOST --port 1777 --grpc 0.0.0.0:3031 --storage-dir ~/.ddk/node-two --name node-two --postgres-url postgres://$POSTGRES_USER:$POSTGRES_PASS@$POSTGRES_HOST/ddk_two --log debug cli-one *args: - cargo run --bin ddk-cli {{args}} @@ -17,7 +24,7 @@ cli-two *args: - cargo run --bin ddk-cli -- --server http://127.0.0.1:3031 {{args}} up: - - DATABASE_URL=postgres://dlcdevkit:dlcdevkit@localhost:5433/ddk_one sqlx migrate run --source ddk/src/storage/postgres/migrations + - DATABASE_URL=$DATABASE_URL sqlx migrate run --source ddk/src/storage/postgres/migrations down: - - DATABASE_URL=postgres://dlcdevkit:dlcdevkit@localhost:5433/ddk_one sqlx migrate revert --source ddk/src/storage/postgres/migrations + - DATABASE_URL=$DATABASE_URL sqlx migrate revert --source ddk/src/storage/postgres/migrations diff --git a/testconfig/scripts/wait_for_container.sh b/testconfig/scripts/wait_for_container.sh index 29970a1f..a2c59ebc 100644 --- a/testconfig/scripts/wait_for_container.sh +++ b/testconfig/scripts/wait_for_container.sh @@ -4,5 +4,5 @@ while [ "`docker inspect -f {{.State.Status}} $1`" != "running" ]; do sleep 2; done -docker exec bitcoin bitcoin-cli --rpcport=18443 --rpcuser=ddk --rpcpassword=ddk createwallet ddk -docker exec bitcoin bitcoin-cli --rpcport=18443 --rpcuser=ddk --rpcpassword=ddk --rpcwallet=ddk -generate 101 +docker exec bitcoin bitcoin-cli --rpcport=18443 --rpcuser=$BITCOIND_USER --rpcpassword=$BITCOIND_PASS createwallet ddk +docker exec bitcoin bitcoin-cli --rpcport=18443 --rpcuser=$BITCOIND_USER --rpcpassword=$BITCOIND_PASS --rpcwallet=ddk -generate 101 diff --git a/testconfig/scripts/wait_for_electrs.sh b/testconfig/scripts/wait_for_electrs.sh index b88cfa70..dc0b6005 100755 --- a/testconfig/scripts/wait_for_electrs.sh +++ b/testconfig/scripts/wait_for_electrs.sh @@ -2,7 +2,7 @@ until $(curl --output /dev/null --silent --fail http://localhost:30000/blocks/tip/height); do printf 'waiting for electrs to start' - docker exec bitcoin bitcoin-cli --rpcport=18443 --rpcuser=ddk --rpcpassword=ddk -rpcwallet=ddk getblockcount - docker exec bitcoin bitcoin-cli --rpcport=18443 --rpcuser=ddk --rpcpassword=ddk -rpcwallet=ddk -generate 1 + docker exec bitcoin bitcoin-cli --rpcport=18443 --rpcuser=$BITCOIND_USER --rpcpassword=$BITCOIND_PASS -rpcwallet=$RPC_WALLET getblockcount + docker exec bitcoin bitcoin-cli --rpcport=18443 --rpcuser=$BITCOIND_USER --rpcpassword=$BITCOIND_PASS -rpcwallet=$RPC_WALLET -generate 1 sleep 5 done \ No newline at end of file