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 executed (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

LogLevel

class firebird.base.logging.LogLevel(value)

Bases: enum.IntEnum

Shadow enumeration for logging levels

CRITICAL = 50
DEBUG = 10
ERROR = 40
FATAL = 50
INFO = 20
NOTSET = 0
WARN = 30
WARNING = 30

BindFlag

class firebird.base.logging.BindFlag(value)

Bases: enum.Flag

Internal flags used by LoggingManager.

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

Functions

bind_logger

firebird.base.logging.bind_logger(agent, context, logger, topic='')

Bind agent and context to specific logger.

Parameters
  • agent (Any) – Agent identification

  • context (Any) – Context identification

  • logger (Union[str, Logger]) – Loger (instance or name)

  • topic (str) – Topic of recorded information

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.

Return type

None

get_logger

firebird.base.logging.get_logger(agent=Sentinel('UNDEFINED'), context=Sentinel('DEFAULT'), topic='')

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.

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.

Return type

FBLoggerAdapter

get_logging_id

firebird.base.logging.get_logging_id(obj)

Returns logging ID for object.

Parameters

obj (Any) – Any object

Return type

Any

Returns

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

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

  3. str(obj)

install_null_logger

firebird.base.logging.install_null_logger()

Installs ‘null’ logger.

Logger adapter

FBLoggerAdapter

class firebird.base.logging.FBLoggerAdapter(logger, agent=Sentinel('UNDEFINED'), context=Sentinel('UNDEFINED'), topic='')

Bases: logging.LoggerAdapter, firebird.base.types.CachedDistinct

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

logger

Adapted Logger instance.

Type

Logger

agent

Agent for logger

Type

str

context

Context for logger

Type

str

topic

Topic for logger.

Type

str

__init__(logger, agent=Sentinel('UNDEFINED'), context=Sentinel('UNDEFINED'), topic='')
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)

Returns instance key extracted from constructor arguments.

Return type

Hashable

get_key()

Returns instance key.

Return type

Hashable

log(level, msg, *args, **kwargs)

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)

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]

Logging manager

LoggingManager

class firebird.base.logging.LoggingManager

Bases: object

Logger manager.

bind_logger(agent, context, logger, topic='')

Bind agent and context to specific logger.

Parameters
  • agent (Any) – Agent identification

  • context (Any) – Context identification

  • logger (Union[str, Logger]) – Loger (instance or name)

  • topic (str) – Topic of recorded information

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.

Return type

None

clear()

Remove all logger bindings

Return type

None

get_logger(agent=Sentinel('UNDEFINED'), context=Sentinel('DEFAULT'), topic='')

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.

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.

Return type

FBLoggerAdapter

unbind(agent, context, topic='')

Drops logger bindings.

Return type

int

Mixins

LoggingIdMixin

class firebird.base.logging.LoggingIdMixin

Bases: object

Mixin class that adds logging_id property and __str__.

__str__()

Returns logging_id

property logging_id

Returns _logging_id_ attribute if defined, else returns qualified class name

Return type

str

Globals

firebird.base.logging.logging_manager: firebird.base.logging.LoggingManager = <firebird.base.logging.LoggingManager object>

Logging Manager