feat: add consistent logging at INFO and DEBUG levels

The goal is to make viewing the logs at the INFO level nice when manually reviewing log output and to make the DEBUG output comprehensive for everything except escrow logging.

Author: kentbull

src/keri/app/cli/commands/ipex/join.py

@@ -104,7 +104,7 @@ def joinDo(self, tymth, tock=0.0):
         self.tock = tock
         _ = (yield self.tock)
 
-        print("Waiting for group ipex events...")
+        print("IPEX JoinDoer: Waiting for group ipex events...")
 
         while True:
 

src/keri/app/cli/commands/multisig/incept.py

@@ -156,7 +156,7 @@ def inceptDo(self, tymth, tock=0.0):
                                   serder=exn,
                                   attachment=ims)
 
-            print(f"Group identifier inception initialized for {ghab.pre}")
+            logger.info(f"MS Incept: Group identifier inception initialized for {ghab.pre}")
             prefixer = coring.Prefixer(qb64=ghab.pre)
             seqner = coring.Seqner(sn=0)
             saider = coring.Saider(qb64=prefixer.qb64)

src/keri/app/cli/commands/multisig/join.py

@@ -111,7 +111,7 @@ def joinDo(self, tymth, tock=0.0):
         self.tock = tock
         _ = (yield self.tock)
 
-        print("Waiting for group multisig events...")
+        print("MS JoinDoer: Waiting for group multisig events...")
 
         while self.notifier.noter.notes.cntAll() == 0:
             yield self.tock

src/keri/app/delegating.py

@@ -188,7 +188,7 @@ def processPartialWitnessEscrow(self):
                             witnessed = True
                     if not witnessed:
                         continue
-                print(f"Witness receipts complete, {pre} confirmed.")
+                print(f"Sealer: 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))
 

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"Counselor: Multisig start; Waiting for other signatures for {serder.ilk} {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"Counselor: 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.delegator, anchor=anchor)
 
-                    print("Waiting for delegation approval...")
+                    logger.info(f"Counselor: 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"Counselor: 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"Counselor: 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"Counselor: 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"Counselor: Delegation approval for {pre} received.")
 
                     # Move to escrow waiting for witness receipts
