From 4789e2a504f3c40c4f5b4e2b330272b6da62e77b Mon Sep 17 00:00:00 2001
From: callebtc <93376500+callebtc@users.noreply.github.com>
Date: Mon, 15 May 2023 00:15:07 +0200
Subject: [PATCH] Mint/moremore_traces (#215)

* more trace logging

* a lot more logging
---
 cashu/mint/ledger.py | 60 ++++++++++++++++++++++++++++++++++++++++----
 cashu/mint/router.py |  7 +++++-
 2 files changed, 61 insertions(+), 6 deletions(-)

diff --git a/cashu/mint/ledger.py b/cashu/mint/ledger.py
index fd91850..ac1d475 100644
--- a/cashu/mint/ledger.py
+++ b/cashu/mint/ledger.py
@@ -45,7 +45,9 @@ class Ledger:
 
     async def load_used_proofs(self):
         """Load all used proofs from database."""
+        logger.trace(f"crud: loading used proofs")
         proofs_used = await self.crud.get_proofs_used(db=self.db)
+        logger.trace(f"crud: loaded {len(proofs_used)} used proofs")
         self.proofs_used = set(proofs_used)
 
     async def load_keyset(self, derivation_path, autosave=True):
@@ -64,9 +66,11 @@ class Ledger:
             version=settings.version,
         )
         # load the keyest from db
+        logger.trace(f"crud: loading keyset for {derivation_path}")
         tmp_keyset_local: List[MintKeyset] = await self.crud.get_keyset(
             derivation_path=derivation_path, db=self.db
         )
+        logger.trace(f"crud: loaded {len(tmp_keyset_local)} keysets")
         if tmp_keyset_local:
             # we have a keyset for this derivation path
             keyset = tmp_keyset_local[0]
@@ -83,8 +87,9 @@ class Ledger:
                 version=settings.version,
             )
             if autosave:
-                logger.debug(f"Storing new keyset {keyset.id}.")
+                logger.debug(f"crud: storing new keyset {keyset.id}.")
                 await self.crud.store_keyset(keyset=keyset, db=self.db)
+                logger.trace(f"crud: stored new keyset {keyset.id}.")
 
         # store the new keyset in the current keysets
         if keyset.id:
@@ -101,7 +106,9 @@ class Ledger:
             generated from `self.derivation_path`. Defaults to True.
         """
         # load all past keysets from db
+        logger.trace(f"crud: loading keysets")
         tmp_keysets: List[MintKeyset] = await self.crud.get_keyset(db=self.db)
+        logger.trace(f"crud: loaded {len(tmp_keysets)} keysets")
         # add keysets from db to current keysets
         for k in tmp_keysets:
             if k.id and k.id not in self.keysets.keysets:
@@ -157,9 +164,11 @@ class Ledger:
         logger.trace(f"Generating promise with keyset {keyset.id}.")
         private_key_amount = keyset.private_keys[amount]
         C_ = b_dhke.step2_bob(B_, private_key_amount)
+        logger.trace(f"crud: _generate_promise storing promise for {amount}")
         await self.crud.store_promise(
             amount=amount, B_=B_.serialize().hex(), C_=C_.serialize().hex(), db=self.db
         )
+        logger.trace(f"crud: _generate_promise stored promise for {amount}")
         return BlindedSignature(id=keyset.id, amount=amount, C_=C_.serialize().hex())
 
     def _check_spendable(self, proof: Proof):
@@ -283,7 +292,11 @@ class Ledger:
         Returns:
             Tuple[str, str]: Bolt11 invoice and payment hash (for lookup)
         """
+        logger.trace(
+            f"_request_lightning_invoice: Requesting Lightning invoice for {amount} satoshis."
+        )
         error, balance = await self.lightning.status()
+        logger.trace(f"_request_lightning_invoice: Lightning wallet balance: {balance}")
         if error:
             raise Exception(f"Lightning wallet not responding: {error}")
         (
@@ -292,6 +305,9 @@ class Ledger:
             payment_request,
             error_message,
         ) = await self.lightning.create_invoice(amount, "cashu deposit")
+        logger.trace(
+            f"_request_lightning_invoice: Lightning invoice: {payment_request}"
+        )
         return payment_request, checking_id
 
     async def _check_lightning_invoice(self, amount: int, hash: str) -> Literal[True]:
