Usage

Setup

StructuredLogger

No special setup is needed for StructuredLogger. Just call logstruct.getLogger to obtain it and use it.

All key logging.Logger methods exist in StructuredLogger. For the ones that don’t, use the public StructuredLogger.logger attribute to manage the stdlib logger.

StructuredFormatter

In order to format incoming log records as JSON, StructuredFormatter needs to be assigned to the log handler in use. Once this is done, log records will be output as JSON, regardless of where they come from - logging.Logger or StructuredLogger.

logging.basicConfig(level=logging.DEBUG)
logging.root.handlers[0].setFormatter(logstruct.StructuredFormatter())

logging.getLogger("stdlib-logger").info("hello world")
{"time": "...", "logger": "stdlib-logger", "level": "INFO", ..., "message": "hello world"}

StructuredFormatter supports the standard dictConfig method and the legacy fileConfig method of file configuration.

Structured data

StructuredLogger’s logging API is nearly identical to the standard library logging.Logger. The key difference is that additional keyword arguments provided to logging functions are automatically included in structured output.

logger = logstruct.getLogger(__name__)
logger.info("hello", request_id=1234, user="black_knight")
{..., "level": "INFO", ..., "message": "hello", "request_id": 1234, "user": "black_knight"}

This works for all logging levels.

logger.debug("good to know", request_id=1234)
logger.info("doing this and that", request_id=1234)
logger.warning("take a look", request_id=1234)
logger.error("uh-oh", request_id=1234)
logger.critical("abort", request_id=1234)
{..., "level": "DEBUG", ..., "message": "good to know", "request_id": 1234}
{..., "level": "INFO", ..., "message": "doing this and that", "request_id": 1234}
{..., "level": "WARNING", ..., "message": "take a look", "request_id": 1234}
{..., "level": "ERROR", ..., "message": "uh-oh", "request_id": 1234}
{..., "level": "CRITICAL", ..., "message": "abort", "request_id": 1234}

Alternatively, structured data can be passed as a dictionary in the extra parameter:

logger.info("hello", extra={"request_id": 1234, "user": "black_knight"})
{..., "message": "hello", "request_id": 1234, "user": "black_knight"}

Passing data in the extra parameter also works for standard library loggers:

standard_logger = logging.getLogger("stdlib-logger")
standard_logger.info("hello", extra={"request_id": 1234})
{..., "message": "hello", "request_id": 1234}

Structured data from dictionaries

It may be tempting to unpack a dictionary like this:

data = {k: v, ...}
log.info("hello", **data)

This will not typecheck correctly due to the inclusion of stdlib arguments like stack_level in log method signatures.

This, however, will typecheck:

log.info("hello", extra=data)

Exception logging

Similar to logging.Logger, you can include exception information using the exc_info parameter:

logger.error("uh-oh", exc_info=ValueError("wrong value"), request_id=1234)
{..., "message": "uh-oh", "exc_text": "ValueError: wrong value", "request_id": 1234}

The currently handled exception is automatically captured if exc_info is true or if logger.exception is called.

try:
    x = 1 / 0
except ZeroDivisionError:
    logger.debug("debug", exc_info=True, request_id=1234)
    logger.exception("error", request_id=1234)
{..., "level": "DEBUG",... "message": "debug", "exc_text": "Traceback ...ZeroDivisionError: division by zero", "request_id": 1234}
{..., "level": "ERROR",... "message": "error", "exc_text": "Traceback ...ZeroDivisionError: division by zero", "request_id": 1234}

exc_text includes the traceback of the exception relative to the logging call. You can customise exception formatting by subclassing StructuredFormatter and overriding logging.Formatter.formatException, just like you would do it with any other logging.Formatter.

Stack logging

Similar to logging.Logger, you can include stack information using the stack_info parameter:

logger.info("with stack", stack_info=True, stacklevel=0)
{..., "stack_info": "Stack (most recent call last):...", ...}

The stacklevel parameter controls the number of stack frames that are omitted from stack_info, relative to the frame from which the log method is called.

Context variables

Logstruct context variables are meant to contain data relevant to the current operation, like message ID, request path, user ID, job name, job ID, etc. Once set, they are shared by all subsequent logs until they are unset.

