Merge pull request #25 from GLEIF-IT/enc/logging

adds more logging and format. updates makefile to multiarch builds

.github/workflows/sally-ci.yml

@@ -17,7 +17,7 @@ jobs:
     strategy:
       fail-fast: false
       matrix:
-        os: [ macos-latest, ubuntu-latest ]
+        os: [ macos-13, ubuntu-latest ]
 
     steps:
       - uses: actions/checkout@v2

Makefile

@@ -1,12 +1,30 @@
 .PHONY: build-sally
-build-sally:
-	@docker buildx build --platform=linux/amd64 --no-cache -f containers/sally.dockerfile --tag gleif/sally:0.8.0 .
-	@docker buildx build --platform=linux/arm64 --no-cache -f containers/sally-arm64.dockerfile --tag gleif/sally:0.8.0-arm64 .
+
+VERSION=0.9.0
+
+define DOCKER_WARNING
+In order to use the multi-platform build enable the containerd image store
+The containerd image store is not enabled by default.
+To enable the feature for Docker Desktop:
+	Navigate to Settings in Docker Desktop.
+	In the General tab, check Use containerd for pulling and storing images.
+	Select Apply and Restart."
+endef
+
+build-sally: .warn
+	@docker build --platform=linux/amd64,linux/arm64 --no-cache -f containers/sally.dockerfile -t gleif/sally:$(VERSION) .
 
 .PHONY: run-sally
 run-agent:
-	@docker run -p 5921:5921 -p 5923:5923 --name agent gleif/sally:0.8.0
+	@docker run -p 5921:5921 -p 5923:5923 --name agent gleif/sally:$(VERSION)
 
 .PHONY: push-all
 push-all:
 	@docker push gleif/sally --all-tags
+
+.warn:
+	@echo -e ${RED}"$$DOCKER_WARNING"${NO_COLOUR}
+
+RED="\033[0;31m"
+NO_COLOUR="\033[0m"
+export DOCKER_WARNING

src/sally/app/cli/commands/hook/demo.py

@@ -4,15 +4,14 @@
 
 """
 import argparse
+import logging
 
 import falcon
-from hio.base import doing
 from hio.core import http
-from keri.app import keeping, habbing, directing, configing
-from keri.app.cli.common import existing
-from keri.end import ending
+from keri import help
+from keri.app import directing
 
-from sally.core import serving
+logger = help.ogler.getLogger()
 
 parser = argparse.ArgumentParser(description='Launch SALLY sample web hook server')
 parser.set_defaults(handler=lambda args: launch(args),
@@ -24,6 +23,12 @@
 
 
 def launch(args, expire=0.0):
+    baseFormatter = logging.Formatter('%(asctime)s [hook] %(levelname)-8s %(message)s')
+    baseFormatter.default_msec_format = None
+    help.ogler.baseConsoleHandler.setFormatter(baseFormatter)
+    help.ogler.level = logging.getLevelName(logging.INFO)
+    help.ogler.reopen(name="hook", temp=True, clear=True)
+
     httpPort = args.http
 
     app = falcon.App(
@@ -36,7 +41,7 @@ def launch(args, expire=0.0):
     server = http.Server(port=httpPort, app=app)
     httpServerDoer = http.ServerDoer(server=server)
 
-    print(f"Sally Web Hook Sample listening on {httpPort}")
+    logger.info(f"Sally Web Hook Sample listening on {httpPort}")
     directing.runController(doers=[httpServerDoer], expire=expire)
 
 
@@ -53,13 +58,11 @@ def on_post(self, req, rep):
             rep: falcon.Response HTTP response
 
         """
-        print("** HEADERS **")
-        print(req.headers)
-        print("*************")
+        logger.info("** HEADERS **")
+        logger.info(req.headers)
+        logger.info("*************")
 
-        print("**** BODY ****")
+        logger.info("**** BODY ****")
         body = req.get_media()
