Skip to content

Commit

Permalink
feat: add TRACE log level and turn down some escrow logs
Browse files Browse the repository at this point in the history
  • Loading branch information
@kentbull
kentbull committed Jan 28, 2025
1 parent 5ba1d5e commit e0c5fde
Show file tree
Hide file tree
Showing 9 changed files with 213 additions and 185 deletions.
2 changes: 2 additions & 0 deletions src/keri/app/cli/commands/challenge/respond.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,7 @@

from hio.base import doing

from keri import help
from keri.app import habbing, forwarding, connecting
from keri.app.cli.common import existing
from keri.app.habbing import GroupHab
Expand All @@ -26,6 +27,7 @@
parser.add_argument('--recipient', '-r', help='Contact alias of the AID to send the signed words to',
action="store", required=True)

logger = help.ogler.getLogger()

def respond(args):
"""
Expand Down
259 changes: 130 additions & 129 deletions src/keri/core/eventing.py
View file

Large diffs are not rendered by default.

26 changes: 21 additions & 5 deletions src/keri/core/parsing.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1007,8 +1007,10 @@ def msgParsator(self, ims=None, framed=True, pipeline=False,
# when present assumes this is source seal of delegating event in delegator's KEL
delseqner, delsaider = sscs[-1] if sscs else (None, None) # use last one if more than one
if not sigers:
raise kering.ValidationError("Missing attached signature(s) for evt "
"= {}.".format(serder.ked))
msg = f"Missing attached signature(s) for evt = {serder.ked['d']}"
logger.info("Parser: %s", msg)
logger.debug("Event Body = \n%s\n", serder.pretty())
raise kering.ValidationError(msg)
try:
kvy.processEvent(serder=serder,
sigers=sigers,
Expand All @@ -1027,13 +1029,15 @@ def msgParsator(self, ims=None, framed=True, pipeline=False,
firner=firner, local=local)

except AttributeError as ex:
raise kering.ValidationError("No kevery to process so dropped msg"
"= {}.".format(serder.pretty())) from ex
msg = f"No kevery to process so dropped msg={serder.said}"
logger.info("Parser: %s", 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(msg)
logger.info("Parser: %s", msg)
logger.debug("Receipt body=\n%s\n", serder.pretty())
raise kering.ValidationError(msg)

Expand All @@ -1053,6 +1057,12 @@ def msgParsator(self, ims=None, framed=True, pipeline=False,
except AttributeError:
raise kering.ValidationError("No kevery to process so dropped msg"
"= {}.".format(serder.pretty()))
except kering.UnverifiedReplyError as e:
if logger.isEnabledFor(logging.DEBUG):
logger.exception("Error processing reply = %s", e)
logger.debug("Reply Body=\n%s\n", serder.pretty())
else:
logger.error("Error processing reply = %s", e)

elif ilk in (Ilks.rpy,): # reply message
if not (cigars or tsgs):
Expand Down Expand Up @@ -1098,6 +1108,12 @@ def msgParsator(self, ims=None, framed=True, pipeline=False,
except AttributeError as e:
raise kering.ValidationError("No tevery to process so dropped msg"
"= {} from {}.".format(serder.pretty(), e))
except kering.QueryNotFoundError as e: # catch escrow error and log it
if logger.isEnabledFor(logging.TRACE):
logger.exception("Error processing query = %s", e)
logger.trace("Query Body=\n%s\n", serder.pretty())
else:
logger.error("Error processing query = %s", e)

else:
raise kering.ValidationError("Invalid resource type {} so dropped msg"
Expand Down
28 changes: 14 additions & 14 deletions src/keri/core/routing.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -267,31 +267,31 @@ 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("Revery: skipped own attachment "
"on nonlocal reply said=", serder.said)
logger.debug("event=\n%s\n", serder.pretty())
logger.info("Revery: skipped own attachment for AID %s"
" on non-local reply at route = %s", aid, serder.ked['r'])
logger.debug("Reply Body=\n%s\n", serder.pretty())

continue # skip own cig attachment on non-local reply msg

if aid != cigar.verfer.qb64: # cig not by aid
logger.debug("Revery: skipped cig not from aid = "
"%s on reply said=%s", aid, serder.said)
logger.debug("event=\n%s\n", serder.pretty())
logger.info("Revery: skipped cig not from aid="
"%s on reply at route %s", aid, serder.ked['r'])
logger.debug("Reply Body=\n%s\n", serder.pretty())
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.debug("Revery: skipped stale update from "
"%s of reply said=%s", aid, serder.said)
logger.debug("event=\n%s\n", serder.pretty())
logger.trace("Revery: skipped stale update from "
"%s of reply at route= %s", aid, serder.ked['r'])
logger.trace("Reply Body=\n%s\n", serder.pretty())
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.debug("Revery: skipped non-verifying cig from "
"%s on reply said=%s", cigar.verfer.qb64, serder.said)
logger.debug("event=\n%s\n", serder.pretty())
logger.info("Revery: skipped non-verifying cig from "
"%s on reply at route = %s", cigar.verfer.qb64, serder.ked['r'])
logger.debug("Reply Body=\n%s\n", serder.pretty())
continue # skip if cig not verify

# All constraints satisfied so update
Expand Down Expand Up @@ -494,8 +494,8 @@ 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", ex.args[0])
if logger.isEnabledFor(logging.TRACE):
logger.trace("Kevery unescrow attempt failed: %s\n", 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
Expand Down
9 changes: 5 additions & 4 deletions src/keri/db/escrowing.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -104,16 +104,17 @@ def processEscrowState(self, typ, processReply, extype: Type[Exception]):
if ((helping.nowUTC() - dater.datetime) >
datetime.timedelta(seconds=self.timeout)):
# escrow stale so raise ValidationError which unescrows below
msg = f"Stale txn state escrow at pre = {pre}."
logger.info("Broker %s: unescrow error %s", typ, msg)
msg = f"Escrow unescrow error: Stale txn state escrow at pre = {pre}"
logger.trace("Broker %s: %s", typ, msg)
raise kering.ValidationError(msg)

processReply(serder=serder, saider=saider, route=serder.ked["r"],
cigars=cigars, tsgs=tsgs, aid=aid)

except extype as ex:
# still waiting on missing prior event to validate
if logger.isEnabledFor(logging.DEBUG):
if logger.isEnabledFor(logging.TRACE):
logger.trace("Broker %s: unescrow attempt failed: %s\n", typ, ex.args[0])
logger.exception("Broker %s: unescrow attempt failed: %s", typ, ex.args[0])

except Exception as ex: # other error so remove from reply escrow
Expand All @@ -127,7 +128,7 @@ def processEscrowState(self, typ, processReply, extype: Type[Exception]):
self.escrowdb.rem(keys=(typ, pre, aid), val=saider) # remove escrow
logger.info("Broker %s: unescrow succeeded for txn state=%s",
typ, serder.said)
logger.debug("event=\n%s\n", serder.pretty())
logger.debug("TXN State Body=\n%s\n", serder.pretty())

except Exception as ex: # log diagnostics errors etc
self.escrowdb.rem(keys=(typ, pre, aid), val=saider) # remove escrow
Expand Down
14 changes: 13 additions & 1 deletion src/keri/help/__init__.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -6,13 +6,25 @@
utility functions
"""
import logging

