Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

to 1.1.30: feat: add consistent logging at INFO and DEBUG levels #930

Open
wants to merge 4 commits into
base: v1.1.30
Choose a base branch
from
Open

to 1.1.30: feat: add consistent logging at INFO and DEBUG levels #930

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
610ab78
feat: add consistent logging at INFO and DEBUG levels
kentbull Jan 27, 2025
9844b9d
feat: add rich logging format string
kentbull Jan 30, 2025
07d15e9
fix: verbose logging in Sally tuned down
kentbull Feb 4, 2025
47f53de
refactor: remove class name prefixes
kentbull Feb 5, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion src/keri/app/cli/commands/multisig/incept.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down
13 changes: 11 additions & 2 deletions src/keri/app/cli/commands/witness/demo.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,7 @@

import argparse
import logging
import os

from hio.base import doing

Expand All @@ -16,18 +17,26 @@
from keri import help

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))


help.ogler.level = logging.INFO
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)
Expand Down
19 changes: 10 additions & 9 deletions src/keri/app/grouping.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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.ilk} {serder.pre}:{seqner.sn}...")
return self.hby.db.gpse.add(keys=(prefixer.qb64,), val=(seqner, saider))

def complete(self, prefixer, seqner, saider=None):
Expand Down Expand Up @@ -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)
Expand All @@ -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"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):
Expand All @@ -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)

Expand All @@ -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))

Expand Down Expand Up @@ -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:
Expand Down Expand Up @@ -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("handling %s event SAID=%s", self.resource, serder.said)
self.mux.add(serder=serder)


Expand Down
28 changes: 16 additions & 12 deletions src/keri/core/eventing.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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())
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -2702,20 +2703,22 @@ def logEvent(self, serder, sigers=None, wigers=None, wits=None, first=False,
if self.cues is not None: # cue to notice BadCloneFN
self.cues.push(dict(kin="noticeBadCloneFN", serder=serder,
fn=fn, firner=firner, dater=dater))
logger.info("Kever: Mismatch Cloned Replay FN: First seen "
logger.info("Mismatch Cloned Replay FN: First seen "
"ordinal fn %s dig %s and clone fn %s event=%s",
fn, serder.pre, firner.sn, serder.said)
logger.debug("Event Body=\n%s\n", serder.pretty())
if dater: # cloned replay use original's dts from dater
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())
pre = self.prefixer.qb64
logger.info("[AID %s...%s]: Added to KEL %s at sn=%s valid event SAID=%s for AID %s",
pre[:4], pre[-4:], 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):
Expand All @@ -2736,7 +2739,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())

Expand Down Expand Up @@ -5037,7 +5040,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
Expand Down Expand Up @@ -5200,7 +5203,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
Expand Down Expand Up @@ -5578,7 +5581,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
Expand Down
Loading