Context variables are automatically incorporated in produced structured logs but they can be overridden by keyword args directly passed to log calls. Context variables are implemented with contextvars.Context which makes them local to the current thread, asyncio task, or gevent task. Context variables are automatically inherited by child tasks but not by spawned threads.

You can use context_scope to add contextual information to all log records within the scope.

with logstruct.context_scope(request_id="1234"):
    logger.info("has context", user="abc")

logger.info("scope ended")
{..., "message": "has context", "request_id": "1234", "user": "abc"}
{..., "message": "scope ended"}

Contexts can be nested. Inner scopes shadow data from outer scopes.

with logstruct.context_scope(outer="outer", redefined="outer"):
    with logstruct.context_scope(inner="inner", redefined="inner"):
        logger.info("inner context")
{..., "message": "inner context", "inner": "inner", "redefined": "inner", "outer": "outer"}

You can modify the current context with add_context, remove_context, or clear_scope.

logstruct.add_context(request_id="1234", user="abc")
logger.info("has context")

logstruct.remove_context("user")
logger.info("only request_id")

logstruct.clear_scope()
logger.info("no context")
{..., "message": "has context", "request_id": "1234", "user": "abc"}
{..., "message": "only request_id", "request_id": "1234"}
{..., "message": "no context"}

Modifications only apply to the current scope. Once the scope ends, all modifications are lost.

with logstruct.context_scope(request_id="1234"):
  logstruct.add_context(user="abc")
  logger.info("modified")

logger.info("unmodified")
{..., "message": "modified", "request_id": "1234", "user": "abc"}
{..., "message": "unmodified"}

Configuration

Logger configuration

There is no configuration specific to StructuredLogger. Since each StructuredLogger is paired with a logging.Logger with the same name, that logger should be configured as in the official docs.

logging.config.fileConfig and logging.config.dictConfig configuration works just like it does in the standard library.

Formatter configuration

A StructuredFormatter is configured using StructuredFormatterConfig.

Logstruct provides two default configs: logstruct.CONFIG_FORMATTED_MESSAGE and logstruct.CONFIG_RAW_MESSAGE, which can be used directly or copied to derive custom configuration.

StructuredFormatterConfig attributes

Attribute

Default

Description

format_message

True

Controls whether log messages should be formatted with positional log call arguments (using record.getMessage()) or left unformatted (keeping record.msg).

uses_time

True

Determines if the current time should be assigned to LogRecord.asctime.

log_fields

DEFAULT_LOG_FIELDS

Defines how LogRecord attributes map to output key-value pairs. See Log field configuration below.

get_context_fn

logstruct.get_context

Function to retrieve context variables that get merged into the output.

dumps_fn

json.dumps with default=repr

Function used to serialise final structured into text for logging.

Log field configuration

The LogField struct allows you to map logging.LogRecord attributes to structured output keys. LogRecord is the piece of log data sent from the logger to the handler to be formatted by its formatter and written out. LogRecord attribute reference can be found in standard library docs.

LogField attributes

Attribute

Default?

Description

LogField.source

(or legacy log_record_attr)

required

Source LogRecord attribute name or a callable that receives a LogRecord and returns a string.

LogField.dest

(or legacy struct_key)

required

The output key in the structured log.

LogField.condition

None

An optional callable to determine if the field should be included. Always included if None.

For example, this LogField will try to pick up the taskName attribute from the LogRecord and include it as the "task" key in the produced log. If the attribute is missing, the key won’t be included.

LogField("taskName", "task", bool),
{"task": "Task-1234"}

If the condition is missing, the key will always be included even if the source LogRecord attribute is missing or evaluates to False.

LogField("taskName", "task"),
{"task": null}

Highly customised configuration example

The following example defines completely custom configuration, featuring:

  • disabling log message formatting

  • specifying own LogFields

  • custom serialisation function

The example configures Logstruct in Python - see Using configuration files for config file examples.

#!/usr/bin/env python3
"""Structured logging demo with customisation."""

import json
import logging
from functools import partial

import logstruct
from logstruct import LogField, StructuredFormatter, StructuredFormatterConfig

logging.basicConfig(level=logging.INFO)