@@ -311,9 +327,11 @@ class Ledger:
         Returns:
             bool: True if invoice has been paid, else False
         """
+        logger.trace(f"crud: _check_lightning_invoice: checking invoice {hash}")
         invoice: Union[Invoice, None] = await self.crud.get_lightning_invoice(
             hash=hash, db=self.db
         )
+        logger.trace(f"crud: _check_lightning_invoice: invoice: {invoice}")
         if invoice is None:
             raise Exception("invoice not found.")
         if invoice.issued:
@@ -321,24 +339,33 @@ class Ledger:
         assert invoice.payment_hash, "invoice has no payment hash."
 
         # set this invoice as issued
+        logger.trace(f"crud: setting invoice {invoice.payment_hash} as issued")
         await self.crud.update_lightning_invoice(hash=hash, issued=True, db=self.db)
+        logger.trace(f"crud: invoice {invoice.payment_hash} set as issued")
 
         try:
             if amount > invoice.amount:
                 raise Exception(
                     f"requested amount too high: {amount}. Invoice amount: {invoice.amount}"
                 )
-
+            logger.trace(
+                f"_check_lightning_invoice: checking invoice {invoice.payment_hash}"
+            )
             status = await self.lightning.get_invoice_status(invoice.payment_hash)
+            logger.trace(
+                f"_check_lightning_invoice: invoice {invoice.payment_hash} status: {status}"
+            )
             if status.paid:
                 return status.paid
             else:
                 raise Exception("Lightning invoice not paid yet.")
         except Exception as e:
             # unset issued
+            logger.trace(f"crud: unsetting invoice {invoice.payment_hash} as issued")
             await self.crud.update_lightning_invoice(
                 hash=hash, issued=False, db=self.db
             )
+            logger.trace(f"crud: invoice {invoice.payment_hash} unset as issued")
             raise e
 
     async def _pay_lightning_invoice(self, invoice: str, fee_limit_msat: int):
@@ -354,7 +381,9 @@ class Ledger:
         Returns:
             Tuple[bool, string, int]: Returns payment status, preimage of invoice, paid fees (in Millisatoshi)
         """
-        error, _ = await self.lightning.status()
+        logger.trace(f"_pay_lightning_invoice: paying Lightning invoice {invoice}")
+        error, balance = await self.lightning.status()
+        logger.trace(f"_pay_lightning_invoice: Lightning wallet balance: {balance}")
         if error:
             raise Exception(f"Lightning wallet not responding: {error}")
         (
@@ -364,6 +393,7 @@ class Ledger:
             preimage,
             error_message,
         ) = await self.lightning.pay_invoice(invoice, fee_limit_msat=fee_limit_msat)
+        logger.trace(f"_pay_lightning_invoice: Lightning payment status: {ok}")
         # make sure that fee is positive
         fee_msat = abs(fee_msat) if fee_msat else fee_msat
         return ok, preimage, fee_msat
@@ -379,8 +409,10 @@ class Ledger:
         proof_msgs = set([p.secret for p in proofs])
         self.proofs_used |= proof_msgs
         # store in db
+        logger.trace(f"crud: storing proofs")
         for p in proofs:
             await self.crud.invalidate_proof(proof=p, db=self.db)
+        logger.trace(f"crud: stored proofs")
 
     async def _set_proofs_pending(self, proofs: List[Proof]):
         """If none of the proofs is in the pending table (_validate_proofs_pending), adds proofs to
@@ -396,7 +428,13 @@ class Ledger:
         await self._validate_proofs_pending(proofs)
         for p in proofs:
             try:
+                logger.trace(
+                    f"crud: _set_proofs_pending setting proof {p.secret} as pending"
+                )
                 await self.crud.set_proof_pending(proof=p, db=self.db)
+                logger.trace(
+                    f"crud: _set_proofs_pending proof {p.secret} set as pending"
+                )
             except:
                 raise Exception("proofs already pending.")
 
@@ -410,7 +448,13 @@ class Ledger:
         # could block the _invalidate_proofs() call that happens afterwards.
         try:
             for p in proofs:
+                logger.trace(
+                    f"crud: _unset_proofs_pending unsetting proof {p.secret} as pending"
+                )
                 await self.crud.unset_proof_pending(proof=p, db=self.db)
+                logger.trace(
+                    f"crud: _unset_proofs_pending proof {p.secret} unset as pending"
+                )
         except Exception as e:
             print(e)
             pass
@@ -424,7 +468,9 @@ class Ledger:
         Raises:
             Exception: At least one of the proofs is in the pending table.
         """
