Merge pull request #77 from bennyhodl/logs

Adding more logging

ddk-manager/Cargo.toml

@@ -29,10 +29,10 @@ dlc-trie = { version = "0.7.1", features = ["use-serde"] }
 futures = "0.3.31"
 hex = { package = "hex-conservative", version = "0.1" }
 lightning = { version = "0.0.125", default-features = false, features = ["grind_signatures"] }
-log = "0.4.14"
 rand_chacha = {version = "0.3.1", optional = true}
 secp256k1-zkp = {version = "0.11.0"}
 serde = {version = "1.0", optional = true}
+tracing = "0.1.41"
 
 [dev-dependencies]
 ddk = { path = "../ddk"}

ddk-manager/src/chain_monitor.rs

@@ -79,7 +79,7 @@ impl ChainMonitor {
     }
 
     pub(crate) fn add_tx(&mut self, txid: Txid, channel_info: ChannelInfo) {
-        log::debug!("Watching transaction {txid}: {channel_info:?}");
+        tracing::debug!("Watching transaction {txid}: {channel_info:?}");
         self.watched_tx.insert(txid, WatchState::new(channel_info));
 
         // When we watch a buffer transaction we also want to watch
@@ -103,13 +103,13 @@ impl ChainMonitor {
     }
 
     fn add_txo(&mut self, outpoint: OutPoint, channel_info: ChannelInfo) {
-        log::debug!("Watching transaction output {outpoint}: {channel_info:?}");
+        tracing::debug!("Watching transaction output {outpoint}: {channel_info:?}");
         self.watched_txo
             .insert(outpoint, WatchState::new(channel_info));
     }
 
     pub(crate) fn cleanup_channel(&mut self, channel_id: ChannelId) {
-        log::debug!("Cleaning up data related to channel {channel_id:?}");
+        tracing::debug!("Cleaning up data related to channel {channel_id:?}");
 
         self.watched_tx
             .retain(|_, state| state.channel_id() != channel_id);
@@ -119,7 +119,7 @@ impl ChainMonitor {
     }
 
     pub(crate) fn remove_tx(&mut self, txid: &Txid) {
-        log::debug!("Stopped watching transaction {txid}");
+        tracing::debug!("Stopped watching transaction {txid}");
         self.watched_tx.remove(txid);
     }
 
@@ -188,7 +188,7 @@ impl WatchState {
     fn confirm(&mut self, transaction: Transaction) {
         match self {
             WatchState::Registered { ref channel_info } => {
-                log::info!(
+                tracing::info!(
                     "Transaction {} confirmed: {channel_info:?}",
                     transaction.compute_txid()
                 );
@@ -202,7 +202,7 @@ impl WatchState {
                 channel_info,
                 transaction,
             } => {
-                log::error!(
+                tracing::error!(
                     "Transaction {} already confirmed: {channel_info:?}",
                     transaction.compute_txid()
                 );

ddk-manager/src/contract/mod.rs

@@ -13,6 +13,7 @@ use secp256k1_zkp::PublicKey;
 #[cfg(feature = "use-serde")]
 use serde::{Deserialize, Serialize};
 use signed_contract::SignedContract;
+use std::fmt::Write;
 
 use self::utils::unordered_equal;
 
@@ -86,6 +87,18 @@ impl Contract {
         }
     }
 
+    /// Get the string representation of the contract id.
+    pub fn get_id_string(&self) -> String {
+        let mut string_id = String::with_capacity(32 * 2 + 2);
+        string_id.push_str("0x");
+        let id = self.get_id();
+        for i in &id {
+            write!(string_id, "{:02x}", i).unwrap();
+        }
+
+        string_id
+    }
+
     /// Returns the temporary contract id of a contract.
     pub fn get_temporary_id(&self) -> ContractId {
         match self {

ddk-manager/src/contract_updater.rs

@@ -13,6 +13,7 @@ use dlc_messages::{
 use secp256k1_zkp::{
     ecdsa::Signature, All, EcdsaAdaptorSignature, PublicKey, Secp256k1, SecretKey, Signing,
 };
+use std::time::Instant;
 
 use crate::{
     contract::{
@@ -111,6 +112,7 @@ where
     )
     .await?;
 
+    let now = Instant::now();
     let dlc_transactions = dlc::create_dlc_transactions(
         &offered_contract.offer_params,
         &accept_params,
@@ -121,6 +123,11 @@ where
         offered_contract.cet_locktime,
         offered_contract.fund_output_serial_id,
     )?;
+    tracing::info!(
+        "Creted {} CETs in {} milliseconds",
+        dlc_transactions.cets.len(),
+        now.elapsed().as_millis()
+    );
 
     let fund_output_value = dlc_transactions.get_fund_output().value;
 
@@ -273,6 +280,7 @@ where
 
     let total_collateral = offered_contract.total_collateral;
 
+    let now = Instant::now();
     let dlc_transactions = dlc::create_dlc_transactions(
         &offered_contract.offer_params,
         &accept_params,
@@ -283,9 +291,15 @@ where
         offered_contract.cet_locktime,
         offered_contract.fund_output_serial_id,
     )?;
+    tracing::info!(
+        "Created {} CETs in {} milliseconds.",
+        dlc_transactions.cets.len(),
+        now.elapsed().as_millis()
+    );
     let fund_output_value = dlc_transactions.get_fund_output().value;
 
     let signer = signer_provider.derive_contract_signer(offered_contract.keys_id)?;
+
     let (signed_contract, adaptor_sigs) = verify_accepted_and_sign_contract_internal(
         secp,
         offered_contract,
@@ -301,13 +315,19 @@ where
         &dlc_transactions,
         None,
     )?;
+    let contract_id = signed_contract.accepted_contract.get_contract_id_string();
+    tracing::info!(contract_id, "Signed and verified contract.");
 
     let signed_msg: SignDlc = signed_contract.get_sign_dlc(adaptor_sigs);
 
     Ok((signed_contract, signed_msg))
 }
 
 fn populate_psbt(psbt: &mut Psbt, all_funding_inputs: &[&FundingInput]) -> Result<(), Error> {
+    tracing::info!(
+        funding_inputs = all_funding_inputs.len(),
+        "Populating PSBT."
+    );
     // add witness utxo to fund_psbt for all inputs
     for (input_index, x) in all_funding_inputs.iter().enumerate() {
         let tx = Transaction::consensus_decode(&mut x.prev_tx.as_slice()).map_err(|_| {
@@ -686,6 +706,11 @@ pub fn get_signed_cet<C: Signing, S: Deref>(
 where
     S::Target: ContractSigner,
 {
+    let contract_id = contract.accepted_contract.get_contract_id_string();
+    tracing::info!(
+        contract_id,
+        "Getting the signed CET for the Oracle Attestation."
+    );
     let (range_info, sigs) =
         crate::utils::get_range_info_and_oracle_sigs(contract_info, adaptor_info, attestations)?;
     let mut cet = contract.accepted_contract.dlc_transactions.cets[range_info.cet_index].clone();
@@ -709,6 +734,7 @@ where
 
     let funding_sk = signer.get_secret_key()?;
 
+    tracing::info!(contract_id, "Getting signed CET.");
     dlc::sign_cet(
         secp,
         &mut cet,
@@ -740,6 +766,7 @@ pub fn get_signed_refund<C: Signing, S: Deref>(
 where
     S::Target: ContractSigner,
 {
+    tracing::info!("Getting signed refund transaction.");
     let accepted_contract = &contract.accepted_contract;
     let offered_contract = &accepted_contract.offered_contract;
     let funding_script_pubkey = &accepted_contract.dlc_transactions.funding_script_pubkey;