From c87cb1caedf1e1665081576568289d99b389db35 Mon Sep 17 00:00:00 2001 From: Kent Bull Date: Tue, 4 Feb 2025 19:47:48 -0700 Subject: [PATCH] refactor: remove class name prefixes and log format string --- .../app/cli/commands/challenge/respond.py | 2 - src/keri/app/cli/commands/delegate/confirm.py | 4 - src/keri/app/cli/commands/delegate/request.py | 10 - src/keri/app/cli/commands/ends/add.py | 4 - src/keri/app/cli/commands/ipex/join.py | 2 +- src/keri/app/cli/commands/multisig/incept.py | 2 +- .../app/cli/commands/multisig/interact.py | 4 - src/keri/app/cli/commands/multisig/join.py | 2 +- src/keri/app/cli/commands/witness/demo.py | 8 +- src/keri/app/delegating.py | 8 +- src/keri/app/grouping.py | 27 +-- src/keri/app/storing.py | 4 +- src/keri/core/eventing.py | 186 +++++++++--------- src/keri/core/parsing.py | 24 +-- src/keri/help/__init__.py | 11 -- src/keri/peer/exchanging.py | 20 +- src/keri/vdr/eventing.py | 4 +- 17 files changed, 148 insertions(+), 174 deletions(-) diff --git a/src/keri/app/cli/commands/challenge/respond.py b/src/keri/app/cli/commands/challenge/respond.py index 3ed3bb7a0..d942312da 100644 --- a/src/keri/app/cli/commands/challenge/respond.py +++ b/src/keri/app/cli/commands/challenge/respond.py @@ -114,8 +114,6 @@ def respondDo(self, tymth, tock=0.0, **opts): del ims[:exn.size] senderHab = hab.mhab if isinstance(hab, GroupHab) else hab - logger.info("RespondDoer: sending challenge exn from %s to %s", senderHab.pre, recp) - logger.debug("RespondDoer: Challenge exn body=\n%s\n", exn.pretty()) self.postman.send(src=senderHab.pre, dest=recp, topic="challenge", serder=exn, attachment=ims) while not self.postman.cues: yield self.tock diff --git a/src/keri/app/cli/commands/delegate/confirm.py b/src/keri/app/cli/commands/delegate/confirm.py index 5765434d9..25eb27764 100644 --- a/src/keri/app/cli/commands/delegate/confirm.py +++ b/src/keri/app/cli/commands/delegate/confirm.py @@ -158,10 +158,6 @@ def confirmDo(self, tymth, tock=0.0): others.remove(hab.mhab.pre) for recpt in others: # send notification to other participants as a signalling mechanism - logger.info( - "ConfirmDoer: sending confirm notification exn from %s to %s", - hab.mhab.pre, recpt) - logger.debug("ConfirmDoer: Notification exn body=\n%s\n", exn.pretty()) self.postman.send(src=hab.mhab.pre, dest=recpt, topic="multisig", serder=exn, attachment=atc) diff --git a/src/keri/app/cli/commands/delegate/request.py b/src/keri/app/cli/commands/delegate/request.py index efa29bbcb..80e152feb 100644 --- a/src/keri/app/cli/commands/delegate/request.py +++ b/src/keri/app/cli/commands/delegate/request.py @@ -98,17 +98,7 @@ def requestDo(self, tymth, tock=0.0): # delegate AID ICP and exn of delegation request EXN srdr = serdering.SerderKERI(raw=evt) del evt[:srdr.size] - - logger.info( - "RequestDoer: sending delegated inception from delegate %s to delegator %s", - phab.pre, delpre) - logger.debug("RequestDoer: Delegated inception body=\n%s\n", exn.pretty()) self.postman.send(src=phab.pre, dest=delpre, topic="delegate", serder=srdr, attachment=evt) - - logger.info( - "RequestDoer: sending request notification exn from delegate %s to delegator %s", - phab.pre, delpre) - logger.debug("RequestDoer: Notification exn body=\n%s\n", exn.pretty()) self.postman.send(src=phab.pre, dest=hab.kever.delpre, topic="delegate", serder=exn, attachment=atc) while True: diff --git a/src/keri/app/cli/commands/ends/add.py b/src/keri/app/cli/commands/ends/add.py index d7ea08d70..08a0e7fd4 100644 --- a/src/keri/app/cli/commands/ends/add.py +++ b/src/keri/app/cli/commands/ends/add.py @@ -104,10 +104,6 @@ def roleDo(self, tymth, tock=0.0): for recp in smids: # this goes to other participants only as a signaling mechanism exn, atc = grouping.multisigRpyExn(ghab=self.hab, rpy=msg) - logger.info( - "RoleDoer: sending endpoint role add exn on %s from %s to %s", - "multisig", self.hab.mhab.pre, recp) - logger.debug("RoleDoer: Endpoint Role Add Exn body=\n%s\n", exn.pretty()) self.postman.send(src=self.hab.mhab.pre, dest=recp, topic="multisig", diff --git a/src/keri/app/cli/commands/ipex/join.py b/src/keri/app/cli/commands/ipex/join.py index 89e928362..897d9287d 100644 --- a/src/keri/app/cli/commands/ipex/join.py +++ b/src/keri/app/cli/commands/ipex/join.py @@ -104,7 +104,7 @@ def joinDo(self, tymth, tock=0.0): self.tock = tock _ = (yield self.tock) - print("IPEX JoinDoer: Waiting for group ipex events...") + print("Waiting for group ipex events...") while True: diff --git a/src/keri/app/cli/commands/multisig/incept.py b/src/keri/app/cli/commands/multisig/incept.py index 92bf1ca8b..57478dfed 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) - logger.info(f"MS Incept: Group identifier inception initialized for {ghab.pre}") + print(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/multisig/interact.py b/src/keri/app/cli/commands/multisig/interact.py index 56b0c9b46..0f5a9345e 100644 --- a/src/keri/app/cli/commands/multisig/interact.py +++ b/src/keri/app/cli/commands/multisig/interact.py @@ -120,10 +120,6 @@ def interactDo(self, tymth, tock=0.0): others.remove(ghab.mhab.pre) for recpt in others: # send notification to other participants as a signalling mechanism - logger.info( - "GroupMultisigInteract: sending multisig interact exn from %s to %s", - ghab.mhab.pre, recpt) - logger.debug("GroupMultisigInteract: interact exn body=\n%s\n", exn.pretty()) self.postman.send(src=ghab.mhab.pre, dest=recpt, topic="multisig", serder=exn, attachment=ims) prefixer = coring.Prefixer(qb64=ghab.pre) diff --git a/src/keri/app/cli/commands/multisig/join.py b/src/keri/app/cli/commands/multisig/join.py index 370de1f4e..829b8a393 100644 --- a/src/keri/app/cli/commands/multisig/join.py +++ b/src/keri/app/cli/commands/multisig/join.py @@ -111,7 +111,7 @@ def joinDo(self, tymth, tock=0.0): self.tock = tock _ = (yield self.tock) - print("MS JoinDoer: Waiting for group multisig events...") + print("Waiting for group multisig events...") while self.notifier.noter.notes.cntAll() == 0: yield self.tock diff --git a/src/keri/app/cli/commands/witness/demo.py b/src/keri/app/cli/commands/witness/demo.py index 912fa0417..4c0c840a8 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 @@ -19,18 +20,21 @@ parser = argparse.ArgumentParser(description="Run a demo collection of witnesses") +parser.add_argument("--loglevel", action="store", required=False, default=os.getenv("KERIA_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 """ + help.ogler.level = logging.getLevelName(args.loglevel.upper()) + logger.setLevel(help.ogler.level) 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/delegating.py b/src/keri/app/delegating.py index b0b3da776..3178ac3d5 100644 --- a/src/keri/app/delegating.py +++ b/src/keri/app/delegating.py @@ -172,7 +172,7 @@ def processPartialWitnessEscrow(self): witnessed = True if not witnessed: continue - logger.info(f"Anchorer: Witness receipts complete, waiting for delegation approval.") + logger.info(f"Witness receipts complete, waiting for delegation approval.") if pre not in self.hby.habs: continue @@ -193,15 +193,15 @@ def processPartialWitnessEscrow(self): srdr = serdering.SerderKERI(raw=evt) exn, atc = delegateRequestExn(phab, delpre=delpre, evt=bytes(evt), aids=smids) - logger.info("Anchorer: Sending delegation request exn for %s from %s to delegator %s", + logger.info("Sending delegation request exn for %s from %s to delegator %s", srdr.ilk, phab.pre, delpre) logger.debug("Delegation request=\n%s\n", exn.pretty()) self.postman.send(hab=phab, dest=hab.kever.delpre, topic="delegate", serder=exn, attachment=atc) del evt[:srdr.size] - logger.info("Anchorer: Sending delegation event %s from %s to delegator %s", + logger.info("Sending delegation event %s from %s to delegator %s", srdr.ilk, phab.pre, delpre) - logger.debug("Anchorer: Delegated inception=\n%s\n", srdr.pretty()) + logger.debug("Delegated inception=\n%s\n", srdr.pretty()) self.postman.send(hab=phab, dest=delpre, topic="delegate", serder=srdr, attachment=evt) seal = dict(i=srdr.pre, s=srdr.snh, d=srdr.said) diff --git a/src/keri/app/grouping.py b/src/keri/app/grouping.py index 1a8954cbf..e5928074f 100644 --- a/src/keri/app/grouping.py +++ b/src/keri/app/grouping.py @@ -49,8 +49,7 @@ def start(self, ghab, prefixer, seqner, saider): """ evt = ghab.makeOwnEvent(sn=seqner.sn, allowPartiallySigned=True) # used just for the log message serder = serdering.SerderKERI(raw=evt) # used just for the log message - logger.info(f"[Counselor {ghab.mhab.pre[:8]}]: Multisig start; " - f"Waiting for other signatures for {serder.ilk} {prefixer.qb64}:{seqner.sn}...") + logger.info("Waiting for other signatures on %s for %s:%s...", serder.ilk, prefixer.qb64, seqner.sn) return self.hby.db.gpse.add(keys=(prefixer.qb64,), val=(seqner, saider)) def complete(self, prefixer, seqner, saider=None): @@ -132,7 +131,8 @@ 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 - logger.info(f"[Counselor {ghab.mhab.pre[:8]}]: We are the witnesser, sending {pre} to delegator") + logger.info("AID %s...%s: We are the witnesser, sending %s to delegator", + pre[:4], pre[-4:], pre) self.swain.delegation(pre=pre, sn=seqner.sn) else: anchor = dict(i=pre, s=seqner.snh, d=saider.qb64) @@ -141,15 +141,17 @@ def processPartialSignedEscrow(self): else: self.witq.query(src=ghab.mhab.pre, pre=kever.delpre, anchor=anchor) - logger.info(f"[Counselor {ghab.mhab.pre[:8]}]: Waiting for delegation approval...") + logger.info("AID %s...%s: Waiting for delegation approval...", pre[:4], pre[-4:]) 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 - logger.info(f"[Counselor {ghab.mhab.pre[:8]}]: We are the fully signed witnesser {seqner.sn}, sending to witnesses") + logger.info("AID %s...%s: We are the fully signed witnesser %s, sending to witnesses", + pre[:4], pre[-4:], seqner.sn) self.witDoer.msgs.append(dict(pre=pre, sn=seqner.sn)) # Move to escrow waiting for witness receipts - logger.info(f"[Counselor {ghab.mhab.pre[:8]}]: Waiting for fully signed witness receipts for {seqner.sn}") + logger.info("AID %s...%s: Waiting for fully signed witness receipts for %s", + pre[:4], pre[-4:], seqner.sn) self.hby.db.gpwe.add(keys=(pre,), val=(seqner, saider)) def processDelegateEscrow(self): @@ -169,7 +171,8 @@ 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,)) - logger.info(f"[Counselor {ghab.mhab.pre[:8]}]: Delegation approval for {pre} received.") + logger.info("AID %s...%s: Delegation approval for %s received.", + pre[:4], pre[-4:], pre) self.hby.db.cgms.put(keys=(pre, seqner.qb64), val=saider) @@ -181,10 +184,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,)) - logger.info(f"[Counselor {ghab.mhab.pre[:8]}]: Delegation approval for {pre} received.") + logger.info("AID %s...%s: Delegation approval for %s received.", pre[:4], pre[-4:], pre) # Move to escrow waiting for witness receipts - logger.info(f"[Counselor {ghab.mhab.pre[:8]}]: Waiting for witness receipts for {pre}") + logger.info("AID %s...%s: Waiting for witness receipts for %s", pre[:4], pre[-4:], pre) self.hby.db.gdee.rem(keys=(pre,)) self.hby.db.gpwe.add(keys=(pre,), val=(seqner, saider)) @@ -212,7 +215,7 @@ def processPartialWitnessEscrow(self): witnessed = True if not witnessed: continue - logger.info(f"[Counselor {ghab.mhab.pre[:8]}]: Witness receipts complete, {pre} confirmed.") + logger.info("AID %s...%s: Witness receipts complete, %s confirmed.", pre[:4], pre[-4:], pre) self.hby.db.gpwe.rem(keys=(pre,)) self.hby.db.cgms.put(keys=(pre, seqner.qb64), val=saider) elif not witer: @@ -243,8 +246,8 @@ def handle(self, serder, attachments=None): attachments (list): list of tuples of pather, CESR SAD path attachments to the exn event """ - logger.info("MS Note Hdlr: %s event SAID=%s", self.resource, serder.said) - logger.debug("MS Note Hdlr: EXN Body=\n%s\n", serder.pretty()) + logger.info("Notification for %s event SAID=%s", self.resource, serder.said) + logger.debug("EXN Body=\n%s\n", serder.pretty()) self.mux.add(serder=serder) diff --git a/src/keri/app/storing.py b/src/keri/app/storing.py index 0e45125bc..f817b67fc 100644 --- a/src/keri/app/storing.py +++ b/src/keri/app/storing.py @@ -224,8 +224,8 @@ def responseDo(self, tymth=None, tock=0.0): # sign the exn to get the signature eattach = senderHab.endorse(exn, last=False, pipelined=False) del eattach[:exn.size] - logger.info("Respondant: sending exn on %s from %s to %s", topic, sender, recipient) - logger.debug("Respondant: exn body=\n%s\n", exn.pretty()) + logger.info("Sending exn on %s from %s to %s", topic, sender, recipient) + logger.debug("exn body=\n%s\n", exn.pretty()) self.postman.send(recipient, topic=topic, serder=exn, hab=forwardHab, attachment=eattach) yield self.tock # throttle just do one cue at a time diff --git a/src/keri/core/eventing.py b/src/keri/core/eventing.py index c142a5e11..96e80189c 100644 --- a/src/keri/core/eventing.py +++ b/src/keri/core/eventing.py @@ -2318,13 +2318,14 @@ def valSigsWigsDel(self, serder, sigers, verfers, tholder, # each wiger now has added to it a werfer of its wit in its .verfer property # escrow if not fully signed vs signing threshold + pre = self.prefixer.qb64 if not tholder.satisfy(indices): # at least one but not enough self.escrowPSEvent(serder=serder, sigers=sigers, wigers=wigers, seqner=delseqner, saider=delsaider, local=local) - msg = (f"[{self.prefixer.qb64[:8]}] Failure satisfying sith = {tholder.sith} " + msg = (f"AID {pre[:4]}...{pre[-4:]}: Failure satisfying sith = {tholder.sith} " f"on sigs {[siger.qb64 for siger in sigers]} " f"for evt = {serder.said}") - logger.trace("Kever: %s", msg) + logger.trace(msg) logger.trace("Event Body=\n%s\n", serder.pretty()) raise MissingSignatureError(msg) @@ -2337,10 +2338,10 @@ def valSigsWigsDel(self, serder, sigers, verfers, tholder, self.escrowPSEvent(serder=serder, sigers=sigers, wigers=wigers, seqner=delseqner, saider=delsaider,local=local) msg = ( - f"[{self.prefixer.qb64[:8]}] Failure satisfying prior nsith = {self.ntholder.sith} " + f"AID {pre[:4]}...{pre[-4:]}: Failure satisfying prior nsith = {self.ntholder.sith} " f"with exposed sigs {[siger.qb64 for siger in sigers]} " f"for new est evt={serder.said}") - logger.trace("Kever: %s", msg) + logger.trace(msg) logger.trace("Event Body=\n%s\n", serder.pretty()) raise MissingSignatureError(msg) @@ -2370,10 +2371,10 @@ def valSigsWigsDel(self, serder, sigers, verfers, tholder, local=local): # cue to query for witness receipts self.cues.push(dict(kin="query", q=dict(pre=serder.pre, sn=serder.snh))) - msg = (f"[{self.prefixer.qb64[:8]}] Failure satisfying toad={toader.num} " + msg = (f"AID {pre[:4]}...{pre[-4:]}: Failure satisfying toad={toader.num} " f"on witness sigs {[siger.qb64 for siger in wigers]} " f"for event={serder.said}") - logger.info("Kever: %s", msg) + logger.info(msg) logger.debug("Event Body=\n%s\n", serder.pretty()) raise MissingWitnessSignatureError(msg) @@ -2397,7 +2398,7 @@ def valSigsWigsDel(self, serder, sigers, verfers, tholder, self.escrowDelegableEvent(serder=serder, sigers=sigers, wigers=wigers, local=local) msg = f"Missing approval for delegation by {delpre} of event = {serder.said}" - logger.info("Kever: %s", msg) + logger.info(msg) logger.debug("Event Body=\n%s\n", serder.pretty()) raise MissingDelegableApprovalError(msg) @@ -2756,7 +2757,7 @@ def validateDelegation(self, serder, sigers, wigers, wits, delpre, *, self.escrowPDEvent(serder=serder, sigers=sigers, wigers=wigers, seqner=delseqner, saider=delsaider, local=local) msg = f"Missing KEL of delegator {delpre} of evt {serder.sn} {serder.ilk} {serder.said}" - logger.info("Kever: %s", msg) + logger.info(msg) logger.debug("Event Body=\n%s\n", serder.pretty()) raise MissingDelegationError(msg) @@ -2765,7 +2766,7 @@ def validateDelegation(self, serder, sigers, wigers, wits, delpre, *, if dkever.doNotDelegate: # drop event if delegation not allowed msg = (f"Delegator {delpre} does not allow delegation on evt " f"{serder.sn} {serder.ilk} {serder.said}") - logger.info("Kever: %s", msg) + logger.info(msg) logger.debug("Event Body=\n%s\n", serder.pretty()) raise ValidationError(msg) @@ -2784,7 +2785,7 @@ def validateDelegation(self, serder, sigers, wigers, wits, delpre, *, seqner=delseqner, saider=delsaider, local=local) msg = (f"No delegation seal for delegator {delpre} on evt " f"{serder.sn} {serder.ilk} {serder.said}") - logger.info("Kever: %s", msg) + logger.info(msg) logger.debug("Event Body=\n%s\n", serder.pretty()) raise MissingDelegationError(msg) @@ -2814,7 +2815,7 @@ def validateDelegation(self, serder, sigers, wigers, wits, delpre, *, seqner=delseqner, saider=delsaider, local=local) msg = (f"No delegating event from {delpre} at {delsaider.qb64} for evt " f"{serder.sn} {serder.ilk} {serder.said}") - logger.info("Kever: %s", msg) + logger.info(msg) logger.debug("Event Body=\n%s\n", serder.pretty()) raise MissingDelegationError(msg) @@ -2825,7 +2826,7 @@ def validateDelegation(self, serder, sigers, wigers, wits, delpre, *, if raw is None: # drop event should never happen unless database is broken msg = (f"Missing delegation from {delpre} at event dig = {ddig} for evt " f"{serder.sn} {serder.ilk} {serder.said}") - logger.info("Kever: %s", msg) + logger.info(msg) logger.debug("Event Body=\n%s\n", serder.pretty()) raise ValidationError(msg) @@ -2853,7 +2854,7 @@ def validateDelegation(self, serder, sigers, wigers, wits, delpre, *, seqner=delseqner, saider=delsaider, local=local) msg = (f"No delegation seal for delegator {delpre} of evt " f"{serder.sn} {serder.ilk} {serder.said}") - logger.info("Kever: %s", msg) + logger.info(msg) logger.debug("Event Body=\n%s\n", serder.pretty()) raise MissingDelegationError(msg) @@ -2899,7 +2900,7 @@ def validateDelegation(self, serder, sigers, wigers, wits, delpre, *, seqner=delseqner, saider=delsaider, local=local) msg = (f"No delegating event from {delpre} at {delsaider.qb64} for evt " f"{serder.sn} {serder.ilk} {serder.said}") - logger.info("Kever: %s", msg) + logger.info(msg) logger.debug("Event Body=\n%s\n", serder.pretty()) raise MissingDelegationError(msg) # already have new potential superseding delegation @@ -2936,7 +2937,7 @@ def validateDelegation(self, serder, sigers, wigers, wits, delpre, *, # ToDo: XXXX may want to cue up business logic for delegator # if self.mine(delegator): # failed attempt at recovery msg = f"Invalid delegation recovery rotation of {serfo.pre} by {serfn.pre}" - logger.info("Kever: %s", msg) + logger.info(msg) logger.debug("Delegate Event Body=\n%s\n", serfo.pretty()) logger.debug("Delegator Event Body=\n%s\n", serfn.pretty()) raise ValidationError(msg) @@ -2950,7 +2951,7 @@ def validateDelegation(self, serder, sigers, wigers, wits, delpre, *, seqner=delseqner, saider=delsaider, local=local) msg = (f"No delegating event from {delpre} at {delsaider.qb64} for evt " f"{serder.sn} {serder.ilk} {serder.said}") - logger.info("Kever: %s", msg) + logger.info(msg) logger.debug("Event Body=\n%s\n", serder.pretty()) raise MissingDelegationError(msg) serfo = bosso @@ -2961,7 +2962,7 @@ def validateDelegation(self, serder, sigers, wigers, wits, delpre, *, seqner=delseqner, saider=delsaider, local=local) msg = (f"No delegating event from {delpre} at {delsaider.qb64} for evt " f"{serder.sn} {serder.ilk} {serder.said}") - logger.info("Kever: %s", msg) + logger.info(msg) logger.debug("Event Body=\n%s\n", serder.pretty()) raise MissingDelegationError(msg) # repeat @@ -3050,7 +3051,7 @@ def fetchDelegatingEvent(self, delpre, serder, *, original=True, eager=False): if not (raw := self.db.getEvt(ddgkey)): # in fons but no event # database broken this should never happen msg = f"Missing delegation event for {serder.said}" - logger.info("Kever: %s", msg) + logger.info(msg) logger.debug("Event Body=\n%s\n", serder.pretty()) raise ValidationError(msg) # original delegating event i.e. boss original @@ -3066,9 +3067,9 @@ def fetchDelegatingEvent(self, delpre, serder, *, original=True, eager=False): # since original must have been validated so it must have # all its delegation chain. msg = f"Missing delegation source seal for {serder.said}" - logger.info("Kever: %s", msg) + logger.info(msg) logger.debug("Event Body=\n%s\n", serder.pretty()) - raise ValidationError(f"Missing delegation source seal for {serder.ked}") + raise ValidationError(msg) else: # only search last events in delegator's kel if not (dserder := self.db.fetchLastSealingEventByEventSeal(pre=delpre, seal=seal)): @@ -3165,6 +3166,7 @@ def logEvent(self, serder, sigers=None, wigers=None, wits=None, first=False, esr = basing.EventSourceRecord(local=local) self.db.esrs.put(keys=dgkeys, val=esr) + pre = self.prefixer.qb64 if first: # append event dig to first seen database in order fn = self.db.appendFe(serder.preb, serder.saidb) if firner and fn != firner.sn: # cloned replay but replay fn not match @@ -3179,13 +3181,13 @@ 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.debug("Kever [%.8s]: First seen %s %s SAID=%s for %s at %s", - self.prefixer.qb64, fn, serder.ilk, serder.said, + logger.debug("[AID %s...%s]: First seen %s at sn=%s valid event SAID=%s for %s at %s", + pre[:4], pre[-4:], serder.ilk, fn, 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 [%.8s]: Added to KEL %s at sn=%s valid event SAID=%s for AID %s", - self.prefixer.qb64, serder.ilk, serder.sn, serder.said, serder.pre) + 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) @@ -3860,7 +3862,7 @@ def processEvent(self, serder, sigers, *, wigers=None, else: # escrow likely duplicitous event self.escrowLDEvent(serder=serder, sigers=sigers) msg = f"Likely Duplicitous Event sn={serder.sn} type={serder.ilk} SAID={serder.said}" - logger.debug("Kevery: %s", msg) + logger.debug(msg) logger.debug("Duplicitous event body=\n%s\n", serder.pretty()) raise LikelyDuplicitousError(msg) @@ -3873,7 +3875,7 @@ def processEvent(self, serder, sigers, *, wigers=None, self.escrowOOEvent(serder=serder, sigers=sigers, seqner=delseqner, saider=delsaider, wigers=wigers, local=local) msg = f"Out-of-order event sn={serder.sn} type={serder.ilk} SAID={serder.said}" - logger.debug("Kevery: %s", msg) + logger.debug(msg) logger.debug("Out-of-order event body=\n%s\n", serder.pretty()) raise OutOfOrderError(msg) @@ -3945,7 +3947,7 @@ def processEvent(self, serder, sigers, *, wigers=None, else: # escrow likely duplicitous event self.escrowLDEvent(serder=serder, sigers=sigers) msg = f"Likely Duplicitous Event sn={serder.sn} type={serder.ilk} SAID={serder.said}" - logger.debug("Kevery: %s", msg) + logger.debug(msg) logger.debug("Duplicitous event body=\n%s\n", serder.pretty()) raise LikelyDuplicitousError(msg) @@ -3993,7 +3995,7 @@ def processReceiptWitness(self, serder, wigers, local=None): if not lserder.compare(said=ked["d"]): # stale receipt at sn discard msg = f"Stale receipt at sn = {ked['s']} for rct = {serder.said}." - logger.info("Kevery: %s", msg) + logger.info(msg) logger.debug("Stale receipt event body=\n%s\n", serder.pretty()) raise ValidationError(msg) @@ -4029,7 +4031,7 @@ def processReceiptWitness(self, serder, wigers, local=None): # get digest from receipt message not receipted event self.escrowUWReceipt(serder=serder, wigers=wigers, said=ked["d"]) msg = f"Unverified witness receipt={serder.said}" - logger.info("Kevery: %s", msg) + logger.info(msg) logger.debug("Event=\n%s\n", serder.pretty()) raise UnverifiedWitnessReceiptError(msg) @@ -4113,7 +4115,7 @@ def processReceipt(self, serder, cigars, local=None): else: # no events to be receipted yet at that sn so escrow self.escrowUReceipt(serder, cigars, said=ked["d"]) # digest in receipt msg = f"Unverified receipt = {serder.said}" - logger.info("Kevery: %s", msg) + logger.info(msg) logger.debug("event=\n%s\n", serder.pretty()) raise UnverifiedReceiptError(msg) @@ -4403,7 +4405,7 @@ def processAttachedReceiptQuadruples(self, serder, trqs, firner=None, local=None self.escrowTRQuadruple(serder, sprefixer, sseqner, saider, siger) msg = (f"Unverified receipt: missing associated event for transferable validator" f"receipt quadruple for event {serder.said}") - logger.info("Kevery: %s", msg) + logger.info(msg) logger.debug("Event=\n%s\n", serder.pretty()) raise UnverifiedTransferableReceiptError(msg) @@ -4950,7 +4952,7 @@ def processQuery(self, serder, source=None, sigers=None, cigars=None): if pre not in self.kevers: self.escrowQueryNotFoundEvent(serder=serder, prefixer=source, sigers=sigers, cigars=cigars) msg = f"Query not found error on event route={route} SAID={serder.said}" - logger.debug("Kevery: %s", msg) + logger.debug(msg) logger.debug("Query Body=\n%s\n", serder.pretty()) raise QueryNotFoundError(msg) @@ -4959,7 +4961,7 @@ def processQuery(self, serder, source=None, sigers=None, cigars=None): if not self.db.fetchAllSealingEventByEventSeal(pre=pre, seal=anchor): self.escrowQueryNotFoundEvent(serder=serder, prefixer=source, sigers=sigers, cigars=cigars) msg = f"Query not found error on event route={route} SAID={serder.said}" - logger.debug("Kevery: %s", msg) + logger.debug(msg) logger.debug("Query Body=\n%s\n", serder.pretty()) raise QueryNotFoundError(msg) @@ -4967,7 +4969,7 @@ def processQuery(self, serder, source=None, sigers=None, cigars=None): if kever.sner.num < sn or not self.db.fullyWitnessed(kever.serder): self.escrowQueryNotFoundEvent(serder=serder, prefixer=source, sigers=sigers, cigars=cigars) msg = f"Query not found error on event route={route} SAID={serder.said}" - logger.debug("Kevery: %s", msg) + logger.debug(msg) logger.debug("Query Body=\n%s\n", serder.pretty()) raise QueryNotFoundError(msg) @@ -4990,7 +4992,7 @@ def processQuery(self, serder, source=None, sigers=None, cigars=None): if pre not in self.kevers: self.escrowQueryNotFoundEvent(serder=serder, prefixer=source, sigers=sigers, cigars=cigars) msg = f"Query not found error on event route={route} SAID={serder.said}" - logger.debug("Kevery: %s", msg) + logger.debug(msg) logger.debug("Query Body=\n%s\n", serder.pretty()) raise QueryNotFoundError(msg) @@ -5031,7 +5033,7 @@ def processQuery(self, serder, source=None, sigers=None, cigars=None): else: self.cues.push(dict(kin="invalid", serder=serder)) msg = f"Invalid query message {ilk} for event route={route} SAID={serder.said}" - logger.info("Kevery: %s", msg) + logger.info(msg) logger.debug("Query Body=\n%s\n", serder.pretty()) raise ValidationError(msg) @@ -5540,7 +5542,7 @@ def processEscrowOutOfOrders(self): # duplicitous so we process remaining escrows in spite of found # valid event escrow. self.db.delOoe(snKey(pre, sn), edig) # removes one escrow at key val - logger.info("Kevery OOO unescrow succeeded in valid event: " + logger.info("Kevery out of order unescrow succeeded in valid event: " "event=%s", eserder.said) logger.debug("Event=\n%s\n", eserder.pretty()) @@ -5593,7 +5595,7 @@ def processEscrowPartialSigs(self): dgkey = dgKey(pre, bytes(edig)) if not (esr := self.db.esrs.get(keys=dgkey)): # get event source, otherwise error # no local source so raise ValidationError which unescrows below - msg = f"PS Missing escrowed event source at dig = {bytes(edig)}" + msg = f"PSE Missing escrowed event source at dig = {bytes(edig)}" logger.info("Kevery unescrow error: %s", msg) raise ValidationError(msg) @@ -5601,7 +5603,7 @@ def processEscrowPartialSigs(self): dtb = self.db.getDts(dgkey) if dtb is None: # othewise is a datetime as bytes # no date time so raise ValidationError which unescrows below - msg = f"PS Missing escrowed event datetime at dig = {bytes(edig)}" + msg = f"PSE Missing escrowed event datetime at dig = {bytes(edig)}" logger.trace("Kevery unescrow error: %s", msg) raise ValidationError(msg) @@ -5610,7 +5612,7 @@ def processEscrowPartialSigs(self): dte = helping.fromIso8601(bytes(dtb)) if (dtnow - dte) > datetime.timedelta(seconds=self.TimeoutPSE): # escrow stale so raise ValidationError which unescrows below - msg = f"PS Stale event escrow at dig = {bytes(edig)}" + msg = f"PSE Stale event escrow at dig = {bytes(edig)}" logger.trace("Kevery unescrow error: %s", msg) raise ValidationError(msg) @@ -5618,7 +5620,7 @@ def processEscrowPartialSigs(self): eraw = self.db.getEvt(dgkey) if eraw is None: # no event so so raise ValidationError which unescrows below - msg = f"PS Missing escrowed evt at dig = {bytes(edig)}" + msg = f"PSE Missing escrowed evt at dig = {bytes(edig)}" logger.trace("Kevery unescrow error: %s", msg) raise ValidationError(msg) @@ -5627,7 +5629,7 @@ def processEscrowPartialSigs(self): sigs = self.db.getSigs(dgkey) if not sigs: # otherwise its a list of sigs # no sigs so raise ValidationError which unescrows below - msg = f"PS Missing escrowed evt sigs at dig = {bytes(edig)}" + msg = f"PSE Missing escrowed evt sigs at dig = {bytes(edig)}" logger.trace("Kevery unescrow error: %s", msg) raise ValidationError(msg) wigs = self.db.getWigs(dgKey(pre, bytes(edig))) # list of wigs @@ -5684,8 +5686,8 @@ def processEscrowPartialSigs(self): # still waiting on missing sigs or missing seal to validate # processEvent idempotently reescrowed if logger.isEnabledFor(logging.TRACE): - logger.trace("Kevery: partial sig escrow unescrow failed: %s\n", ex.args[0]) - logger.exception("Kevery: partial sig escrow unescrow failed: %s\n", ex.args[0]) + logger.trace("Kevery: PSE unescrow failed: %s\n", ex.args[0]) + logger.exception("Kevery: PSE unescrow failed: %s\n", ex.args[0]) except Exception as ex: # log diagnostics errors etc # error other than waiting on sigs so remove from escrow @@ -5696,9 +5698,9 @@ def processEscrowPartialSigs(self): self.cues.push(dict(kin="psUnescrow", serder=eserder)) if logger.isEnabledFor(logging.DEBUG): - logger.trace("Kevery: partial sig escrow other error on unescrow: %s\n", + logger.trace("Kevery: PSE other error on unescrow: %s\n", ex.args[0]) - logger.exception("Kevery: partial sig escrow other error on unescrow: %s\n", + logger.exception("Kevery: PSE other error on unescrow: %s\n", ex.args[0]) else: # unescrow succeeded, remove from escrow @@ -5761,7 +5763,7 @@ def processEscrowPartialWigs(self): dgkey = dgKey(pre, bytes(edig)) if not (esr := self.db.esrs.get(keys=dgkey)): # get event source, otherwise error # no local source so raise ValidationError which unescrows below - msg = f"PW Missing escrowed event source at dig = {bytes(edig)}" + msg = f"PWE Missing escrowed event source at dig = {bytes(edig)}" logger.info("Kevery unescrow error: %s", msg) raise ValidationError(msg) @@ -5769,7 +5771,7 @@ def processEscrowPartialWigs(self): dtb = self.db.getDts(dgkey) if dtb is None: # othewise is a datetime as bytes # no date time so raise ValidationError which unescrows below - msg = f"PW Missing escrowed event datetime at dig = {bytes(edig)}" + msg = f"PWE Missing escrowed event datetime at dig = {bytes(edig)}" logger.trace("Kevery unescrow error: %s", msg) raise ValidationError(msg) @@ -5778,7 +5780,7 @@ def processEscrowPartialWigs(self): dte = helping.fromIso8601(bytes(dtb)) if (dtnow - dte) > datetime.timedelta(seconds=self.TimeoutPWE): # escrow stale so raise ValidationError which unescrows below - msg = f"PW Stale event escrow at dig = {bytes(edig)}" + msg = f"PWE Stale event escrow at dig = {bytes(edig)}" logger.trace("Kevery unescrow error: %s", msg) raise ValidationError(msg) @@ -5786,7 +5788,7 @@ def processEscrowPartialWigs(self): eraw = self.db.getEvt(dgKey(pre, bytes(edig))) if eraw is None: # no event so so raise ValidationError which unescrows below - msg = f"PW Missing escrowed evt at dig = {bytes(edig)}" + msg = f"PWE Missing escrowed evt at dig = {bytes(edig)}" logger.trace("Kevery unescrow error: %s", msg) raise ValidationError(msg) @@ -5796,7 +5798,7 @@ def processEscrowPartialWigs(self): sigs = self.db.getSigs(dgKey(pre, bytes(edig))) # list of sigs if not sigs: # empty list # no sigs so raise ValidationError which unescrows below - msg = f"PW Missing escrowed evt sigs at dig = {bytes(edig)}" + msg = f"PWE Missing escrowed evt sigs at dig = {bytes(edig)}" logger.trace("Kevery unescrow error: %s", msg) raise ValidationError(msg) @@ -5862,17 +5864,17 @@ def processEscrowPartialWigs(self): # still waiting on missing witness sigs or delegation # processEvent idempotently reescrowed if logger.isEnabledFor(logging.TRACE): - logger.trace("Kevery: partial wig escrow unescrow failed: %s\n", ex.args[0]) - logger.exception("Kevery: partial wig escrow unescrow failed: %s\n", ex.args[0]) + logger.trace("Kevery: PWE unescrow failed: %s\n", ex.args[0]) + logger.exception("Kevery: PWE unescrow failed: %s\n", ex.args[0]) except Exception as ex: # log diagnostics errors etc # error other than waiting on wigs so remove from escrow self.db.delPwe(snKey(pre, sn), edig) # removes one escrow at key val #self.db.udes.rem(keys=dgkey) # leave here since could PartialDelegationEscrow if logger.isEnabledFor(logging.TRACE): - logger.trace("Kevery: partial wig escrow other error on unescrow: %s\n", + logger.trace("Kevery: PWE other error on unescrow: %s\n", ex.args[0]) - logger.exception("Kevery: partial wig escrow other error unescrow: %s\n", + logger.exception("Kevery: PWE other error unescrow: %s\n", ex.args[0]) else: # unescrow succeeded, remove from escrow @@ -5919,7 +5921,7 @@ def processEscrowPartialDels(self): dgkey = dgKey(epre, edig) if not (esr := self.db.esrs.get(keys=dgkey)): # get event source, otherwise error # no local source so raise ValidationError which unescrows below - msg = f"PD Missing escrowed event source at dig = {bytes(edig)}" + msg = f"PDE Missing escrowed event source at dig = {bytes(edig)}" logger.info("Kevery unescrow error: %s", msg) raise ValidationError(msg) @@ -5927,7 +5929,7 @@ def processEscrowPartialDels(self): dtb = self.db.getDts(dgkey) if dtb is None: # othewise is a datetime as bytes # no date time so raise ValidationError which unescrows below - msg = f"PD Missing escrowed event datetime at dig = {bytes(edig)}" + msg = f"PDE Missing escrowed event datetime at dig = {bytes(edig)}" logger.info("Kevery unescrow error: %s", msg) raise ValidationError(msg) @@ -5936,7 +5938,7 @@ def processEscrowPartialDels(self): dte = helping.fromIso8601(bytes(dtb)) if (dtnow - dte) > datetime.timedelta(seconds=self.TimeoutPWE): # escrow stale so raise ValidationError which unescrows below - msg = f"PD Stale event escrow at dig = {bytes(edig)}" + msg = f"PDE Stale event escrow at dig = {bytes(edig)}" logger.info("Kevery unescrow error: %s", msg) raise ValidationError(msg) @@ -5944,7 +5946,7 @@ def processEscrowPartialDels(self): eraw = self.db.getEvt(dgkey) if eraw is None: # no event so so raise ValidationError which unescrows below - msg = f"PD Missing escrowed evt at dig = {bytes(edig)}" + msg = f"PDE Missing escrowed evt at dig = {bytes(edig)}" logger.info("Kevery unescrow error: %s", msg) raise ValidationError(msg) @@ -5954,7 +5956,7 @@ def processEscrowPartialDels(self): sigs = self.db.getSigs(dgkey) # list of sigs if not sigs: # empty list # no sigs so raise ValidationError which unescrows below - msg = f"PD Missing escrowed evt sigs at dig = {bytes(edig)}" + msg = f"PDE Missing escrowed evt sigs at dig = {bytes(edig)}" logger.info("Kevery unescrow error: %s", bytes(edig)) raise ValidationError(msg) @@ -6023,7 +6025,7 @@ def processEscrowPartialDels(self): # still waiting on missing delegation source seal # processEvent idempotently reescrowed if logger.isEnabledFor(logging.DEBUG): - logger.exception("Kevery unescrow failed: %s", ex.args[0]) + logger.exception("Kevery PDE unescrow failed: %s", ex.args[0]) except Exception as ex: # log diagnostics errors etc # error other than waiting on sigs or seal so remove from escrow @@ -6031,9 +6033,9 @@ def processEscrowPartialDels(self): self.db.pdes.remOn(keys=epre, on=esn, val=edig) # event idx escrow self.db.udes.rem(keys=dgkey) # remove source seal escrow if any if logger.isEnabledFor(logging.DEBUG): - logger.exception("Kevery unescrowed: %s", ex.args[0]) + logger.exception("Kevery PDE unescrowed: %s", ex.args[0]) else: - logger.error("Kevery unescrowed: %s", ex.args[0]) + logger.error("Kevery PDE unescrowed: %s", ex.args[0]) else: # unescrow succeeded, remove from escrow # We don't remove all escrows at pre,sn because some might be @@ -6042,7 +6044,7 @@ def processEscrowPartialDels(self): # removes one event escrow at key val self.db.pdes.remOn(keys=epre, on=esn, val=edig) # event idx escrow self.db.udes.rem(keys=dgkey) # remove source seal escrow if any - logger.info("Kevery PD unescrow succeeded in valid event: " + logger.info("Kevery partial delegation escrow unescrow succeeded in valid event: " "event=%s", eserder.said) logger.debug("Event=\n%s\n", eserder.pretty()) @@ -6223,7 +6225,7 @@ def processEscrowUnverNonTrans(self): dtb = self.db.getDts(dgKey(pre, bytes(rsaider.qb64b))) if dtb is None: # othewise is a datetime as bytes # no date time so raise ValidationError which unescrows below - msg = f"UNT Missing escrowed event datetime at dig = {rsaider.qb64b}" + msg = f"URE Missing escrowed event datetime at dig = {rsaider.qb64b}" logger.trace("Kevery unescrow error: %s", msg) raise ValidationError(msg) @@ -6232,7 +6234,7 @@ def processEscrowUnverNonTrans(self): dte = helping.fromIso8601(bytes(dtb)) if (dtnow - dte) > datetime.timedelta(seconds=self.TimeoutURE): # escrow stale so raise ValidationError which unescrows below - msg = f"UNT Stale event escrow at dig = {rsaider.qb64b}" + msg = f"URE Stale event escrow at dig = {rsaider.qb64b}" logger.trace("Kevery unescrow error: %s", msg) raise ValidationError(msg) @@ -6251,14 +6253,14 @@ def processEscrowUnverNonTrans(self): dig = self.db.getKeLast(snKey(pre, sn)) if dig is None: # no receipted event so keep in escrow - msg = f"UNT Missing receipted evt at pre={pre} sn={sn:x}" + msg = f"URE Missing receipted evt at pre={pre} sn={sn:x}" logger.trace("Kevery unescrow error: %s", msg) raise UnverifiedReceiptError(msg) # get receipted event using pre and edig raw = self.db.getEvt(dgKey(pre, dig)) if raw is None: # receipted event superseded so remove from escrow - msg = f"UNT Invalid receipted event reference at pre={pre} sn={sn:x}" + msg = f"URE Invalid receipted event reference at pre={pre} sn={sn:x}" logger.trace("Kevery unescrow error: %s", msg) raise ValidationError(msg) @@ -6266,14 +6268,14 @@ def processEscrowUnverNonTrans(self): # compare digs if rsaider.qb64b != serder.saidb: - msg = f"UNT Bad escrowed receipt dig at pre={pre} sn={sn:x} receipter={sprefixer.qb64}" + msg = f"URE Bad escrowed receipt dig at pre={pre} sn={sn:x} receipter={sprefixer.qb64}" logger.trace("Kevery unescrow error: %s", msg) raise ValidationError(msg) # verify sig verfer key is prefixer from triple if not cigar.verfer.verify(cigar.raw, serder.raw): # no sigs so raise ValidationError which unescrows below - msg = f"UNT Bad escrowed receipt sig at pre={pre} sn={sn:x} receipter={sprefixer.qb64}" + msg = f"URE Bad escrowed receipt sig at pre={pre} sn={sn:x} receipter={sprefixer.qb64}" logger.trace("Kevery unescrow error: %s", msg) raise ValidationError(msg) @@ -6298,16 +6300,16 @@ def processEscrowUnverNonTrans(self): # still waiting on missing prior event to validate # only happens if we process above if logger.isEnabledFor(logging.TRACE): # adds exception data - logger.trace("Kevery: UNT escrow other error on unescrow: %s\n", ex.args[0]) - logger.exception("Kevery: UNT escrow other error on unescrow: %s\n", ex.args[0]) + logger.trace("Kevery: URE escrow other error on unescrow: %s\n", ex.args[0]) + logger.exception("Kevery: URE escrow other error on unescrow: %s\n", ex.args[0]) except Exception as ex: # log diagnostics errors etc # error other than out of order so remove from OO escrow self.db.delUre(snKey(pre, sn), etriplet) # removes one escrow at key val if logger.isEnabledFor(logging.DEBUG): # adds exception data - logger.exception("Kevery unescrowed: %s", ex.args[0]) + logger.exception("Kevery URE unescrowed: %s", ex.args[0]) else: - logger.error("Kevery unescrowed: %s", ex.args[0]) + logger.error("Kevery URE unescrowed: %s", ex.args[0]) else: # unescrow succeeded, remove from escrow # We don't remove all escrows at pre,sn because some might be @@ -6426,7 +6428,7 @@ def processEscrowDelegables(self): # duplicitous so we process remaining escrows in spite of found # valid event escrow. self.db.delegables.rem(keys=(pre, sn,), val=edig) # removes one escrow at key val - logger.info("Kevery DEL unescrow succeeded in valid event: " + logger.info("Kevery delegables escrow unescrow succeeded in valid event: " "event=%s", eserder.said) logger.debug("event=\n%s\n", eserder.pretty()) @@ -6533,7 +6535,7 @@ def processQueryNotFound(self): # duplicitous so we process remaining escrows in spite of found # valid event escrow. self.db.qnfs.rem(keys=(pre, said), val=edig) # removes one escrow at key val - logger.info("Kevery: QNF unescrow succeeded in valid event: " + logger.info("Kevery: query not found escrow unescrow succeeded in valid event: " "key = %s \tdigest = %s", ekey.decode(), edig) logger.debug("Event=\n%s\n", eserder.pretty()) @@ -6703,7 +6705,7 @@ def processEscrowUnverTrans(self): dtb = self.db.getDts(dgKey(pre, bytes(esaider.qb64b))) if dtb is None: # othewise is a datetime as bytes # no date time so raise ValidationError which unescrows below - msg = f"UVT Missing escrowed event datetime at dig = {esaider.qb64b}" + msg = f"VRE Missing escrowed event datetime at dig = {esaider.qb64b}" logger.trace("Kevery unescrow error: %s", msg) raise ValidationError(msg) @@ -6712,7 +6714,7 @@ def processEscrowUnverTrans(self): dte = helping.fromIso8601(bytes(dtb)) if (dtnow - dte) > datetime.timedelta(seconds=self.TimeoutVRE): # escrow stale so raise ValidationError which unescrows below - msg = f"UVT Stale event escrow at dig = {esaider.qb64b}" + msg = f"VRE Stale event escrow at dig = {esaider.qb64b}" logger.trace("Kevery unescrow error: %s", msg) raise ValidationError(msg) @@ -6720,7 +6722,7 @@ def processEscrowUnverTrans(self): raw = self.db.getKeLast(snKey(pre, sn)) if raw is None: # no event so keep in escrow - msg = f"UVT Missing receipted evt at pre={pre} sn={sn:x}" + msg = f"VRE Missing receipted evt at pre={pre} sn={sn:x}" logger.trace("Kevery unescrow error: %s", msg) raise UnverifiedTransferableReceiptError(msg) @@ -6728,7 +6730,7 @@ def processEscrowUnverTrans(self): # get receipted event using pre and edig raw = self.db.getEvt(dgKey(pre, dig)) if raw is None: # receipted event superseded so remove from escrow - msg = f"UVT Invalid receipted evt reference at pre={pre} sn={sn:x}" + msg = f"VRE Invalid receipted evt reference at pre={pre} sn={sn:x}" logger.trace("Kevery unescrow error: %s", msg) raise ValidationError(msg) @@ -6736,7 +6738,7 @@ def processEscrowUnverTrans(self): # compare digs if esaider.qb64b != serder.saidb: - msg = f"UVT Bad escrowed receipt dig at pre={pre} sn={sn:x} receipter={sprefixer.qb64}" + msg = f"VRE Bad escrowed receipt dig at pre={pre} sn={sn:x} receipter={sprefixer.qb64}" logger.trace("Kevery unescrow error: %s", msg) raise ValidationError(msg) @@ -6746,7 +6748,7 @@ def processEscrowUnverTrans(self): sn=sseqner.sn)) if sdig is None: # no event so keep in escrow - msg = f"UVT Missing receipted evt at pre={pre} sn={sn:x}" + msg = f"VRE Missing receipted evt at pre={pre} sn={sn:x}" logger.trace("Kevery unescrow error: %s", msg) raise UnverifiedTransferableReceiptError(msg) @@ -6756,14 +6758,14 @@ def processEscrowUnverTrans(self): sserder = serdering.SerderKERI(raw=bytes(sraw)) if not sserder.compare(said=ssaider.qb64): # seal dig not match event # this unescrows - msg = f"UVT Bad chit seal at sn = {sseqner.sn} for rct = {sserder.ked}" + msg = f"VRE Bad chit seal at sn = {sseqner.sn} for rct = {sserder.ked}" logger.info("Kevery unescrow error: %s", msg) raise ValidationError(msg) # verify sigs and if so write quadruple to database verfers = sserder.verfers if not verfers: - msg = (f"UVT Invalid seal est. event dig = {ssaider.qb64} " + msg = (f"VRE Invalid seal est. event dig = {ssaider.qb64} " f"for receipt from pre = {sprefixer.qb64} no keys") logger.info("Kevery unescrow error: %s", msg) raise ValidationError(msg) @@ -6772,13 +6774,13 @@ def processEscrowUnverTrans(self): sealet = sprefixer.qb64b + sseqner.qb64b + ssaider.qb64b if siger.index >= len(verfers): - msg = f"UVT Index = {siger.index} too large for keys" + msg = f"VRE Index = {siger.index} too large for keys" logger.info("Kevery unescrow error: %s", msg) raise ValidationError(msg) siger.verfer = verfers[siger.index] # assign verfer if not siger.verfer.verify(siger.raw, serder.raw): # verify sig - msg = f"UVT Bad escrowed trans receipt sig at pre={pre} sn={sn:x} receipter={sprefixer.qb64}" + msg = f"VRE Bad escrowed trans receipt sig at pre={pre} sn={sn:x} receipter={sprefixer.qb64}" logger.trace("Kevery unescrow error: %s", msg) raise ValidationError(msg) @@ -6791,22 +6793,22 @@ def processEscrowUnverTrans(self): # still waiting on missing prior event to validate # only happens if we process above if logger.isEnabledFor(logging.TRACE): # adds exception data - logger.trace("Kevery: UVT escrow unescrow failed: %s\n", ex.args[0]) - logger.exception("Kevery: UVT escrow unescrow failed: %s\n", ex.args[0]) + logger.trace("Kevery: VRE escrow unescrow failed: %s\n", ex.args[0]) + logger.exception("Kevery: VRE escrow unescrow failed: %s\n", ex.args[0]) except Exception as ex: # log diagnostics errors etc # error other than out of order so remove from OO escrow self.db.delVre(snKey(pre, sn), equinlet) # removes one escrow at key val if logger.isEnabledFor(logging.DEBUG): # adds exception data - logger.debug("Kevery: UVT escrow other error on unescrow: %s\n", ex.args[0]) - logger.exception("Kevery: UVT escrow other error on unescrow: %s\n", ex.args[0]) + logger.debug("Kevery: VRE escrow other error on unescrow: %s\n", ex.args[0]) + logger.exception("Kevery: VRE escrow other error on unescrow: %s\n", ex.args[0]) else: # unescrow succeeded, remove from escrow # We don't remove all escrows at pre,sn because some might be # 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 UVT unescrow succeeded for event = %s", serder.said) + logger.info("Kevery VRE unescrow succeeded for event = %s", serder.said) logger.debug("Event=\n%s\n", serder.pretty()) if ekey == key: # still same so no escrows found on last while iteration @@ -6931,7 +6933,7 @@ def processEscrowDuplicitous(self): # duplicitous so we process remaining escrows in spite of found # valid event escrow. self.db.delLde(snKey(pre, sn), edig) # removes one escrow at key val - logger.info("Kevery DUP unescrow succeeded in valid event: event=%s", eserder.said) + logger.info("Kevery duplicitous escrow unescrow succeeded in valid event: event=%s", eserder.said) logger.debug("event=\n%s\n", eserder.pretty()) if ekey == key: # still same so no escrows found on last while iteration diff --git a/src/keri/core/parsing.py b/src/keri/core/parsing.py index 9d5cc2e65..98fe18e4b 100644 --- a/src/keri/core/parsing.py +++ b/src/keri/core/parsing.py @@ -443,9 +443,9 @@ def allParsator(self, ims=None, framed=None, pipeline=None, kvy=None, except kering.SizedGroupError as ex: # error inside sized group # processOneIter already flushed group so do not flush stream if logger.isEnabledFor(logging.DEBUG): - logger.exception("Parser msg extraction error: %s", ex.args[0]) + logger.exception("Parser sized group error: %s", ex.args[0]) else: - logger.error("Parser msg extraction error: %s", ex.args[0]) + logger.error("Parser sized group error: %s", ex.args[0]) except (kering.ColdStartError, kering.ExtractionError) as ex: # some extraction error if logger.isEnabledFor(logging.DEBUG): @@ -457,10 +457,10 @@ def allParsator(self, ims=None, framed=None, pipeline=None, kvy=None, except (kering.ValidationError, Exception) as ex: # non Extraction Error # Non extraction errors happen after successfully extracted from stream # so we don't flush rest of stream just resume + if logger.isEnabledFor(logging.TRACE): + logger.exception("Parser msg validation or non-extraction error: %s", ex) if logger.isEnabledFor(logging.DEBUG): - logger.exception("Parser msg non-extraction error: %s", ex) - else: - logger.error("Parser msg non-extraction error: %s", ex) + logger.error("Parser msg validation or non-extraction error: %s", ex) yield return True @@ -618,9 +618,9 @@ def parsator(self, ims=None, framed=None, pipeline=None, kvy=None, tvy=None, except kering.SizedGroupError as ex: # error inside sized group # processOneIter already flushed group so do not flush stream if logger.isEnabledFor(logging.DEBUG): - logger.exception("Parser msg extraction error: %s", ex.args[0]) + logger.exception("Parser sized group error: %s", ex.args[0]) else: - logger.error("Parser msg extraction error: %s", ex.args[0]) + logger.error("Parser sized group error: %s", ex.args[0]) except (kering.ColdStartError, kering.ExtractionError) as ex: # some extraction error if logger.isEnabledFor(logging.DEBUG): @@ -632,9 +632,9 @@ def parsator(self, ims=None, framed=None, pipeline=None, kvy=None, tvy=None, except (kering.ValidationError, Exception) as ex: # non Extraction Error # Non extraction errors happen after successfully extracted from stream # so we don't flush rest of stream just resume - if logger.isEnabledFor(logging.DEBUG): + if logger.isEnabledFor(logging.TRACE): logger.exception("Parser msg non-extraction error: %s", ex.args[0]) - else: + if logger.isEnabledFor(logging.DEBUG): logger.error("Parser msg non-extraction error: %s", ex.args[0]) yield @@ -1008,7 +1008,7 @@ def msgParsator(self, ims=None, framed=True, pipeline=False, delseqner, delsaider = sscs[-1] if sscs else (None, None) # use last one if more than one if not sigers: msg = f"Missing attached signature(s) for evt = {serder.ked['d']}" - logger.info("Parser: %s", msg) + logger.info(msg) logger.debug("Event Body = \n%s\n", serder.pretty()) raise kering.ValidationError(msg) try: @@ -1030,14 +1030,14 @@ def msgParsator(self, ims=None, framed=True, pipeline=False, except AttributeError as ex: msg = f"No kevery to process so dropped msg={serder.said}" - logger.info("Parser: %s", msg) + logger.info(msg) logger.debug("Event Body = \n%s\n", serder.pretty()) raise kering.ValidationError(msg) from ex elif ilk in [Ilks.rct]: # event receipt msg (nontransferable) if not (cigars or wigers or tsgs): msg = f"Missing attached signatures on receipt msg sn={serder.sn} SAID={serder.said}" - logger.info("Parser: %s", msg) + logger.info(msg) logger.debug("Receipt body=\n%s\n", serder.pretty()) raise kering.ValidationError(msg) diff --git a/src/keri/help/__init__.py b/src/keri/help/__init__.py index 42a477a11..a7bf9ad5a 100644 --- a/src/keri/help/__init__.py +++ b/src/keri/help/__init__.py @@ -28,16 +28,5 @@ def trace(self, message, *args, **kwargs): # want help.ogler always defined by default ogler = ogling.initOgler(prefix='keri', syslogged=False) # inits once only on first import -# set log formatters with detailed log output -logFmt = "%(asctime)s [keri] %(levelname)-8s %(message)s" -formatter = logging.Formatter(logFmt) - -ch = logging.StreamHandler() -ch.setFormatter(formatter) -ogler.baseConsoleHandler = ch -ogler.baseFormatter = formatter - -ogler.reopen(headDirPath=ogler.headDirPath) - from .helping import (nowIso8601, toIso8601, fromIso8601, nonStringSequence, nonStringIterable) diff --git a/src/keri/peer/exchanging.py b/src/keri/peer/exchanging.py index 3b4cba2b2..ee6f985d6 100644 --- a/src/keri/peer/exchanging.py +++ b/src/keri/peer/exchanging.py @@ -82,7 +82,7 @@ def processEvent(self, serder, tsgs=None, cigars=None, **kwargs): if sender != prefixer.qb64: # sig not by aid msg = (f"Skipped signature not from aid = " f"{sender}, from {prefixer.qb64} on exn msg = {serder.said}") - logger.info("Exchanger: %s", msg) + logger.info(msg) logger.debug("Exchange message body=\n%s\n", serder.pretty()) raise MissingSignatureError(msg) @@ -90,7 +90,7 @@ def processEvent(self, serder, tsgs=None, cigars=None, **kwargs): 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))) msg = f"Unable to find sender {prefixer.qb64} in kevers for evt = {serder.said}" - logger.info("Exchanger: %s", msg) + logger.info(msg) logger.debug("Exchange message body=\n%s\n", serder.pretty()) raise MissingSignatureError(msg) @@ -103,7 +103,7 @@ def processEvent(self, serder, tsgs=None, cigars=None, **kwargs): self.cues.append(dict(kin="query", q=dict(r="logs", pre=prefixer.qb64, sn=seqner.snh))) msg = (f"Not enough signatures in idx={indices} route={route} " f"for evt = {serder.said} recipient={serder.ked.get('rp', '')}") - logger.info("Exchanger: %s", msg) + logger.info(msg) logger.debug("Exchange message body=\n%s\n", serder.pretty()) raise MissingSignatureError(msg) @@ -112,14 +112,14 @@ def processEvent(self, serder, tsgs=None, cigars=None, **kwargs): if sender != cigar.verfer.qb64: # cig not by aid msg = (f"Skipped cig not from aid={sender} route={route} " f"for exn evt = {serder.said} recipient={serder.ked.get('rp', '')}") - logger.info("Exchanger: %s", msg) + logger.info(msg) logger.debug("Exchange message body=\n%s\n", serder.pretty()) raise MissingSignatureError(msg) if not cigar.verfer.verify(cigar.raw, serder.raw): # cig not verify msg = (f"Failure satisfying exn on cigs for {cigar} route={route} " f"for evt = {serder.said} recipient={serder.ked.get('rp', '')}") - logger.info("Exchanger: %s", msg) + logger.info(msg) logger.debug("Exchange message body=\n%s\n", serder.pretty()) raise MissingSignatureError(msg) else: @@ -127,7 +127,7 @@ def processEvent(self, serder, tsgs=None, cigars=None, **kwargs): msg = ( f"Failure satisfying exn, no cigs or sigs for evt = {serder.said} " f"on route {route} recipient = {serder.ked.get('rp', '')}") - logger.info("Exchanger: %s", msg) + logger.info(msg) logger.debug("Exchange message body=\n%s\n", serder.pretty()) raise MissingSignatureError(msg) @@ -555,7 +555,7 @@ def verify(hby, serder): for prefixer, seqner, ssaider, sigers in tsgs: if prefixer.qb64 not in hby.kevers or hby.kevers[prefixer.qb64].sn < seqner.sn: msg = f"Unable to find sender {prefixer.qb64} in kevers for evt = {serder.said}" - logger.info("exchanging.verify: %s", msg) + logger.info(msg) logger.debug("Exn Body=\n%s\n", serder.pretty()) raise MissingSignatureError(msg) @@ -565,7 +565,7 @@ def verify(hby, serder): if not tholder.satisfy(indices): # We still don't have all the sigers, need to escrow msg = f"Not enough signatures in idx={indices} for evt = {serder.said}" - logger.info("exchanging.verify: %s", msg) + logger.info(msg) logger.debug("Exn Body=\n%s\n", serder.pretty()) raise MissingSignatureError(msg) accepted = True @@ -574,14 +574,14 @@ def verify(hby, serder): for cigar in cigars: if not cigar.verfer.verify(cigar.raw, serder.raw): # cig not verify msg = f"Failure satisfying exn on cigs for {cigar} for evt = {serder.said}" - logger.info("exchanging.verify: %s", msg) + logger.info(msg) logger.debug("Exn Body=\n%s\n", serder.pretty()) raise MissingSignatureError(msg) accepted = True if not accepted: msg = f"No valid signatures stored for evt = {serder.said}" - logger.info("exchanging.verify: %s", msg) + logger.info(msg) logger.debug("Exn Body=\n%s\n", serder.pretty()) raise MissingSignatureError(msg) diff --git a/src/keri/vdr/eventing.py b/src/keri/vdr/eventing.py index aee554fe0..3f008bae2 100644 --- a/src/keri/vdr/eventing.py +++ b/src/keri/vdr/eventing.py @@ -1253,8 +1253,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 [reg=%.8s iss=%.8s]: Added to TEL valid %s event %s said=%s", - self.regk, self.pre, serder.ilk, pre.decode(), serder.said) + logger.info("Tever: Added to TEL valid %s event %s said=%s reg=%.8s iss=%.8s", + serder.ilk, pre.decode(), 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):