diff --git a/src/keri/app/agenting.py b/src/keri/app/agenting.py index b0b866726..2fd13cf49 100644 --- a/src/keri/app/agenting.py +++ b/src/keri/app/agenting.py @@ -273,7 +273,7 @@ class WitnessReceiptor(doing.DoDoer): """ - def __init__(self, hby, msgs=None, cues=None, force=False, **kwa): + def __init__(self, hby, msgs=None, cues=None, force=False, auths=None, **kwa): """ For the current event, gather the current set of witnesses, send the event, gather all receipts and send them to all other witnesses @@ -289,6 +289,7 @@ def __init__(self, hby, msgs=None, cues=None, force=False, **kwa): self.force = force self.msgs = msgs if msgs is not None else decking.Deck() self.cues = cues if cues is not None else decking.Deck() + self.auths = auths if auths is not None else dict() super(WitnessReceiptor, self).__init__(doers=[doing.doify(self.receiptDo)], **kwa) @@ -332,7 +333,8 @@ def receiptDo(self, tymth=None, tock=0.0): witers = [] for wit in wits: - witer = messenger(hab, wit) + auth = self.auths[wit] if wit in self.auths else None + witer = messenger(hab, wit, auth=auth) witers.append(witer) self.extend([witer]) @@ -836,7 +838,7 @@ class HTTPMessenger(doing.DoDoer): """ - def __init__(self, hab, wit, url, msgs=None, sent=None, doers=None, **kwa): + def __init__(self, hab, wit, url, msgs=None, sent=None, doers=None, auth=None, **kwa): """ For the current event, gather the current set of witnesses, send the event, gather all receipts and send them to all other witnesses @@ -851,6 +853,7 @@ def __init__(self, hab, wit, url, msgs=None, sent=None, doers=None, **kwa): self.msgs = msgs if msgs is not None else decking.Deck() self.sent = sent if sent is not None else decking.Deck() self.parser = None + self.auth = auth doers = doers if doers is not None else [] doers.extend([doing.doify(self.msgDo), doing.doify(self.responseDo)]) @@ -881,7 +884,11 @@ def msgDo(self, tymth=None, tock=0.0): yield self.tock msg = self.msgs.popleft() - self.posted += httping.streamCESRRequests(client=self.client, dest=self.wit, ims=msg) + headers = dict() + if self.auth is not None: + headers["Authorization"] = self.auth + + self.posted += httping.streamCESRRequests(client=self.client, dest=self.wit, ims=msg, headers=headers) while self.client.requests: yield self.tock @@ -983,34 +990,36 @@ def mailbox(hab, cid): return mbx -def messenger(hab, pre): +def messenger(hab, pre, auth=None): """ Create a Messenger (tcp or http) based on available endpoints Parameters: hab (Habitat): Environment to use to look up witness URLs pre (str): qb64 identifier prefix of recipient to create a messanger for + auth (str): optional auth code to send with any request for messenger Returns: Optional(TcpWitnesser, HTTPMessenger): witnesser for ensuring full reciepts """ urls = hab.fetchUrls(eid=pre) - return messengerFrom(hab, pre, urls) + return messengerFrom(hab, pre, urls, auth) -def messengerFrom(hab, pre, urls): +def messengerFrom(hab, pre, urls, auth=None): """ Create a Witnesser (tcp or http) based on provided endpoints Parameters: hab (Habitat): Environment to use to look up witness URLs pre (str): qb64 identifier prefix of recipient to create a messanger for urls (dict): map of schemes to urls of available endpoints + auth (str): optional auth code to send with any request for messenger Returns: Optional(TcpWitnesser, HTTPMessenger): witnesser for ensuring full reciepts """ if kering.Schemes.http in urls or kering.Schemes.https in urls: url = urls[kering.Schemes.http] if kering.Schemes.http in urls else urls[kering.Schemes.https] - witer = HTTPMessenger(hab=hab, wit=pre, url=url) + witer = HTTPMessenger(hab=hab, wit=pre, url=url, auth=auth) elif kering.Schemes.tcp in urls: url = urls[kering.Schemes.tcp] witer = TCPMessenger(hab=hab, wit=pre, url=url) diff --git a/src/keri/app/cli/commands/interact.py b/src/keri/app/cli/commands/interact.py index eedea2d0f..53cabce75 100644 --- a/src/keri/app/cli/commands/interact.py +++ b/src/keri/app/cli/commands/interact.py @@ -103,21 +103,22 @@ def interactDo(self, tymth, tock=0.0, **opts): hab = self.hby.habByName(name=self.alias) hab.interact(data=self.data) - if self.endpoint or self.authenticate: + auths = {} + if self.authenticate: + for wit in hab.kever.wits: + code = input(f"Entire code for {wit}: ") + auths[wit] = f"{code}#{helping.nowIso8601()}" + + if self.endpoint: receiptor = agenting.Receiptor(hby=self.hby) self.extend([receiptor]) - auths = {} - if self.authenticate: - for wit in hab.kever.wits: - code = input(f"Entire code for {wit}: ") - auths[wit] = f"{code}#{helping.nowIso8601()}" yield from receiptor.receipt(hab.pre, sn=hab.kever.sn, auths=auths) self.remove([receiptor]) else: - witDoer = agenting.WitnessReceiptor(hby=self.hby) + witDoer = agenting.WitnessReceiptor(hby=self.hby, auths=auths) self.extend(doers=[witDoer]) if hab.kever.wits: diff --git a/src/keri/app/cli/commands/rotate.py b/src/keri/app/cli/commands/rotate.py index cb9b34c9e..c5eb3b586 100644 --- a/src/keri/app/cli/commands/rotate.py +++ b/src/keri/app/cli/commands/rotate.py @@ -191,6 +191,12 @@ def rotateDo(self, tymth, tock=0.0): cuts=list(self.cuts), adds=list(self.adds), data=self.data) + auths = {} + if self.authenticate: + for wit in hab.kever.wits: + code = input(f"Entire code for {wit}: ") + auths[wit] = f"{code}#{helping.nowIso8601()}" + if hab.kever.delpre: self.swain.delegation(pre=hab.pre, sn=hab.kever.sn, proxy=self.hby.habByName(self.proxy)) print("Waiting for delegation approval...") @@ -198,19 +204,14 @@ def rotateDo(self, tymth, tock=0.0): yield self.tock elif hab.kever.wits: - if self.endpoint or self.authenticate: - auths = {} - if self.authenticate: - for wit in hab.kever.wits: - code = input(f"Entire code for {wit}: ") - auths[wit] = f"{code}#{helping.nowIso8601()}" + if self.endpoint: yield from receiptor.receipt(hab.pre, sn=hab.kever.sn, auths=auths) else: for wit in self.adds: self.mbx.addPoller(hab, witness=wit) print("Waiting for witness receipts...") - witDoer = agenting.WitnessReceiptor(hby=self.hby) + witDoer = agenting.WitnessReceiptor(hby=self.hby, auths=auths) self.extend(doers=[witDoer]) yield self.tock diff --git a/src/keri/app/cli/commands/witness/start.py b/src/keri/app/cli/commands/witness/start.py index 400b75468..8e47df39a 100644 --- a/src/keri/app/cli/commands/witness/start.py +++ b/src/keri/app/cli/commands/witness/start.py @@ -55,7 +55,7 @@ def launch(args): help.ogler.level = logging.getLevelName(args.loglevel) - if(args.logfile != None): + if args.logfile is not None: help.ogler.headDirPath = args.logfile help.ogler.reopen(name=args.name, temp=False, clear=True) logger = help.ogler.getLogger() diff --git a/src/keri/app/cli/commands/witness/submit.py b/src/keri/app/cli/commands/witness/submit.py index f2f317ac0..9f46a1a52 100644 --- a/src/keri/app/cli/commands/witness/submit.py +++ b/src/keri/app/cli/commands/witness/submit.py @@ -10,6 +10,7 @@ from keri.app import habbing, agenting, indirecting from keri.app.cli.common import existing, displaying +from keri.help import helping logger = help.ogler.getLogger() @@ -30,6 +31,10 @@ parser.add_argument('--force', action="store_true", required=False, help='True means to send witnesses all receipts even if we have a full compliment of receipts for ' 'the current event') +parser.add_argument("--receipt-endpoint", help="Attempt to connect to witness receipt endpoint for witness receipts.", + dest="endpoint", action='store_true') +parser.add_argument("--authenticate", '-z', help="Prompt the controller for authentication codes for each witness", + action='store_true') def handler(args): @@ -46,17 +51,18 @@ def handler(args): alias = args.alias force = args.force - icpDoer = InceptDoer(name=name, base=base, alias=alias, bran=bran, force=force) + subDoer = SubmitDoer(name=name, base=base, alias=alias, bran=bran, force=force, authenticate=args.authenticate, + endpoint=args.endpoint) - doers = [icpDoer] + doers = [subDoer] return doers -class InceptDoer(doing.DoDoer): +class SubmitDoer(doing.DoDoer): """ DoDoer for creating a new identifier prefix and Hab with an alias. """ - def __init__(self, name, base, alias, bran, force): + def __init__(self, name, base, alias, bran, force, endpoint=False, authenticate=False): hby = existing.setupHby(name=name, base=base, bran=bran) self.hbyDoer = habbing.HaberyDoer(habery=hby) # setup doer @@ -64,13 +70,14 @@ def __init__(self, name, base, alias, bran, force): self.alias = alias self.hby = hby self.force = force + self.endpoint = endpoint + self.authenticate = authenticate - self.witDoer = None - doers = [self.hbyDoer, self.mbx, doing.doify(self.inceptDo)] + doers = [self.hbyDoer, self.mbx, doing.doify(self.submitDo)] - super(InceptDoer, self).__init__(doers=doers) + super(SubmitDoer, self).__init__(doers=doers) - def inceptDo(self, tymth, tock=0.0): + def submitDo(self, tymth, tock=0.0): """ Parameters: tymth (function): injected function wrapper closure returned by .tymen() of @@ -85,18 +92,34 @@ def inceptDo(self, tymth, tock=0.0): _ = (yield self.tock) hab = self.hby.habByName(name=self.alias) - self.witDoer = agenting.WitnessReceiptor(hby=self.hby, force=self.force) - self.extend([self.witDoer]) + auths = {} + if self.authenticate: + for wit in hab.kever.wits: + code = input(f"Entire code for {wit}: ") + auths[wit] = f"{code}#{helping.nowIso8601()}" - if hab.kever.wits: - print("Waiting for witness receipts...") - self.witDoer.msgs.append(dict(pre=hab.pre)) - while not self.witDoer.cues: - _ = yield self.tock + if self.endpoint: + receiptor = agenting.Receiptor(hby=self.hby) + self.extend([receiptor]) + + yield from receiptor.receipt(hab.pre, sn=hab.kever.sn, auths=auths) + self.remove([receiptor]) + + else: + witDoer = agenting.WitnessReceiptor(hby=self.hby, force=self.force, auths=auths) + self.extend([witDoer]) + + if hab.kever.wits: + print("Waiting for witness receipts...") + witDoer.msgs.append(dict(pre=hab.pre)) + while not witDoer.cues: + _ = yield self.tock + + self.remove([witDoer]) displaying.printIdentifier(self.hby, hab.pre) - toRemove = [self.hbyDoer, self.witDoer, self.mbx] + toRemove = [self.hbyDoer, self.mbx] self.remove(toRemove) return diff --git a/src/keri/app/delegating.py b/src/keri/app/delegating.py index 0823af1b1..2ffa80ce6 100644 --- a/src/keri/app/delegating.py +++ b/src/keri/app/delegating.py @@ -12,7 +12,7 @@ from . import agenting, forwarding from .habbing import GroupHab from .. import kering -from ..core import coring, eventing, serdering +from ..core import coring, serdering from ..db import dbing from ..peer import exchanging @@ -162,7 +162,7 @@ def processUnanchoredEscrow(self): self.witDoer.msgs.append(dict(pre=pre, sn=serder.sn)) # Move to escrow waiting for witness receipts - print(f"Waiting for fully signed witness receipts for {serder.sn}") + logger.info(f"Waiting for fully signed witness receipts for {serder.sn}") self.hby.db.dpwe.pin(keys=(pre, said), val=serder) self.hby.db.dune.rem(keys=(pre, said)) @@ -188,7 +188,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.dpwe.rem(keys=(pre, said)) self.hby.db.cdel.put(keys=(pre, seqner.qb64), val=coring.Saider(qb64=serder.said)) diff --git a/src/keri/app/grouping.py b/src/keri/app/grouping.py index 2f4bd3e82..bbefab2da 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.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.delpre, anchor=anchor) - print("Waiting for delegation approval...") + logger.info("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: diff --git a/src/keri/app/habbing.py b/src/keri/app/habbing.py index 95cbc8d51..0bf3f2c24 100644 --- a/src/keri/app/habbing.py +++ b/src/keri/app/habbing.py @@ -2084,8 +2084,9 @@ def processCuesIter(self, cues): cuedSerder = cue["serder"] # Serder of received event for other pre cuedKed = cuedSerder.ked cuedPrefixer = coring.Prefixer(qb64=cuedKed["i"]) - logger.info("%s got cue: kin=%s\n%s\n\n", self.pre, cueKin, - json.dumps(cuedKed, indent=1)) + logger.info("%s got cue: kin=%s%s", self.pre, cueKin, + cuedSerder.said) + logger.debug(f"event=\n{cuedSerder.pretty()}\n") if cuedKed["t"] == coring.Ilks.icp: dgkey = dbing.dgKey(self.pre, self.iserder.said) diff --git a/src/keri/app/indirecting.py b/src/keri/app/indirecting.py index c2aef5a14..031c9cf53 100644 --- a/src/keri/app/indirecting.py +++ b/src/keri/app/indirecting.py @@ -192,7 +192,7 @@ def msgDo(self, tymth=None, tock=0.0): _ = (yield self.tock) if self.parser.ims: - logger.info("Client %s received:\n%s\n...\n", self.kvy, self.parser.ims[:1024]) + logger.debug("Client %s received:\n%s\n...\n", self.kvy, self.parser.ims[:1024]) done = yield from self.parser.parsator(local=True) # process messages continuously return done # should nover get here except forced close @@ -381,7 +381,7 @@ def msgDo(self, tymth=None, tock=0.0): _ = (yield self.tock) if self.parser.ims: - logger.info("Client %s received:\n%s\n...\n", self.hab.pre, self.parser.ims[:1024]) + logger.debug("Client %s received:\n%s\n...\n", self.hab.pre, self.parser.ims[:1024]) done = yield from self.parser.parsator(local=True) # process messages continuously return done # should nover get here except forced close @@ -444,7 +444,7 @@ def sendMessage(self, msg, label=""): Sends message msg and loggers label if any """ self.client.tx(msg) # send to remote - logger.info("%s sent %s:\n%s\n\n", self.hab.pre, label, bytes(msg)) + logger.debug("%s sent %s:\n%s\n\n", self.hab.pre, label, bytes(msg)) class MailboxDirector(doing.DoDoer): diff --git a/src/keri/core/eventing.py b/src/keri/core/eventing.py index be5ed47d8..d256b5448 100644 --- a/src/keri/core/eventing.py +++ b/src/keri/core/eventing.py @@ -7,7 +7,6 @@ import json import logging from collections import namedtuple -from dataclasses import dataclass, astuple, asdict, field from urllib.parse import urlsplit from math import ceil from ordered_set import OrderedSet as oset @@ -16,27 +15,26 @@ from .. import kering from ..kering import (MissingEntryError, - ValidationError, DerivationError, MissingSignatureError, + ValidationError, MissingSignatureError, MissingWitnessSignatureError, UnverifiedReplyError, MissingDelegationError, OutOfOrderError, LikelyDuplicitousError, UnverifiedWitnessReceiptError, UnverifiedReceiptError, UnverifiedTransferableReceiptError, QueryNotFoundError, MisfitEventSourceError, MissingDelegableApprovalError) -from ..kering import Version, Versionage, TraitCodex, TraitDex -from ..kering import Coldage, Colds, ColdDex +from ..kering import Version, Versionage, TraitDex from .. import help from ..help import helping from . import coring -from .coring import (versify, Serials, Ilks, MtrDex, PreDex, DigDex, +from .coring import (versify, Serials, Ilks, PreDex, DigDex, NonTransDex, CtrDex, Counter, Number, Seqner, Cigar, Dater, Verfer, Diger, Prefixer, Tholder, Saider) from . import indexing -from .indexing import (IdrDex, Indexer, Siger) +from .indexing import Siger from . import serdering @@ -390,7 +388,7 @@ def verifySigs(raw, sigers, verfers): # verfer to each siger for siger in usigers: if siger.index >= len(verfers): - logger.info("Skipped sig: Index=%s to large.\n", siger.index) + logger.info("Skipped sig: Index=%s to large.", siger.index) siger.verfer = verfers[siger.index] # assign verfer # create lists of unique verified signatures and indices @@ -667,9 +665,9 @@ def incept(keys, Parameters: keys (list): current signing keys qb64 - sith (int | str | list | None): current signing threshold input to Tholder + isith (int | str | list | None): current signing threshold input to Tholder ndigs (list | None): current signing key digests qb64 - nsith int | str | list | None): next signing threshold input to Tholder + nsith (int | str | list | None): next signing threshold input to Tholder toad (int | str | None): witness threshold number if str then hex str wits (list | None): witness identifier prefixes qb64 cnfg (list | None): configuration traits from TraitDex @@ -818,9 +816,9 @@ def rotate(pre, dig (str): SAID of previous event qb64 ilk (str): ilk of event. Must be in (Ilks.rot, Ilks.drt) sn (int | str): sequence number int or hex str - sith (int | str | list | None): current signing threshold input to Tholder + isith (int | str | list | None): current signing threshold input to Tholder ndigs (list | None): current signing key digests qb64 - nsith int | str | list | None): next signing threshold input to Tholder + nsith (int | str | list | None): next signing threshold input to Tholder toad (int | str | None): witness threshold number if str then hex str wits (list | None): prior witness identifier prefixes qb64 cuts (list | None): witness prefixes to cut qb64 @@ -2893,19 +2891,22 @@ def logEvent(self, serder, sigers=None, wigers=None, wits=None, first=False, if firner and fn != firner.sn: # cloned replay but replay fn not match if self.cues is not None: # cue to notice BadCloneFN self.cues.push(dict(kin="noticeBadCloneFN", serder=serder, - fn=fn, firner=firner, dater=dater)) + fn=fn, firner=firner, dater=dater)) logger.info("Kever Mismatch Cloned Replay FN: %s First seen " - "ordinal fn %s and clone fn %s \nEvent=\n%s\n", - serder.preb, fn, firner.sn, serder.pretty()) + "ordinal fn %s and clone fn %s, said=%s", + serder.preb, fn, firner.sn, serder.said) + logger.debug(f"event=\n{serder.pretty()}\n") if dater: # cloned replay use original's dts from dater 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 state: %s First seen ordinal %s at %s\nEvent=\n%s\n", - serder.preb, fn, dtsb.decode("utf-8"), serder.pretty()) + logger.info("Kever state: %s First seen ordinal %s at %s, said=%s", + serder.pre, fn, dtsb.decode("utf-8"), serder.said) + logger.debug(f"event=\n{serder.pretty()}\n") self.db.addKe(snKey(serder.preb, serder.sn), serder.saidb) - logger.info("Kever state: %s Added to KEL valid event=\n%s\n", - serder.preb, serder.pretty()) + logger.info("Kever state: %s Added to KEL valid said=%s", + serder.pre, serder.said) + logger.debug(f"event=\n{serder.pretty()}\n") return (fn, dtsb.decode("utf-8")) # (fn int, dts str) if first else (None, dts str) @@ -2947,7 +2948,7 @@ def escrowMFEvent(self, serder, sigers, wigers=None, res = self.db.misfits.add(keys=(serder.pre, serder.snh), val=serder.saidb) # log escrowed - logger.info("Kever state: escrowed misfit event=\n%s\n", + logger.debug("Kever state: escrowed misfit event=\n%s\n", json.dumps(serder.ked, indent=1)) @@ -2985,7 +2986,7 @@ def escrowDelegableEvent(self, serder, sigers, wigers=None, local=True): self.db.putWigs(dgkey, [siger.qb64b for siger in wigers]) self.db.delegables.add(snKey(serder.preb, serder.sn), serder.saidb) # log escrowed - logger.info("Kever state: escrowed delegable event=\n%s\n", + logger.debug("Kever state: escrowed delegable event=\n%s\n", json.dumps(serder.ked, indent=1)) @@ -3023,7 +3024,7 @@ def escrowPSEvent(self, serder, sigers, wigers=None, local=True): snkey = snKey(serder.preb, serder.sn) self.db.addPse(snkey, serder.saidb) # b'EOWwyMU3XA7RtWdelFt-6waurOTH_aW_Z9VTaU-CshGk.00000000000000000000000000000001' - logger.info("Kever state: Escrowed partially signed or delegated " + logger.debug("Kever state: Escrowed partially signed or delegated " "event = %s\n", serder.ked) @@ -3051,7 +3052,7 @@ def escrowPACouple(self, serder, seqner, saider, local=True): dgkey = dgKey(serder.preb, serder.saidb) couple = seqner.qb64b + saider.qb64b self.db.putPde(dgkey, couple) # idempotent - logger.info("Kever state: Escrowed source couple for partially signed " + logger.debug("Kever state: Escrowed source couple for partially signed " "or delegated event = %s\n", serder.ked) @@ -3094,7 +3095,7 @@ def escrowPWEvent(self, serder, wigers, sigers=None, esr = basing.EventSourceRecord(local=local) self.db.esrs.put(keys=dgkey, val=esr) - logger.info("Kever state: Escrowed partially witnessed " + logger.debug("Kever state: Escrowed partially witnessed " "event = %s\n", serder.ked) return self.db.addPwe(snKey(serder.preb, serder.sn), serder.saidb) @@ -3708,11 +3709,14 @@ def processReceiptWitness(self, serder, wigers, local=None): if pre in self.prefixes: # skip own receiptor of own event # sign own events not receipt them logger.info("Kevery process: skipped own receipt attachment" - " on own event receipt=\n%s\n", serder.pretty()) + " on own event receipt=%s", serder.said) + logger.debug(f"event=\n{serder.pretty()}\n") + continue # skip own receipt attachment on own event if not local: # so skip own receipt on other event when non-local source logger.info("Kevery process: skipped own receipt attachment" - " on nonlocal event receipt=\n%s\n", serder.pretty()) + " on nonlocal event receipt=%s", serder.said) + logger.debug(f"event=\n{serder.pretty()}\n") continue # skip own receipt attachment on non-local event if wiger.verfer.verify(wiger.raw, lserder.raw): @@ -3780,11 +3784,14 @@ def processReceipt(self, serder, cigars, local=None): if pre in self.prefixes: # skip own receipter of own event # sign own events not receipt them logger.info("Kevery process: skipped own receipt attachment" - " on own event receipt=\n%s\n", serder.pretty()) + " on own event receipt=%s", serder.said) + logger.debug(f"event=\n{serder.pretty()}\n") + continue # skip own receipt attachment on own event if not local: # skip own receipt on other event when not local logger.info("Kevery process: skipped own receipt attachment" - " on nonlocal event receipt=\n%s\n", serder.pretty()) + " on nonlocal event receipt=%s", serder.said) + logger.debug(f"event=\n{serder.pretty()}\n") continue # skip own receipt attachment on non-local event if cigar.verfer.verify(cigar.raw, lserder.raw): @@ -3861,11 +3868,15 @@ def processAttachedReceiptCouples(self, serder, cigars, firner=None, local=None) if pre in self.prefixes: # skip own receipter on own event # sign own events not receipt them logger.info("Kevery process: skipped own receipt attachment" - " on own event receipt=\n%s\n", serder.pretty()) + " on own event receipt=%s", serder.said) + logger.debug(f"event=\n{serder.pretty()}\n") + continue # skip own receipt attachment on own event if not local: # own receipt on other event when not local logger.info("Kevery process: skipped own receipt attachment" - " on nonlocal event receipt=\n%s\n", serder.pretty()) + " on nonlocal event receipt=%s", serder.said) + logger.debug(f"event=\n{serder.pretty()}\n") + continue # skip own receipt attachment on non-local event if cigar.verfer.verify(cigar.raw, serder.raw): @@ -4071,7 +4082,7 @@ def processAttachedReceiptQuadruples(self, serder, trqs, firner=None, local=None siger.verfer = sverfers[siger.index] # assign verfer if not siger.verfer.verify(siger.raw, serder.raw): # verify sig logger.info("Kevery unescrow error: Bad trans receipt sig." - "pre=%s sn=%x receipter=%s\n", pre, sn, sprefixer.qb64) + "pre=%s sn=%x receipter=%s", pre, sn, sprefixer.qb64) raise ValidationError("Bad escrowed trans receipt sig at " "pre={} sn={:x} receipter={}." @@ -4662,7 +4673,7 @@ def escrowMFEvent(self, serder, sigers, wigers=None, self.db.putPde(dgkey, couple) # idempotent self.db.misfits.add(keys=(serder.pre, serder.snh), val=serder.saidb) # log escrowed - logger.info("Kevery process: escrowed misfit event=\n%s\n", + logger.debug("Kevery process: escrowed misfit event=\n%s", json.dumps(serder.ked, indent=1)) @@ -4702,8 +4713,8 @@ def escrowOOEvent(self, serder, sigers, seqner=None, saider=None, wigers=None, l self.db.putPde(dgkey, couple) # idempotent self.db.addOoe(snKey(serder.preb, serder.sn), serder.saidb) # log escrowed - logger.info("Kevery process: escrowed out of order event=\n%s\n", - json.dumps(serder.ked, indent=1)) + logger.debug("Kevery process: escrowed out of order event=\n%s", + json.dumps(serder.ked, indent=1)) def escrowQueryNotFoundEvent(self, prefixer, serder, sigers, cigars=None): """ @@ -4726,8 +4737,8 @@ def escrowQueryNotFoundEvent(self, prefixer, serder, sigers, cigars=None): self.db.addRct(key=dgkey, val=cigar.verfer.qb64b + cigar.qb64b) # log escrowed - logger.info("Kevery process: escrowed query not found event=\n%s\n", - json.dumps(serder.ked, indent=1)) + logger.debug("Kevery process: escrowed query not found event=\n%s", + json.dumps(serder.ked, indent=1)) def escrowLDEvent(self, serder, sigers, local=True): """ @@ -4757,8 +4768,8 @@ def escrowLDEvent(self, serder, sigers, local=True): self.db.putEvt(dgkey, serder.raw) self.db.addLde(snKey(serder.preb, serder.sn), serder.saidb) # log duplicitous - logger.info("Kevery process: escrowed likely duplicitous event=\n%s\n", - json.dumps(serder.ked, indent=1)) + logger.debug("Kevery process: escrowed likely duplicitous event=\n%s", + json.dumps(serder.ked, indent=1)) def escrowUWReceipt(self, serder, wigers, said): """ @@ -4793,8 +4804,8 @@ def escrowUWReceipt(self, serder, wigers, said): couple = said.encode("utf-8") + wiger.qb64b self.db.addUwe(key=snKey(serder.preb, serder.sn), val=couple) # log escrowed - logger.info("Kevery process: escrowed unverified witness indexed receipt" - " of pre= %s sn=%x dig=%s\n", serder.pre, serder.sn, said) + logger.debug("Kevery process: escrowed unverified witness indexed receipt" + " of pre= %s sn=%x dig=%s", serder.pre, serder.sn, said) def escrowUReceipt(self, serder, cigars, said): """ @@ -4824,8 +4835,8 @@ def escrowUReceipt(self, serder, cigars, said): triple = said.encode("utf-8") + cigar.verfer.qb64b + cigar.qb64b self.db.addUre(key=snKey(serder.preb, serder.sn), val=triple) # should be snKey # log escrowed - logger.info("Kevery process: escrowed unverified receipt of pre= %s " - " sn=%x dig=%s\n", serder.pre, serder.sn, said) + logger.debug("Kevery process: escrowed unverified receipt of pre= %s " + " sn=%x dig=%s", serder.pre, serder.sn, said) def escrowTRGroups(self, serder, tsgs): """ @@ -4868,9 +4879,9 @@ def escrowTRGroups(self, serder, tsgs): quintuple = prelet + siger.qb64b # quintuple self.db.addVre(key=snKey(serder.preb, serder.sn), val=quintuple) # log escrowed - logger.info("Kevery process: escrowed unverified transferable receipt " - "of pre=%s sn=%x dig=%s by pre=%s\n", serder.pre, - serder.sn, serder.ked["d"], prefixer.qb64) + logger.debug("Kevery process: escrowed unverified transferable receipt " + "of pre=%s sn=%x dig=%s by pre=%s", serder.pre, + serder.sn, serder.ked["d"], prefixer.qb64) def escrowTReceipts(self, serder, prefixer, seqner, saider, sigers): """ @@ -4910,8 +4921,8 @@ def escrowTReceipts(self, serder, prefixer, seqner, saider, sigers): quintuple = prelet + siger.qb64b # quintuple self.db.addVre(key=snKey(serder.preb, serder.sn), val=quintuple) # log escrowed - logger.info("Kevery process: escrowed unverified transferable receipt " - "of pre=%s sn=%x dig=%s by pre=%s\n", serder.pre, + logger.debug("Kevery process: escrowed unverified transferable receipt " + "of pre=%s sn=%x dig=%s by pre=%s", serder.pre, serder.sn, serder.ked["d"], prefixer.qb64) def escrowTRQuadruple(self, serder, sprefixer, sseqner, saider, siger): @@ -4943,9 +4954,9 @@ def escrowTRQuadruple(self, serder, sprefixer, sseqner, saider, siger): saider.qb64b + siger.qb64b) self.db.addVre(key=snKey(serder.preb, serder.sn), val=quintuple) # log escrowed - logger.info("Kevery process: escrowed unverified transferabe validator " - "receipt of pre= %s sn=%x dig=%s\n", serder.pre, serder.sn, - serder.said) + logger.debug("Kevery process: escrowed unverified transferabe validator " + "receipt of pre= %s sn=%x dig=%s", serder.pre, serder.sn, + serder.said) def processEscrows(self): """ @@ -4966,9 +4977,9 @@ def processEscrows(self): except Exception as ex: # log diagnostics errors etc if logger.isEnabledFor(logging.DEBUG): - logger.exception("Kevery escrow process error: %s\n", ex.args[0]) + logger.exception("Kevery escrow process error: %s", ex.args[0]) else: - logger.error("Kevery escrow process error: %s\n", ex.args[0]) + logger.error("Kevery escrow process error: %s", ex.args[0]) raise ex def processEscrowOutOfOrders(self): @@ -5025,7 +5036,7 @@ def processEscrowOutOfOrders(self): if dtb is None: # othewise is a datetime as bytes # no date time so raise ValidationError which unescrows below logger.info("Kevery unescrow error: Missing event datetime" - " at dig = %s\n", bytes(edig)) + " at dig = %s", bytes(edig)) raise ValidationError("Missing escrowed event datetime " "at dig = {}.".format(bytes(edig))) @@ -5036,7 +5047,7 @@ def processEscrowOutOfOrders(self): if (dtnow - dte) > datetime.timedelta(seconds=self.TimeoutOOE): # escrow stale so raise ValidationError which unescrows below logger.info("Kevery unescrow error: Stale event escrow " - " at dig = %s\n", bytes(edig)) + " at dig = %s", bytes(edig)) raise ValidationError("Stale event escrow " "at dig = {}.".format(bytes(edig))) @@ -5046,7 +5057,7 @@ def processEscrowOutOfOrders(self): if eraw is None: # no event so raise ValidationError which unescrows below logger.info("Kevery unescrow error: Missing event at." - "dig = %s\n", bytes(edig)) + "dig = %s", bytes(edig)) raise ValidationError("Missing escrowed evt at dig = {}." "".format(bytes(edig))) @@ -5058,7 +5069,7 @@ def processEscrowOutOfOrders(self): if not sigs: # otherwise its a list of sigs # no sigs so raise ValidationError which unescrows below logger.info("Kevery unescrow error: Missing event sigs at." - "dig = %s\n", bytes(edig)) + "dig = %s", bytes(edig)) raise ValidationError("Missing escrowed evt sigs at " "dig = {}.".format(bytes(edig))) @@ -5089,17 +5100,17 @@ def processEscrowOutOfOrders(self): except OutOfOrderError as ex: # still waiting on missing prior event to validate if logger.isEnabledFor(logging.DEBUG): - logger.exception("Kevery unescrow failed: %s\n", ex.args[0]) + logger.exception("Kevery unescrow failed: %s", ex.args[0]) else: - logger.error("Kevery unescrow failed: %s\n", ex.args[0]) + logger.error("Kevery unescrow failed: %s", ex.args[0]) except Exception as ex: # log diagnostics errors etc # error other than out of order so remove from OO escrow self.db.delOoe(snKey(pre, sn), edig) # removes one escrow at key val if logger.isEnabledFor(logging.DEBUG): - logger.exception("Kevery unescrowed: %s\n", ex.args[0]) + logger.exception("Kevery unescrowed: %s", ex.args[0]) else: - logger.error("Kevery unescrowed: %s\n", ex.args[0]) + logger.error("Kevery unescrowed: %s", ex.args[0]) else: # unescrow succeeded, remove from escrow # We don't remove all escrows at pre,sn because some might be @@ -5107,7 +5118,8 @@ def processEscrowOutOfOrders(self): # valid event escrow. self.db.delOoe(snKey(pre, sn), edig) # removes one escrow at key val logger.info("Kevery unescrow succeeded in valid event: " - "event=\n%s\n", json.dumps(eserder.ked, indent=1)) + "event=%s", eserder.said) + logger.debug(f"event=\n{eserder.pretty()}\n") if ekey == key: # still same so no escrows found on last while iteration break @@ -5165,7 +5177,7 @@ def processEscrowPartialSigs(self): if dtb is None: # othewise is a datetime as bytes # no date time so raise ValidationError which unescrows below logger.info("Kevery unescrow error: Missing event datetime" - " at dig = %s\n", bytes(edig)) + " at dig = %s", bytes(edig)) raise ValidationError("Missing escrowed event datetime " "at dig = {}.".format(bytes(edig))) @@ -5176,7 +5188,7 @@ def processEscrowPartialSigs(self): if (dtnow - dte) > datetime.timedelta(seconds=self.TimeoutPSE): # escrow stale so raise ValidationError which unescrows below logger.info("Kevery unescrow error: Stale event escrow " - " at dig = %s\n", bytes(edig)) + " at dig = %s", bytes(edig)) raise ValidationError("Stale event escrow " "at dig = {}.".format(bytes(edig))) @@ -5186,7 +5198,7 @@ def processEscrowPartialSigs(self): if eraw is None: # no event so so raise ValidationError which unescrows below logger.info("Kevery unescrow error: Missing event at." - "dig = %s\n", bytes(edig)) + "dig = %s", bytes(edig)) raise ValidationError("Missing escrowed evt at dig = {}." "".format(bytes(edig))) @@ -5197,7 +5209,7 @@ def processEscrowPartialSigs(self): if not sigs: # otherwise its a list of sigs # no sigs so raise ValidationError which unescrows below logger.info("Kevery unescrow error: Missing event sigs at." - "dig = %s\n", bytes(edig)) + "dig = %s", bytes(edig)) raise ValidationError("Missing escrowed evt sigs at " "dig = {}.".format(bytes(edig))) @@ -5244,9 +5256,9 @@ def processEscrowPartialSigs(self): except (MissingSignatureError, MissingDelegationError) as ex: # still waiting on missing sigs or missing seal to validate if logger.isEnabledFor(logging.DEBUG): - logger.exception("Kevery unescrow failed: %s\n", ex.args[0]) + logger.exception("Kevery unescrow failed: %s", ex.args[0]) else: - logger.error("Kevery unescrow failed: %s\n", ex.args[0]) + logger.error("Kevery 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 @@ -5256,9 +5268,9 @@ def processEscrowPartialSigs(self): self.cues.push(dict(kin="psUnescrow", serder=eserder)) if logger.isEnabledFor(logging.DEBUG): - logger.exception("Kevery unescrowed: %s\n", ex.args[0]) + logger.exception("Kevery unescrowed: %s", ex.args[0]) else: - logger.error("Kevery unescrowed: %s\n", ex.args[0]) + logger.error("Kevery unescrowed: %s", ex.args[0]) else: # unescrow succeeded, remove from escrow # We don't remove all escrows at pre,sn because some might be @@ -5271,7 +5283,8 @@ def processEscrowPartialSigs(self): self.cues.push(dict(kin="psUnescrow", serder=eserder)) logger.info("Kevery unescrow succeeded in valid event: " - "event=\n%s\n", json.dumps(eserder.ked, indent=1)) + "event=%s", eserder.said) + logger.debug(f"event=\n{eserder.pretty()}\n") if ekey == key: # still same so no escrows found on last while iteration break @@ -5330,7 +5343,7 @@ def processEscrowPartialWigs(self): if dtb is None: # othewise is a datetime as bytes # no date time so raise ValidationError which unescrows below logger.info("Kevery unescrow error: Missing event datetime" - " at dig = %s\n", bytes(edig)) + " at dig = %s", bytes(edig)) raise ValidationError("Missing escrowed event datetime " "at dig = {}.".format(bytes(edig))) @@ -5341,7 +5354,7 @@ def processEscrowPartialWigs(self): if (dtnow - dte) > datetime.timedelta(seconds=self.TimeoutPWE): # escrow stale so raise ValidationError which unescrows below logger.info("Kevery unescrow error: Stale event escrow " - " at dig = %s\n", bytes(edig)) + " at dig = %s", bytes(edig)) raise ValidationError("Stale event escrow " "at dig = {}.".format(bytes(edig))) @@ -5351,7 +5364,7 @@ def processEscrowPartialWigs(self): if eraw is None: # no event so so raise ValidationError which unescrows below logger.info("Kevery unescrow error: Missing event at." - "dig = %s\n", bytes(edig)) + "dig = %s", bytes(edig)) raise ValidationError("Missing escrowed evt at dig = {}." "".format(bytes(edig))) @@ -5363,7 +5376,7 @@ def processEscrowPartialWigs(self): if not sigs: # empty list # no sigs so raise ValidationError which unescrows below logger.info("Kevery unescrow error: Missing event sigs at." - "dig = %s\n", bytes(edig)) + "dig = %s", bytes(edig)) raise ValidationError("Missing escrowed evt sigs at " "dig = {}.".format(bytes(edig))) @@ -5376,8 +5389,8 @@ def processEscrowPartialWigs(self): # which may not arrive until some time after event is fully signed # so just log for debugging but do not unescrow by raising # ValidationError - logger.info("Kevery unescrow wigs: No event wigs yet at." - "dig = %s\n", bytes(edig)) + logger.debug("Kevery unescrow wigs: No event wigs yet at." + "dig = %s", bytes(edig)) # raise ValidationError("Missing escrowed evt wigs at " # "dig = {}.".format(bytes(edig))) @@ -5415,17 +5428,17 @@ def processEscrowPartialWigs(self): except MissingWitnessSignatureError as ex: # still waiting on missing witness sigs if logger.isEnabledFor(logging.DEBUG): - logger.exception("Kevery unescrow failed: %s\n", ex.args[0]) + logger.exception("Kevery unescrow failed: %s", ex.args[0]) else: - logger.error("Kevery unescrow failed: %s\n", ex.args[0]) + logger.error("Kevery 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 self.db.delPwe(snKey(pre, sn), edig) # removes one escrow at key val if logger.isEnabledFor(logging.DEBUG): - logger.exception("Kevery unescrowed: %s\n", ex.args[0]) + logger.exception("Kevery unescrowed: %s", ex.args[0]) else: - logger.error("Kevery unescrowed: %s\n", ex.args[0]) + logger.error("Kevery unescrowed: %s", ex.args[0]) else: # unescrow succeeded, remove from escrow # We don't remove all escrows at pre,sn because some might be @@ -5433,7 +5446,8 @@ def processEscrowPartialWigs(self): # valid event escrow. self.db.delPwe(snKey(pre, sn), edig) # removes one escrow at key val logger.info("Kevery unescrow succeeded in valid event: " - "event=\n%s\n", json.dumps(eserder.ked, indent=1)) + "event=%s", eserder.said) + logger.debug(f"event=\n{eserder.pretty()}\n") if ekey == key: # still same so no escrows found on last while iteration break @@ -5504,7 +5518,7 @@ def processEscrowUnverWitness(self): if dtb is None: # othewise is a datetime as bytes # no date time so raise ValidationError which unescrows below logger.info("Kevery unescrow error: Missing event datetime" - " at dig = %s\n", rdiger.qb64b) + " at dig = %s", rdiger.qb64b) raise ValidationError("Missing escrowed event datetime " "at dig = {}.".format(rdiger.qb64b)) @@ -5515,7 +5529,7 @@ def processEscrowUnverWitness(self): if (dtnow - dte) > datetime.timedelta(seconds=self.TimeoutUWE): # escrow stale so raise ValidationError which unescrows below logger.info("Kevery unescrow error: Stale event escrow " - " at dig = %s\n", rdiger.qb64b) + " at dig = %s", rdiger.qb64b) raise ValidationError("Stale event escrow " "at dig = {}.".format(rdiger.qb64b)) @@ -5529,8 +5543,8 @@ def processEscrowUnverWitness(self): if not found: # no partial witness escrow of event found # so keep in escrow by raising UnverifiedWitnessReceiptError - logger.info("Kevery unescrow error: Missing witness " - "receipted evt at pre=%s sn=%x\n", (pre, sn)) + logger.debug("Kevery unescrow error: Missing witness " + "receipted evt at pre=%s sn=%x", (pre, sn)) raise UnverifiedWitnessReceiptError("Missing witness " "receipted evt at pre={} sn={:x}".format(pre, sn)) @@ -5539,17 +5553,17 @@ def processEscrowUnverWitness(self): # still waiting on missing prior event to validate # only happens if we process above if logger.isEnabledFor(logging.DEBUG): # adds exception data - logger.exception("Kevery unescrow failed: %s\n", ex.args[0]) + logger.exception("Kevery unescrow failed: %s", ex.args[0]) else: - logger.error("Kevery unescrow failed: %s\n", ex.args[0]) + logger.error("Kevery unescrow failed: %s", ex.args[0]) except Exception as ex: # log diagnostics errors etc # error other than out of order so remove from OO escrow self.db.delUwe(snKey(pre, sn), ecouple) # removes one escrow at key val if logger.isEnabledFor(logging.DEBUG): # adds exception data - logger.exception("Kevery unescrowed: %s\n", ex.args[0]) + logger.exception("Kevery unescrowed: %s", ex.args[0]) else: - logger.error("Kevery unescrowed: %s\n", ex.args[0]) + logger.error("Kevery unescrowed: %s", ex.args[0]) else: # unescrow succeeded, remove from escrow # We don't remove all escrows at pre,sn because some might be @@ -5557,7 +5571,7 @@ def processEscrowUnverWitness(self): # valid event escrow. self.db.delUwe(snKey(pre, sn), ecouple) # removes one escrow at key val logger.info("Kevery 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 @@ -5624,7 +5638,7 @@ def processEscrowUnverNonTrans(self): if dtb is None: # othewise is a datetime as bytes # no date time so raise ValidationError which unescrows below logger.info("Kevery unescrow error: Missing event datetime" - " at dig = %s\n", rsaider.qb64b) + " at dig = %s", rsaider.qb64b) raise ValidationError("Missing escrowed event datetime " "at dig = {}.".format(rsaider.qb64b)) @@ -5635,7 +5649,7 @@ def processEscrowUnverNonTrans(self): if (dtnow - dte) > datetime.timedelta(seconds=self.TimeoutURE): # escrow stale so raise ValidationError which unescrows below logger.info("Kevery unescrow error: Stale event escrow " - " at dig = %s\n", rsaider.qb64b) + " at dig = %s", rsaider.qb64b) raise ValidationError("Stale event escrow " "at dig = {}.".format(rsaider.qb64b)) @@ -5655,8 +5669,8 @@ def processEscrowUnverNonTrans(self): dig = self.db.getKeLast(snKey(pre, sn)) if dig is None: # no receipted event so keep in escrow - logger.info("Kevery unescrow error: Missing receipted " - "event at pre=%s sn=%x\n", pre, sn) + logger.debug("Kevery unescrow error: Missing receipted " + "event at pre=%s sn=%x", pre, sn) raise UnverifiedReceiptError("Missing receipted evt " "at pre={} sn={:x}".format(pre, sn)) @@ -5665,7 +5679,7 @@ def processEscrowUnverNonTrans(self): raw = self.db.getEvt(dgKey(pre, dig)) if raw is None: # receipted event superseded so remove from escrow logger.info("Kevery unescrow error: Invalid receipted " - "event refereance at pre=%s sn=%x\n", pre, sn) + "event refereance at pre=%s sn=%x", pre, sn) raise ValidationError("Invalid receipted evt reference" " at pre={} sn={:x}".format(pre, sn)) @@ -5675,7 +5689,7 @@ def processEscrowUnverNonTrans(self): # compare digs if rsaider.qb64b != serder.saidb: logger.info("Kevery unescrow error: Bad receipt dig." - "pre=%s sn=%x receipter=%s\n", pre, sn, sprefixer.qb64) + "pre=%s sn=%x receipter=%s", pre, sn, sprefixer.qb64) raise ValidationError("Bad escrowed receipt dig at " "pre={} sn={:x} receipter={}." @@ -5685,7 +5699,7 @@ def processEscrowUnverNonTrans(self): if not cigar.verfer.verify(cigar.raw, serder.raw): # no sigs so raise ValidationError which unescrows below logger.info("Kevery unescrow error: Bad receipt sig." - "pre=%s sn=%x receipter=%s\n", pre, sn, sprefixer.qb64) + "pre=%s sn=%x receipter=%s", pre, sn, sprefixer.qb64) raise ValidationError("Bad escrowed receipt sig at " "pre={} sn={:x} receipter={}." @@ -5712,17 +5726,17 @@ def processEscrowUnverNonTrans(self): # still waiting on missing prior event to validate # only happens if we process above if logger.isEnabledFor(logging.DEBUG): # adds exception data - logger.exception("Kevery unescrow failed: %s\n", ex.args[0]) + logger.exception("Kevery unescrow failed: %s", ex.args[0]) else: - logger.error("Kevery unescrow failed: %s\n", ex.args[0]) + logger.error("Kevery unescrow failed: %s", 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\n", ex.args[0]) + logger.exception("Kevery unescrowed: %s", ex.args[0]) else: - logger.error("Kevery unescrowed: %s\n", ex.args[0]) + logger.error("Kevery unescrowed: %s", ex.args[0]) else: # unescrow succeeded, remove from escrow # We don't remove all escrows at pre,sn because some might be @@ -5730,7 +5744,7 @@ def processEscrowUnverNonTrans(self): # valid event escrow. self.db.delUre(snKey(pre, sn), etriplet) # removes one escrow at key val logger.info("Kevery 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 @@ -5773,7 +5787,7 @@ def processQueryNotFound(self): if dtb is None: # othewise is a datetime as bytes # no date time so raise ValidationError which unescrows below logger.info("Kevery unescrow error: Missing event datetime" - " at dig = %s\n", bytes(edig)) + " at dig = %s", bytes(edig)) raise ValidationError("Missing escrowed event datetime " "at dig = {}.".format(bytes(edig))) @@ -5784,7 +5798,7 @@ def processQueryNotFound(self): if (dtnow - dte) > datetime.timedelta(seconds=self.TimeoutQNF): # escrow stale so raise ValidationError which unescrows below logger.info("Kevery unescrow error: Stale qry event escrow " - " at dig = %s\n", bytes(edig)) + " at dig = %s", bytes(edig)) raise ValidationError("Stale qry event escrow " "at dig = {}.".format(bytes(edig))) @@ -5794,7 +5808,7 @@ def processQueryNotFound(self): if eraw is None: # no event so raise ValidationError which unescrows below logger.info("Kevery unescrow error: Missing event at." - "dig = %s\n", bytes(edig)) + "dig = %s", bytes(edig)) raise ValidationError("Missing escrowed evt at dig = {}." "".format(bytes(edig))) @@ -5806,7 +5820,7 @@ def processQueryNotFound(self): if not sigs: # otherwise its a list of sigs # no sigs so raise ValidationError which unescrows below logger.info("Kevery unescrow error: Missing event sigs at." - "dig = %s\n", bytes(edig)) + "dig = %s", bytes(edig)) raise ValidationError("Missing escrowed evt sigs at " "dig = {}.".format(bytes(edig))) @@ -5833,24 +5847,25 @@ def processQueryNotFound(self): except QueryNotFoundError as ex: # still waiting on missing prior event to validate if logger.isEnabledFor(logging.DEBUG): - logger.exception("Kevery unescrow failed: %s\n", ex.args[0]) + logger.exception("Kevery unescrow failed: %s", ex.args[0]) else: - logger.error("Kevery unescrow failed: %s\n", ex.args[0]) + logger.error("Kevery unescrow failed: %s", ex.args[0]) except Exception as ex: # log diagnostics errors etc # error other than out of order so remove from OO escrow self.db.delQnf(dgKey(pre, edig), edig) # removes one escrow at key val if logger.isEnabledFor(logging.DEBUG): - logger.exception("Kevery unescrowed: %s\n", ex.args[0]) + logger.exception("Kevery unescrowed: %s", ex.args[0]) else: - logger.error("Kevery unescrowed: %s\n", ex.args[0]) + logger.error("Kevery unescrowed: %s", 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.delQnf(dgKey(pre, edig), edig) # removes one escrow at key val logger.info("Kevery unescrow succeeded in valid event: " - "event=\n%s\n", json.dumps(eserder.ked, indent=1)) + "event=%s", eserder.said) + logger.debug(f"event=\n{eserder.pretty()}\n") if ekey == key: # still same so no escrows found on last while iteration break @@ -5942,7 +5957,7 @@ def _processEscrowFindUnver(self, pre, sn, rsaider, wiger=None, cigar=None): if wiger.index >= len(wits): # bad index # raise ValidationError which removes from escrow by caller logger.info("Kevery unescrow error: Bad witness receipt" - " index=%i for pre=%s sn=%x\n", wiger.index, pre, sn) + " index=%i for pre=%s sn=%x", wiger.index, pre, sn) raise ValidationError("Bad escrowed witness receipt index={}" " at pre={} sn={:x}.".format(wiger.index, pre, sn)) @@ -5954,7 +5969,7 @@ def _processEscrowFindUnver(self, pre, sn, rsaider, wiger=None, cigar=None): if not wiger.verfer.verify(wiger.raw, serder.raw): # not verify # raise ValidationError which unescrows .Uwes or .Ures in caller logger.info("Kevery unescrow error: Bad witness receipt" - " wig. pre=%s sn=%x\n", pre, sn) + " wig. pre=%s sn=%x", pre, sn) raise ValidationError("Bad escrowed witness receipt wig" " at pre={} sn={:x}." @@ -6023,7 +6038,7 @@ def processEscrowUnverTrans(self): if dtb is None: # othewise is a datetime as bytes # no date time so raise ValidationError which unescrows below logger.info("Kevery unescrow error: Missing event datetime" - " at dig = %s\n", esaider.qb64b) + " at dig = %s", esaider.qb64b) raise ValidationError("Missing escrowed event datetime " "at dig = {}.".format(esaider.qb64b)) @@ -6034,7 +6049,7 @@ def processEscrowUnverTrans(self): if (dtnow - dte) > datetime.timedelta(seconds=self.TimeoutVRE): # escrow stale so raise ValidationError which unescrows below logger.info("Kevery unescrow error: Stale event escrow " - " at dig = %s\n", esaider.qb64b) + " at dig = %s", esaider.qb64b) raise ValidationError("Stale event escrow " "at dig = {}.".format(esaider.qb64b)) @@ -6043,8 +6058,8 @@ def processEscrowUnverTrans(self): raw = self.db.getKeLast(snKey(pre, sn)) if raw is None: # no event so keep in escrow - logger.info("Kevery unescrow error: Missing receipted " - "event at pre=%s sn=%x\n", pre, sn) + logger.debug("Kevery unescrow error: Missing receipted " + "event at pre=%s sn=%x", pre, sn) raise UnverifiedTransferableReceiptError("Missing receipted evt at pre={} " " sn={:x}".format(pre, sn)) @@ -6054,7 +6069,7 @@ def processEscrowUnverTrans(self): raw = self.db.getEvt(dgKey(pre, dig)) if raw is None: # receipted event superseded so remove from escrow logger.info("Kevery unescrow error: Invalid receipted " - "event referenace at pre=%s sn=%x\n", pre, sn) + "event referenace at pre=%s sn=%x", pre, sn) raise ValidationError("Invalid receipted evt reference " "at pre={} sn={:x}".format(pre, sn)) @@ -6064,7 +6079,7 @@ def processEscrowUnverTrans(self): # compare digs if esaider.qb64b != serder.saidb: logger.info("Kevery unescrow error: Bad receipt dig." - "pre=%s sn=%x receipter=%s\n", (pre, sn, sprefixer.qb64)) + "pre=%s sn=%x receipter=%s", (pre, sn, sprefixer.qb64)) raise ValidationError("Bad escrowed receipt dig at " "pre={} sn={:x} receipter={}." @@ -6076,8 +6091,8 @@ def processEscrowUnverTrans(self): sn=sseqner.sn)) if sdig is None: # no event so keep in escrow - logger.info("Kevery unescrow error: Missing receipted " - "event at pre=%s sn=%x\n", pre, sn) + logger.debug("Kevery unescrow error: Missing receipted " + "event at pre=%s sn=%x", pre, sn) raise UnverifiedTransferableReceiptError("Missing receipted evt at pre={} " " sn={:x}".format(pre, sn)) @@ -6108,7 +6123,7 @@ def processEscrowUnverTrans(self): siger.verfer = verfers[siger.index] # assign verfer if not siger.verfer.verify(siger.raw, serder.raw): # verify sig logger.info("Kevery unescrow error: Bad trans receipt sig." - "pre=%s sn=%x receipter=%s\n", pre, sn, sprefixer.qb64) + "pre=%s sn=%x receipter=%s", pre, sn, sprefixer.qb64) raise ValidationError("Bad escrowed trans receipt sig at " "pre={} sn={:x} receipter={}." @@ -6123,24 +6138,25 @@ def processEscrowUnverTrans(self): # still waiting on missing prior event to validate # only happens if we process above if logger.isEnabledFor(logging.DEBUG): # adds exception data - logger.exception("Kevery unescrow failed: %s\n", ex.args[0]) + logger.exception("Kevery unescrow failed: %s", ex.args[0]) else: - logger.error("Kevery unescrow failed: %s\n", ex.args[0]) + logger.error("Kevery unescrow failed: %s", 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.exception("Kevery unescrowed: %s\n", ex.args[0]) + logger.exception("Kevery unescrowed: %s", ex.args[0]) else: - logger.error("Kevery unescrowed: %s\n", ex.args[0]) + logger.error("Kevery unescrowed: %s", 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 unescrow succeeded for event = %s\n", serder.ked) + logger.info("Kevery unescrow succeeded for event = %s", serder.said) + logger.debug(f"event=\n{serder.pretty()}\n") if ekey == key: # still same so no escrows found on last while iteration break @@ -6198,7 +6214,7 @@ def processEscrowDuplicitous(self): if dtb is None: # othewise is a datetime as bytes # no date time so raise ValidationError which unescrows below logger.info("Kevery unescrow error: Missing event datetime" - " at dig = %s\n", bytes(edig)) + " at dig = %s", bytes(edig)) raise ValidationError("Missing escrowed event datetime " "at dig = {}.".format(bytes(edig))) @@ -6209,7 +6225,7 @@ def processEscrowDuplicitous(self): if (dtnow - dte) > datetime.timedelta(seconds=self.TimeoutLDE): # escrow stale so raise ValidationError which unescrows below logger.info("Kevery unescrow error: Stale event escrow " - " at dig = %s\n", bytes(edig)) + " at dig = %s", bytes(edig)) raise ValidationError("Stale event escrow " "at dig = {}.".format(bytes(edig))) @@ -6219,7 +6235,7 @@ def processEscrowDuplicitous(self): if eraw is None: # no event so raise ValidationError which unescrows below logger.info("Kevery unescrow error: Missing event at." - "dig = %s\n", bytes(edig)) + "dig = %s", bytes(edig)) raise ValidationError("Missing escrowed evt at dig = {}." "".format(bytes(edig))) @@ -6231,7 +6247,7 @@ def processEscrowDuplicitous(self): if not sigs: # otherwise its a list of sigs # no sigs so raise ValidationError which unescrows below logger.info("Kevery unescrow error: Missing event sigs at." - "dig = %s\n", bytes(edig)) + "dig = %s", bytes(edig)) raise ValidationError("Missing escrowed evt sigs at " "dig = {}.".format(bytes(edig))) @@ -6256,17 +6272,17 @@ def processEscrowDuplicitous(self): except LikelyDuplicitousError as ex: # still can't determine if duplicitous if logger.isEnabledFor(logging.DEBUG): - logger.exception("Kevery unescrow failed: %s\n", ex.args[0]) + logger.exception("Kevery unescrow failed: %s", ex.args[0]) else: - logger.error("Kevery unescrow failed: %s\n", ex.args[0]) + logger.error("Kevery unescrow failed: %s", ex.args[0]) except Exception as ex: # log diagnostics errors etc # error other than likely duplicitous so remove from escrow self.db.delLde(snKey(pre, sn), edig) # removes one escrow at key val if logger.isEnabledFor(logging.DEBUG): - logger.exception("Kevery unescrowed: %s\n", ex.args[0]) + logger.exception("Kevery unescrowed: %s", ex.args[0]) else: - logger.error("Kevery unescrowed: %s\n", ex.args[0]) + logger.error("Kevery unescrowed: %s", ex.args[0]) else: # unescrow succeeded, remove from escrow # We don't remove all escrows at pre,sn because some might be @@ -6274,7 +6290,8 @@ def processEscrowDuplicitous(self): # valid event escrow. self.db.delLde(snKey(pre, sn), edig) # removes one escrow at key val logger.info("Kevery unescrow succeeded in valid event: " - "event=\n%s\n", json.dumps(eserder.ked, indent=1)) + "event=%s", eserder.said) + logger.debug(f"event=\n{eserder.pretty()}\n") 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 88d572e4d..e1275075c 100644 --- a/src/keri/core/parsing.py +++ b/src/keri/core/parsing.py @@ -6,17 +6,14 @@ """ import logging -import traceback -from collections import namedtuple -from dataclasses import dataclass, astuple from .coring import (Ilks, CtrDex, Counter, Seqner, Cigar, - Dater, Verfer, Prefixer, Saider, Pather, Protocols ) + Dater, Verfer, Prefixer, Saider, Pather) from .indexing import (Siger, ) from . import serdering from .. import help from .. import kering -from ..kering import ColdDex, Colds, sniff +from ..kering import Colds, sniff logger = help.ogler.getLogger() @@ -430,25 +427,25 @@ 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.ERROR): - logger.exception("Parser msg extraction error: %s\n", ex.args[0]) + if logger.isEnabledFor(logging.DEBUG): + logger.exception("Parser msg extraction error: %s", ex.args[0]) else: - logger.error("Parser msg extraction error: %s\n", ex.args[0]) + logger.error("Parser msg extraction error: %s", ex.args[0]) except (kering.ColdStartError, kering.ExtractionError) as ex: # some extraction error - if logger.isEnabledFor(logging.ERROR): - logger.exception("Parser msg extraction error: %s\n", ex.args[0]) + if logger.isEnabledFor(logging.DEBUG): + logger.exception("Parser msg extraction error: %s", ex.args[0]) else: - logger.error("Parser msg extraction error: %s\n", ex.args[0]) + logger.error("Parser msg extraction error: %s", ex.args[0]) del ims[:] # delete rest of stream to force cold restart 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.ERROR): - logger.exception("Parser msg non-extraction error: %s\n", ex) + if logger.isEnabledFor(logging.DEBUG): + logger.exception("Parser msg non-extraction error: %s", ex) else: - logger.error("Parser msg non-extraction error: %s\n", ex) + logger.error("Parser msg non-extraction error: %s", ex) yield return True @@ -515,25 +512,25 @@ def onceParsator(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.ERROR): - logger.exception("Kevery msg extraction error: %s\n", ex.args[0]) + if logger.isEnabledFor(logging.DEBUG): + logger.exception("Kevery msg extraction error: %s", ex.args[0]) else: - logger.error("Kevery msg extraction error: %s\n", ex.args[0]) + logger.error("Kevery msg extraction error: %s", ex.args[0]) except (kering.ColdStartError, kering.ExtractionError) as ex: # some extraction error - if logger.isEnabledFor(logging.ERROR): - logger.exception("Kevery msg extraction error: %s\n", ex.args[0]) + if logger.isEnabledFor(logging.DEBUG): + logger.exception("Kevery msg extraction error: %s", ex.args[0]) else: - logger.error("Kevery msg extraction error: %s\n", ex.args[0]) + logger.error("Kevery msg extraction error: %s", ex.args[0]) del ims[:] # delete rest of stream to force cold restart 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.ERROR): - logger.exception("Kevery msg non-extraction error: %s\n", ex.args[0]) + if logger.isEnabledFor(logging.DEBUG): + logger.exception("Kevery msg non-extraction error: %s", ex.args[0]) else: - logger.error("Kevery msg non-extraction error: %s\n", ex.args[0]) + logger.error("Kevery msg non-extraction error: %s", ex.args[0]) finally: done = True @@ -605,25 +602,25 @@ 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.ERROR): - logger.exception("Parser msg extraction error: %s\n", ex.args[0]) + if logger.isEnabledFor(logging.DEBUG): + logger.exception("Parser msg extraction error: %s", ex.args[0]) else: - logger.error("Parser msg extraction error: %s\n", ex.args[0]) + logger.error("Parser msg extraction error: %s", ex.args[0]) except (kering.ColdStartError, kering.ExtractionError) as ex: # some extraction error - if logger.isEnabledFor(logging.ERROR): - logger.exception("Parser msg extraction error: %s\n", ex.args[0]) + if logger.isEnabledFor(logging.DEBUG): + logger.exception("Parser msg extraction error: %s", ex.args[0]) else: - logger.error("Parser msg extraction error: %s\n", ex.args[0]) + logger.error("Parser msg extraction error: %s", ex.args[0]) del ims[:] # delete rest of stream to force cold restart 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.ERROR): - logger.exception("Parser msg non-extraction error: %s\n", ex.args[0]) + if logger.isEnabledFor(logging.DEBUG): + logger.exception("Parser msg non-extraction error: %s", ex.args[0]) else: - logger.error("Parser msg non-extraction error: %s\n", ex.args[0]) + logger.error("Parser msg non-extraction error: %s", ex.args[0]) yield return True # should never return diff --git a/src/keri/core/routing.py b/src/keri/core/routing.py index 2b3856b41..8d119a27b 100644 --- a/src/keri/core/routing.py +++ b/src/keri/core/routing.py @@ -267,25 +267,30 @@ def acceptReply(self, serder, saider, route, aid, osaider=None, if not self.lax and cigar.verfer.qb64 in self.prefixes: # own cig if not self.local: # own cig when not local so ignore logger.info("Kevery process: skipped own attachment" - " on nonlocal reply msg=\n%s\n", serder.pretty()) + " on nonlocal reply said=", serder.said) + logger.debug(f"event=\n{serder.pretty()}\n") + continue # skip own cig attachment on non-local reply msg if aid != cigar.verfer.qb64: # cig not by aid logger.info("Kevery process: skipped cig not from aid=" - "%s on reply msg=\n%s\n", aid, serder.pretty()) + "%s on reply said=%s", aid, serder.said) + logger.debug(f"event=\n{serder.pretty()}\n") continue # skip invalid cig's verfer is not aid if odater: # get old compare datetimes to see if later if dater.datetime <= odater.datetime: logger.info("Kevery process: skipped stale update from " - "%s of reply msg=\n%s\n", aid, serder.pretty()) + "%s of reply said=%s", aid, serder.said) + logger.debug(f"event=\n{serder.pretty()}\n") continue # skip if not later # raise ValidationError(f"Stale update of {route} from {aid} " # f"via {Ilks.rpy}={serder.ked}.") if not cigar.verfer.verify(cigar.raw, serder.raw): # cig not verify logger.info("Kevery process: skipped nonverifying cig from " - "%s on reply msg=\n%s\n", cigar.verfer.qb64, serder.pretty()) + "%s on reply said=%s", cigar.verfer.qb64, serder.said) + logger.debug(f"event=\n{serder.pretty()}\n") continue # skip if cig not verify # All constraints satisfied so update @@ -298,13 +303,15 @@ def acceptReply(self, serder, saider, route, aid, osaider=None, if not self.lax and prefixer.qb64 in self.prefixes: # own sig if not self.local: # own sig when not local so ignore logger.info("Kevery process: skipped own attachment" - " on nonlocal reply msg=\n%s\n", serder.pretty()) + " on nonlocal reply said=%s", serder.said) + logger.debug(f"event=\n{serder.pretty()}\n") continue # skip own sig attachment on non-local reply msg spre = prefixer.qb64 if aid != spre: # sig not by aid logger.info("Kevery process: skipped signature not from aid=" - "%s on reply msg=\n%s\n", aid, serder.pretty()) + "%s on reply said=%s", aid, serder.said) + logger.debug(f"event=\n{serder.pretty()}\n") continue # skip invalid signature is not from aid if osaider: # check if later logic sn > or sn == and dt > @@ -313,16 +320,18 @@ def acceptReply(self, serder, saider, route, aid, osaider=None, if seqner.sn < osqr.sn: # sn earlier logger.info("Kevery process: skipped stale key state sig" - "from %s sn=%s<%s on reply msg=\n%s\n", - aid, seqner.sn, osqr.sn, serder.pretty()) + "from %s sn=%s<%s on reply said=%s", + aid, seqner.sn, osqr.sn, serder.said) + logger.debug(f"event=\n{serder.pretty()}\n") continue # skip if sn earlier 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()) + "state sig datetime from %s on reply said=%s", + aid, serder.said) + logger.debug(f"event=\n{serder.pretty()}\n") continue # skip if not later # retrieve sdig of last event at sn of signer. @@ -475,7 +484,7 @@ def processEscrowReply(self): datetime.timedelta(seconds=self.TimeoutRPE)): # escrow stale so raise ValidationError which unescrows below logger.info("Kevery unescrow error: Stale reply escrow " - " at route = %s\n", route) + " at route = %s", route) raise kering.ValidationError(f"Stale reply escrow at route = {route}.") @@ -484,30 +493,31 @@ def processEscrowReply(self): except kering.UnverifiedReplyError as ex: # still waiting on missing prior event to validate if logger.isEnabledFor(logging.DEBUG): - logger.exception("Kevery unescrow attempt failed: %s\n", ex.args[0]) + logger.exception("Kevery unescrow attempt failed: %s", ex.args[0]) else: - logger.error("Kevery unescrow attempt failed: %s\n", ex.args[0]) + logger.error("Kevery unescrow attempt failed: %s", ex.args[0]) except Exception as ex: # other error so remove from reply escrow self.db.rpes.rem(keys=(route, ), val=saider) # remove escrow only self.removeReply(saider) # remove escrow reply artifacts if logger.isEnabledFor(logging.DEBUG): - logger.exception("Kevery unescrowed due to error: %s\n", ex.args[0]) + logger.exception("Kevery unescrowed due to error: %s", ex.args[0]) else: - logger.error("Kevery unescrowed due to error: %s\n", ex.args[0]) + logger.error("Kevery unescrowed due to error: %s", ex.args[0]) 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 said=%s", + serder.said) + logger.debug(f"event=\n{serder.pretty()}\n") except Exception as ex: # log diagnostics errors etc self.db.rpes.rem(keys=(route,), val=saider) # remove escrow only self.removeReply(saider) # remove escrow reply artifacts if logger.isEnabledFor(logging.DEBUG): - logger.exception("Kevery unescrowed due to error: %s\n", ex.args[0]) + logger.exception("Kevery unescrowed due to error: %s", ex.args[0]) else: - logger.error("Kevery unescrowed due to error: %s\n", ex.args[0]) + logger.error("Kevery unescrowed due to error: %s", ex.args[0]) class Route: diff --git a/src/keri/db/escrowing.py b/src/keri/db/escrowing.py index 71fe06248..e1818b993 100644 --- a/src/keri/db/escrowing.py +++ b/src/keri/db/escrowing.py @@ -104,7 +104,7 @@ def processEscrowState(self, typ, processReply, extype: Type[Exception]): datetime.timedelta(seconds=self.timeout)): # escrow stale so raise ValidationError which unescrows below logger.info("Kevery unescrow error: Stale txn state escrow " - " at pre = %s\n", pre) + " at pre = %s", pre) raise kering.ValidationError(f"Stale txn state escrow at pre = {pre}.") @@ -114,29 +114,30 @@ def processEscrowState(self, typ, processReply, extype: Type[Exception]): except extype as ex: # still waiting on missing prior event to validate if logger.isEnabledFor(logging.DEBUG): - logger.exception("Kevery unescrow attempt failed: %s\n", ex.args[0]) + logger.exception("Kevery unescrow attempt failed: %s", ex.args[0]) else: - logger.error("Kevery unescrow attempt failed: %s\n", ex.args[0]) + logger.error("Kevery unescrow attempt failed: %s", 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("Kevery unescrowed due to error: %s\n", ex.args[0]) + logger.exception("Kevery unescrowed due to error: %s", ex.args[0]) else: - logger.error("Kevery unescrowed due to error: %s\n", ex.args[0]) + logger.error("Kevery unescrowed due to error: %s", ex.args[0]) else: # unescrow succeded self.escrowdb.remIokey(iokeys=(typ, pre, aid, ion)) # remove escrow only - logger.info("Kevery unescrow succeeded for txn state=\n%s\n", - serder.pretty()) + logger.info("Kevery unescrow succeeded for txn state=%s", + serder.said) + logger.debug(f"event=\n{serder.pretty()}\n") except Exception as ex: # log diagnostics errors etc self.escrowdb.remIokey(iokeys=(typ, pre, aid, ion)) # remove escrow self.removeState(saider) if logger.isEnabledFor(logging.DEBUG): - logger.exception("Kevery unescrowed due to error: %s\n", ex.args[0]) + logger.exception("Kevery unescrowed due to error: %s", ex.args[0]) else: - logger.error("Kevery unescrowed due to error: %s\n", ex.args[0]) + logger.error("Kevery unescrowed due to error: %s", 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 570e1492d..fcbefa8a8 100644 --- a/src/keri/peer/exchanging.py +++ b/src/keri/peer/exchanging.py @@ -121,11 +121,13 @@ def processEvent(self, serder, tsgs=None, cigars=None, **kwargs): # Perform behavior specific verification, think IPEX chaining requirements try: if not behavior.verify(serder=serder, attachments=attachments): - logger.info(f"exn event for route {route} failed behavior verfication. exn={serder.ked}") + logger.info(f"exn event for route {route} failed behavior verfication. said={serder.said}") + logger.debug(f"event=\n{serder.pretty()}\n") return except AttributeError: - logger.info(f"Behavior for {route} missing or does not have verify for exn={serder.ked}") + logger.info(f"Behavior for {route} missing or does not have verify for said={serder.said}") + logger.debug(f"event=\n{serder.pretty()}\n") # Always persis events self.logEvent(serder, pathed, tsgs, cigars) @@ -135,7 +137,8 @@ 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.ked}") + logger.info(f"Behavior for {route} missing or does not have handle for said={serder.said}") + logger.debug(f"event=\n{serder.pretty()}\n") def processEscrow(self): """ Process all escrows for `exn` messages @@ -190,21 +193,22 @@ def processEscrowPartialSigned(self): except MissingSignatureError as ex: if logger.isEnabledFor(logging.DEBUG): - logger.info("Exchange partially signed unescrow failed: %s\n", ex.args[0]) + logger.info("Exchange partially signed unescrow failed: %s", ex.args[0]) else: - logger.info("Exchange partially signed failed: %s\n", ex.args[0]) + logger.info("Exchange partially signed failed: %s", ex.args[0]) except Exception as ex: self.hby.db.epse.rem(dig) self.hby.db.esigs.rem(dig) if logger.isEnabledFor(logging.DEBUG): - logger.info("Exchange partially signed unescrowed: %s\n", ex.args[0]) + logger.info("Exchange partially signed unescrowed: %s", ex.args[0]) else: - logger.info("Exchange partially signed unescrowed: %s\n", ex.args[0]) + logger.info("Exchange partially signed unescrowed: %s", ex.args[0]) else: self.hby.db.epse.rem(dig) self.hby.db.esigs.rem(dig) logger.info("Exchanger unescrow succeeded in valid exchange: " - "creder=\n%s\n", serder.pretty()) + "creder=%s", serder.said) + logger.debug(f"event=\n{serder.pretty()}\n") def logEvent(self, serder, pathed=None, tsgs=None, cigars=None): dig = serder.said diff --git a/src/keri/vdr/credentialing.py b/src/keri/vdr/credentialing.py index 8a85c8e54..7200f8192 100644 --- a/src/keri/vdr/credentialing.py +++ b/src/keri/vdr/credentialing.py @@ -232,7 +232,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(f"event=\n{serder.pretty()}\n") 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 3bd5ab55f..278eb4bac 100644 --- a/src/keri/vdr/eventing.py +++ b/src/keri/vdr/eventing.py @@ -1265,8 +1265,9 @@ 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 state: %s Added to TEL valid event=\n%s\n", - pre, json.dumps(serder.ked, indent=1)) + logger.info("Tever state: %s Added to TEL valid said=%s", + pre, serder.said) + logger.debug(f"event=\n{serder.pretty()}\n") def valAnchorBigs(self, serder, seqner, saider, bigers, toad, baks): """ Validate anchor and backer signatures (bigers) when provided. @@ -1394,8 +1395,8 @@ def escrowPWEvent(self, serder, seqner, saider, bigers=None): self.reger.putTibs(dgkey, [biger.qb64b for biger in bigers]) self.reger.putTvt(dgkey, serder.raw) self.reger.putTwe(snKey(serder.preb, serder.sn), serder.saidb) - logger.info("Tever state: Escrowed partially witnessed " - "event = %s\n", serder.ked) + logger.debug("Tever state: Escrowed partially witnessed " + "event = %s", serder.ked) def escrowALEvent(self, serder, seqner, saider, bigers=None, baks=None): """ Update associated logs for escrow of anchorless event @@ -1421,8 +1422,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.debug("Tever state: Escrowed anchorless event " + "event = %s", serder.ked) return self.reger.putTae(snKey(serder.preb, serder.sn), serder.saidb) def getBackerState(self, ked): @@ -2005,8 +2006,8 @@ def escrowOOEvent(self, serder, seqner, saider): sealet = seqner.qb64b + saider.qb64b self.reger.putAnc(key, sealet) self.reger.putOot(snKey(serder.preb, serder.sn), serder.saidb) - logger.info("Tever state: Escrowed our of order TEL event " - "event = %s\n", serder.ked) + logger.debug("Tever state: Escrowed our of order TEL event " + "event = %s", serder.ked) def processEscrows(self): """ Loop through escrows and process and events that may now be finalized """ @@ -2027,9 +2028,9 @@ def processEscrows(self): except Exception as ex: # log diagnostics errors etc if logger.isEnabledFor(logging.DEBUG): - logger.exception("Tevery escrow process error: %s\n", ex.args[0]) + logger.exception("Tevery escrow process error: %s", ex.args[0]) else: - logger.error("Tevery escrow process error: %s\n", ex.args[0]) + logger.error("Tevery escrow process error: %s", ex.args[0]) def processEscrowOutOfOrders(self): """ Loop through out of order escrow: @@ -2050,7 +2051,7 @@ def processEscrowOutOfOrders(self): if traw is None: # no event so raise ValidationError which unescrows below logger.info("Tevery unescrow error: Missing event at." - "dig = %s\n", bytes(digb)) + "dig = %s", bytes(digb)) raise ValidationError("Missing escrowed evt at dig = {}." "".format(bytes(digb))) @@ -2064,7 +2065,7 @@ def processEscrowOutOfOrders(self): couple = self.reger.getAnc(dgkey) if couple is None: logger.info("Tevery unescrow error: Missing anchor at." - "dig = %s\n", bytes(digb)) + "dig = %s", bytes(digb)) raise ValidationError("Missing escrowed anchor at dig = {}." "".format(bytes(digb))) @@ -2077,17 +2078,17 @@ def processEscrowOutOfOrders(self): except OutOfOrderError as ex: # still waiting on missing prior event to validate if logger.isEnabledFor(logging.DEBUG): - logger.exception("Tevery unescrow failed: %s\n", ex.args[0]) + logger.exception("Tevery unescrow failed: %s", ex.args[0]) else: - logger.error("Tevery unescrow failed: %s\n", ex.args[0]) + logger.error("Tevery unescrow failed: %s", ex.args[0]) except Exception as ex: # log diagnostics errors etc # error other than out of order so remove from OO escrow self.reger.delOot(snKey(pre, sn)) # removes one escrow at key val if logger.isEnabledFor(logging.DEBUG): - logger.exception("Tevery unescrowed: %s\n", ex.args[0]) + logger.exception("Tevery unescrowed: %s", ex.args[0]) else: - logger.error("Tevery unescrowed: %s\n", ex.args[0]) + logger.error("Tevery unescrowed: %s", ex.args[0]) else: # unescrow succeeded, remove from escrow # We don't remove all escrows at pre,sn because some might be @@ -2095,7 +2096,8 @@ def processEscrowOutOfOrders(self): # valid event escrow. self.reger.delOot(snKey(pre, sn)) # removes from escrow logger.info("Tevery unescrow succeeded in valid event: " - "event=\n%s\n", json.dumps(tserder.ked, indent=1)) + "said=%s", tserder.said) + logger.debug(f"event=\n{tserder.pretty()}\n") def processEscrowAnchorless(self): """ Process escrow of TEL events received before the anchoring KEL event. @@ -2117,7 +2119,7 @@ def processEscrowAnchorless(self): if traw is None: # no event so raise ValidationError which unescrows below logger.info("Tevery unescrow error: Missing event at." - "dig = %s\n", bytes(digb)) + "dig = %s", bytes(digb)) raise ValidationError("Missing escrowed evt at dig = {}." "".format(bytes(digb))) @@ -2131,7 +2133,7 @@ def processEscrowAnchorless(self): couple = self.reger.getAnc(dgkey) if couple is None: logger.info("Tevery unescrow error: Missing anchor at." - "dig = %s\n", bytes(digb)) + "dig = %s", bytes(digb)) raise MissingAnchorError("Missing escrowed anchor at dig = {}." "".format(bytes(digb))) @@ -2144,17 +2146,17 @@ def processEscrowAnchorless(self): except MissingAnchorError as ex: # still waiting on missing prior event to validate if logger.isEnabledFor(logging.DEBUG): - logger.exception("Tevery unescrow failed: %s\n", ex.args[0]) + logger.exception("Tevery unescrow failed: %s", ex.args[0]) else: - logger.error("Tevery unescrow failed: %s\n", ex.args[0]) + logger.error("Tevery unescrow failed: %s", ex.args[0]) except Exception as ex: # log diagnostics errors etc # error other than out of order so remove from OO escrow self.reger.delTae(snKey(pre, sn)) # removes one escrow at key val if logger.isEnabledFor(logging.DEBUG): - logger.exception("Tevery unescrowed: %s\n", ex.args[0]) + logger.exception("Tevery unescrowed: %s", ex.args[0]) else: - logger.error("Tevery unescrowed: %s\n", ex.args[0]) + logger.error("Tevery unescrowed: %s", ex.args[0]) else: # unescrow succeeded, remove from escrow # We don't remove all escrows at pre,sn because some might be @@ -2162,4 +2164,5 @@ def processEscrowAnchorless(self): # valid event escrow. self.reger.delTae(snKey(pre, sn)) # removes from escrow logger.info("Tevery unescrow succeeded in valid event: " - "event=\n%s\n", json.dumps(tserder.ked, indent=1)) + "said=%s", tserder.said) + logger.debug(f"event=\n{tserder.pretty()}\n") diff --git a/src/keri/vdr/verifying.py b/src/keri/vdr/verifying.py index 7f1c1a237..e9bdf5858 100644 --- a/src/keri/vdr/verifying.py +++ b/src/keri/vdr/verifying.py @@ -255,7 +255,7 @@ def _processEscrow(self, db, timeout, etype: Type[Exception]): if (dtnow - dte) > datetime.timedelta(seconds=timeout): # escrow stale so raise ValidationError which unescrows below logger.info("Verifier unescrow error: Stale event escrow " - " at said = %s\n", said) + " at said = %s", said) raise kering.ValidationError("Stale event escrow " "at said = {}.".format(said)) @@ -264,20 +264,21 @@ def _processEscrow(self, db, timeout, etype: Type[Exception]): except etype as ex: if logger.isEnabledFor(logging.DEBUG): - logger.exception("Verifiery unescrow failed: %s\n", ex.args[0]) + logger.exception("Verifiery unescrow failed: %s", ex.args[0]) else: - logger.error("Verifier unescrow failed: %s\n", ex.args[0]) + logger.error("Verifier unescrow failed: %s", ex.args[0]) except Exception as ex: # log diagnostics errors etc # error other than missing sigs so remove from PA escrow db.rem(said) if logger.isEnabledFor(logging.DEBUG): - logger.exception("Verifier unescrowed: %s\n", ex.args[0]) + logger.exception("Verifier unescrowed: %s", ex.args[0]) else: - logger.error("Verifier unescrowed: %s\n", ex.args[0]) + logger.error("Verifier unescrowed: %s", ex.args[0]) 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(f"event=\n{creder.pretty()}\n") def saveCredential(self, creder, prefixer, seqner, saider): """ Write the credential and associated indicies to the database