custom_json_formatter = StructuredFormatter(
    datefmt="%Y-%m-%d %H:%M:%S",
    structured_formatter_config=StructuredFormatterConfig(
        format_message=False,
        log_fields=[
            LogField("asctime", "ts", bool),
            LogField("name", "name"),
            LogField("levelname", "level"),
            LogField("module", "module"),
            LogField("funcName", "func"),
            LogField("lineno", "line"),
            LogField("message", "event"),
            LogField("exc_text", "exc_text", bool),
            LogField("stack_info", "stack_info", bool),
            LogField("args", "positional_args", bool),
        ],
        # without `default=repr` it's very easy to cause serialisation errors
        dumps_fn=partial(json.dumps, indent=4, default=repr),
    ),
)
logging.root.handlers[0].setFormatter(custom_json_formatter)

log = logstruct.getLogger(__name__)

log.info("An info message")
log.info("An info message with stack info", stack_info=True)
log.info("An info message with data (traditional)", extra={"log": "struct", "unrepresentable": logging})
log.info("An info message with data (kwargs)", log="struct", unrepresentable=logging)

try:
    print(1 / 0)
except Exception:
    log.exception("Division error")
log output
{
    "ts": "2025-03-22 17:42:04",
    "name": "__main__",
    "level": "INFO",
    "module": "demo_custom",
    "func": "<module>",
    "line": 37,
    "event": "An info message"
}
{
    "ts": "2025-03-22 17:42:04",
    "name": "__main__",
    "level": "INFO",
    "module": "demo_custom",
    "func": "<module>",
    "line": 38,
    "event": "An info message with stack info",
    "stack_info": "Stack (most recent call last):\n  File \"/home/docs/checkouts/readthedocs.org/user_builds/logstruct/checkouts/stable/docs/../demo_custom.py\", line 38, in <module>\n    log.info(\"An info message with stack info\", stack_info=True)"
}
{
    "ts": "2025-03-22 17:42:04",
    "name": "__main__",
    "level": "INFO",
    "module": "demo_custom",
    "func": "<module>",
    "line": 39,
    "event": "An info message with data (traditional)",
    "log": "struct",
    "unrepresentable": "<module 'logging' from '/home/docs/.asdf/installs/python/3.12.7/lib/python3.12/logging/__init__.py'>"
}
{
    "ts": "2025-03-22 17:42:04",
    "name": "__main__",
    "level": "INFO",
    "module": "demo_custom",
    "func": "<module>",
    "line": 40,
    "event": "An info message with data (kwargs)",
    "log": "struct",
    "unrepresentable": "<module 'logging' from '/home/docs/.asdf/installs/python/3.12.7/lib/python3.12/logging/__init__.py'>"
}
{
    "ts": "2025-03-22 17:42:04",
    "name": "__main__",
    "level": "ERROR",
    "module": "demo_custom",
    "func": "<module>",
    "line": 45,
    "event": "Division error",
    "exc_text": "Traceback (most recent call last):\n  File \"/home/docs/checkouts/readthedocs.org/user_builds/logstruct/checkouts/stable/docs/../demo_custom.py\", line 43, in <module>\n    print(1 / 0)\n          ~~^~~\nZeroDivisionError: division by zero"
}

Using configuration files

File configuration of StructuredFormatter is fully supported, including configuring LogFields.

Basic dictConfig

You can configure logstruct with a data file by loading it and passing it to logging.config.dictConfig.

example_config.yaml
version: 1
disable_existing_loggers: false

handlers:
  stream:
    class: logging.StreamHandler
    formatter: structured
    level: INFO
    stream: ext://sys.stderr
formatters:
  structured:
    class: logstruct.StructuredFormatter
root:
  level: INFO
  handlers: [stream]
config = yaml.safe_load(Path("example_config.yaml").read_text())
logging.config.dictConfig(config)
logger = logstruct.getLogger(__name__)
logger.info("hello", request_id=1234)
{"time": "...", "level": "INFO", ..., "message": "hello", "request_id": 1234}

StructuredFormatter config in dictConfig

Formatter configuration is available thanks to the () feature in dictConfig, allowing to pass custom parameters to the formatter’s constructor.

