Skip to content

Latest commit

 

History

History
238 lines (170 loc) · 8.93 KB

logging.md

File metadata and controls

238 lines (170 loc) · 8.93 KB

logging - Context-based logging

Overview

::: firebird.base.logging options: members: false

Basics

Normally, when you want to use a logger, you call the [logging.getLogger][] function and pass it a logger name (or not to get the root logger). The common (and recommended) practice is to use getLogger(__name__) which often leads to logging configuration problems as complex applications with many modules (including used libraries) may create complex logger hierarchy.

Our logging module solves the problem by replacing the logger name with agent identification. 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). In most cases, the agent is an instance of some class.

So, from user's perspective, the context logging is used similarly to normal Python logging - but you pass the agent identification instead logger name to [get_logger][firebird.base.logging.get_logger] function. If agent identification is a string, it's used as is. If it's an object, it uses value of its _agent_name_ attribute if defined, otherwise it uses name in "MODULE_NAME.CLASS_QUALNAME" format. If _agent_name_ value is not a string, it's converted to string.

The typical usage pattern inside a class is therefore:

logger = get_logger(self)

or for direct use:

get_logger(self).debug("message")

The [get_logger][firebird.base.logging.get_logger] also has an optional topic string parameter that could be used to differentiate between various logging "streams". For example the [firebird.base.trace][] module uses context logging with topic "trace", so it's possible to configure the logging system to handle "trace" output in specific way.

The underlying machinery behind [get_logger][firebird.base.logging.get_logger] function maps the agent and its context to particular [logging.Logger][], and returns a [firebird.base.logging.ContextLoggerAdapter][] that you can use as normal logger. This adapter is responsible to add context information into [logging.LogRecord][].

Context information

The context information added by [ContextLoggerAdapter][firebird.base.logging.ContextLoggerAdapter] into [logging.LogRecord][] consists from next items:

  • agent: String representation of the agent identification described above.
  • context: Agent context that could be defined via log_context attribute on agent instance, or by assigning its value directly to extra['context'] on adapter returned by get_logger() function.
  • domain: A name assigned to a group of agents (more about that later).
  • topic: Name of a logging stream.

The adapter keeps context in its extra dictionary. When processing a log message, it copies agent.log_context into extra['context'] only if that key is absent (using None when the agent has no log_context attribute). Once set, the value remains in the adapter; later changes to agent.log_context do not overwrite it. You can set or change log.extra['context'] yourself at any time, including before the first log message.

To have the adapter read agent.log_context again on its next log message, delete the cached key:

log = get_logger(agent)  # An existing agent object
log.extra['context'] = 'manual context'
log.info('Uses the manual context')

agent.log_context = 'current request'
del log.extra['context']
log.info('Uses the current request context')

These record fields can be used in [logging.Formatter][] templates. If you want to combine normal and context logging, assign [ContextFilter][firebird.base.logging.ContextFilter] to your [logging.Handler][] to add (empty) context information into LogRecords that are produced by normal loggers.

LoggingManager

The [firebird.base.logging][] module defines a global [LoggingManager][firebird.base.logging.LoggingManager] instance [logging_manager][firebird.base.logging.logging_manager] that manages several mappings and implements the LoggingManager.get_logger method.

Some methods are also provided as global functions for conveniense: get_logger, set_agent_mapping, set_domain_mapping and get_agent_name.

Mappings and Logger names

The [logging.Logger][] wrapped by the get_logger function is determined by applying the values ​​of several parameters to the logger name format. These parameters are:

  • Domain: String used to group output from agents.
  • Topic: String identification of particular logging stream.

The logger name format is a list that can contain any number of string values and at most one occurrence of DOMAIN or TOPIC enum values. Empty strings are removed.

The final [logging.Logger][] name is constructed by joining elements of this list with dots, and with sentinels replaced with domain and topic names.

For example, if values are defined as:

logger_fmt = ['app', DOMAIN, TOPIC]
domain = 'database'
topic = 'trace'

