From 68d9020cb375f0583d87dfa93ccf722a37e65dab Mon Sep 17 00:00:00 2001 From: callebtc <93376500+callebtc@users.noreply.github.com> Date: Sun, 14 May 2023 23:06:35 +0200 Subject: [PATCH] mint: add trace logs (#213) --- cashu/core/settings.py | 1 + cashu/mint/app.py | 4 +++- cashu/mint/ledger.py | 38 ++++++++++++++++++++++++++++++++------ cashu/mint/router.py | 11 +++++++++++ 4 files changed, 47 insertions(+), 7 deletions(-) diff --git a/cashu/core/settings.py b/cashu/core/settings.py index c23bbc4..6a66723 100644 --- a/cashu/core/settings.py +++ b/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")) diff --git a/cashu/mint/app.py b/cashu/mint/app.py index 2852899..5bdf58b 100644 --- a/cashu/mint/app.py +++ b/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) diff --git a/cashu/mint/ledger.py b/cashu/mint/ledger.py index bb418a2..6fc1236 100644 --- a/cashu/mint/ledger.py +++ b/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 diff --git a/cashu/mint/router.py b/cashu/mint/router.py index 43a69e8..c65f9d6 100644 --- a/cashu/mint/router.py +++ b/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(