mint: add trace logs (#213)

cashu/core/settings.py

@@ -42,6 +42,7 @@ class CashuSettings(BaseSettings):
 
 class EnvSettings(CashuSettings):
     debug: bool = Field(default=False)
+    log_level: str = Field(default="INFO")
     host: str = Field(default="127.0.0.1")
     port: int = Field(default=3338)
     cashu_dir: str = Field(default=os.path.join(str(Path.home()), ".cashu"))

cashu/mint/app.py

@@ -52,7 +52,9 @@ def create_app(config_object="core.settings") -> FastAPI:
                 logger.log(level, record.getMessage())
 
         logger.remove()
-        log_level: str = "DEBUG" if settings.debug else "INFO"
+        log_level = settings.log_level
+        if settings.debug and log_level == "INFO":
+            log_level = "DEBUG"
         formatter = Formatter()
         logger.add(sys.stderr, level=log_level, format=formatter.format)
 

cashu/mint/ledger.py

@@ -536,13 +536,15 @@ class Ledger:
         Returns:
             Tuple[str, str]: Bolt11 invoice and a hash (for looking it up later)
         """
-
+        logger.trace(f"called request_mint")
         if settings.mint_max_peg_in and amount > settings.mint_max_peg_in:
             raise Exception(f"Maximum mint amount is {settings.mint_max_peg_in} sats.")
         if settings.mint_peg_out_only:
             raise Exception("Mint does not allow minting new tokens.")
 
+        logger.trace(f"requesting invoice for {amount} satoshis")
         payment_request, payment_hash = await self._request_lightning_invoice(amount)
+        logger.trace(f"got invoice {payment_request} with hash {payment_hash}")
         assert payment_request and payment_hash, Exception(
             "could not fetch invoice from Lightning backend"
         )
@@ -556,6 +558,7 @@ class Ledger:
         )
 
         await self.crud.store_lightning_invoice(invoice=invoice, db=self.db)
+        logger.trace(f"stored invoice {invoice.hash} in db")
         return payment_request, invoice.hash
 
     async def mint(
@@ -579,6 +582,7 @@ class Ledger:
         Returns:
             List[BlindedSignature]: Signatures on the outputs.
         """
+        logger.trace("called mint")
         amounts = [b.amount for b in B_s]
         amount = sum(amounts)
         # check if lightning invoice was paid
@@ -586,7 +590,9 @@ class Ledger:
             if not hash:
                 raise Exception("no hash provided.")
             try:
+                logger.trace("checking lightning invoice")
                 paid = await self._check_lightning_invoice(amount, hash)
+                logger.trace(f"invoice paid: {paid}")
             except Exception as e:
                 raise e
 
@@ -597,6 +603,7 @@ class Ledger:
                 )
 
         promises = await self._generate_promises(B_s, keyset)
