feat: adds TRACE logging level and adjust log levels for escrows

src/keri/app/cli/commands/challenge/respond.py

@@ -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
@@ -26,6 +27,8 @@
 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):
     """
@@ -112,6 +115,8 @@ def respondDo(self, tymth, tock=0.0, **opts):
         del ims[:exn.size]
 
         senderHab = hab.mhab if isinstance(hab, GroupHab) else hab
+        logger.info("RespondDoer: sending challenge exn from %s to %s", senderHab.pre, recp)
+        logger.debug("RespondDoer: Challenge exn body=\n%s\n", exn.pretty())
         self.postman.send(src=senderHab.pre, dest=recp, topic="challenge", serder=exn, attachment=ims)
         while not self.postman.cues:
             yield self.tock

src/keri/app/cli/commands/delegate/confirm.py

@@ -158,6 +158,10 @@ def confirmDo(self, tymth, tock=0.0):
                         others.remove(hab.mhab.pre)
 
                         for recpt in others:  # send notification to other participants as a signalling mechanism
+                            logger.info(
+                                "ConfirmDoer: sending confirm notification exn from %s to %s",
+                                hab.mhab.pre, recpt)
+                            logger.debug("ConfirmDoer: Notification exn body=\n%s\n", exn.pretty())
                             self.postman.send(src=hab.mhab.pre, dest=recpt, topic="multisig", serder=exn,
                                               attachment=atc)
 

src/keri/app/cli/commands/delegate/request.py

@@ -98,7 +98,17 @@ def requestDo(self, tymth, tock=0.0):
         # delegate AID ICP and exn of delegation request EXN
         srdr = serdering.SerderKERI(raw=evt)
         del evt[:srdr.size]
+
+        logger.info(
+            "RequestDoer: sending delegated inception from delegate %s to delegator %s",
+            phab.pre, delpre)
+        logger.debug("RequestDoer: Delegated inception body=\n%s\n", exn.pretty())
         self.postman.send(src=phab.pre, dest=delpre, topic="delegate", serder=srdr, attachment=evt)
+
+        logger.info(
+            "RequestDoer: sending request notification exn from delegate %s to delegator %s",
+            phab.pre, delpre)
+        logger.debug("RequestDoer: Notification exn body=\n%s\n", exn.pretty())
         self.postman.send(src=phab.pre, dest=hab.kever.delpre, topic="delegate", serder=exn, attachment=atc)
 
         while True:

src/keri/app/cli/commands/ends/add.py

@@ -103,6 +103,10 @@ def roleDo(self, tymth, tock=0.0):
 
             for recp in smids:  # this goes to other participants only as a signaling mechanism
                 exn, atc = grouping.multisigRpyExn(ghab=self.hab, rpy=msg)
+                logger.info(
+                    "RoleDoer: sending endpoint role add exn on %s from %s to %s",
+                    "multisig", self.hab.mhab.pre, recp)
+                logger.debug("RoleDoer: Endpoint Role Add Exn body=\n%s\n", exn.pretty())
                 self.postman.send(src=self.hab.mhab.pre,
                                   dest=recp,
                                   topic="multisig",

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/interact.py

@@ -119,6 +119,10 @@ def interactDo(self, tymth, tock=0.0):
         others.remove(ghab.mhab.pre)
 
         for recpt in others:  # send notification to other participants as a signalling mechanism
+            logger.info(
+                "GroupMultisigInteract: sending multisig interact exn from %s to %s",
+                ghab.mhab.pre, recpt)
+            logger.debug("GroupMultisigInteract: interact exn body=\n%s\n", exn.pretty())
             self.postman.send(src=ghab.mhab.pre, dest=recpt, topic="multisig", serder=exn, attachment=ims)
 
         prefixer = coring.Prefixer(qb64=ghab.pre)

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/cli/commands/multisig/rotate.py

@@ -43,7 +43,7 @@ def rotateGroupIdentifier(args):
     Performs a rotation on the group identifier specified as an argument.  The identifier prefix of the environment
     represented by the name parameter must be a member of the group identifier.  This command will perform a rotation
     of the local identifier if the sequence number of the local identifier is the same as the group identifier sequence
-    number.  It will wait for all other members of the group to acheive the same sequence number (group + 1) and then
+    number.  It will wait for all other members of the group to achieve the same sequence number (group + 1) and then
     publish the signed rotation event for the group identifier to all witnesses and wait for receipts.
 
     Parameters:

src/keri/app/delegating.py

@@ -172,7 +172,7 @@ def processPartialWitnessEscrow(self):
                             witnessed = True
                     if not witnessed:
                         continue
-                logger.info(f"Witness receipts complete, waiting for delegation approval.")
+                logger.info(f"Anchorer: Witness receipts complete, waiting for delegation approval.")
                 if pre not in self.hby.habs:
                     continue
 
@@ -190,12 +190,19 @@ def processPartialWitnessEscrow(self):
                     raise kering.ValidationError("no proxy to send messages for delegation")
 
                 evt = hab.db.cloneEvtMsg(pre=serder.pre, fn=0, dig=serder.said)
+                srdr = serdering.SerderKERI(raw=evt)
                 exn, atc = delegateRequestExn(phab, delpre=delpre, evt=bytes(evt), aids=smids)
 
+                logger.info(
+                    "Anchorer: Sending delegation request exn for %s from %s to delegator %s",
+                    srdr.ilk, phab.pre, delpre)
+                logger.debug("Delegation request=\n%s\n", exn.pretty())
                 self.postman.send(hab=phab, dest=hab.kever.delpre, topic="delegate", serder=exn, attachment=atc)
 
-                srdr = serdering.SerderKERI(raw=evt)
                 del evt[:srdr.size]
+                logger.info("Anchorer: Sending delegation event %s from %s to delegator %s",
+                            srdr.ilk, phab.pre, delpre)
+                logger.debug("Anchorer: Delegated inception=\n%s\n", srdr.pretty())
                 self.postman.send(hab=phab, dest=delpre, topic="delegate", serder=srdr, attachment=evt)
 
                 seal = dict(i=srdr.pre, s=srdr.snh, d=srdr.said)

src/keri/app/grouping.py

@@ -46,7 +46,11 @@ def start(self, ghab, prefixer, seqner, saider):
             saider (Saider): saider of event of group identifier
 
         """