# Setup module global ogler as package logger factory. This must be done on
# import to ensure global is defined so all modules in package have access to
# logggers via ogling.ogler.getLoggers(). May always change level and reopen log file
# if need be

from hio.help import ogling


# Custom TRACE log level configuration
TRACE = 5 # TRACE (5) logging level value between DEBUG (10) and NOTSET (0)
logging.TRACE = TRACE # add TRACE logging level to logging module
logging.addLevelName(logging.TRACE, "TRACE")
def trace(self, message, *args, **kwargs):
"""Trace logging function - logs message if TRACE (5) level enabled"""
if self.isEnabledFor(TRACE):
self._log(TRACE, message, args, **kwargs)
logging.Logger.trace = trace

# want help.ogler always defined by default
ogler = ogling.initOgler(prefix='keri', syslogged=False) # inits once only on first import

Expand Down
9 changes: 4 additions & 5 deletions src/keri/peer/exchanging.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -159,7 +159,7 @@ def processEvent(self, serder, tsgs=None, cigars=None, **kwargs):
# Perform behavior specific verification, think IPEX chaining requirements
try:
if not behavior.verify(serder=serder, **kwargs):
logger.info("exn event for route %s failed behavior verification. said=%s", route, serder.said)
logger.error("exn event for route %s failed behavior verification. said=%s", route, serder.said)
logger.debug(f"Event=\n%s\n", serder.pretty())
return

Expand Down Expand Up @@ -248,10 +248,9 @@ def processEscrowPartialSigned(self):
self.processEvent(serder=serder, tsgs=tsgs, pathed=pathed, **kwargs)

except MissingSignatureError as ex:
if logger.isEnabledFor(logging.DEBUG):
logger.info("Exchanger: partially signed unescrow failed: %s", ex.args[0])
else:
logger.info("Exchanger: partially signed failed: %s", ex.args[0])
if logger.isEnabledFor(logging.TRACE):
logger.trace("Exchange partially signed unescrow failed: %s\n", ex.args[0])
logger.debug(f"Event body=\n%s\n", serder.pretty())
except Exception as ex:
self.hby.db.epse.rem(dig)
self.hby.db.epsd.rem(dig)
Expand Down
42 changes: 20 additions & 22 deletions src/keri/vdr/eventing.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1255,7 +1255,7 @@ def logEvent(self, pre, sn, serder, seqner, saider, bigers=None, baks=None):
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.debug("event=\n%s\n", serder.pretty())
logger.debug("TEL Event Body=\n%s\n", serder.pretty())