-                    print(f"Waiting for witness receipts for {pre}")
+                    logger.info(f"Counselor: 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"Counselor: 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:
@@ -243,6 +243,7 @@ def handle(self, serder, attachments=None):
             attachments (list): list of tuples of pather, CESR SAD path attachments to the exn event
 
         """
+        logger.info("MultisigNotificationHandler: handling %s event SAID=%s", self.resource, serder.said)
         self.mux.add(serder=serder)
 
 

src/keri/core/eventing.py

@@ -2294,7 +2294,7 @@ def valSigsDelWigs(self, serder, sigers, verfers, tholder,
             if delseqner and delsaider:
                 self.escrowPACouple(serder=serder, seqner=delseqner, saider=delsaider)
             msg=(f"Failure satisfying sith = {tholder.sith} "
-                 f"on sigs {[siger.qb64 for siger in sigers]}"
+                 f"on sigs {[siger.qb64 for siger in sigers]} "
                  f"for evt = {serder.said}")
             logger.trace(msg)
             logger.trace("Event Body=\n%s\n", serder.pretty())
@@ -2496,8 +2496,9 @@ def validateDelegation(self, serder, sigers, wigers=None, delseqner=None, delsai
         # during initial delegation we just escrow the delcept event
         if delseqner is None and delsaider is None and delegator is not None:
             self.escrowPSEvent(serder=serder, sigers=sigers, wigers=wigers)
-            raise MissingDelegationError("No delegation seal for delegator {} "
-                                         "with evt = {}.".format(delegator, serder.ked))
+            msg = (f"No delegation seal for delegator {delegator} with event = {serder.said}")
+            logger.debug("Event Body=\n%s\n", serder.pretty())
+            raise MissingDelegationError(msg)
 
         ssn = validateSN(sn=delseqner.snh, inceptive=False)  # delseqner Number should already do this
         #ssn = sner.num sner is Number seqner is Seqner need to replace Seqners with Numbers
@@ -2710,12 +2711,13 @@ def logEvent(self, serder, sigers=None, wigers=None, wits=None, first=False,
                 dtsb = dater.dtsb
             self.db.setDts(dgkey, dtsb)  # first seen so set dts to now
             self.db.fons.pin(keys=dgkey, val=Seqner(sn=fn))
-            logger.info("Kever: First seen ordinal %s dig: %s at %s",
-                        fn, serder.pre, dtsb.decode())
+            logger.debug("Kever: First seen %s %s SAID=%s for %s at %s",
+                         fn, serder.ilk, serder.said, serder.pre, dtsb.decode("utf-8"))
             logger.debug("Event Body=\n%s\n", serder.pretty())
         self.db.addKe(snKey(serder.preb, serder.sn), serder.saidb)
-        logger.info("Kever: Added to KEL valid %s event %s for AID %s", serder.ilk, serder.said, serder.pre)
-        logger.debug("KEL Event Body=\n%s\n", serder.pretty())
+        logger.info("Kever [%.8s]: Added to KEL %s at sn=%s valid event SAID=%s for AID %s",
+                    self.prefixer.qb64, serder.ilk, serder.sn, serder.said, serder.pre)
+        logger.debug("Event Body=\n%s\n", serder.pretty())
         return (fn, dtsb.decode("utf-8"))  # (fn int, dts str) if first else (None, dts str)
 
     def escrowPSEvent(self, serder, sigers, wigers=None):
@@ -2736,7 +2738,7 @@ def escrowPSEvent(self, serder, sigers, wigers=None):
         self.db.putEvt(dgkey, serder.raw)
         snkey = snKey(serder.preb, serder.sn)
         self.db.addPse(snkey, serder.saidb)  # b'EOWwyMU3XA7RtWdelFt-6waurOTH_aW_Z9VTaU-CshGk.00000000000000000000000000000001'
-        logger.info("Kever: Escrowed partially signed or delegated "
+        logger.debug("Kever: Escrowed partially signed or delegated "
                     "event %s for AID %s", serder.said, serder.pre)
         logger.debug("Event Body=\n%s\n", serder.pretty())
 
@@ -5037,7 +5039,7 @@ def processEscrowUnverWitness(self):
                     # valid event escrow.
                     self.db.delUwe(snKey(pre, sn), ecouple)  # removes one escrow at key val
                     logger.info("Kevery: unver wit escrow 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
@@ -5200,7 +5202,7 @@ def processEscrowUnverNonTrans(self):
                     # valid event escrow.
                     self.db.delUre(snKey(pre, sn), etriplet)  # removes one escrow at key val
                     logger.info("Kevery: unver nontrans escrow 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
@@ -5578,7 +5580,8 @@ def processEscrowUnverTrans(self):
                     # 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: unver trans escrow unescrow succeeded for event = %s\n", serder.ked)
+                    logger.info("Kevery: unver trans escrow unescrow succeeded for event = %s", serder.said)
+                    logger.debug("Event Body= \n%s\n", serder.pretty())
 
             if ekey == key:  # still same so no escrows found on last while iteration
                 break

src/keri/core/parsing.py

@@ -1041,7 +1041,7 @@ def msgParsator(self, ims=None, framed=True, pipeline=False,
 
             elif ilk in [Ilks.rct]:  # event receipt msg (nontransferable)
                 if not (cigars or wigers or tsgs):
-                    logger.debug("Parser: Missing attached signatures on receipt msg = %s.", serder.ked)
+                    logger.debug("Parser: Missing attached signatures on receipt msg event =\n%s\n", serder.pretty())
                     raise kering.ValidationError(f"Missing attached sigs on receipt msg={serder.ked['d']}")
 
                 try:
@@ -1055,13 +1055,17 @@ def msgParsator(self, ims=None, framed=True, pipeline=False,
                         kvy.processReceiptTrans(serder=serder, tsgs=tsgs)
 
                 except AttributeError:
-                    raise kering.ValidationError("No kevery to process so dropped msg"
-                                                 "= {}.".format(serder.pretty()))
+                    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)
 
             elif ilk in (Ilks.rpy,):  # reply message
                 if not (cigars or tsgs):
-                    raise kering.ValidationError("Missing attached endorser signature(s) "
-                                                 "to reply msg = {}.".format(serder.pretty()))
+                    msg = f"Missing attached endorser signature(s) to reply msg = {serder.said}"
+                    logger.info("Parser: %s", msg)
+                    logger.debug("Event body=\n%s\n", serder.pretty())
+                    raise kering.ValidationError(msg)
 
                 try:
                     if cigars:  # process separately so do not clash on errors
@@ -1071,8 +1075,10 @@ def msgParsator(self, ims=None, framed=True, pipeline=False,
                         rvy.processReply(serder, tsgs=tsgs)  # trans
 
                 except AttributeError as e:
-                    raise kering.ValidationError("No kevery to process so dropped msg"
-                                                 "= {}.".format(serder.pretty()))
+                    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)
                 except kering.UnverifiedReplyError as e:
                     if logger.isEnabledFor(logging.DEBUG):
                         logger.exception("Error processing reply = %s", e)
@@ -1091,16 +1097,20 @@ def msgParsator(self, ims=None, framed=True, pipeline=False,
                     args["cigars"] = cigars
 
                 else:
-                    raise kering.ValidationError("Missing attached requester signature(s) "
-                                                 "to key log query msg = {}.".format(serder.pretty()))
+                    msg = f"Missing attached requester signature(s) to key log query msg = {serder.said}"
+                    logger.info("Parser: %s", msg)
+                    logger.debug("Event body=\n%s\n", serder.pretty())
+                    raise kering.ValidationError(msg)
 
                 route = serder.ked["r"]
                 if route in ["logs", "ksn", "mbx"]:
                     try:
                         kvy.processQuery(**args)
                     except AttributeError:
-                        raise kering.ValidationError("No kevery to process so dropped msg"
-                                                     "= {}.".format(serder.pretty()))
+                        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)
                     except kering.QueryNotFoundError as e: # catch escrow error and log it
                         if logger.isEnabledFor(logging.TRACE):
                             logger.exception("Error processing query = %s", e)
@@ -1112,12 +1122,16 @@ def msgParsator(self, ims=None, framed=True, pipeline=False,
                     try:
                         tvy.processQuery(**args)
                     except AttributeError as e:
-                        raise kering.ValidationError("No tevery to process so dropped msg"
-                                                     "= {} from {}.".format(serder.pretty(), e))
+                        msg = f"No tevery to process so dropped msg = {serder.said} from {e}"
+                        logger.info("Parser: %s", msg)
+                        logger.debug("Event body=\n%s\n", serder.pretty())
+                        raise kering.ValidationError(msg)
 
                 else:
-                    raise kering.ValidationError("Invalid resource type {} so dropped msg"
-                                                 "= {}.".format(route, serder.pretty()))
+                    msg = f"Invalid resource type {route} so dropped msg = {serder.said}"
+                    logger.info("Parser: %s", msg)
+                    logger.debug("Event body=\n%s\n", serder.pretty())
+                    raise kering.ValidationError(msg)
 
             elif ilk in (Ilks.exn,):
                 args = dict(serder=serder)
@@ -1132,8 +1146,10 @@ def msgParsator(self, ims=None, framed=True, pipeline=False,
                         exc.processEvent(tsgs=tsgs, **args)
 
                 except AttributeError:
-                    raise kering.ValidationError("No Exchange to process so dropped msg"
-                                                 "= {}.".format(serder.pretty()))
+                    msg = "No Exchange 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)
 
             elif ilk in (Ilks.vcp, Ilks.vrt, Ilks.iss, Ilks.rev, Ilks.bis, Ilks.brv):
                 # TEL msg
@@ -1143,11 +1159,15 @@ def msgParsator(self, ims=None, framed=True, pipeline=False,
                     tvy.processEvent(serder=serder, seqner=seqner, saider=saider, wigers=wigers)
 
                 except AttributeError as e:
-                    raise kering.ValidationError("No tevery to process so dropped msg"
-                                                 "= {}.".format(serder.pretty()))
+                    msg = f"No Tevery 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)
             else:
-                raise kering.ValidationError("Unexpected message ilk = {} for evt ="
-                                             " {}.".format(ilk, serder.pretty()))
+                msg = f"Unexpected message ilk = {ilk} for evt = {serder.said}"
+                logger.info("Parser: %s", msg)
+                logger.debug("Event body=\n%s\n", serder.pretty())
+                raise kering.ValidationError(msg)
 
         elif isinstance(serder, serdering.SerderACDC):
             ilk = serder.ilk  # dispatch based on ilk
@@ -1157,14 +1177,20 @@ def msgParsator(self, ims=None, framed=True, pipeline=False,
                     prefixer, seqner, saider = ssts[-1] if ssts else (None, None, None)  # use last one if more than one
                     vry.processCredential(creder=serder, prefixer=prefixer, seqner=seqner, saider=saider)
                 except AttributeError as e:
-                    raise kering.ValidationError("No verifier to process so dropped credential"
-                                                 "= {}.".format(serder.pretty()))
+                    msg = f"No verifier to process so dropped credential {serder.said}"
+                    logger.info("Parser: %s", msg)
+                    logger.debug("Credential body=\n%s\n", serder.pretty())
+                    raise kering.ValidationError(msg)
             else:
-                raise kering.ValidationError("Unexpected message ilk = {} for evt ="
-                                             " {}.".format(ilk, serder.pretty()))
+                msg = f"Unexpected message ilk = {ilk} for evt = {serder.said}"
+                logger.info("Parser: %s", msg)
+                logger.debug("Event body=\n%s\n", serder.pretty())
+                raise kering.ValidationError(msg)
 
         else:
-            raise kering.ValidationError("Unexpected protocol type = {} for event message ="
-                                         " {}.".format(serder.proto, serder.pretty()))
+            msg = f"Unexpected protocol type = {serder.proto} for event message = {serder.said}"
+            logger.info("Parser: %s", msg)
+            logger.debug("Event body=\n%s\n", serder.pretty())
+            raise kering.ValidationError(msg)
 
         return True  # done state