example_config.yaml
formatters:
  structured:
    (): logstruct.StructuredFormatter
    structured_formatter_config:
      format_message: False
      uses_time: True

Refer to Advanced dictConfig example for complete code.

Callables in dictConfig

Some values, for example StructuredFormatterConfig.dumps_fn, are callables. While it isn’t possible to define functions in config files, config attributes can still reference Python functions. For example, if user_module.submodule.user_func is passed as a value of a callable config field, the user_module.submodule module will be imported and user_func will be retrieved from it.

example_config.yaml
formatters:
  structured:
    (): logstruct.StructuredFormatter
    structured_formatter_config:
      dumps_fn: logstruct.DEFAULT_DUMPS_FN  # This is the default but you can import anything

LogFields in dictConfig

It is also possible to configure LogFields via dictConfig.

example_config.yaml
formatters:
  structured:
    (): logstruct.StructuredFormatter
    structured_formatter_config:
      log_fields:
        - source: asctime
          dest: ts
          condition: bool
        - source: levelname
          dest: level
... etc ...

Note

LogField.source can be either a string or a callable and the two are distinguished by the presence of a dot in the value, so:

  • source: lineno will be the LogRecord.lineno attribute

  • source: my_module.get_line_no will be the get_line_no function in my_module.

If for whatever reason you want your source callable to be a built-in, you need to spell out the __builtins__ module explicitly, e.g. source: __builtins__.vars

Advanced dictConfig example

The following example uses a YAML file to define data passed to logging.config.dictConfig and specify custom StructuredFormatterConfig, including log fields. Callables are referenced from the dumps_fn and a number of condition keys. No Python code is used to specify configuration.

example_config.yaml
version: 1
disable_existing_loggers: false

handlers:
  stream:
    class: logging.StreamHandler
    formatter: structured
    level: INFO
    stream: ext://sys.stderr
formatters:
  structured:
    (): logstruct.StructuredFormatter
    structured_formatter_config:
      format_message: False
      uses_time: True
      log_fields:
        - source: asctime
          dest: ts
          condition: bool
        - source: levelname
          dest: level
        - source: name
          dest: logger
        - source: lineno
          dest: line
        - source: message
          dest: msg
        - source: args
          dest: msg_args
          condition: bool
        - source: exc_text
          dest: exc
          condition: bool
        - source: stack_info
          dest: stack_info
          condition: bool
      dumps_fn: logstruct.DEFAULT_DUMPS_FN  # This is the default but you can import anything
root:
  level: INFO
  handlers: [stream]
config = yaml.safe_load(Path("example_config_advanced.yaml").read_text())
logging.config.dictConfig(config)
logger = logstruct.getLogger(__name__)
logger.info("hello", request_id=1234)
{"ts": "...", "level": "INFO", "logger": "...", "line": ..., "msg": "hello", "request_id": 1234}

Note

Sadly, YAML sucks. It is used here only because Python uses it in its dictConfig documentation.

Legacy fileConfig (ini files)

logstruct can be configured with the standard library’s configuration file format and the fileConfig function. Unlike dictConfig, this method doesn’t allow for custom formatter configuration.

example_config.ini
[loggers]
keys=root

[handlers]
keys=stream

[formatters]
keys=structured

[handler_stream]
class=logging.StreamHandler
formatter=structured
level=INFO
stream=ext://sys.stderr

[formatter_structured]
class=logstruct.StructuredFormatter

[logger_root]
level=INFO
handlers = stream
logging.config.fileConfig("example_config.ini", disable_existing_loggers=False)
logger = getLogger(__name__)
logger.info("hello", request_id=1234)
{"time": "...", "level": "INFO", ..., "message": "hello", "request_id": 1234}

Development mode logging

In this demo the DEBUG env var set to a non-empty value makes logs formatted in a developer-friendly way, but unlike the default formatter, will include the extra dictionary, where our log call key-values go.

#!/usr/bin/env python3
"""Structured logging demo - dev-friendly console renderer."""

import logging
import os

import logstruct
from logstruct import (
    StructuredFormatter,
    StructuredFormatterConfig,
    make_friendly_dump_fn,
)

logging.basicConfig(level=logging.DEBUG)
handler = logging.root.handlers[0]