-        print(body)
-        print("**************")
-
-
+        logger.info(body)
+        logger.info("**************")

src/sally/app/cli/commands/server/start.py

@@ -4,12 +4,16 @@
 
 """
 import argparse
+import logging
 
+from keri import help
 from keri.app import keeping, habbing, directing, configing, oobiing
 from keri.app.cli.common import existing
-
 from sally.core import serving
 
+help.ogler.level = logging.getLevelName(logging.INFO)
+logger = help.ogler.getLogger()
+
 parser = argparse.ArgumentParser(description='Launch SALLY micro-service')
 parser.set_defaults(handler=lambda args: launch(args),
                     transferable=True)
@@ -51,20 +55,26 @@
 
 
 def launch(args, expire=0.0):
+    base_formatter = logging.Formatter('%(asctime)s [sally] %(levelname)-8s %(message)s')
+    base_formatter.default_msec_format = None
+    help.ogler.baseConsoleHandler.setFormatter(base_formatter)
+    help.ogler.level = logging.getLevelName(logging.INFO)
+    help.ogler.reopen(name="sally", temp=True, clear=True)
+
     hook = args.web_hook
     name = args.name
     base = args.base
     bran = args.bran
-    httpPort = args.http
+    http_port = args.http
     auth = args.auth
 
     listen = args.listen
     timeout = args.escrow_timeout
     retry = args.retry_delay
 
     alias = args.alias
-    configFile = args.configFile
-    configDir = args.configDir
+    config_file = args.configFile
+    config_dir = args.configDir
 
     ks = keeping.Keeper(name=name,
                         base=base,
@@ -75,10 +85,10 @@ def launch(args, expire=0.0):
 
     cf = None
     if aeid is None:
-        if configFile is not None:
-            cf = configing.Configer(name=configFile,
+        if config_file is not None:
+            cf = configing.Configer(name=config_file,
                                     base=base,
-                                    headDirPath=configDir,
+                                    headDirPath=config_dir,
                                     temp=False,
                                     reopen=True,
                                     clear=False)
@@ -92,8 +102,8 @@ def launch(args, expire=0.0):
 
     doers = [hbyDoer, *obl.doers]
 
-    doers += serving.setup(hby, alias=alias, httpPort=httpPort, hook=hook, auth=auth,
+    doers += serving.setup(hby, alias=alias, httpPort=http_port, hook=hook, auth=auth,
                            listen=listen, timeout=timeout, retry=retry)
 
-    print(f"Sally Server listening on {httpPort}")
+    logger.info(f"Sally Server listening on {http_port}")
     directing.runController(doers=doers, expire=expire)

src/sally/app/cli/kli.py

@@ -4,14 +4,8 @@
 
 """
 import multicommand
-import logging
 
 from sally.app.cli import commands
-from keri import help
-
-
-help.ogler.level = logging.CRITICAL
-help.ogler.reopen(name="sally", temp=True, clear=True)
 
 
 def main():

src/sally/core/handling.py