+        logger.trace("generated promises")
         return promises
 
     async def melt(
@@ -615,12 +622,15 @@ class Ledger:
         Returns:
             List[BlindedMessage]: Signed outputs for returning overpaid fees to wallet.
         """
-
+        logger.trace("melt called")
         # validate and set proofs as pending
+        logger.trace("setting proofs pending")
         await self._set_proofs_pending(proofs)
+        logger.trace(f"set proofs as pending")
 
         try:
             await self._verify_proofs(proofs)
+            logger.trace("verified proofs")
 
             total_provided = sum_proofs(proofs)
             invoice_obj = bolt11.decode(invoice)
@@ -638,15 +648,21 @@ class Ledger:
             return_promises: List[BlindedSignature] = []
 
             if settings.lightning:
+                logger.trace("paying lightning invoice")
                 status, preimage, fee_msat = await self._pay_lightning_invoice(
                     invoice, fees_msat
                 )
+                logger.trace("paid lightning invoice")
             else:
                 status, preimage, fee_msat = True, "preimage", 0
 
+            logger.trace(
+                f"status: {status}, preimage: {preimage}, fee_msat: {fee_msat}"
+            )
+
             if status == True:
                 await self._invalidate_proofs(proofs)
-
+                logger.trace("invalidated proofs")
                 # prepare change to compensate wallet for overpaid fees
                 assert fee_msat is not None, Exception("fees not valid")
                 if outputs:
@@ -657,13 +673,16 @@ class Ledger:
                         outputs=outputs,
                     )
             else:
+                logger.trace("lightning payment unsuccessful")
                 raise Exception("Lightning payment unsuccessful.")
 
         except Exception as e:
             raise e
         finally:
             # delete proofs from pending list
+            logger.trace("unsetting proofs pending")
             await self._unset_proofs_pending(proofs)
+            logger.trace("unset proofs pending")
 
         return status, preimage, return_promises
 
@@ -729,10 +748,11 @@ class Ledger:
         Returns:
             Tuple[List[BlindSignature],List[BlindSignature]]: Promises on both sides of the split.
         """
-
+        logger.trace(f"splitting {amount} from {proofs}")
         # set proofs as pending
+        logger.trace(f"setting proofs as pending")
         await self._set_proofs_pending(proofs)
-
+        logger.trace(f"set proofs as pending")
         total = sum_proofs(proofs)
 
         try:
@@ -743,21 +763,25 @@ class Ledger:
                 raise Exception("split amount is higher than the total sum.")
 
             await self._verify_proofs(proofs)
-
+            logger.trace(f"verified proofs")
             # verify that only unique outputs were used
             if not self._verify_no_duplicate_outputs(outputs):
                 raise Exception("duplicate promises.")
             # verify that outputs have the correct amount
             if not self._verify_outputs(total, amount, outputs):
                 raise Exception("split of promises is not as expected.")
+            logger.trace(f"verified outputs")
         except Exception as e:
             raise e
         finally:
             # delete proofs from pending list
+            logger.trace(f"unsetting proofs as pending")
             await self._unset_proofs_pending(proofs)
+            logger.trace(f"unset proofs as pending")
 
         # Mark proofs as used and prepare new promises
         await self._invalidate_proofs(proofs)
+        logger.trace(f"invalidated proofs")
 
         # split outputs according to amount
         outs_fst = amount_split(total - amount)
@@ -771,4 +795,6 @@ class Ledger:
 
         # verify amounts in produced proofs
         self._verify_equation_balanced(proofs, prom_fst + prom_snd)
+
+        logger.trace(f"split successful")
         return prom_fst, prom_snd

cashu/mint/router.py

@@ -1,6 +1,7 @@
 from typing import Dict, List, Optional, Union
 
 from fastapi import APIRouter
+from loguru import logger
 from secp256k1 import PublicKey
 
 from ..core.base import (
@@ -36,6 +37,7 @@ router: APIRouter = APIRouter()
     response_model_exclude_none=True,
 )
 async def info():
+    logger.trace(f"> GET /info")
     return GetInfoResponse(
         name=settings.mint_info_name,
         pubkey=ledger.pubkey.serialize().hex() if ledger.pubkey else None,
@@ -60,6 +62,7 @@ async def info():
 )
 async def keys() -> KeysResponse:
     """This endpoint returns a dictionary of all supported token values of the mint and their associated public key."""
+    logger.trace(f"> GET /keys")
     keyset = ledger.get_keyset()
     keys = KeysResponse.parse_obj(keyset)
     return keys
@@ -76,6 +79,7 @@ async def keyset_keys(idBase64Urlsafe: str) -> Union[KeysResponse, CashuError]:
     The id is encoded in idBase64Urlsafe (by a wallet) and is converted back to
     normal base64 before it can be processed (by the mint).
     """
+    logger.trace(f"> GET /keys/{idBase64Urlsafe}")
     try:
         id = idBase64Urlsafe.replace("-", "+").replace("_", "/")
         keyset = ledger.get_keyset(keyset_id=id)
@@ -90,6 +94,7 @@ async def keyset_keys(idBase64Urlsafe: str) -> Union[KeysResponse, CashuError]:
 )
 async def keysets() -> KeysetsResponse:
     """This endpoint returns a list of keysets that the mint currently supports and will accept tokens from."""
+    logger.trace(f"> GET /keysets")
     keysets = KeysetsResponse(keysets=ledger.keysets.get_ids())
     return keysets
 
@@ -102,6 +107,7 @@ async def request_mint(amount: int = 0) -> Union[GetMintResponse, CashuError]:
 
     Call `POST /mint` after paying the invoice.
     """
+    logger.trace(f"> GET /mint: amount={amount}")
     if settings.mint_peg_out_only:
         return CashuError(code=0, error="Mint does not allow minting new tokens.")
     try:
@@ -128,6 +134,7 @@ async def mint(
 
     Call this endpoint after `GET /mint`.
     """
+    logger.trace(f"> POST /mint: {payload}")
     try:
         # BEGIN: backwards compatibility < 0.12 where we used to lookup payments with payment_hash
         # We use the payment_hash to lookup the hash from the database and pass that one along.
@@ -149,6 +156,7 @@ async def melt(payload: PostMeltRequest) -> Union[CashuError, GetMeltResponse]:
     """
     Requests tokens to be destroyed and sent out via Lightning.
     """
+    logger.trace(f"> POST /melt: {payload}")
     try:
         ok, preimage, change_promises = await ledger.melt(
             payload.proofs, payload.pr, payload.outputs
@@ -168,6 +176,7 @@ async def check_spendable(
     payload: CheckSpendableRequest,
 ) -> CheckSpendableResponse:
     """Check whether a secret has been spent already or not."""
+    logger.trace(f"> POST /check: {payload}")
     spendableList = await ledger.check_spendable(payload.proofs)
     return CheckSpendableResponse(spendable=spendableList)
 
@@ -183,6 +192,7 @@ async def check_fees(payload: CheckFeesRequest) -> CheckFeesResponse:
     Used by wallets for figuring out the fees they need to supply together with the payment amount.
     This is can be useful for checking whether an invoice is internal (Cashu-to-Cashu).
     """
+    logger.trace(f"> POST /checkfees: {payload}")
     fees_sat = await ledger.check_fees(payload.pr)
     return CheckFeesResponse(fee=fees_sat)
 
@@ -198,6 +208,7 @@ async def split(
     This endpoint is used by Alice to split a set of proofs before making a payment to Carol.
     It is then used by Carol (by setting split=total) to redeem the tokens.
     """
+    logger.trace(f"> POST /split: {payload}")
     assert payload.outputs, Exception("no outputs provided.")
     try:
         split_return = await ledger.split(