Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

refactor: move escrow logs to TRACE and msg body logs to DEBUG #913

Merged
merged 4 commits into from
Jan 2, 2025
Merged

refactor: move escrow logs to TRACE and msg body logs to DEBUG #913

Show file tree
Hide file tree
Changes from 3 commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
1550ac1
refactor: move escrow logs to TRACE and msg body logs to DEBUG
kentbull Dec 23, 2024
2b7e0ca
refactor: move some qnf error bodies and TEL success body to debug
kentbull Dec 26, 2024
30a51b1
refactor: move Likely Duplicitous Event bodies to DEBUG
kentbull Dec 26, 2024
41a85e4
refactor: add a few more logging changes
kentbull Dec 31, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
646 changes: 294 additions & 352 deletions src/keri/core/eventing.py
View file
Open in desktop

Large diffs are not rendered by default.

25 changes: 18 additions & 7 deletions src/keri/core/parsing.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -6,7 +6,6 @@
"""

import logging
import traceback
from collections import namedtuple
from dataclasses import dataclass, astuple

Expand Down Expand Up @@ -1020,8 +1019,8 @@ 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))
logger.debug("Parser: Missing attached signature(s) for evt = \n%s\n", serder.ked)
raise kering.ValidationError(f"Missing attached signature(s) for evt={serder.ked['d']}")
try:
kvy.processEvent(serder=serder,
sigers=sigers,
Expand All @@ -1037,13 +1036,13 @@ def msgParsator(self, ims=None, framed=True, pipeline=False,
kvy.processReceiptQuadruples(serder, trqs, firner=firner)

except AttributeError as ex:
raise kering.ValidationError("No kevery to process so dropped msg"
"= {}.".format(serder.pretty())) from ex
logger.debug("Parser: No kevery to process so dropped msg = %s", serder.pretty())
raise kering.ValidationError(f"No kevery to process so dropped msg={serder.ked['d']}") from ex

elif ilk in [Ilks.rct]: # event receipt msg (nontransferable)
if not (cigars or wigers or tsgs):
raise kering.ValidationError("Missing attached signatures on receipt"
"msg = {}.".format(serder.ked))
logger.debug("Parser: Missing attached signatures on receipt msg = %s.", serder.ked)
raise kering.ValidationError(f"Missing attached sigs on receipt msg={serder.ked['d']}")

try:
if cigars:
Expand Down Expand Up @@ -1074,6 +1073,12 @@ def msgParsator(self, ims=None, framed=True, pipeline=False,
except AttributeError as e:
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.qry,): # query message
args = dict(serder=serder)
Expand All @@ -1096,6 +1101,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.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)

elif route in ["tels", "tsn"]:
try:
Expand Down
27 changes: 15 additions & 12 deletions src/keri/core/routing.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -183,7 +183,7 @@ def processReply(self, serder, cigars=None, tsgs=None):
Escrow process logic is route dependent and is dispatched by route,
i.e. route is address of buffer with route specific handler of escrow.
"""
for k in eventing.RPY_LABELS:
for k in kering.RPY_LABELS:
if k not in serder.ked:
raise kering.ValidationError(f"Missing element={k} from {coring.Ilks.rpy}"
f" msg={serder.ked}.")
Expand Down Expand Up @@ -265,26 +265,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())
logger.info("Kevery: 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.info("Kevery process: skipped cig not from aid="
"%s on reply msg=\n%s\n", aid, serder.pretty())
logger.info("Kevery: 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.info("Kevery process: skipped stale update from "
"%s of reply msg=\n%s\n", aid, serder.pretty())
logger.trace("Kevery: 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.info("Kevery process: skipped nonverifying cig from "
"%s on reply msg=\n%s\n", cigar.verfer.qb64, serder.pretty())
logger.info("Kevery: 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 @@ -482,10 +486,9 @@ def processEscrowReply(self):

except kering.UnverifiedReplyError as ex:
# still waiting on missing prior event to validate
if logger.isEnabledFor(logging.DEBUG):
if logger.isEnabledFor(logging.TRACE):
logger.trace("Kevery unescrow attempt failed: %s\n", ex.args[0])
logger.exception("Kevery unescrow attempt failed: %s\n", ex.args[0])
else:
logger.error("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
29 changes: 14 additions & 15 deletions src/keri/db/escrowing.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -88,7 +88,7 @@ def processEscrowState(self, typ, processReply, extype: Type[Exception]):

try:
if not (dater and serder and (tsgs or vcigars)):
raise ValueError(f"Missing escrow artifacts at said={saider.qb64}"
raise ValueError(f"Broker: Missing escrow artifacts at said={saider.qb64}"
f"for pre={pre}.")

cigars = []
Expand All @@ -101,40 +101,39 @@ 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
logger.info("Kevery unescrow error: Stale txn state escrow "
" at pre = %s\n", pre)

raise kering.ValidationError(f"Stale txn state escrow at pre = {pre}.")
msg = f"Broker: {typ} escrow unescrow error: Stale txn state escrow at pre = {pre}"
logger.trace(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):
logger.exception("Kevery unescrow attempt failed: %s\n", ex.args[0])
else:
logger.error("Kevery unescrow attempt failed: %s\n", ex.args[0])
if logger.isEnabledFor(logging.TRACE):
logger.trace("Broker: %s escrow unescrow attempt failed: %s\n", typ, ex.args[0])
logger.exception("Broker: %s escrow unescrow attempt failed: %s\n", typ, ex.args[0])

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("Broker: %s escrow other error on unescrow: %s\n", typ, ex.args[0])
else:
logger.error("Kevery unescrowed due to error: %s\n", ex.args[0])
logger.error("Broker: %s escrow other error on unescrow: %s\n", typ, ex.args[0])

else: # unescrow succeded
self.escrowdb.remIokey(iokeys=(typ, pre, aid, ion)) # remove escrow only
logger.info("Kevery unescrow succeeded for txn state=\n%s\n",
serder.pretty())
logger.info("Broker: %s escrow unescrow succeeded for txn state=%s",
typ, serder.said)
logger.debug("TXN State Body=\n%s\n", serder.pretty())

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("Broker: %s escrow unescrowed due to error: %s\n", typ, ex.args[0])
else:
logger.error("Kevery unescrowed due to error: %s\n", ex.args[0])
logger.error("Broker: %s escrow unescrowed due to error: %s\n", typ, ex.args[0])

def escrowStateNotice(self, *, typ, pre, aid, serder, saider, dater, cigars=None, tsgs=None):
"""
Expand Down
12 changes: 12 additions & 0 deletions src/keri/help/__init__.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -13,6 +13,18 @@

from hio.help import ogling

import logging

# 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
28 changes: 14 additions & 14 deletions src/keri/peer/exchanging.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -121,11 +121,12 @@ 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 verification. exn={serder.said}")
logger.debug(f"exn body=\n{serder.ked}\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 exn={serder.said}")
logger.debug(f"exn Body=\n{serder.ked}\n")

# Always persis events
self.logEvent(serder, pathed, tsgs, cigars)
Expand All @@ -135,7 +136,9 @@ 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 exn={serder.said}")
logger.debug(
f"exn body=\n{serder.ked}\n")

def processEscrow(self):
""" Process all escrows for `exn` messages
Expand Down Expand Up @@ -187,24 +190,21 @@ def processEscrowPartialSigned(self):

try:
self.processEvent(serder=serder, tsgs=tsgs, pathed=pathed)

except MissingSignatureError as ex:
if logger.isEnabledFor(logging.DEBUG):
logger.info("Exchange partially signed unescrow failed: %s\n", ex.args[0])
else:
logger.info("Exchange partially signed failed: %s\n", ex.args[0])
logger.trace("Exchange partially signed unescrow failed: %s\n", ex.args[0])
if logger.isEnabledFor(logging.TRACE):
logger.debug(f"Event body=\n{serder.pretty()}\n")
except Exception as ex:
self.hby.db.epse.rem(dig)
self.hby.db.esigs.rem(dig)
logger.info("Exchange partially signed unescrowed: %s\n", ex.args[0])
if logger.isEnabledFor(logging.DEBUG):
logger.info("Exchange partially signed unescrowed: %s\n", ex.args[0])
else:
logger.info("Exchange partially signed unescrowed: %s\n", ex.args[0])
logger.debug(f"Event body=\n{serder.pretty()}\n")
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())
logger.info(f"Exchanger unescrow succeeded in valid exchange: serder={serder.said}")
logger.debug(f"Serder Body=\n{serder.pretty()}\n")

def logEvent(self, serder, pathed=None, tsgs=None, cigars=None):
dig = serder.said
Expand Down
Loading
Loading