@@ -70,6 +70,7 @@ def recur(self, tyme):
                 Tymist instance. Calling tymth() returns associated Tymist .tyme.
         """
         for keys, notice in self.notifier.noter.notes.getItemIter():
+            logger.info(f"Processing notice {notice}")
             attrs = notice.attrs
             route = attrs['r']
 
@@ -143,7 +144,7 @@ def processPresentations(self):
         for (said,), dater in self.cdb.iss.getItemIter():
             # cancel presentations that have been around longer than timeout
             now = helping.nowUTC()
-            print(f"looking for credential {said}")
+            logger.info(f"looking for credential {said}")
             if now - dater.datetime > datetime.timedelta(minutes=self.timeout):
                 self.cdb.iss.rem(keys=(said,))
                 continue
@@ -165,7 +166,6 @@ def processPresentations(self):
                         raise kering.ValidationError(f"credential {creder.said} is of unsupported schema"
                                                      f" {creder.schema} from issuer {creder.issuer}")
                 except kering.ValidationError as ex:
-                    print(ex)
                     logger.error(f"credential {creder.said} from issuer {creder.issuer} failed validation: {ex}")
                 else:
                     self.cdb.recv.pin(keys=(said, dater.qb64), val=creder)
@@ -212,6 +212,7 @@ def processReceived(self, db, action):
                     elif creder.schema == OOR_SCHEMA:
                         data = self.roleCredentialPayload(self.reger, creder)
                     else:
+                        logger.error(f"invalid credential with schema {creder.schema} said {creder.said} issuer {creder.issuer}")
                         raise kering.ValidationError("this will never happen because all credentials that get here are"
                                                      " valid")
                 else:  # revocation of credential
@@ -239,7 +240,7 @@ def processReceived(self, db, action):
     def processAcks(self):
         for (said,), creder in self.cdb.ack.getItemIter():
             # TODO: generate EXN ack message with credential information
-            print(f"ACK for credential {said} will be sent to {creder.issuer}")
+            logger.info(f"ACK for credential {said} will be sent to {creder.issuer}")
             self.cdb.ack.rem(keys=(said,))
 
     def escrowDo(self, tymth, tock=1.0):
@@ -268,7 +269,7 @@ def escrowDo(self, tymth, tock=1.0):
             try:
                 self.processEscrows()
             except Exception as e:
-                print(e)
+                logger.error(e)
 
             yield self.retry
 
@@ -379,6 +380,7 @@ def validateOfficialRole(self, creder):
         asaid = edges["auth"]["n"]
         auth = self.reger.creds.get(asaid)
         if auth is None:
+            logger.error(f"AUTH credential {asaid} not found for OOR credential {creder.said}")
             raise kering.ValidationError(f"AUTH credential {asaid} not found for OOR credential {creder.said}")
 
         if auth.sad["a"]["AID"] != creder.attrib["i"]:

src/sally/core/httping.py

@@ -5,10 +5,10 @@
 
 HTTP utility
 """
-from http_sfv import List, Dictionary
 from base64 import urlsafe_b64encode as encodeB64
 from collections import namedtuple
 
+from http_sfv import Dictionary
 from keri.help import helping
 
 DEFAULTHEADERS = ('(created)', '(request-target)')

src/sally/core/serving.py

@@ -45,9 +45,9 @@ def setup(hby, *, alias, httpPort, hook, auth, listen=False, timeout=10, retry=3
     if hab is None:
         hab = hby.makeHab(name=alias, transferable=True)
 
-    print(f"Using hab {hab.name}:{hab.pre}")
-    print(f"\tCESR Qualifed Base64 Public Key:  {hab.kever.serder.verfers[0].qb64}")
-    print(f"\tPlain Base64 Public Key:          {encodeB64(hab.kever.serder.verfers[0].raw).decode('utf-8')}")
+    logger.info(f"Using hab {hab.name}:{hab.pre}")
+    logger.info(f"\tCESR Qualifed Base64 Public Key:  {hab.kever.serder.verfers[0].qb64}")
+    logger.info(f"\tPlain Base64 Public Key:          {encodeB64(hab.kever.serder.verfers[0].raw).decode('utf-8')}")
     mbx = storing.Mailboxer(name=hby.name)
     reger = viring.Reger(name=hab.name, db=hab.db, temp=False)
     rep = storing.Respondant(hby=hby, mbx=mbx)
@@ -93,7 +93,7 @@ def setup(hby, *, alias, httpPort, hook, auth, listen=False, timeout=10, retry=3
 
     doers = [httpServerDoer, comms, tc]
     if listen:
-        print("This is where we start HttpEnd instead of MailboxDirector")
+        logger.info("This is where we start HttpEnd instead of MailboxDirector")
     else:
         mbd = indirecting.MailboxDirector(hby=hby,
                                           exc=exc,