logging - Context-based logging

Overview

This module provides context-based logging system built on top of standard logging module.

The context-based logging:

  1. Adds context information into LogRecord, that could be used in logging message.

  2. Adds support for f-string message format.

  3. 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

class firebird.base.logging.LogLevel(value, names=None, *, module=None, qualname=None, type=None, start=1, boundary=None)[source]

Bases: IntEnum

Shadow enumeration for logging levels.

CRITICAL = 50
DEBUG = 10
ERROR = 40
FATAL = 50
INFO = 20
NOTSET = 0
WARN = 30
WARNING = 30
class firebird.base.logging.BindFlag(value, names=None, *, module=None, qualname=None, type=None, start=1, boundary=None)[source]

Bases: Flag

Internal flags used by LoggingManager.

ANY_AGENT = 2
ANY_ANY = 8
ANY_CTX = 4
DIRECT = 1

Functions

firebird.base.logging.bind_logger(agent: Any, context: Any, logger: str | Logger, topic: str = '') → None

shortcut for logging_manager.bind_logger()

Parameters:
Return type:

None

firebird.base.logging.get_logger(agent: Any = Sentinel('UNDEFINED'), context: Any = Sentinel('DEFAULT'), topic: str = '') → FBLoggerAdapter

shortcut for logging_manager.get_logger()

Parameters:

  • agent (Any) –

  • context (Any) –

  • topic (str) –

Return type:

FBLoggerAdapter

firebird.base.logging.get_logging_id(obj: Any) → Any[source]

Returns logging ID for object.

Parameters:

obj (Any) – Any object

Returns:

  1. logging_id attribute if obj does have it, or..

  2. __qualname__ attribute if obj does have it, or..

  3. str(obj)

Return type:

Any

firebird.base.logging.install_null_logger()[source]

Installs ‘null’ logger.

Logger adapter

class firebird.base.logging.FBLoggerAdapter(*args, **kwargs)[source]

Bases: LoggerAdapter, CachedDistinct

LoggerAdapter that injects information about context, agent and topic into extra and with f-string log message support.

__init__(logger: Logger, agent: Any = Sentinel('UNDEFINED'), context: Any = Sentinel('UNDEFINED'), topic: str = '')[source]
Parameters:

  • logger (Logger) – Adapted Logger instance.

  • agent (Any) – Agent for logger

  • context (Any) – Context for logger

  • topic (str) – Topic of recorded information.

classmethod extract_key(*args, **kwargs) → Hashable[source]

Returns instance key extracted from constructor arguments.

Return type:

Hashable

get_key() → Hashable[source]

Returns instance key.

Return type:

Hashable

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 or args has more than one item, adds args into namespace for interpolation.

Moves ‘context’, ‘agent’ and ‘topic’ keyword arguments into extra.

Strips out all keyword arguments not expected by logging.Logger.

process(msg, kwargs) → Tuple[str, Dict][source]

Process the logging message and keyword arguments passed into a logging call to insert contextual information. You can either manipulate the message itself, the keyword args or both. Return the message and kwargs modified (or not) to suit your needs.

Return type:

Tuple[str, Dict]

agent: Any

Agent for logger.

context: Any

Context for logger.

logger: Logger

Adapted Logger instance.

topic: str

Topic for 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:

  • agent (Any) – Agent identification

  • context (Any) – Context identification

  • logger (str | Logger) – Loger (instance or name)

  • topic (str) – Topic of recorded information

Return type:

None

The identification of agent and context could be:

  1. String

  2. Object instance. Uses get_logging_id() to retrieve its logging ID.

  3. 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.

Important

You SHOULD NOT use sentinel ALL for agent or context identification! This sentinel is used by unbind(), so bindings that use ALL could not be removed by unbind().

clear() → None[source]

Remove all logger bindings.

Return type:

None

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:

  • agent (Any) – Agent identification.

  • context (Any) – Context identification.

  • topic (str) – Topic of recorded information.

Return type:

FBLoggerAdapter

The identification of agent and context could be:

  1. String

  2. Object instance. Uses get_logging_id() to retrieve its logging ID.

  3. Sentinel UNDEFINED

  4. When context is sentinel DEFAULT, uses agent attribute log_context (if defined) or sentinel UNDEFINED otherwise.

The search for a suitable topic logger proceeds as follows:

  1. Return logger registered for specified agent and context, or…

  2. Return logger registered for ANY agent and specified context, or…

  3. Return logger registered for specified agent and ANY context, or…

  4. Return logger registered for ANY agent and ANY context, or…

  5. Return the root logger.

unbind(agent: Any, context: Any, topic: str = '') → int[source]

Drops logger bindings.

Parameters:

  • agent (Any) –

  • context (Any) –

  • topic (str) –

Return type:

int

Mixins

class firebird.base.logging.LoggingIdMixin[source]

Bases: object

Mixin class that adds logging_id property and __str__ that returns logging_id.

property logging_id: str

Returns _logging_id_ attribute if defined, else returns qualified class name.

Globals

firebird.base.logging.logging_manager: LoggingManager

Logging Manager