the Logger name will be: "app.database.trace"

The logger name format is defined in LoggingManager.logger_fmt property, and it's an empty list by default, which means that get_logger function always maps to root logger.

The domain is determined from agent passed to get_logger. You can use set_domain_mapping to assign agent identifications to particular domain. The agents that are not assigned to domain belong to default domain specifid in LoggingManager.default_domain, which is None by default.

It's also possible to change agent identification used for logger name mapping porposes to different value with set_agent_mapping function.

Lazy Formatting Messages

This module also provides message wrapper classes (FStrMessage, BraceMessage, DollarMessage) that defer string formatting until the log record is actually processed by a handler. This avoids the performance cost of formatting messages that might be filtered out due to log levels.

Basic Setup Example

import logging
from firebird.base.logging import (
    get_logger, LogLevel, ContextFilter, logging_manager,
    DOMAIN, TOPIC # For logger_fmt
)

# 1. Configure standard logging (handlers, formatters)
log_format = "[%(levelname)-8s] %(asctime)s %(name)s (%(agent)s) - %(message)s"
formatter = logging.Formatter(log_format)
handler = logging.StreamHandler()
handler.setFormatter(formatter)

# 2. Add ContextFilter to handler(s) to ensure context fields exist
handler.addFilter(ContextFilter())

# 3. Get the root logger or specific standard loggers and add the handler
root_logger = logging.getLogger()
root_logger.addHandler(handler)
root_logger.setLevel(LogLevel.DEBUG) # Use LogLevel enum or logging constants

# 4. (Optional) Configure logging_manager mappings
logging_manager.logger_fmt = ['app', DOMAIN, TOPIC] # Logger name format
logging_manager.default_domain = 'web'            # Default domain if not mapped
logging_manager.set_domain_mapping('db', ['myapp.database.Connection']) # Map agent to domain

# 5. Use in your code
class RequestHandler:
    _agent_name_ = 'myapp.web.RequestHandler' # Optional explicit agent name
    log_context = None # Can be set per request, e.g., client IP

    def handle(self, request_id):
        self.log_context = f"ReqID:{request_id}"
        logger = get_logger(self, topic='requests') # Get context logger
        logger.info("Handling request...")
        # ... processing ...
        logger.debug("Request handled successfully.")

class DbConnection:
    _agent_name_ = 'myapp.database.Connection'
    log_context = None # e.g., DB user

    def query(self, sql):
        self.log_context = "user:admin"
        logger = get_logger(self) # Use default topic (None)
        logger.debug("Executing query: %s", sql) # Standard formatting works too
        # ... execute ...

# --- Execution ---
handler_instance = RequestHandler()
db_conn = DbConnection()

handler_instance.handle("12345")
db_conn.query("SELECT * FROM T")

# --- Example Output ---
# [INFO    ] 2023-10-27... app.web.requests (myapp.web.RequestHandler) - Handling request...
# [DEBUG   ] 2023-10-27... app.web.requests (myapp.web.RequestHandler) - Request handled successfully.
# [DEBUG   ] 2023-10-27... app.db (myapp.database.Connection) - Executing query: SELECT * FROM T

Enums & Flags

::: firebird.base.logging.FormatElement

::: firebird.base.logging.LogLevel

Constants

::: firebird.base.logging.DOMAIN

::: firebird.base.logging.TOPIC

Functions

::: firebird.base.logging.get_logger

::: firebird.base.logging.set_domain_mapping

::: firebird.base.logging.set_agent_mapping

::: firebird.base.logging.get_agent_name

Adapters and Filters

::: firebird.base.logging.ContextLoggerAdapter

::: firebird.base.logging.ContextFilter

Logging manager

::: firebird.base.logging.LoggingManager

Messages

::: firebird.base.logging.FStrMessage

::: firebird.base.logging.BraceMessage

::: firebird.base.logging.DollarMessage

Globals

::: firebird.base.logging.logging_manager