diff --git a/src/keri/app/cli/commands/multisig/incept.py b/src/keri/app/cli/commands/multisig/incept.py index 1c589ab5..605a9104 100644 --- a/src/keri/app/cli/commands/multisig/incept.py +++ b/src/keri/app/cli/commands/multisig/incept.py @@ -156,7 +156,7 @@ def inceptDo(self, tymth, tock=0.0): serder=exn, attachment=ims) - print(f"Group identifier inception initialized for {ghab.pre}") + logger.info(f"Group identifier inception initialized for {ghab.pre}") prefixer = coring.Prefixer(qb64=ghab.pre) seqner = coring.Seqner(sn=0) saider = coring.Saider(qb64=prefixer.qb64) diff --git a/src/keri/app/cli/commands/witness/demo.py b/src/keri/app/cli/commands/witness/demo.py index dd83dc84..8a9a27a3 100644 --- a/src/keri/app/cli/commands/witness/demo.py +++ b/src/keri/app/cli/commands/witness/demo.py @@ -8,6 +8,7 @@ import argparse import logging +import os from hio.base import doing @@ -16,18 +17,26 @@ from keri import help parser = argparse.ArgumentParser(description="Run a demo collection of witnesses") +parser.add_argument("--loglevel", action="store", required=False, default=os.getenv("KERI_LOG_LEVEL", "CRITICAL"), + help="Set log level to DEBUG | INFO | WARNING | ERROR | CRITICAL. Default is CRITICAL") parser.set_defaults(handler=lambda args: demo(args)) -help.ogler.level = logging.INFO logger = help.ogler.getLogger() -def demo(_): +def demo(args): """ Run set of three witnesses for demo """ + base_formatter = logging.Formatter( + '%(asctime)s [keri] %(module)s.%(funcName)s-%(lineno)s %(levelname)-8s %(message)s') + base_formatter.default_msec_format = None + help.ogler.baseConsoleHandler.setFormatter(base_formatter) + help.ogler.level = logging.getLevelName(args.loglevel.upper()) + logger.setLevel(help.ogler.level) + help.ogler.reopen(name="keri", temp=True, clear=True) wancf = configing.Configer(name="wan", headDirPath="scripts", temp=False, reopen=True, clear=False) wilcf = configing.Configer(name="wil", headDirPath="scripts", temp=False, reopen=True, clear=False) diff --git a/src/keri/app/grouping.py b/src/keri/app/grouping.py index 1607ee29..51f58ce0 100644 --- a/src/keri/app/grouping.py +++ b/src/keri/app/grouping.py @@ -51,7 +51,7 @@ def start(self, ghab, prefixer, seqner, saider): serder = serdering.SerderKERI(raw=evt) del evt[:serder.size] - print(f"Waiting for other signatures for {serder.pre}:{seqner.sn}...") + logger.info(f"Waiting for other signatures for {serder.ilk} {serder.pre}:{seqner.sn}...") return self.hby.db.gpse.add(keys=(prefixer.qb64,), val=(seqner, saider)) def complete(self, prefixer, seqner, saider=None): @@ -133,7 +133,7 @@ def processPartialSignedEscrow(self): if kever.delegated and kever.ilk in (coring.Ilks.dip, coring.Ilks.drt): # We are a delegated identifier, must wait for delegator approval for dip and drt if witered: # We are elected to perform delegation and witnessing messaging - print(f"We are the witnesser, sending {pre} to delegator") + logger.info(f"We are the witnesser, sending {pre} to delegator") self.swain.delegation(pre=pre, sn=seqner.sn) else: anchor = dict(i=pre, s=seqner.snh, d=saider.qb64) @@ -142,15 +142,15 @@ def processPartialSignedEscrow(self): else: self.witq.query(src=ghab.mhab.pre, pre=kever.delegator, anchor=anchor) - print("Waiting for delegation approval...") + logger.info(f"Waiting for delegation approval...") self.hby.db.gdee.add(keys=(pre,), val=(seqner, saider)) else: # Non-delegation, move on to witnessing if witered: # We are elected witnesser, send off event to witnesses - print(f"We are the fully signed witnesser {seqner.sn}, sending to witnesses") + logger.info(f"We are the fully signed witnesser {seqner.sn}, sending to witnesses") self.witDoer.msgs.append(dict(pre=pre, sn=seqner.sn)) # Move to escrow waiting for witness receipts - print(f"Waiting for fully signed witness receipts for {seqner.sn}") + logger.info(f"Waiting for fully signed witness receipts for {seqner.sn}") self.hby.db.gpwe.add(keys=(pre,), val=(seqner, saider)) def processDelegateEscrow(self): @@ -170,7 +170,7 @@ def processDelegateEscrow(self): if witer: # We are elected witnesser, We've already done out part in Boatswain, we are done. if self.swain.complete(prefixer=kever.prefixer, seqner=coring.Seqner(sn=kever.sn)): self.hby.db.gdee.rem(keys=(pre,)) - print(f"Delegation approval for {pre} received.") + logger.info(f"Delegation approval for {pre} received.") self.hby.db.cgms.put(keys=(pre, seqner.qb64), val=saider) @@ -181,10 +181,10 @@ def processDelegateEscrow(self): dgkey = dbing.dgKey(pre, saider.qb64b) self.hby.db.setAes(dgkey, couple) # authorizer event seal (delegator/issuer) self.hby.db.gdee.rem(keys=(pre,)) - print(f"Delegation approval for {pre} received.") + logger.info(f"Delegation approval for {pre} received.") # Move to escrow waiting for witness receipts - print(f"Waiting for witness receipts for {pre}") + logger.info(f"Waiting for witness receipts for {pre}") self.hby.db.gdee.rem(keys=(pre,)) self.hby.db.gpwe.add(keys=(pre,), val=(seqner, saider)) @@ -212,7 +212,7 @@ def processPartialWitnessEscrow(self): witnessed = True if not witnessed: continue - print(f"Witness receipts complete, {pre} confirmed.") + logger.info(f"Witness receipts complete, {pre} confirmed.") self.hby.db.gpwe.rem(keys=(pre,)) self.hby.db.cgms.put(keys=(pre, seqner.qb64), val=saider) elif not witer: @@ -243,6 +243,7 @@ def handle(self, serder, attachments=None): attachments (list): list of tuples of pather, CESR SAD path attachments to the exn event """ + logger.info("handling %s event SAID=%s", self.resource, serder.said) self.mux.add(serder=serder) diff --git a/src/keri/core/eventing.py b/src/keri/core/eventing.py index 591fa9ac..5bbe5f2c 100644 --- a/src/keri/core/eventing.py +++ b/src/keri/core/eventing.py @@ -2294,7 +2294,7 @@ def valSigsDelWigs(self, serder, sigers, verfers, tholder, if delseqner and delsaider: self.escrowPACouple(serder=serder, seqner=delseqner, saider=delsaider) msg=(f"Failure satisfying sith = {tholder.sith} " - f"on sigs {[siger.qb64 for siger in sigers]}" + f"on sigs {[siger.qb64 for siger in sigers]} " f"for evt = {serder.said}") logger.trace(msg) logger.trace("Event Body=\n%s\n", serder.pretty()) @@ -2496,8 +2496,9 @@ def validateDelegation(self, serder, sigers, wigers=None, delseqner=None, delsai # during initial delegation we just escrow the delcept event if delseqner is None and delsaider is None and delegator is not None: self.escrowPSEvent(serder=serder, sigers=sigers, wigers=wigers) - raise MissingDelegationError("No delegation seal for delegator {} " - "with evt = {}.".format(delegator, serder.ked)) + msg = (f"No delegation seal for delegator {delegator} with event = {serder.said}") + logger.debug("Event Body=\n%s\n", serder.pretty()) + raise MissingDelegationError(msg) ssn = validateSN(sn=delseqner.snh, inceptive=False) # delseqner Number should already do this #ssn = sner.num sner is Number seqner is Seqner need to replace Seqners with Numbers @@ -2702,7 +2703,7 @@ def logEvent(self, serder, sigers=None, wigers=None, wits=None, first=False, if self.cues is not None: # cue to notice BadCloneFN self.cues.push(dict(kin="noticeBadCloneFN", serder=serder, fn=fn, firner=firner, dater=dater)) - logger.info("Kever: Mismatch Cloned Replay FN: First seen " + logger.info("Mismatch Cloned Replay FN: First seen " "ordinal fn %s dig %s and clone fn %s event=%s", fn, serder.pre, firner.sn, serder.said) logger.debug("Event Body=\n%s\n", serder.pretty()) @@ -2710,12 +2711,14 @@ def logEvent(self, serder, sigers=None, wigers=None, wits=None, first=False, dtsb = dater.dtsb self.db.setDts(dgkey, dtsb) # first seen so set dts to now self.db.fons.pin(keys=dgkey, val=Seqner(sn=fn)) - logger.info("Kever: First seen ordinal %s dig: %s at %s", - fn, serder.pre, dtsb.decode()) + logger.debug("Kever: First seen %s %s SAID=%s for %s at %s", + fn, serder.ilk, serder.said, serder.pre, dtsb.decode("utf-8")) logger.debug("Event Body=\n%s\n", serder.pretty()) self.db.addKe(snKey(serder.preb, serder.sn), serder.saidb) - logger.info("Kever: Added to KEL valid %s event %s for AID %s", serder.ilk, serder.said, serder.pre) - logger.debug("KEL Event Body=\n%s\n", serder.pretty()) + pre = self.prefixer.qb64 + logger.info("[AID %s...%s]: Added to KEL %s at sn=%s valid event SAID=%s for AID %s", + pre[:4], pre[-4:], serder.ilk, serder.sn, serder.said, serder.pre) + logger.debug("Event Body=\n%s\n", serder.pretty()) return (fn, dtsb.decode("utf-8")) # (fn int, dts str) if first else (None, dts str) def escrowPSEvent(self, serder, sigers, wigers=None): @@ -2736,7 +2739,7 @@ def escrowPSEvent(self, serder, sigers, wigers=None): self.db.putEvt(dgkey, serder.raw) snkey = snKey(serder.preb, serder.sn) self.db.addPse(snkey, serder.saidb) # b'EOWwyMU3XA7RtWdelFt-6waurOTH_aW_Z9VTaU-CshGk.00000000000000000000000000000001' - logger.info("Kever: Escrowed partially signed or delegated " + logger.debug("Kever: Escrowed partially signed or delegated " "event %s for AID %s", serder.said, serder.pre) logger.debug("Event Body=\n%s\n", serder.pretty()) @@ -5037,7 +5040,7 @@ def processEscrowUnverWitness(self): # valid event escrow. self.db.delUwe(snKey(pre, sn), ecouple) # removes one escrow at key val logger.info("Kevery: unver wit escrow unescrow succeeded for event pre=%s " - "sn=%s\n", pre, sn) + "sn=%s", pre, sn) if ekey == key: # still same so no escrows found on last while iteration break @@ -5200,7 +5203,7 @@ def processEscrowUnverNonTrans(self): # valid event escrow. self.db.delUre(snKey(pre, sn), etriplet) # removes one escrow at key val logger.info("Kevery: unver nontrans escrow unescrow succeeded for event pre=%s " - "sn=%s\n", pre, sn) + "sn=%s", pre, sn) if ekey == key: # still same so no escrows found on last while iteration break @@ -5578,7 +5581,8 @@ def processEscrowUnverTrans(self): # duplicitous so we process remaining escrows in spite of found # valid event escrow. self.db.delVre(snKey(pre, sn), equinlet) # removes one escrow at key val - logger.info("Kevery: unver trans escrow unescrow succeeded for event = %s\n", serder.ked) + logger.info("Kevery: unver trans escrow unescrow succeeded for event = %s", serder.said) + logger.debug("Event Body= \n%s\n", serder.pretty()) if ekey == key: # still same so no escrows found on last while iteration break diff --git a/src/keri/core/parsing.py b/src/keri/core/parsing.py index 2b4798db..145bbec4 100644 --- a/src/keri/core/parsing.py +++ b/src/keri/core/parsing.py @@ -1041,7 +1041,7 @@ def msgParsator(self, ims=None, framed=True, pipeline=False, elif ilk in [Ilks.rct]: # event receipt msg (nontransferable) if not (cigars or wigers or tsgs): - logger.debug("Parser: Missing attached signatures on receipt msg = %s.", serder.ked) + logger.debug("Parser: Missing attached signatures on receipt msg event =\n%s\n", serder.pretty()) raise kering.ValidationError(f"Missing attached sigs on receipt msg={serder.ked['d']}") try: @@ -1055,13 +1055,17 @@ def msgParsator(self, ims=None, framed=True, pipeline=False, kvy.processReceiptTrans(serder=serder, tsgs=tsgs) except AttributeError: - raise kering.ValidationError("No kevery to process so dropped msg" - "= {}.".format(serder.pretty())) + msg = f"No kevery to process so dropped msg = {serder.said}" + logger.info(msg) + logger.debug("Event body=\n%s\n", serder.pretty()) + raise kering.ValidationError(msg) elif ilk in (Ilks.rpy,): # reply message if not (cigars or tsgs): - raise kering.ValidationError("Missing attached endorser signature(s) " - "to reply msg = {}.".format(serder.pretty())) + msg = f"Missing attached endorser signature(s) to reply msg = {serder.said}" + logger.info(msg) + logger.debug("Event body=\n%s\n", serder.pretty()) + raise kering.ValidationError(msg) try: if cigars: # process separately so do not clash on errors @@ -1071,8 +1075,10 @@ def msgParsator(self, ims=None, framed=True, pipeline=False, rvy.processReply(serder, tsgs=tsgs) # trans except AttributeError as e: - raise kering.ValidationError("No kevery to process so dropped msg" - "= {}.".format(serder.pretty())) + msg = f"No kevery to process so dropped msg = {serder.said}" + logger.info(msg) + logger.debug("Event body=\n%s\n", serder.pretty()) + raise kering.ValidationError(msg) except kering.UnverifiedReplyError as e: if logger.isEnabledFor(logging.DEBUG): logger.exception("Error processing reply = %s", e) @@ -1091,16 +1097,20 @@ def msgParsator(self, ims=None, framed=True, pipeline=False, args["cigars"] = cigars else: - raise kering.ValidationError("Missing attached requester signature(s) " - "to key log query msg = {}.".format(serder.pretty())) + msg = f"Missing attached requester signature(s) to key log query msg = {serder.said}" + logger.info(msg) + logger.debug("Event body=\n%s\n", serder.pretty()) + raise kering.ValidationError(msg) route = serder.ked["r"] if route in ["logs", "ksn", "mbx"]: try: kvy.processQuery(**args) except AttributeError: - raise kering.ValidationError("No kevery to process so dropped msg" - "= {}.".format(serder.pretty())) + msg = f"No kevery to process so dropped msg = {serder.said}" + logger.info(msg) + logger.debug("Event body=\n%s\n", serder.pretty()) + raise kering.ValidationError(msg) except kering.QueryNotFoundError as e: # catch escrow error and log it if logger.isEnabledFor(logging.TRACE): logger.exception("Error processing query = %s", e) @@ -1112,12 +1122,16 @@ def msgParsator(self, ims=None, framed=True, pipeline=False, try: tvy.processQuery(**args) except AttributeError as e: - raise kering.ValidationError("No tevery to process so dropped msg" - "= {} from {}.".format(serder.pretty(), e)) + msg = f"No tevery to process so dropped msg = {serder.said} from {e}" + logger.info(msg) + logger.debug("Event body=\n%s\n", serder.pretty()) + raise kering.ValidationError(msg) else: - raise kering.ValidationError("Invalid resource type {} so dropped msg" - "= {}.".format(route, serder.pretty())) + msg = f"Invalid resource type {route} so dropped msg = {serder.said}" + logger.info(msg) + logger.debug("Event body=\n%s\n", serder.pretty()) + raise kering.ValidationError(msg) elif ilk in (Ilks.exn,): args = dict(serder=serder) @@ -1132,8 +1146,10 @@ def msgParsator(self, ims=None, framed=True, pipeline=False, exc.processEvent(tsgs=tsgs, **args) except AttributeError: - raise kering.ValidationError("No Exchange to process so dropped msg" - "= {}.".format(serder.pretty())) + msg = "No Exchange to process so dropped msg = {serder.said}" + logger.info(msg) + logger.debug("Event body=\n%s\n", serder.pretty()) + raise kering.ValidationError(msg) elif ilk in (Ilks.vcp, Ilks.vrt, Ilks.iss, Ilks.rev, Ilks.bis, Ilks.brv): # TEL msg @@ -1143,11 +1159,15 @@ def msgParsator(self, ims=None, framed=True, pipeline=False, tvy.processEvent(serder=serder, seqner=seqner, saider=saider, wigers=wigers) except AttributeError as e: - raise kering.ValidationError("No tevery to process so dropped msg" - "= {}.".format(serder.pretty())) + msg = f"No Tevery to process so dropped msg = {serder.said}" + logger.debug(msg) + logger.debug("Event body=\n%s\n", serder.pretty()) + raise kering.ValidationError(msg) else: - raise kering.ValidationError("Unexpected message ilk = {} for evt =" - " {}.".format(ilk, serder.pretty())) + msg = f"Unexpected message ilk = {ilk} for evt = {serder.said}" + logger.info(msg) + logger.debug("Event body=\n%s\n", serder.pretty()) + raise kering.ValidationError(msg) elif isinstance(serder, serdering.SerderACDC): ilk = serder.ilk # dispatch based on ilk @@ -1157,14 +1177,20 @@ def msgParsator(self, ims=None, framed=True, pipeline=False, prefixer, seqner, saider = ssts[-1] if ssts else (None, None, None) # use last one if more than one vry.processCredential(creder=serder, prefixer=prefixer, seqner=seqner, saider=saider) except AttributeError as e: - raise kering.ValidationError("No verifier to process so dropped credential" - "= {}.".format(serder.pretty())) + msg = f"No verifier to process so dropped credential {serder.said}" + logger.debug(msg) + logger.debug("Credential body=\n%s\n", serder.pretty()) + raise kering.ValidationError(msg) else: - raise kering.ValidationError("Unexpected message ilk = {} for evt =" - " {}.".format(ilk, serder.pretty())) + msg = f"Unexpected message ilk = {ilk} for evt = {serder.said}" + logger.info(msg) + logger.debug("Event body=\n%s\n", serder.pretty()) + raise kering.ValidationError(msg) else: - raise kering.ValidationError("Unexpected protocol type = {} for event message =" - " {}.".format(serder.proto, serder.pretty())) + msg = f"Unexpected protocol type = {serder.proto} for event message = {serder.said}" + logger.info(msg) + logger.debug("Event body=\n%s\n", serder.pretty()) + raise kering.ValidationError(msg) return True # done state diff --git a/src/keri/core/routing.py b/src/keri/core/routing.py index f335b074..68692968 100644 --- a/src/keri/core/routing.py +++ b/src/keri/core/routing.py @@ -323,9 +323,10 @@ def acceptReply(self, serder, saider, route, aid, osaider=None, if seqner.sn == osqr.sn: # sn same so check datetime if odater: if dater.datetime <= odater.datetime: - logger.info("Kevery process: skipped stale key" - "state sig datetime from %s on reply msg=\n%s\n", - aid, serder.pretty()) + logger.debug("Kevery process: skipped stale key " + "state sig datetime from %s on reply msg = %s", + aid, serder.said) + logger.debug("Reply Body=\n%s\n", serder.pretty()) continue # skip if not later # retrieve sdig of last event at sn of signer. @@ -500,8 +501,8 @@ def processEscrowReply(self): else: # unescrow succeded self.db.rpes.rem(keys=(route, ), val=saider) # remove escrow only - logger.info("Kevery unescrow succeeded for reply=\n%s\n", - serder.pretty()) + logger.info("Kevery unescrow succeeded for reply = %s", serder.said) + logger.debug("Reply Body=\n%s\n", serder.pretty()) except Exception as ex: # log diagnostics errors etc self.db.rpes.rem(keys=(route,), val=saider) # remove escrow only diff --git a/src/keri/db/escrowing.py b/src/keri/db/escrowing.py index ff6fd526..b903373e 100644 --- a/src/keri/db/escrowing.py +++ b/src/keri/db/escrowing.py @@ -88,7 +88,7 @@ def processEscrowState(self, typ, processReply, extype: Type[Exception]): try: if not (dater and serder and (tsgs or vcigars)): - raise ValueError(f"Broker: Missing escrow artifacts at said={saider.qb64}" + raise ValueError(f"Missing escrow artifacts at said={saider.qb64}" f"for pre={pre}.") cigars = [] @@ -101,7 +101,7 @@ def processEscrowState(self, typ, processReply, extype: Type[Exception]): if ((helping.nowUTC() - dater.datetime) > datetime.timedelta(seconds=self.timeout)): # escrow stale so raise ValidationError which unescrows below - msg = f"Broker: {typ} escrow unescrow error: Stale txn state escrow at pre = {pre}" + msg = f"{typ} escrow unescrow error: Stale txn state escrow at pre = {pre}" logger.trace(msg) raise kering.ValidationError(msg) @@ -111,19 +111,19 @@ def processEscrowState(self, typ, processReply, extype: Type[Exception]): except extype as ex: # still waiting on missing prior event to validate if logger.isEnabledFor(logging.TRACE): - logger.trace("Broker: %s escrow unescrow attempt failed: %s\n", typ, ex.args[0]) - logger.exception("Broker: %s escrow unescrow attempt failed: %s\n", typ, ex.args[0]) + logger.trace("%s escrow unescrow attempt failed: %s\n", typ, ex.args[0]) + logger.exception("%s escrow unescrow attempt failed: %s\n", typ, ex.args[0]) except Exception as ex: # other error so remove from reply escrow self.escrowdb.remIokey(iokeys=(typ, pre, aid, ion)) # remove escrow if logger.isEnabledFor(logging.DEBUG): - logger.exception("Broker: %s escrow other error on unescrow: %s\n", typ, ex.args[0]) + logger.exception("%s escrow other error on unescrow: %s\n", typ, ex.args[0]) else: - logger.error("Broker: %s escrow other error on unescrow: %s\n", typ, ex.args[0]) + logger.error("%s escrow other error on unescrow: %s\n", typ, ex.args[0]) else: # unescrow succeded self.escrowdb.remIokey(iokeys=(typ, pre, aid, ion)) # remove escrow only - logger.info("Broker: %s escrow unescrow succeeded for txn state=%s", + logger.info("%s escrow unescrow succeeded for txn state = %s", typ, serder.said) logger.debug("TXN State Body=\n%s\n", serder.pretty()) @@ -131,9 +131,9 @@ def processEscrowState(self, typ, processReply, extype: Type[Exception]): self.escrowdb.remIokey(iokeys=(typ, pre, aid, ion)) # remove escrow self.removeState(saider) if logger.isEnabledFor(logging.DEBUG): - logger.exception("Broker: %s escrow unescrowed due to error: %s\n", typ, ex.args[0]) + logger.exception("%s escrow unescrowed due to error: %s\n", typ, ex.args[0]) else: - logger.error("Broker: %s escrow unescrowed due to error: %s\n", typ, ex.args[0]) + logger.error("%s escrow unescrowed due to error: %s\n", typ, ex.args[0]) def escrowStateNotice(self, *, typ, pre, aid, serder, saider, dater, cigars=None, tsgs=None): """ diff --git a/src/keri/peer/exchanging.py b/src/keri/peer/exchanging.py index 1b100d66..5302efd2 100644 --- a/src/keri/peer/exchanging.py +++ b/src/keri/peer/exchanging.py @@ -92,8 +92,10 @@ def processEvent(self, serder, tsgs=None, cigars=None, **kwargs): if not tholder.satisfy(indices): # We still don't have all the sigers, need to escrow if self.escrowPSEvent(serder=serder, tsgs=tsgs, pathed=pathed): self.cues.append(dict(kin="query", q=dict(r="logs", pre=prefixer.qb64, sn=seqner.snh))) - raise MissingSignatureError(f"Not enough signatures in {indices}" - f" for evt = {serder.ked}.") + msg = f"Not enough signatures in {indices} for evt = {serder.said}" + logger.info(msg) + logger.debug(f"Event body=\n%20\n", serder.pretty()) + raise MissingSignatureError(msg) elif cigars is not None: for cigar in cigars: @@ -136,7 +138,7 @@ def processEvent(self, serder, tsgs=None, cigars=None, **kwargs): try: behavior.handle(serder=serder, attachments=attachments) except AttributeError: - logger.info(f"Behavior for {route} missing or does not have handle for exn={serder.said}") + logger.debug(f"Behavior for {route} missing or does not have handle for exn={serder.said}") logger.debug( f"exn body=\n{serder.ked}\n") @@ -193,18 +195,18 @@ def processEscrowPartialSigned(self): except MissingSignatureError as ex: logger.trace("Exchange partially signed unescrow failed: %s\n", ex.args[0]) if logger.isEnabledFor(logging.TRACE): - logger.debug(f"Event body=\n{serder.pretty()}\n") + logger.debug("Event body=\n%s\n", serder.pretty()) except Exception as ex: self.hby.db.epse.rem(dig) self.hby.db.esigs.rem(dig) logger.info("Exchange partially signed unescrowed: %s\n", ex.args[0]) if logger.isEnabledFor(logging.DEBUG): - logger.debug(f"Event body=\n{serder.pretty()}\n") + logger.debug("Event body=\n%s\n", serder.pretty()) else: self.hby.db.epse.rem(dig) self.hby.db.esigs.rem(dig) - logger.info(f"Exchanger unescrow succeeded in valid exchange: serder={serder.said}") - logger.debug(f"Serder Body=\n{serder.pretty()}\n") + logger.info("Exchanger unescrow succeeded in valid exchange: serder = %s", serder.said) + logger.debug("Serder Body=\n%s\n", serder.pretty()) def logEvent(self, serder, pathed=None, tsgs=None, cigars=None): dig = serder.said @@ -226,6 +228,12 @@ def logEvent(self, serder, pathed=None, tsgs=None, cigars=None): self.hby.db.erpy.pin(keys=(pdig,), val=saider) self.hby.db.exns.put(keys=(dig,), val=serder) + recipient = serder.ked['rp'] + sender = serder.ked['i'] + route = serder.ked['r'] + logger.info("Saved exn event route = %s SAID = %s sender %s -> recipient %s", + route, dig, sender, recipient) + logger.debug("EXN Event Body=\n%s\n", serder.pretty()) def lead(self, hab, said): """ Determines is current member represented by hab is the lead of an exn message @@ -480,8 +488,10 @@ def verify(hby, serder): _, indices = eventing.verifySigs(serder.raw, sigers, verfers) if not tholder.satisfy(indices): # We still don't have all the sigers, need to escrow - raise MissingSignatureError(f"Not enough signatures in {indices}" - f" for evt = {serder.ked}.") + msg = f"Not enough signatures in {indices} for evt = {serder.said}" + logger.info("exchanging.verify: %s", msg) + logger.debug(f"Event body=\n%s\n", serder.pretty()) + raise MissingSignatureError(msg) accepted = True cigars = hby.db.ecigs.get(keys=(serder.said,)) diff --git a/src/keri/vdr/credentialing.py b/src/keri/vdr/credentialing.py index c249736c..d3ba18c0 100644 --- a/src/keri/vdr/credentialing.py +++ b/src/keri/vdr/credentialing.py @@ -234,7 +234,8 @@ def processEvent(self, serder): try: self.tvy.processEvent(serder=serder) except kering.MissingAnchorError: - logger.info("Credential registry missing anchor for inception = {}".format(serder.ked)) + logger.info("Credential registry missing anchor for inception = {}".format(serder.said)) + logger.debug("Inception body = {}".format(serder.pretty())) def anchorMsg(self, pre, regd, seqner, saider): """ Create key event with seal to serder anchored as data. diff --git a/src/keri/vdr/eventing.py b/src/keri/vdr/eventing.py index 030ce18b..bedfe98f 100644 --- a/src/keri/vdr/eventing.py +++ b/src/keri/vdr/eventing.py @@ -1267,7 +1267,8 @@ def logEvent(self, pre, sn, serder, seqner, saider, bigers=None, baks=None): self.reger.tets.pin(keys=(pre.decode("utf-8"), dig.decode("utf-8")), val=coring.Dater()) self.reger.putTvt(key, serder.raw) self.reger.putTel(snKey(pre, sn), dig) - logger.info("Tever: Added to TEL valid %s event=%s for AID %s", serder.ilk, serder.said, serder.pre) + logger.info("Tever: Added to TEL %s valid event=%s SAID=%s reg=%.8s... iss=%s", + serder.ilk, serder.pre, serder.said, self.regk, self.pre) logger.debug("TEL Event Body=\n%s\n", serder.pretty()) def valAnchorBigs(self, serder, seqner, saider, bigers, toad, baks): @@ -1423,8 +1424,8 @@ def escrowALEvent(self, serder, seqner, saider, bigers=None, baks=None): self.reger.delBaks(key) self.reger.putBaks(key, [bak.encode("utf-8") for bak in baks]) self.reger.putTvt(key, serder.raw) - logger.info("Tever state: Escrowed anchorless event " - "event = %s\n", serder.ked) + logger.info("Tever: Escrowed anchorless event event = %s", serder.said) + logger.debug("Event body=\n%s\n", serder.ked) return self.reger.putTae(snKey(serder.preb, serder.sn), serder.saidb) def getBackerState(self, ked): @@ -2096,8 +2097,8 @@ def processEscrowOutOfOrders(self): # duplicitous so we process remaining escrows in spite of found # valid event escrow. self.reger.delOot(snKey(pre, sn)) # removes from escrow - logger.info("Tevery unescrow succeeded in valid event: " - "event=\n%s\n", tserder.pretty()) + logger.info("Tevery unescrow succeeded in valid event: event = %s", tserder.said) + logger.debug("Event Body=\n%s\n", tserder.pretty()) def processEscrowAnchorless(self): """ Process escrow of TEL events received before the anchoring KEL event. @@ -2159,4 +2160,5 @@ def processEscrowAnchorless(self): # valid event escrow. self.reger.delTae(snKey(pre, sn)) # removes from escrow logger.info("Tevery: anchorless escrow unescrow succeeded in valid event: " - "event=\n%s\n", tserder.pretty()) + "event = %s", tserder.said) + logger.debug("Event body=\n%s\n", tserder.pretty()) diff --git a/src/keri/vdr/verifying.py b/src/keri/vdr/verifying.py index 39e4e052..4ebf9b42 100644 --- a/src/keri/vdr/verifying.py +++ b/src/keri/vdr/verifying.py @@ -276,7 +276,8 @@ def _processEscrow(self, db, timeout, etype: Type[Exception]): else: db.rem(said) logger.info("Verifier unescrow succeeded in valid group op: " - "creder=\n%s\n", creder.pretty()) + "creder = %s", creder.said) + logger.debug("Creder body=\n%s\n", creder.pretty()) def saveCredential(self, creder, prefixer, seqner, saider): """ Write the credential and associated indicies to the database