-        print(f"Waiting for other signatures for {prefixer.qb64}:{seqner.sn}...")
+        evt = ghab.makeOwnEvent(sn=seqner.sn,
+                                allowPartiallySigned=True)  # used just for the log message
+        serder = serdering.SerderKERI(raw=evt)  # used just for the log message
+        logger.info(f"[Counselor {ghab.mhab.pre[:8]}]: Multisig start; "
+                    f"Waiting for other signatures for {serder.ilk} {prefixer.qb64}:{seqner.sn}...")
         return self.hby.db.gpse.add(keys=(prefixer.qb64,), val=(seqner, saider))
 
     def complete(self, prefixer, seqner, saider=None):
@@ -128,7 +132,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
-                        logger.info(f"We are the witnesser, sending {pre} to delegator")
+                        logger.info(f"[Counselor {ghab.mhab.pre[:8]}]: 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)
@@ -137,15 +141,15 @@ def processPartialSignedEscrow(self):
                         else:
                             self.witq.query(src=ghab.mhab.pre, pre=kever.delpre, anchor=anchor)
 
-                    logger.info("Waiting for delegation approval...")
+                    logger.info(f"[Counselor {ghab.mhab.pre[:8]}]: 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
-                        logger.info(f"We are the fully signed witnesser {seqner.sn}, sending to witnesses")
+                        logger.info(f"[Counselor {ghab.mhab.pre[:8]}]: 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
-                    logger.info(f"Waiting for fully signed witness receipts for {seqner.sn}")
+                    logger.info(f"[Counselor {ghab.mhab.pre[:8]}]: Waiting for fully signed witness receipts for {seqner.sn}")
                     self.hby.db.gpwe.add(keys=(pre,), val=(seqner, saider))
 
     def processDelegateEscrow(self):
@@ -165,7 +169,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,))
-                    logger.info(f"Delegation approval for {pre} received.")
+                    logger.info(f"[Counselor {ghab.mhab.pre[:8]}]: Delegation approval for {pre} received.")
 
                     self.hby.db.cgms.put(keys=(pre, seqner.qb64), val=saider)
 
@@ -177,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,))
-                    logger.info(f"Delegation approval for {pre} received.")
+                    logger.info(f"[Counselor {ghab.mhab.pre[:8]}]: Delegation approval for {pre} received.")
 
                     # Move to escrow waiting for witness receipts
-                    logger.info(f"Waiting for witness receipts for {pre}")
+                    logger.info(f"[Counselor {ghab.mhab.pre[:8]}]: Waiting for witness receipts for {pre}")
                     self.hby.db.gdee.rem(keys=(pre,))
                     self.hby.db.gpwe.add(keys=(pre,), val=(seqner, saider))
 
@@ -208,7 +212,7 @@ def processPartialWitnessEscrow(self):
                             witnessed = True
                     if not witnessed:
                         continue
-                logger.info(f"Witness receipts complete, {pre} confirmed.")
+                logger.info(f"[Counselor {ghab.mhab.pre[:8]}]: 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:
@@ -239,6 +243,8 @@ def handle(self, serder, attachments=None):
             attachments (list): list of tuples of pather, CESR SAD path attachments to the exn event
 
         """
+        logger.info("MS Note Hdlr: %s handling event SAID=%s", self.resource, serder.said)
+        logger.debug("MS Note Hdlr: EXN Body=\n%s\n", serder.pretty())
         self.mux.add(serder=serder)
 
 

src/keri/app/indirecting.py

@@ -479,13 +479,11 @@ class MailboxDirector(doing.DoDoer):
         hby (Habitat: local controller's context
 
     Properties:
-        tyme (float): relative cycle time of associated Tymist, obtained
-            via injected .tymth function wrapper closure.
-        tymth (function): function wrapper closure returned by Tymist .tymeth()
-            method.  When .tymth is called it returns associated Tymist .tyme.
-            .tymth provides injected dependency on Tymist tyme base.
-        tock (float): desired time in seconds between runs or until next run,
-            non negative, zero means run asap
+        hby (Habery): the Habery in which mailbox messages are routed
+        verifier (Verifier): TEL event acceptor and validator
+        exchanger (Exchanger): Exchange (exn) message delivery component
+        rep (Respondant): Respondant for reply messages
+        cues (Deck): Queue for new actions to schedule shared between the Revery, Kevery (and Kever), and Tevery (and Tever)
 
 
     Methods:

src/keri/app/storing.py

@@ -224,6 +224,8 @@ def responseDo(self, tymth=None, tock=0.0):
                 # sign the exn to get the signature
                 eattach = senderHab.endorse(exn, last=False, pipelined=False)
                 del eattach[:exn.size]
+                logger.info("Respondant: sending exn on %s from %s to %s", topic, sender, recipient)
+                logger.debug("Respondant: exn body=\n%s\n", exn.pretty())
                 self.postman.send(recipient, topic=topic, serder=exn, hab=forwardHab, attachment=eattach)
 
                 yield self.tock  # throttle just do one cue at a time