logging - Context-based logging¶
Overview¶
This module provides context-based logging system built on top of standard logging
module.
The context-based logging:
Adds context information into
LogRecord
, that could be used in logging message.Adds support for f-string message format.
Allows assignment of loggers to specific contexts.
The logging context¶
The logging context is defined as combination of topic
, agent
and context
string values.
The agent
is typically an unit of code that works in specific execution contexts. For
example a code that process client request in web application (where request is the context),
or executes SQL command (the context could be a database connection, or transaction).
The topic
is optional. It could be any string value that can be used as secondary context.
Agent and Context identification¶
Agents and contexts could be identified by string value, or by any object (i.e. you can use
the object that implement the agent or context). If object is used, the ID could be
provided as logging_id
attribute, __name__
attribute or by __str__()
return value.
A LoggingIdMixin
class could be used to add logging_id
support to any class.
The LoggingManager¶
The LoggingManager
class maintains a set of bindings between Logger
objects and
combination of agent
, context
and topic
specifications. It’s possible to bind loggers
to exact combination of values, or whole sets of values using ANY
sentinel. It means that
is possible to assign specific Logger
to log messages for particular agent in
any context, or any agent operating in specific context etc.
To log agent
activities, use a logger returned by get_logger()
function/method.
Example¶
The following program is an example of small but complex enough code that you can use to experiment with contextual logging options. Parts relevant to logging are highlighted in the code by embedded comments. The program is very simple simulation of virtual “human” agents that can change their mood during mutual interaction.
# test-logging.py
from __future__ import annotations
import logging
from time import monotonic
from decimal import Decimal
from enum import IntEnum, auto
from firebird.base.types import *
from firebird.base.logging import LogLevel, LoggingIdMixin, get_logger
class Mood(IntEnum):
"Agent moods"
ANGRY = auto()
SAD = auto()
NEUTRAL = auto()
PLEASED = auto()
HAPPY = auto()
class Person(LoggingIdMixin): # LOGGING
"Sample virtual human agent"
def __init__(self, name: str, mood: Mood=Mood.NEUTRAL):
self.name: str = name
self.mood: Mood = mood
self.partners: List[Person] = []
# >>> LOGGING
@property
def _logging_id_(self) -> str:
return f"{self.mood.name} {self.name}"
# <<< LOGGING
def change_mood(self, offset: int) -> None:
result = self.mood + offset
if result < Mood.ANGRY:
self.mood = Mood.ANGRY
elif result > Mood.HAPPY:
self.mood = Mood.HAPPY
else:
self.mood = Mood(result)
def process(self, message: str) -> None:
msg = message.lower()
if msg == "what you are doing here":
self.change_mood(-1)
if 'awful' in msg:
self.change_mood(-1)
if ('nice' in msg) or ('wonderful' in msg) or ('pleased' in msg):
if self.mood != Mood.ANGRY:
self.change_mood(1)
if 'happy' in msg:
if self.mood != Mood.ANGRY:
self.change_mood(2)
if 'very nice' in msg:
if self.mood != Mood.ANGRY:
self.change_mood(1)
if 'get lost' in msg:
self.change_mood(-2)
if self.name.lower() in msg:
if self.mood == Mood.SAD:
self.change_mood(1)
if self.name.lower() not in msg:
if self.mood == Mood.NEUTRAL:
self.change_mood(-1)
def process_response(self, to: str, mood: Mood) -> None:
if to == 'greeting':
if self.mood == Mood.NEUTRAL:
if mood > Mood.NEUTRAL:
self.mood = Mood.PLEASED
elif mood == Mood.ANGRY:
self.mood = Mood.SAD
elif self.mood == Mood.SAD:
if mood == Mood.SAD:
self.mood = Mood.NEUTRAL
elif mood == Mood.HAPPY:
self.mood = Mood.ANGRY
elif self.mood == Mood.ANGRY and mood == Mood.SAD:
self.mood = Mood.NEUTRAL
elif to == 'chat':
if self.mood == Mood.SAD and mood > Mood.NEUTRAL:
self.mood = Mood.NEUTRAL
elif self.mood == Mood.ANGRY and mood == Mood.SAD:
self.mood = Mood.NEUTRAL
elif self.mood == Mood.PLEASED and mood == Mood.ANGRY:
self.mood = Mood.NEUTRAL
elif self.mood == Mood.HAPPY and mood == Mood.ANGRY:
self.mood = Mood.SAD
elif to == 'bye':
if self.mood == Mood.NEUTRAL:
if mood == Mood.ANGRY:
self.mood = Mood.ANGRY
elif mood > Mood.NEUTRAL:
self.mood = Mood.PLEASED
elif self.mood == Mood.HAPPY and mood == Mood.ANGRY:
self.mood = Mood.NEUTRAL
def meet(self, other: Person) -> None:
self.partners.append(other)
self.greeting(other)
def interact(self, other: Person, message: str) -> Mood:
print(f"[{other.name}] {message}")
# >>> LOGGING
get_logger(self, topic='Person').debug(f'Processing "{message}" from [{other.name}]')
# <<< LOGGING
self.process(message)
return self.mood
def greeting(self, other: Person) -> None:
if self.mood == Mood.NEUTRAL:
msg = f"Hi {other.name}, I'm {self.name}"
elif self.mood == Mood.ANGRY:
msg = "Hi"
elif self.mood == Mood.SAD:
msg = f"Hi {other.name}"
else:
msg = f"Hi {other.name}, I'm {self.name}. I'm {self.mood.name} to meet you."
self.process_response('greeting', other.interact(self, msg))
def chat(self) -> None:
for other in self.partners:
if self.mood == Mood.ANGRY:
msg = "What you are doing here?"
elif self.mood == Mood.SAD:
msg = "The weather is awful today, don't you think?"
elif self.mood == Mood.NEUTRAL:
msg = "It's a fine day, don't you think?"
elif self.mood == Mood.PLEASED:
msg = "It's a very nice day, don't you think?"
else:
msg = "Today is a wonderful day!"
self.process_response('chat', other.interact(self, msg))
def bye(self) -> str:
while self.partners:
other = self.partners.pop()
if self.mood == Mood.ANGRY:
msg = "Get lost!"
elif self.mood == Mood.SAD:
msg = "Bye"
elif self.mood == Mood.NEUTRAL:
msg = f"Bye, {other.name}."
elif self.mood == Mood.PLEASED:
msg = f"See you, {other.name}!"
else:
msg = f"Bye, {other.name}. Have a nice day!"
self.process_response('bye', other.interact(self, msg))
if self.mood == Mood.ANGRY:
result = "I hate this meeting!"
elif self.mood == Mood.SAD:
result = "It was a waste of time!"
elif self.mood == Mood.NEUTRAL:
result = "It was OK."
elif self.mood == Mood.PLEASED:
result = "Nice meeting, I think."
else:
result = "What a wonderful meeting!"
return result
def __repr__(self) -> str:
return f"{self.name} [{self.mood.name}]"
def meeting(name: str, persons: List[Person]):
"Simulation of virtual agents meeting"
for person in persons:
person.log_context = name
start = monotonic()
print("Meeting started...")
print(f"Attendees: {', '.join(f'{x.name} [{x.mood.name}]' for x in persons)}")
for person in persons:
for other in persons:
if other is not person:
person.meet(other)
for person in persons:
person.chat()
for person in persons:
person.bye()
e = str(Decimal(monotonic() - start))
print(f"Meeting closed in {e[:e.find('.')+6]} sec.")
print(f"Outcome: {', '.join(f'{x.name} [{x.mood.name}]' for x in persons)}")
def test_loggig(name: str, first: Mood, second: Mood) -> None:
meeting(name, [Person('Alex', first), Person('David', second)])
if __name__ == '__main__':
# >>> LOGGING
logger = logging.getLogger()
logger.setLevel(LogLevel.NOTSET)
sh = logging.StreamHandler()
sh.setFormatter(logging.Formatter('%(levelname)-10s: [%(topic)s][%(agent)s][%(context)s] %(message)s'))
logger.addHandler(sh)
# <<< LOGGING
test_loggig('TEST-1', Mood.SAD, Mood.PLEASED)
print('-'*20)
test_loggig('TEST-2', Mood.HAPPY, Mood.ANGRY)
Output from sample code:
> python test-logging.py
Meeting started...
Attendees: Alex [SAD], David [PLEASED]
[Alex] Hi David
DEBUG : [Person][PLEASED David][TEST-1] Processing "Hi David" from [Alex]
[David] Hi Alex, I'm David. I'm PLEASED to meet you.
DEBUG : [Person][SAD Alex][TEST-1] Processing "Hi Alex, I'm David. I'm PLEASED to meet you." from [David]
[Alex] It's a fine day, don't you think?
DEBUG : [Person][PLEASED David][TEST-1] Processing "It's a fine day, don't you think?" from [Alex]
[David] It's a very nice day, don't you think?
DEBUG : [Person][NEUTRAL Alex][TEST-1] Processing "It's a very nice day, don't you think?" from [David]
[Alex] Bye, David. Have a nice day!
DEBUG : [Person][PLEASED David][TEST-1] Processing "Bye, David. Have a nice day!" from [Alex]
[David] Bye, Alex. Have a nice day!
DEBUG : [Person][HAPPY Alex][TEST-1] Processing "Bye, Alex. Have a nice day!" from [David]
Meeting closed in 0.00132 sec.
Outcome: Alex [HAPPY], David [HAPPY]
--------------------
Meeting started...
Attendees: Alex [HAPPY], David [ANGRY]
[Alex] Hi David, I'm Alex. I'm HAPPY to meet you.
DEBUG : [Person][ANGRY David][TEST-2] Processing "Hi David, I'm Alex. I'm HAPPY to meet you." from [Alex]
[David] Hi
DEBUG : [Person][HAPPY Alex][TEST-2] Processing "Hi" from [David]
[Alex] Today is a wonderful day!
DEBUG : [Person][ANGRY David][TEST-2] Processing "Today is a wonderful day!" from [Alex]
[David] What you are doing here?
DEBUG : [Person][SAD Alex][TEST-2] Processing "What you are doing here?" from [David]
[Alex] Bye
DEBUG : [Person][NEUTRAL David][TEST-2] Processing "Bye" from [Alex]
[David] Bye
DEBUG : [Person][SAD Alex][TEST-2] Processing "Bye" from [David]
Meeting closed in 0.00050 sec.
Outcome: Alex [SAD], David [SAD]
Enums & Flags¶
Functions¶
- firebird.base.logging.bind_logger(agent: Any, context: Any, logger: str | Logger, topic: str = '') None ¶
shortcut for
logging_manager.bind_logger()
- firebird.base.logging.get_logger(agent: Any = Sentinel('UNDEFINED'), context: Any = Sentinel('DEFAULT'), topic: str = '') FBLoggerAdapter ¶
shortcut for
logging_manager.get_logger()
- Parameters:
- Return type:
Logger adapter¶
- class firebird.base.logging.FBLoggerAdapter(*args, **kwargs)[source]¶
Bases:
LoggerAdapter
,CachedDistinct
LoggerAdapter
that injects information about context, agent and topic intoextra
and with f-string log message support.- __init__(logger: Logger, agent: Any = Sentinel('UNDEFINED'), context: Any = Sentinel('UNDEFINED'), topic: str = '')[source]¶
- classmethod extract_key(*args, **kwargs) Hashable [source]¶
Returns instance key extracted from constructor arguments.
- Return type:
- log(level, msg, *args, **kwargs)[source]¶
Delegate a log call to the underlying logger after processing.
Interpolates the message as f-string using either
kwargs
or dict passed as only one positional argument. If sole positional argument is not dictionary orargs
has more than one item, addsargs
into namespace for interpolation.Moves ‘context’, ‘agent’ and ‘topic’ keyword arguments into
extra
.Strips out all keyword arguments not expected by
logging.Logger
.
Logging manager¶
- class firebird.base.logging.LoggingManager[source]¶
Bases:
object
Logger manager.
- bind_logger(agent: Any, context: Any, logger: str | Logger, topic: str = '') None [source]¶
Bind agent and context to specific logger.
- Parameters:
- Return type:
None
The identification of agent and context could be:
String
Object instance. Uses
get_logging_id()
to retrieve its logging ID.Sentinel. The ANY sentinel matches any particular agent or context. You can use sentinel
UNDEFINED
to register a logger for cases when agent or context are not specified in logger lookup.
- get_logger(agent: Any = Sentinel('UNDEFINED'), context: Any = Sentinel('DEFAULT'), topic: str = '') FBLoggerAdapter [source]¶
Return a logger for the specified agent and context combination.
- Parameters:
- Return type:
The identification of agent and context could be:
String
Object instance. Uses
get_logging_id()
to retrieve its logging ID.Sentinel
UNDEFINED
When
context
is sentinelDEFAULT
, usesagent
attributelog_context
(if defined) or sentinelUNDEFINED
otherwise.
The search for a suitable topic logger proceeds as follows:
Return logger registered for specified agent and context, or…
Return logger registered for ANY agent and specified context, or…
Return logger registered for specified agent and ANY context, or…
Return logger registered for ANY agent and ANY context, or…
Return the root logger.
Mixins¶
- class firebird.base.logging.LoggingIdMixin[source]¶
Bases:
object
Mixin class that adds
logging_id
property and__str__
that returnslogging_id
.
Globals¶
- firebird.base.logging.logging_manager: LoggingManager¶
Logging Manager