Usage

Setup

logstruct provides a formatter that formats all log records from standard library logging.Logger or its own StructuredLogger as JSON.

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

logging.getLogger("stdlib-logger").info("hello world")

{"time": "...", "logger": "stdlib-logger", "level": "INFO", ..., "message": "hello world"}

Structured data

StructuredLogger is a replacement for the standard library logging.Logger with an almost identical API. 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.warning("take a look", request_id=1234)
logger.error("uh-oh", request_id=1234)

{..., "level": "DEBUG", ..., "message": "good to know", "request_id": 1234}
{..., "level": "WARNING", ..., "message": "take a look", "request_id": 1234}
{..., "level": "ERROR", ..., "message": "uh-oh", "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"}

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}

Logging config file (YAML)

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]

demo_dict_config.py

#!/usr/bin/env python3
"""Structured logging demo with dict config from YAML."""

import logging
import logging.config
from pathlib import Path

import yaml

import logstruct

config_file = Path(__file__).parent / "example_config.yaml"
with open(config_file) as f:
    config = yaml.safe_load(f)
    logging.config.dictConfig(config)

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

{"time": "2025-03-02 01:07:23,832", "logger": "__main__", "level": "INFO", "func": "<module>", "line": 19, "message": "An info message"}
{"time": "2025-03-02 01:07:23,833", "logger": "__main__", "level": "INFO", "func": "<module>", "line": 20, "message": "An info message with stack info", "stack_info": "Stack (most recent call last):\n  File \"/home/docs/checkouts/readthedocs.org/user_builds/logstruct/checkouts/0.1.1/docs/../demo_dict_config.py\", line 20, in <module>\n    log.info(\"An info message with stack info\", stack_info=True)"}
{"time": "2025-03-02 01:07:23,833", "logger": "__main__", "level": "INFO", "func": "<module>", "line": 21, "message": "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'>"}
{"time": "2025-03-02 01:07:23,833", "logger": "__main__", "level": "INFO", "func": "<module>", "line": 22, "message": "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'>"}
{"time": "2025-03-02 01:07:23,833", "logger": "__main__", "level": "ERROR", "func": "<module>", "line": 27, "message": "Division error", "exc_text": "Traceback (most recent call last):\n  File \"/home/docs/checkouts/readthedocs.org/user_builds/logstruct/checkouts/0.1.1/docs/../demo_dict_config.py\", line 25, in <module>\n    print(1 / 0)\n          ~~^~~\nZeroDivisionError: division by zero"}

Logging config file (ini)

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

demo_file_config.py

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

import logging
import logging.config
from pathlib import Path

import logstruct

config_file = Path(__file__).parent / "example_config.ini"
logging.config.fileConfig(config_file, disable_existing_loggers=False)

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

{"time": "2025-03-02 01:07:23,897", "logger": "__main__", "level": "INFO", "func": "<module>", "line": 15, "message": "An info message"}
{"time": "2025-03-02 01:07:23,897", "logger": "__main__", "level": "INFO", "func": "<module>", "line": 16, "message": "An info message with stack info", "stack_info": "Stack (most recent call last):\n  File \"/home/docs/checkouts/readthedocs.org/user_builds/logstruct/checkouts/0.1.1/docs/../demo_file_config.py\", line 16, in <module>\n    log.info(\"An info message with stack info\", stack_info=True)"}
{"time": "2025-03-02 01:07:23,897", "logger": "__main__", "level": "INFO", "func": "<module>", "line": 17, "message": "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'>"}
{"time": "2025-03-02 01:07:23,898", "logger": "__main__", "level": "INFO", "func": "<module>", "line": 18, "message": "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'>"}
{"time": "2025-03-02 01:07:23,898", "logger": "__main__", "level": "ERROR", "func": "<module>", "line": 23, "message": "Division error", "exc_text": "Traceback (most recent call last):\n  File \"/home/docs/checkouts/readthedocs.org/user_builds/logstruct/checkouts/0.1.1/docs/../demo_file_config.py\", line 21, in <module>\n    print(1 / 0)\n          ~~^~~\nZeroDivisionError: division by zero"}

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, and clear_scope.

logstruct.add_context(request_id="1234")
logstruct.add_context(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"}

Highly customised config

#!/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].formatter = 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-02 01:07:23",
    "name": "__main__",
    "level": "INFO",
    "module": "demo_custom",
    "func": "<module>",
    "line": 37,
    "event": "An info message"
}
{
    "ts": "2025-03-02 01:07:23",
    "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/0.1.1/docs/../demo_custom.py\", line 38, in <module>\n    log.info(\"An info message with stack info\", stack_info=True)"
}
{
    "ts": "2025-03-02 01:07:23",
    "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-02 01:07:23",
    "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-02 01:07:23",
    "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/0.1.1/docs/../demo_custom.py\", line 43, in <module>\n    print(1 / 0)\n          ~~^~~\nZeroDivisionError: division by zero"
}

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-02 01:07:23,996 DEBUG    __main__:<module>:31 A debug message
2025-03-02 01:07:23,996 INFO     __main__:<module>:32 An info message
2025-03-02 01:07:23,996 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/0.1.1/docs/../demo_dev_mode.py", line 33, in <module>
    log.warning("A warning message with stack info", stack_info=True)
2025-03-02 01:07:23,996 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-02 01:07:23,996 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-02 01:07:23,996 ERROR    __main__:<module>:40 Division error
Traceback (most recent call last):
  File "/home/docs/checkouts/readthedocs.org/user_builds/logstruct/checkouts/0.1.1/docs/../demo_dev_mode.py", line 38, in <module>
    print(1 / 0)
          ~~^~~
ZeroDivisionError: division by zero

DEBUG not set

{"time": "2025-03-02 01:07:24,044", "logger": "__main__", "level": "DEBUG", "func": "<module>", "line": 31, "message": "A debug message"}
{"time": "2025-03-02 01:07:24,044", "logger": "__main__", "level": "INFO", "func": "<module>", "line": 32, "message": "An info message"}
{"time": "2025-03-02 01:07:24,045", "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/0.1.1/docs/../demo_dev_mode.py\", line 33, in <module>\n    log.warning(\"A warning message with stack info\", stack_info=True)"}
{"time": "2025-03-02 01:07:24,045", "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-02 01:07:24,045", "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-02 01:07:24,045", "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/0.1.1/docs/../demo_dev_mode.py\", line 38, in <module>\n    print(1 / 0)\n          ~~^~~\nZeroDivisionError: division by zero"}