if os.environ.get("DEBUG"):
    handler.formatter = StructuredFormatter(
        structured_formatter_config=StructuredFormatterConfig(
            dumps_fn=make_friendly_dump_fn(
                # Enable colours only if the handler pointed to a teletype.
                colours=isinstance(handler, logging.StreamHandler) and handler.stream.isatty()
            ),
        )
    )
else:
    handler.formatter = StructuredFormatter()

log = logstruct.getLogger(__name__)

log.debug("A debug message")
log.info("An info message")
log.warning("A warning message with stack info", stack_info=True)
log.error("An error message with data (traditional)", extra={"log": "struct", "unrepresentable": logging})
log.critical("A critical message with data (kwargs)", log="struct", unrepresentable=logging)

try:
    print(1 / 0)
except Exception:
    log.exception("Division error")
DEBUG=1
2025-03-22 17:42:04,407 DEBUG    __main__:<module>:31 A debug message
2025-03-22 17:42:04,407 INFO     __main__:<module>:32 An info message
2025-03-22 17:42:04,407 WARNING  __main__:<module>:33 A warning message with stack info
Stack (most recent call last):
  File "/home/docs/checkouts/readthedocs.org/user_builds/logstruct/checkouts/stable/docs/../demo_dev_mode.py", line 33, in <module>
    log.warning("A warning message with stack info", stack_info=True)
2025-03-22 17:42:04,407 ERROR    __main__:<module>:34 An error message with data (traditional) {"log": "struct", "unrepresentable": "<module 'logging' from '/home/docs/.asdf/installs/python/3.12.7/lib/python3.12/logging/__init__.py'>"}
2025-03-22 17:42:04,407 CRITICAL __main__:<module>:35 A critical message with data (kwargs) {"log": "struct", "unrepresentable": "<module 'logging' from '/home/docs/.asdf/installs/python/3.12.7/lib/python3.12/logging/__init__.py'>"}
2025-03-22 17:42:04,407 ERROR    __main__:<module>:40 Division error
Traceback (most recent call last):
  File "/home/docs/checkouts/readthedocs.org/user_builds/logstruct/checkouts/stable/docs/../demo_dev_mode.py", line 38, in <module>
    print(1 / 0)
          ~~^~~
ZeroDivisionError: division by zero
DEBUG not set
{"time": "2025-03-22 17:42:04,458", "logger": "__main__", "level": "DEBUG", "func": "<module>", "line": 31, "message": "A debug message"}
{"time": "2025-03-22 17:42:04,458", "logger": "__main__", "level": "INFO", "func": "<module>", "line": 32, "message": "An info message"}
{"time": "2025-03-22 17:42:04,458", "logger": "__main__", "level": "WARNING", "func": "<module>", "line": 33, "message": "A warning message with stack info", "stack_info": "Stack (most recent call last):\n  File \"/home/docs/checkouts/readthedocs.org/user_builds/logstruct/checkouts/stable/docs/../demo_dev_mode.py\", line 33, in <module>\n    log.warning(\"A warning message with stack info\", stack_info=True)"}
{"time": "2025-03-22 17:42:04,458", "logger": "__main__", "level": "ERROR", "func": "<module>", "line": 34, "message": "An error message with data (traditional)", "log": "struct", "unrepresentable": "<module 'logging' from '/home/docs/.asdf/installs/python/3.12.7/lib/python3.12/logging/__init__.py'>"}
{"time": "2025-03-22 17:42:04,458", "logger": "__main__", "level": "CRITICAL", "func": "<module>", "line": 35, "message": "A critical message with data (kwargs)", "log": "struct", "unrepresentable": "<module 'logging' from '/home/docs/.asdf/installs/python/3.12.7/lib/python3.12/logging/__init__.py'>"}
{"time": "2025-03-22 17:42:04,458", "logger": "__main__", "level": "ERROR", "func": "<module>", "line": 40, "message": "Division error", "exc_text": "Traceback (most recent call last):\n  File \"/home/docs/checkouts/readthedocs.org/user_builds/logstruct/checkouts/stable/docs/../demo_dev_mode.py\", line 38, in <module>\n    print(1 / 0)\n          ~~^~~\nZeroDivisionError: division by zero"}