def valAnchorBigs(self, serder, seqner, saider, bigers, toad, baks):
""" Validate anchor and backer signatures (bigers) when provided.
Expand Down Expand Up @@ -1306,12 +1306,11 @@ def valAnchorBigs(self, serder, seqner, saider, bigers, toad, baks):

if len(bindices) < toad: # not fully witnessed yet
self.escrowPWEvent(serder=serder, seqner=seqner, saider=saider, bigers=bigers)

raise MissingWitnessSignatureError("Failure satisfying toad = {} "
"on witness sigs for {} for evt = {}.".format(toad,
[siger.qb64 for siger
in bigers],
serder.ked))
msg = (f"Failure satisfying toad = {toad} on witness sigs "
f"for {[siger.qb64 for siger in bigers]} for evt = {serder.said}")
logger.info("Tever: %s", msg)
logger.debug(f"Event Body=\n%s\n", serder.pretty())
raise MissingWitnessSignatureError(msg)
return bigers

def verifyAnchor(self, serder, seqner=None, saider=None):
Expand Down Expand Up @@ -2071,25 +2070,24 @@ 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", ex.args[0])
else:
logger.error("Tevery unescrow failed: %s", ex.args[0])
if logger.isEnabledFor(logging.TRACE):
logger.trace("Tevery: OOO unescrow failed: %s\n", ex.args[0])
logger.exception("Tevery: OOO 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.reger.delOot(snKey(pre, sn)) # removes one escrow at key val
if logger.isEnabledFor(logging.DEBUG):
logger.exception("Tevery unescrowed: %s", ex.args[0])
logger.exception("Tevery: OOO unescrowed: %s", ex.args[0])
else:
logger.error("Tevery unescrowed: %s", ex.args[0])
logger.error("Tevery: OOO 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.reger.delOot(snKey(pre, sn)) # removes from escrow
logger.info("Tevery OOO unescrow succeeded in valid event: "
logger.info("Tevery: OOO unescrow succeeded in valid event: "
"said=%s", tserder.said)
logger.debug("Event=\n%s\n", tserder.pretty())

Expand All @@ -2113,8 +2111,8 @@ def processEscrowAnchorless(self):
traw = self.reger.getTvt(dgkey)
if traw is None:
# no event so raise ValidationError which unescrows below
msg = f"Missing escrowed event at dig = {bytes(digb).decode()}"
logger.info("Tevery unescrow error: %s", msg)
msg = f"ANC Missing escrowed event at dig = {bytes(digb).decode()}"
logger.trace("Tevery unescrow error: %s", msg)
raise ValidationError(msg)

tserder = serdering.SerderKERI(raw=bytes(traw)) # escrowed event
Expand All @@ -2125,8 +2123,8 @@ def processEscrowAnchorless(self):

couple = self.reger.getAnc(dgkey)
if couple is None:
msg = f"Missing escrowed anchor at dig = {bytes(digb).decode()}"
logger.info("Tevery unescrow error: %s", msg)
msg = f"ANC Missing escrowed anchor at dig = {bytes(digb).decode()}"
logger.trace("Tevery unescrow error: %s", msg)
raise MissingAnchorError(msg)
ancb = bytearray(couple)
seqner = coring.Seqner(qb64b=ancb, strip=True)
Expand All @@ -2137,17 +2135,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", ex.args[0])
logger.exception("Tevery ANC unescrow failed: %s", ex.args[0])
else:
logger.error("Tevery unescrow failed: %s", ex.args[0])
logger.error("Tevery ANC 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", ex.args[0])
logger.exception("Tevery ANC unescrowed: %s", ex.args[0])
else:
logger.error("Tevery unescrowed: %s", ex.args[0])
logger.error("Tevery ANC unescrowed: %s", ex.args[0])

else: # unescrow succeeded, remove from escrow
# We don't remove all escrows at pre,sn because some might be
Expand Down
9 changes: 4 additions & 5 deletions src/keri/vdr/verifying.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -263,10 +263,9 @@ def _processEscrow(self, db, timeout, etype: Type[Exception]):
self.processCredential(creder, prefixer, seqner, saider)

except etype as ex:
if logger.isEnabledFor(logging.DEBUG):
logger.exception("Verifiery unescrow failed: %s", ex.args[0])
else:
logger.error("Verifier unescrow failed: %s", ex.args[0])
if logger.isEnabledFor(logging.TRACE):
logger.trace("Verifier unescrow failed: %s\n", ex.args[0])
logger.exception("Verifier unescrow failed: %s\n", ex.args[0])
except Exception as ex: # log diagnostics errors etc
# error other than missing sigs so remove from PA escrow
db.rem(said)
Expand All @@ -278,7 +277,7 @@ def _processEscrow(self, db, timeout, etype: Type[Exception]):
db.rem(said)
logger.info("Verifier unescrow succeeded in valid group op: "
"creder=%s", creder.said)
logger.debug(f"event=\n{creder.pretty()}\n")
logger.debug(f"Event=\n%s\n", creder.pretty())

def saveCredential(self, creder, prefixer, seqner, saider):
""" Write the credential and associated indicies to the database
Expand Down

0 comments on commit e0c5fde

Please sign in to comment.