Standard Library Logging¶
Ideally, structlog
should be able to be used as a drop-in replacement for standard library’s logging
by wrapping it.
In other words, you should be able to replace your call to logging.getLogger
by a call to structlog.get_logger
and things should keep working as before (if structlog
is configured right, see Suggested Configurations below).
If you run into incompatibilities, it is a bug so please take the time to report it!
If you’re a heavy logging
user, your help to ensure a better compatibility would be highly appreciated!
Just Enough logging
¶
If you want to use structlog
with logging
, you still have to have at least fleeting understanding on how the standard library operates because structlog
will not do any magic things in the background for you.
Most importantly you have to configure the logging
system additionally to configuring structlog
.
Usually it is enough to use:
import logging
import sys
logging.basicConfig(
format="%(message)s",
stream=sys.stdout,
level=logging.INFO,
)
This will send all log messages with the log level logging.INFO
and above (that means that e.g. logging.debug
calls are ignored) to standard out without any special formatting by the standard library.
If you require more complex behavior, please refer to the standard library’s logging
documentation.
Concrete Bound Logger¶
To make structlog
’s behavior less magicy, it ships with a standard library-specific wrapper class that has an explicit API instead of improvising: structlog.stdlib.BoundLogger
.
It behaves exactly like the generic structlog.BoundLogger
except:
it’s slightly faster due to less overhead,
has an explicit API that mirrors the log methods of standard library’s
logging.Logger
,it has correct type hints,
hence causing less cryptic error messages if you get method names wrong.
If you’re using static types (e.g. with Mypy) you also may want to use structlog.stdlib.get_logger()
that has the appropriate type hints if you’re using structlog.stdlib.BoundLogger
.
Please note though, that it will neither configure nor verify your configuration.
It will call structlog.get_logger()
just like if you would’ve called it – the only difference are the type hints.
asyncio
¶
For asyncio
applications, you may not want your whole application to block while your processor chain is formatting your log entries.
For that use case structlog
comes with structlog.stdlib.AsyncBoundLogger
that will do all processing in a thread pool executor.
This means an increased computational cost per log entry but your application will never block because of logging.
To use it, configure structlog
to use AsyncBoundLogger
as wrapper_class
.
Processors¶
structlog
comes with a few standard library-specific processors:
render_to_log_kwargs
:Renders the event dictionary into keyword arguments for
logging.log
that attaches everything except theevent
field to the extra argument. This is useful if you want to render your log entries entirely withinlogging
.filter_by_level
:Checks the log entry’s log level against the configuration of standard library’s logging. Log entries below the threshold get silently dropped. Put it at the beginning of your processing chain to avoid expensive operations from happening in the first place.
add_logger_name
:Adds the name of the logger to the event dictionary under the key
logger
.add_log_level()
:Adds the log level to the event dictionary under the key
level
.add_log_level_number
:Adds the log level number to the event dictionary under the key
level_number
. Log level numbers map to the log level names. The Python stdlib uses them for filtering logic. This adds the same numbers so users can leverage similar filtering. Compare:level in ("warning", "error", "critical") level_number >= 30
The mapping of names to numbers is in
structlog.stdlib._NAME_TO_LEVEL
.PositionalArgumentsFormatter
:This processes and formats positional arguments (if any) passed to log methods in the same way the
logging
module would do, e.g.logger.info("Hello, %s", name)
.
structlog
also comes with ProcessorFormatter
which is a logging.Formatter
that enables you to format non-structlog
log entries using structlog
renderers and multiplex structlog
’s output with different renderers (see below for an example).
Suggested Configurations¶
Note
We do appreciate that fully integrating structlog
with standard library’s logging
is fiddly when done for the first time.
This is the price of flexibility and unfortunately – given the different needs of our users – we can’t make it any simpler without compromising someone’s use-cases. However, once it is set up, you can rely on not having to ever touch it again.
Depending where you’d like to do your formatting, you can take one of three approaches:
Rendering Within structlog
¶
This is the simplest approach where structlog
does all the heavy lifting and passes a fully-formatted string to logging
.
Chances are, this is all you need.
A basic configuration to output structured logs in JSON format looks like this:
import structlog
structlog.configure(
processors=[
# If log level is too low, abort pipeline and throw away log entry.
structlog.stdlib.filter_by_level,
# Add the name of the logger to event dict.
structlog.stdlib.add_logger_name,
# Add log level to event dict.
structlog.stdlib.add_log_level,
# Perform %-style formatting.
structlog.stdlib.PositionalArgumentsFormatter(),
# Add a timestamp in ISO 8601 format.
structlog.processors.TimeStamper(fmt="iso"),
# If the "stack_info" key in the event dict is true, remove it and
# render the current stack trace in the "stack" key.
structlog.processors.StackInfoRenderer(),
# If the "exc_info" key in the event dict is either true or a
# sys.exc_info() tuple, remove "exc_info" and render the exception
# with traceback into the "exception" key.
structlog.processors.format_exc_info,
# If some value is in bytes, decode it to a unicode str.
structlog.processors.UnicodeDecoder(),
# Render the final event dict as JSON.
structlog.processors.JSONRenderer()
],
# `wrapper_class` is the bound logger that you get back from
# get_logger(). This one imitates the API of `logging.Logger`.
wrapper_class=structlog.stdlib.BoundLogger,
# `logger_factory` is used to create wrapped loggers that are used for
# OUTPUT. This one returns a `logging.Logger`. The final value (a JSON
# string) from the final processor (`JSONRenderer`) will be passed to
# the method of the same name as that you've called on the bound logger.
logger_factory=structlog.stdlib.LoggerFactory(),
# Effectively freeze configuration after creating the first bound
# logger.
cache_logger_on_first_use=True,
)
To make your program behave like a proper 12 factor app that outputs only JSON to stdout
, configure the logging
module like this:
import logging
import sys
logging.basicConfig(
format="%(message)s",
stream=sys.stdout,
level=logging.INFO,
)
In this case only your own logs are formatted as JSON:
>>> structlog.get_logger("test").warning("hello")
{"event": "hello", "logger": "test", "level": "warning", "timestamp": "2017-03-06T07:39:09.518720Z"}
>>> logging.getLogger("test").warning("hello")
hello
Rendering Using logging
-based Formatters¶
import structlog
structlog.configure(
processors=[
structlog.stdlib.filter_by_level,
structlog.stdlib.add_logger_name,
structlog.stdlib.add_log_level,
structlog.stdlib.PositionalArgumentsFormatter(),
structlog.processors.StackInfoRenderer(),
structlog.processors.format_exc_info,
structlog.processors.UnicodeDecoder(),
# Transform event dict into `logging.Logger` method arguments.
# "event" becomes "msg" and the rest is passed as a dict in
# "extra". IMPORTANT: This means that the standard library MUST
# render "extra" for the context to appear in log entries! See
# warning below.
structlog.stdlib.render_to_log_kwargs,
],
logger_factory=structlog.stdlib.LoggerFactory(),
wrapper_class=structlog.stdlib.BoundLogger,
cache_logger_on_first_use=True,
)
Now you have the event dict available within each log record.
If you want all your log entries (i.e. also those not from your app/structlog
) to be formatted as JSON, you can use the python-json-logger library:
import logging
import sys
from pythonjsonlogger import jsonlogger
handler = logging.StreamHandler(sys.stdout)
handler.setFormatter(jsonlogger.JsonFormatter())
root_logger = logging.getLogger()
root_logger.addHandler(handler)
Now both structlog
and logging
will emit JSON logs:
>>> structlog.get_logger("test").warning("hello")
{"message": "hello", "logger": "test", "level": "warning"}
>>> logging.getLogger("test").warning("hello")
{"message": "hello"}
Warning
With this approach, it’s the standard library logging
formatter’s duty to do something useful with the event dict.
In the above example that’s jsonlogger.JsonFormatter
.
Keep this in mind if you only get the event name without any context, and exceptions are ostensibly swallowed.
Rendering Using structlog
-based Formatters Within logging
¶
structlog
comes with a ProcessorFormatter
that can be used as a logging.Formatter
in any stdlib Handler
object.
The ProcessorFormatter
has two parts to its API:
The
structlog.stdlib.ProcessorFormatter.wrap_for_formatter
method must be used as the last processor instructlog.configure
, it converts the processed event dict to something that theProcessorFormatter
understands.The
ProcessorFormatter
itself, which can wrap anystructlog
renderer to handle the output of bothstructlog
and standard library events.
Thus, the simplest possible configuration looks like the following:
import logging
import structlog
structlog.configure(
processors=[
# Prepare event dict for `ProcessorFormatter`.
structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
],
logger_factory=structlog.stdlib.LoggerFactory(),
)
formatter = structlog.stdlib.ProcessorFormatter(
processor=structlog.dev.ConsoleRenderer(),
)
handler = logging.StreamHandler()
# Use OUR `ProcessorFormatter` to format all `logging` entries.
handler.setFormatter(formatter)
root_logger = logging.getLogger()
root_logger.addHandler(handler)
root_logger.setLevel(logging.INFO)
which will allow both of these to work in other modules:
>>> import logging
>>> import structlog
>>> logging.getLogger("stdlog").info("woo")
woo
>>> structlog.get_logger("structlog").info("amazing", events="oh yes")
amazing events=oh yes
Of course, you probably want timestamps and log levels in your output.
The ProcessorFormatter
has a foreign_pre_chain
argument which is responsible for adding properties to events from the standard library – i.e. that do not originate from a structlog
logger – and which should in general match the processors
argument to structlog.configure
so you get a consistent output.
For example, to add timestamps, log levels, and traceback handling to your logs you should do:
timestamper = structlog.processors.TimeStamper(fmt="%Y-%m-%d %H:%M:%S")
shared_processors = [
structlog.stdlib.add_log_level,
timestamper,
]
structlog.configure(
processors=shared_processors + [
structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
],
logger_factory=structlog.stdlib.LoggerFactory(),
cache_logger_on_first_use=True,
)
formatter = structlog.stdlib.ProcessorFormatter(
processor=structlog.dev.ConsoleRenderer(),
# These run ONLY on `logging` entries that do NOT originate within
# structlog.
foreign_pre_chain=shared_processors,
)
which (given the same logging.*
calls as in the previous example) will result in:
>>> logging.getLogger("stdlog").info("woo")
2017-03-06 14:59:20 [info ] woo
>>> structlog.get_logger("structlog").info("amazing", events="oh yes")
2017-03-06 14:59:20 [info ] amazing events=oh yes
This allows you to set up some sophisticated logging configurations.
For example, to use the standard library’s logging.config.dictConfig
to log colored logs to the console and plain logs to a file you could do:
import logging.config
import structlog
timestamper = structlog.processors.TimeStamper(fmt="%Y-%m-%d %H:%M:%S")
pre_chain = [
# Add the log level and a timestamp to the event_dict if the log entry
# is not from structlog.
structlog.stdlib.add_log_level,
timestamper,
]
logging.config.dictConfig({
"version": 1,
"disable_existing_loggers": False,
"formatters": {
"plain": {
"()": structlog.stdlib.ProcessorFormatter,
"processor": structlog.dev.ConsoleRenderer(colors=False),
"foreign_pre_chain": pre_chain,
},
"colored": {
"()": structlog.stdlib.ProcessorFormatter,
"processor": structlog.dev.ConsoleRenderer(colors=True),
"foreign_pre_chain": pre_chain,
},
},
"handlers": {
"default": {
"level": "DEBUG",
"class": "logging.StreamHandler",
"formatter": "colored",
},
"file": {
"level": "DEBUG",
"class": "logging.handlers.WatchedFileHandler",
"filename": "test.log",
"formatter": "plain",
},
},
"loggers": {
"": {
"handlers": ["default", "file"],
"level": "DEBUG",
"propagate": True,
},
}
})
structlog.configure(
processors=[
structlog.stdlib.add_log_level,
structlog.stdlib.PositionalArgumentsFormatter(),
timestamper,
structlog.processors.StackInfoRenderer(),
structlog.processors.format_exc_info,
structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
],
logger_factory=structlog.stdlib.LoggerFactory(),
wrapper_class=structlog.stdlib.BoundLogger,
cache_logger_on_first_use=True,
)
This defines two formatters: one plain and one colored.
Both are run for each log entry.
Log entries that do not originate from structlog
, are additionally pre-processed using a cached timestamper
and add_log_level()
.
>>> logging.getLogger().warning("bar")
2017-03-06 11:49:27 [warning ] bar
>>> structlog.get_logger("structlog").warning("foo", x=42)
2017-03-06 11:49:32 [warning ] foo x=42
>>> print(open("test.log").read())
2017-03-06 11:49:27 [warning ] bar
2017-03-06 11:49:32 [warning ] foo x=42
(Sadly, you have to imagine the colors in the first two outputs.)
If you leave foreign_pre_chain
as None
, formatting will be left to logging
.
Meaning: you can define a format
for ProcessorFormatter
too!