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

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"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/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/cli/commands/witness/demo.py

@@ -8,6 +8,7 @@
 
 import argparse
 import logging
+import os
 
 from hio.base import doing
 
@@ -19,14 +20,24 @@
 
 
 parser = argparse.ArgumentParser(description="Run a demo collection of witnesses")
+parser.add_argument("--loglevel", action="store", required=False, default=os.getenv("KERI_LOG_LEVEL", "CRITICAL"),
+                    help="Set log level to DEBUG | INFO | WARNING | ERROR | CRITICAL. Default is CRITICAL")
 parser.set_defaults(handler=lambda args: demo(args))
 
+logger = help.ogler.getLogger()
 
-def demo(_):
+def demo(args):
     """
     Run set of three witnesses for demo
 
     """
+    base_formatter = logging.Formatter(
+        '%(asctime)s [keri] %(module)s.%(funcName)s-%(lineno)s %(levelname)-8s %(message)s')
+    base_formatter.default_msec_format = None
+    help.ogler.baseConsoleHandler.setFormatter(base_formatter)
+    help.ogler.level = logging.getLevelName(args.loglevel.upper())
+    logger.setLevel(help.ogler.level)
+    help.ogler.reopen(name="keri", temp=True, clear=True)
 
     wancf = configing.Configer(name="wan", headDirPath="scripts", temp=False, reopen=True, clear=False)
     wilcf = configing.Configer(name="wil", headDirPath="scripts", temp=False, reopen=True, clear=False)

src/keri/app/delegating.py

@@ -190,12 +190,17 @@ 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(
+                    "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("Sending delegation event %s from %s to delegator %s", srdr.ilk, phab.pre, delpre)
+                logger.debug("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,9 @@ 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("Waiting for other signatures on %s for %s:%s...", 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 +130,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("AID %s...%s: We are the witnesser, sending %s to delegator", pre[:4], pre[-4:], pre)
                         self.swain.delegation(pre=pre, sn=seqner.sn)
                     else:
                         anchor = dict(i=pre, s=seqner.snh, d=saider.qb64)
@@ -137,15 +139,18 @@ def processPartialSignedEscrow(self):
                         else:
                             self.witq.query(src=ghab.mhab.pre, pre=kever.delpre, anchor=anchor)
 
-                    logger.info("Waiting for delegation approval...")
+                    logger.info("AID %s...%s: Waiting for delegation approval...", pre[:4], pre[-4:])
                     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(
+                            "AID %s...%s: We are the fully signed witnesser %s, sending to witnesses",
+                            pre[:4], pre[-4:], seqner.sn)
                         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("AID %s...%s: Waiting for fully signed witness receipts for %s",
+                                pre[:4], pre[-4:], seqner.sn)
                     self.hby.db.gpwe.add(keys=(pre,), val=(seqner, saider))
 
     def processDelegateEscrow(self):
@@ -165,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,))
-                    logger.info(f"Delegation approval for {pre} received.")
+                    logger.info("AID %s...%s: Delegation approval for %s received.", pre[:4], pre[-4:], pre)
 
                     self.hby.db.cgms.put(keys=(pre, seqner.qb64), val=saider)
 
@@ -177,10 +182,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("AID %s...%s: Delegation approval for %s received.", pre[:4], pre[-4:], pre)
 
                     # Move to escrow waiting for witness receipts
-                    logger.info(f"Waiting for witness receipts for {pre}")
+                    logger.info("AID %s...%s: Waiting for witness receipts for %s", pre[:4], pre[-4:], pre)
                     self.hby.db.gdee.rem(keys=(pre,))
                     self.hby.db.gpwe.add(keys=(pre,), val=(seqner, saider))
 
@@ -208,7 +213,7 @@ def processPartialWitnessEscrow(self):
                             witnessed = True
                     if not witnessed:
                         continue
-                logger.info(f"Witness receipts complete, {pre} confirmed.")
+                logger.info("AID %s...%s: Witness receipts complete, %s confirmed.", pre[:4], pre[-4:], pre)
                 self.hby.db.gpwe.rem(keys=(pre,))
                 self.hby.db.cgms.put(keys=(pre, seqner.qb64), val=saider)
             elif not witer:
@@ -239,6 +244,8 @@ def handle(self, serder, attachments=None):
             attachments (list): list of tuples of pather, CESR SAD path attachments to the exn event
 
         """
+        logger.info("Notification for %s event SAID=%s", self.resource, serder.said)
+        logger.debug("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("Sending exn on %s from %s to %s", topic, sender, recipient)
+                logger.debug("xn 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