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

src/keri/core/parsing.py

@@ -6,7 +6,6 @@
 """
 
 import logging
-import traceback
 from collections import namedtuple
 from dataclasses import dataclass, astuple
 
@@ -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,
@@ -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:
@@ -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)

src/keri/core/routing.py

@@ -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}.")
@@ -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
@@ -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

src/keri/db/escrowing.py

@@ -88,7 +88,7 @@ def processEscrowState(self, typ, processReply, extype: Type[Exception]):
 
                 try:
                     if not (dater and serder and (tsgs or vcigars)):
-                        raise ValueError(f"Missing escrow artifacts at said={saider.qb64}"
+                        raise ValueError(f"Broker: Missing escrow artifacts at said={saider.qb64}"
                                          f"for pre={pre}.")
 
                     cigars = []
@@ -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):
         """

src/keri/help/__init__.py

@@ -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
 

src/keri/peer/exchanging.py

@@ -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)
@@ -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
@@ -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