Logging updates (WebOfTrust#755)

* Add support to stream CESR over HTTP path for authentication headers. Signed-off-by: pfeairheller <[email protected]> * Updates to logging. - Removed logging at any level bug debug for messages in the escrow loops. - Removed line feeds from all log levels but debug - Ensured stack traces are only logged in debug - Removed full event logging from info, moved to debug level. Replaced with SAID in info. - Replaced print statements in grouping and delegating with logger.info statements. Signed-off-by: pfeairheller <[email protected]> * Makes things more pythonic Signed-off-by: pfeairheller <[email protected]> --------- Signed-off-by: pfeairheller <[email protected]>
kentbull · Sep 3, 2024 · 2b0df44 · 2b0df44
1 parent 839c3f1
commit 2b0df44
Show file tree

Hide file tree

Showing 16 changed files with 351 additions and 283 deletions.
diff --git a/src/keri/app/agenting.py b/src/keri/app/agenting.py
@@ -273,7 +273,7 @@ class WitnessReceiptor(doing.DoDoer):
 
     """
 
-    def __init__(self, hby, msgs=None, cues=None, force=False, **kwa):
+    def __init__(self, hby, msgs=None, cues=None, force=False, auths=None, **kwa):
         """
         For the current event, gather the current set of witnesses, send the event,
         gather all receipts and send them to all other witnesses
@@ -289,6 +289,7 @@ def __init__(self, hby, msgs=None, cues=None, force=False, **kwa):
         self.force = force
         self.msgs = msgs if msgs is not None else decking.Deck()
         self.cues = cues if cues is not None else decking.Deck()
+        self.auths = auths if auths is not None else dict()
 
         super(WitnessReceiptor, self).__init__(doers=[doing.doify(self.receiptDo)], **kwa)
 
@@ -332,7 +333,8 @@ def receiptDo(self, tymth=None, tock=0.0):
 
                 witers = []
                 for wit in wits:
-                    witer = messenger(hab, wit)
+                    auth = self.auths[wit] if wit in self.auths else None
+                    witer = messenger(hab, wit, auth=auth)
                     witers.append(witer)
                     self.extend([witer])
 
@@ -836,7 +838,7 @@ class HTTPMessenger(doing.DoDoer):
 
     """
 
-    def __init__(self, hab, wit, url, msgs=None, sent=None, doers=None, **kwa):
+    def __init__(self, hab, wit, url, msgs=None, sent=None, doers=None, auth=None, **kwa):
         """
         For the current event, gather the current set of witnesses, send the event,
         gather all receipts and send them to all other witnesses
@@ -851,6 +853,7 @@ def __init__(self, hab, wit, url, msgs=None, sent=None, doers=None, **kwa):
         self.msgs = msgs if msgs is not None else decking.Deck()
         self.sent = sent if sent is not None else decking.Deck()
         self.parser = None
+        self.auth = auth
         doers = doers if doers is not None else []
         doers.extend([doing.doify(self.msgDo), doing.doify(self.responseDo)])
 
@@ -881,7 +884,11 @@ def msgDo(self, tymth=None, tock=0.0):
                 yield self.tock
 
             msg = self.msgs.popleft()
-            self.posted += httping.streamCESRRequests(client=self.client, dest=self.wit, ims=msg)
+            headers = dict()
+            if self.auth is not None:
+                headers["Authorization"] = self.auth
+
+            self.posted += httping.streamCESRRequests(client=self.client, dest=self.wit, ims=msg, headers=headers)
             while self.client.requests:
                 yield self.tock
 
@@ -983,34 +990,36 @@ def mailbox(hab, cid):
     return mbx
 
 
-def messenger(hab, pre):
+def messenger(hab, pre, auth=None):
     """ Create a Messenger (tcp or http) based on available endpoints
 
     Parameters:
         hab (Habitat): Environment to use to look up witness URLs
         pre (str): qb64 identifier prefix of recipient to create a messanger for
+        auth (str): optional auth code to send with any request for messenger
 
     Returns:
         Optional(TcpWitnesser, HTTPMessenger): witnesser for ensuring full reciepts
     """
     urls = hab.fetchUrls(eid=pre)
-    return messengerFrom(hab, pre, urls)
+    return messengerFrom(hab, pre, urls, auth)
 
 
-def messengerFrom(hab, pre, urls):
+def messengerFrom(hab, pre, urls, auth=None):
     """ Create a Witnesser (tcp or http) based on provided endpoints
 
     Parameters:
         hab (Habitat): Environment to use to look up witness URLs
         pre (str): qb64 identifier prefix of recipient to create a messanger for
         urls (dict): map of schemes to urls of available endpoints
+        auth (str): optional auth code to send with any request for messenger
 
     Returns:
         Optional(TcpWitnesser, HTTPMessenger): witnesser for ensuring full reciepts
     """
     if kering.Schemes.http in urls or kering.Schemes.https in urls:
         url = urls[kering.Schemes.http] if kering.Schemes.http in urls else urls[kering.Schemes.https]
-        witer = HTTPMessenger(hab=hab, wit=pre, url=url)
+        witer = HTTPMessenger(hab=hab, wit=pre, url=url, auth=auth)
     elif kering.Schemes.tcp in urls:
         url = urls[kering.Schemes.tcp]
         witer = TCPMessenger(hab=hab, wit=pre, url=url)

diff --git a/src/keri/app/cli/commands/interact.py b/src/keri/app/cli/commands/interact.py
@@ -103,21 +103,22 @@ def interactDo(self, tymth, tock=0.0, **opts):
         hab = self.hby.habByName(name=self.alias)
         hab.interact(data=self.data)
 
-        if self.endpoint or self.authenticate:
+        auths = {}
+        if self.authenticate:
+            for wit in hab.kever.wits:
+                code = input(f"Entire code for {wit}: ")
+                auths[wit] = f"{code}#{helping.nowIso8601()}"
+
+        if self.endpoint:
             receiptor = agenting.Receiptor(hby=self.hby)
             self.extend([receiptor])
 
-            auths = {}
-            if self.authenticate:
-                for wit in hab.kever.wits:
-                    code = input(f"Entire code for {wit}: ")
-                    auths[wit] = f"{code}#{helping.nowIso8601()}"
             yield from receiptor.receipt(hab.pre, sn=hab.kever.sn, auths=auths)
             self.remove([receiptor])
 
         else:
 
-            witDoer = agenting.WitnessReceiptor(hby=self.hby)
+            witDoer = agenting.WitnessReceiptor(hby=self.hby, auths=auths)
             self.extend(doers=[witDoer])
 
             if hab.kever.wits:

diff --git a/src/keri/app/cli/commands/witness/start.py b/src/keri/app/cli/commands/witness/start.py
@@ -55,7 +55,7 @@
 
 def launch(args):
     help.ogler.level = logging.getLevelName(args.loglevel)
-    if(args.logfile != None):
+    if args.logfile is not None:
         help.ogler.headDirPath = args.logfile
         help.ogler.reopen(name=args.name, temp=False, clear=True)
     logger = help.ogler.getLogger()

diff --git a/src/keri/app/cli/commands/witness/submit.py b/src/keri/app/cli/commands/witness/submit.py
@@ -10,6 +10,7 @@
 
 from keri.app import habbing, agenting, indirecting
 from keri.app.cli.common import existing, displaying
+from keri.help import helping
 
 logger = help.ogler.getLogger()
 
@@ -30,6 +31,10 @@
 parser.add_argument('--force', action="store_true", required=False,
                     help='True means to send witnesses all receipts even if we have a full compliment of receipts for '
                          'the current event')
+parser.add_argument("--receipt-endpoint", help="Attempt to connect to witness receipt endpoint for witness receipts.",
+                    dest="endpoint", action='store_true')
+parser.add_argument("--authenticate", '-z', help="Prompt the controller for authentication codes for each witness",
+                    action='store_true')
 
 
 def handler(args):
@@ -46,31 +51,33 @@ def handler(args):
     alias = args.alias
     force = args.force
 
-    icpDoer = InceptDoer(name=name, base=base, alias=alias, bran=bran, force=force)
+    subDoer = SubmitDoer(name=name, base=base, alias=alias, bran=bran, force=force, authenticate=args.authenticate,
+                         endpoint=args.endpoint)
 
-    doers = [icpDoer]
+    doers = [subDoer]
     return doers
 
 
-class InceptDoer(doing.DoDoer):
+class SubmitDoer(doing.DoDoer):
     """ DoDoer for creating a new identifier prefix and Hab with an alias.
     """
 
-    def __init__(self, name, base, alias, bran, force):
+    def __init__(self, name, base, alias, bran, force, endpoint=False, authenticate=False):
 
         hby = existing.setupHby(name=name, base=base, bran=bran)
         self.hbyDoer = habbing.HaberyDoer(habery=hby)  # setup doer
         self.mbx = indirecting.MailboxDirector(hby=hby, topics=['/receipt', "/replay", "/reply"])
         self.alias = alias
         self.hby = hby
         self.force = force
+        self.endpoint = endpoint
+        self.authenticate = authenticate
 
-        self.witDoer = None
-        doers = [self.hbyDoer, self.mbx, doing.doify(self.inceptDo)]
+        doers = [self.hbyDoer, self.mbx, doing.doify(self.submitDo)]
 
-        super(InceptDoer, self).__init__(doers=doers)
+        super(SubmitDoer, self).__init__(doers=doers)
 
-    def inceptDo(self, tymth, tock=0.0):
+    def submitDo(self, tymth, tock=0.0):
         """
         Parameters:
             tymth (function): injected function wrapper closure returned by .tymen() of
@@ -85,18 +92,34 @@ def inceptDo(self, tymth, tock=0.0):
         _ = (yield self.tock)
 
         hab = self.hby.habByName(name=self.alias)
-        self.witDoer = agenting.WitnessReceiptor(hby=self.hby, force=self.force)
-        self.extend([self.witDoer])
+        auths = {}
+        if self.authenticate:
+            for wit in hab.kever.wits:
+                code = input(f"Entire code for {wit}: ")
+                auths[wit] = f"{code}#{helping.nowIso8601()}"
 
-        if hab.kever.wits:
-            print("Waiting for witness receipts...")
-            self.witDoer.msgs.append(dict(pre=hab.pre))
-            while not self.witDoer.cues:
-                _ = yield self.tock
+        if self.endpoint:
+            receiptor = agenting.Receiptor(hby=self.hby)
+            self.extend([receiptor])
+
+            yield from receiptor.receipt(hab.pre, sn=hab.kever.sn, auths=auths)
+            self.remove([receiptor])
+
+        else:
+            witDoer = agenting.WitnessReceiptor(hby=self.hby, force=self.force, auths=auths)
+            self.extend([witDoer])
+
+            if hab.kever.wits:
+                print("Waiting for witness receipts...")
+                witDoer.msgs.append(dict(pre=hab.pre))
+                while not witDoer.cues:
+                    _ = yield self.tock
+
+            self.remove([witDoer])
 
         displaying.printIdentifier(self.hby, hab.pre)
 
-        toRemove = [self.hbyDoer, self.witDoer, self.mbx]
+        toRemove = [self.hbyDoer, self.mbx]
         self.remove(toRemove)
 
         return
diff --git a/src/keri/app/delegating.py b/src/keri/app/delegating.py
@@ -12,7 +12,7 @@
 from . import agenting, forwarding
 from .habbing import GroupHab
 from .. import kering
-from ..core import coring, eventing, serdering
+from ..core import coring, serdering
 from ..db import dbing
 from ..peer import exchanging
 
@@ -162,7 +162,7 @@ def processUnanchoredEscrow(self):
                 self.witDoer.msgs.append(dict(pre=pre, sn=serder.sn))
 
                 # Move to escrow waiting for witness receipts
-                print(f"Waiting for fully signed witness receipts for {serder.sn}")
+                logger.info(f"Waiting for fully signed witness receipts for {serder.sn}")
                 self.hby.db.dpwe.pin(keys=(pre, said), val=serder)
                 self.hby.db.dune.rem(keys=(pre, said))
 
@@ -188,7 +188,7 @@ def processPartialWitnessEscrow(self):
                             witnessed = True
                     if not witnessed:
                         continue
-                print(f"Witness receipts complete, {pre} confirmed.")
+                logger.info(f"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))
 

diff --git a/src/keri/app/grouping.py b/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"Waiting for other signatures for {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"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.delpre, anchor=anchor)
 
-                    print("Waiting for delegation approval...")
+                    logger.info("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"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"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"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"Delegation approval for {pre} received.")
 
                     # Move to escrow waiting for witness receipts
-                    print(f"Waiting for witness receipts for {pre}")
+                    logger.info(f"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"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:

diff --git a/src/keri/app/habbing.py b/src/keri/app/habbing.py
@@ -2084,8 +2084,9 @@ def processCuesIter(self, cues):
                 cuedSerder = cue["serder"]  # Serder of received event for other pre
                 cuedKed = cuedSerder.ked
                 cuedPrefixer = coring.Prefixer(qb64=cuedKed["i"])
-                logger.info("%s got cue: kin=%s\n%s\n\n", self.pre, cueKin,
-                            json.dumps(cuedKed, indent=1))
+                logger.info("%s got cue: kin=%s%s", self.pre, cueKin,
+                            cuedSerder.said)
+                logger.debug(f"event=\n{cuedSerder.pretty()}\n")
 
                 if cuedKed["t"] == coring.Ilks.icp:
                     dgkey = dbing.dgKey(self.pre, self.iserder.said)

diff --git a/src/keri/app/indirecting.py b/src/keri/app/indirecting.py
@@ -192,7 +192,7 @@ def msgDo(self, tymth=None, tock=0.0):
         _ = (yield self.tock)
 
         if self.parser.ims:
-            logger.info("Client %s received:\n%s\n...\n", self.kvy, self.parser.ims[:1024])
+            logger.debug("Client %s received:\n%s\n...\n", self.kvy, self.parser.ims[:1024])
         done = yield from self.parser.parsator(local=True)  # process messages continuously
         return done  # should nover get here except forced close
 
@@ -381,7 +381,7 @@ def msgDo(self, tymth=None, tock=0.0):
         _ = (yield self.tock)
 
         if self.parser.ims:
-            logger.info("Client %s received:\n%s\n...\n", self.hab.pre, self.parser.ims[:1024])
+            logger.debug("Client %s received:\n%s\n...\n", self.hab.pre, self.parser.ims[:1024])
         done = yield from self.parser.parsator(local=True)  # process messages continuously
         return done  # should nover get here except forced close
 
@@ -444,7 +444,7 @@ def sendMessage(self, msg, label=""):
         Sends message msg and loggers label if any
         """
         self.client.tx(msg)  # send to remote
-        logger.info("%s sent %s:\n%s\n\n", self.hab.pre, label, bytes(msg))
+        logger.debug("%s sent %s:\n%s\n\n", self.hab.pre, label, bytes(msg))
 
 
 class MailboxDirector(doing.DoDoer):