+        logger.trace(f"crud: _validate_proofs_pending validating proofs")
         proofs_pending = await self.crud.get_proofs_pending(db=self.db)
+        logger.trace(f"crud: _validate_proofs_pending got proofs pending")
         for p in proofs:
             for pp in proofs_pending:
                 if p.secret == pp.secret:
@@ -556,9 +602,9 @@ class Ledger:
             payment_hash=payment_hash,  # what we got from the backend
             issued=False,
         )
-
+        logger.trace(f"crud: storing invoice {invoice.hash} in db")
         await self.crud.store_lightning_invoice(invoice=invoice, db=self.db)
-        logger.trace(f"stored invoice {invoice.hash} in db")
+        logger.trace(f"crud: stored invoice {invoice.hash} in db")
         return payment_request, invoice.hash
 
     async def mint(
@@ -718,7 +764,11 @@ class Ledger:
         if settings.lightning:
             decoded_invoice = bolt11.decode(pr)
             amount = math.ceil(decoded_invoice.amount_msat / 1000)
+            logger.trace(
+                f"check_fees: checking lightning invoice: {decoded_invoice.payment_hash}"
+            )
             paid = await self.lightning.get_invoice_status(decoded_invoice.payment_hash)
+            logger.trace(f"check_fees: paid: {paid}")
             internal = paid.paid == False
         else:
             amount = 0
diff --git a/cashu/mint/router.py b/cashu/mint/router.py
index c65f9d6..5c21c25 100644
--- a/cashu/mint/router.py
+++ b/cashu/mint/router.py
@@ -112,8 +112,8 @@ async def request_mint(amount: int = 0) -> Union[GetMintResponse, CashuError]:
         return CashuError(code=0, error="Mint does not allow minting new tokens.")
     try:
         payment_request, hash = await ledger.request_mint(amount)
-        print(f"Lightning invoice: {payment_request}")
         resp = GetMintResponse(pr=payment_request, hash=hash)
+        logger.trace(f"< GET /mint: {resp}")
         return resp
     except Exception as exc:
         return CashuError(code=0, error=str(exc))
@@ -142,6 +142,7 @@ async def mint(
         # END: backwards compatibility < 0.12
         promises = await ledger.mint(payload.outputs, hash=hash)
         blinded_signatures = PostMintResponse(promises=promises)
+        logger.trace(f"< POST /mint: {blinded_signatures}")
         return blinded_signatures
     except Exception as exc:
         return CashuError(code=0, error=str(exc))
@@ -162,6 +163,7 @@ async def melt(payload: PostMeltRequest) -> Union[CashuError, GetMeltResponse]:
             payload.proofs, payload.pr, payload.outputs
         )
         resp = GetMeltResponse(paid=ok, preimage=preimage, change=change_promises)
+        logger.trace(f"< POST /melt: {resp}")
         return resp
     except Exception as exc:
         return CashuError(code=0, error=str(exc))
@@ -178,6 +180,7 @@ async def check_spendable(
     """Check whether a secret has been spent already or not."""
     logger.trace(f"> POST /check: {payload}")
     spendableList = await ledger.check_spendable(payload.proofs)
+    logger.trace(f"< POST /check: {spendableList}")
     return CheckSpendableResponse(spendable=spendableList)
 
 
@@ -194,6 +197,7 @@ async def check_fees(payload: CheckFeesRequest) -> CheckFeesResponse:
     """
     logger.trace(f"> POST /checkfees: {payload}")
     fees_sat = await ledger.check_fees(payload.pr)
+    logger.trace(f"< POST /checkfees: {fees_sat}")
     return CheckFeesResponse(fee=fees_sat)
 
 
@@ -220,4 +224,5 @@ async def split(
         return CashuError(code=0, error="there was an error with the split")
     frst_promises, scnd_promises = split_return
     resp = PostSplitResponse(fst=frst_promises, snd=scnd_promises)
+    logger.trace(f"< POST /split: {resp}")
     return resp