From 79b4f096ecf9c21d125c2d37585182c7470dc47c Mon Sep 17 00:00:00 2001
From: Chris Stewart <stewart.chris1234@gmail.com>
Date: Thu, 28 Apr 2022 17:09:27 -0500
Subject: [PATCH] Improve logging around signDLC (#4299)

* Improve logging around signDLC

* Improve logging so we can see what specific transaction fails when processing a block
---
 .../scala/org/bitcoins/dlc/wallet/DLCWallet.scala   | 13 +++++++++----
 .../wallet/internal/TransactionProcessing.scala     |  9 ++++++++-
 2 files changed, 17 insertions(+), 5 deletions(-)

diff --git a/dlc-wallet/src/main/scala/org/bitcoins/dlc/wallet/DLCWallet.scala b/dlc-wallet/src/main/scala/org/bitcoins/dlc/wallet/DLCWallet.scala
index e0822234b1..5619c8a288 100644
--- a/dlc-wallet/src/main/scala/org/bitcoins/dlc/wallet/DLCWallet.scala
+++ b/dlc-wallet/src/main/scala/org/bitcoins/dlc/wallet/DLCWallet.scala
@@ -869,7 +869,7 @@ abstract class DLCWallet
 
   def registerDLCAccept(
       accept: DLCAccept): Future[(DLCDb, Vector[DLCCETSignaturesDb])] = {
-    logger.debug(
+    logger.info(
       s"Checking if DLC Accept with tempContractId ${accept.tempContractId.hex} has already been registered")
     val dbsF = for {
       dlcDbOpt <- dlcDAO.findByTempContractId(accept.tempContractId)
@@ -892,7 +892,8 @@ abstract class DLCWallet
           dlc.isInitiator,
           s"We cannot register a DLCAccept if we are not the initiator, got $dlc")
 
-        logger.debug(s"DLC Offer (${dlc.dlcId.hex}) found, adding accept data")
+        logger.info(
+          s"DLC Offer contractId=${dlc.contractIdOpt.map(_.toHex)} dlcId=(${dlc.dlcId.hex}) found, adding accept data")
 
         val dlcId = dlc.dlcId
         lazy val dlcAcceptDb = DLCAcceptDbHelper.fromDLCAccept(dlcId, accept)
@@ -998,8 +999,8 @@ abstract class DLCWallet
               .updateFundingOutPoint(outPoint))
         } yield (updatedDLCDb, sigsDbs)
       case (dlc, Some(_)) =>
-        logger.debug(
-          s"DLC Accept (${dlc.contractIdOpt.get.toHex}) has already been registered")
+        logger.info(
+          s"DLC Accept contractId=(${dlc.contractIdOpt.get.toHex}) dlcId=${dlc.dlcId.hex} has already been registered")
         dlcSigsDAO
           .findByDLCId(dlc.dlcId)
           .map(sigOpt => (dlc, sigOpt))
@@ -1030,6 +1031,8 @@ abstract class DLCWallet
     * This is the second step of the initiator
     */
   override def signDLC(accept: DLCAccept): Future[DLCSign] = {
+    logger.info(
+      s"Received accept message, tempContractId=${accept.tempContractId.hex}")
     for {
       (dlc, cetSigsDbs) <- registerDLCAccept(accept)
       // .get should be safe now
@@ -1094,6 +1097,8 @@ abstract class DLCWallet
       status <- findDLC(dlcId)
       _ <- dlcConfig.walletCallbacks.executeOnDLCStateChange(logger, status.get)
     } yield {
+      logger.info(
+        s"Done creating sign message with contractId=${contractId.toHex} tempContractId=${dlc.tempContractId.hex}")
       //?? is signer.signRefundTx persisted anywhere ??
       DLCSign(cetSigs,
               signerOpt.map(_.signRefundTx).get,
diff --git a/wallet/src/main/scala/org/bitcoins/wallet/internal/TransactionProcessing.scala b/wallet/src/main/scala/org/bitcoins/wallet/internal/TransactionProcessing.scala
index 8abd86ca85..19b3b7432e 100644
--- a/wallet/src/main/scala/org/bitcoins/wallet/internal/TransactionProcessing.scala
+++ b/wallet/src/main/scala/org/bitcoins/wallet/internal/TransactionProcessing.scala
@@ -407,7 +407,7 @@ private[bitcoins] trait TransactionProcessing extends WalletLogger {
       }
     }
 
-    for {
+    val processTxF = for {
       receivedSpendingInfoDbs <- receivedSpendingInfoDbsF
       receivedStart = TimeUtil.currentEpochMs
       incoming <- processReceivedUtxos(
@@ -439,6 +439,13 @@ private[bitcoins] trait TransactionProcessing extends WalletLogger {
     } yield {
       ProcessTxResult(incoming, outgoing)
     }
+
+    processTxF.failed.foreach { case err =>
+      logger.error(
+        s"Failed to process transaction=${transaction.txIdBE.hex} blockHash=${blockHashOpt}",
+        err)
+    }
+    processTxF
   }
 
   /** If the given UTXO is marked as unspent and returns it so it can be updated