Examples¶
This chapter is intended to give you a taste of realistic usage of structlog
.
Flask and Thread-Local Data¶
Let’s assume you want to bind a unique request ID, the URL path, and the peer’s IP to every log entry:
import logging
import sys
import uuid
import flask
from some_module import some_function
import structlog
logger = structlog.get_logger()
app = flask.Flask(__name__)
@app.route("/login", methods=["POST", "GET"])
def some_route():
# You would put this into some kind of middleware or processor so it's set
# automatically for all requests in all views.
structlog.threadlocal.clear_threadlocal()
structlog.threadlocal.bind_threadlocal(
view=flask.request.path,
request_id=str(uuid.uuid4()),
peer=flask.request.access_route[0],
)
# End of belongs-to-middleware.
log = logger.bind()
# do something
# ...
log.info("user logged in", user="test-user")
# ...
some_function()
# ...
return "logged in!"
if __name__ == "__main__":
logging.basicConfig(
format="%(message)s", stream=sys.stdout, level=logging.INFO
)
structlog.configure(
processors=[
structlog.threadlocal.merge_threadlocal, # <--!!!
structlog.processors.KeyValueRenderer(
key_order=["event", "view", "peer"]
),
],
logger_factory=structlog.stdlib.LoggerFactory(),
)
app.run()
some_module.py
from structlog import get_logger
logger = get_logger()
def some_function():
# ...
logger.error("user did something", something="shot_in_foot")
# ...
This would result among other the following lines to be printed:
event='user logged in' view='/login' peer='127.0.0.1' user='test-user' request_id='e08ddf0d-23a5-47ce-b20e-73ab8877d736'
event='user did something' view='/login' peer='127.0.0.1' something='shot_in_foot' request_id='e08ddf0d-23a5-47ce-b20e-73ab8877d736'
As you can see, view
, peer
, and request_id
are present in both log entries.
While wrapped loggers are immutable by default, this example demonstrates how to circumvent that using a thread-local storage for request-wide context:
structlog.threadlocal.clear_threadlocal()
ensures the thread-local storage is empty for each request.structlog.threadlocal.bind_threadlocal()
puts your key-value pairs into thread-local storage.The
structlog.threadlocal.merge_threadlocal()
processor merges the thread-local context into the event dict.
Please note that the user
field is only present in the view because it wasn’t bound into the thread-local storage.
See Thread-Local Context for more details.
structlog.stdlib.LoggerFactory
is a totally magic-free class that just deduces the name of the caller’s module and does a logging.getLogger
with it.
It’s used by structlog.get_logger
to rid you of logging boilerplate in application code.
If you prefer to name your standard library loggers explicitly, a positional argument to structlog.get_logger
gets passed to the factory and used as the name.
Processors¶
Processors are a both simple and powerful feature of structlog
.
The following example demonstrates how easy it is to add timestamps, censor passwords, filter out log entries below your log level before they even get rendered, and get your output as JSON for convenient parsing.
It also demonstrates how to use structlog.wrap_logger
that allows you to use structlog
without any global configuration (a rather uncommon pattern, but can be useful):
>>> import datetime, logging, sys
>>> from structlog import wrap_logger
>>> from structlog.processors import JSONRenderer
>>> from structlog.stdlib import filter_by_level
>>> logging.basicConfig(stream=sys.stdout, format="%(message)s")
>>> def add_timestamp(_, __, event_dict):
... event_dict["timestamp"] = datetime.datetime.utcnow()
... return event_dict
>>> def censor_password(_, __, event_dict):
... pw = event_dict.get("password")
... if pw:
... event_dict["password"] = "*CENSORED*"
... return event_dict
>>> log = wrap_logger(
... logging.getLogger(__name__),
... processors=[
... filter_by_level,
... add_timestamp,
... censor_password,
... JSONRenderer(indent=1, sort_keys=True)
... ]
... )
>>> log.info("something.filtered")
>>> log.warning("something.not_filtered", password="secret")
{
"event": "something.not_filtered",
"password": "*CENSORED*",
"timestamp": "datetime.datetime(..., ..., ..., ..., ...)"
}
structlog
comes with many handy processors build right in, so check the API documentation before you write your own.
For example, you probably don’t want to write your own timestamper.
Twisted, and Logging Out Objects¶
If you prefer to log less but with more context in each entry, you can bind everything important to your logger and log it out with each log entry.
import sys
import uuid
import twisted
from twisted.internet import protocol, reactor
import structlog
logger = structlog.getLogger()
class Counter:
i = 0
def inc(self):
self.i += 1
def __repr__(self):
return str(self.i)
class Echo(protocol.Protocol):
def connectionMade(self):
self._counter = Counter()
self._log = logger.new(
connection_id=str(uuid.uuid4()),
peer=self.transport.getPeer().host,
count=self._counter,
)
def dataReceived(self, data):
self._counter.inc()
log = self._log.bind(data=data)
self.transport.write(data)
log.msg("echoed data!")
if __name__ == "__main__":
structlog.configure(
processors=[structlog.twisted.EventAdapter()],
logger_factory=structlog.twisted.LoggerFactory(),
)
twisted.python.log.startLogging(sys.stderr)
reactor.listenTCP(1234, protocol.Factory.forProtocol(Echo))
reactor.run()
gives you something like:
... peer='127.0.0.1' connection_id='1c6c0cb5-...' count=1 data='123\n' event='echoed data!'
... peer='127.0.0.1' connection_id='1c6c0cb5-...' count=2 data='456\n' event='echoed data!'
... peer='127.0.0.1' connection_id='1c6c0cb5-...' count=3 data='foo\n' event='echoed data!'
... peer='10.10.0.1' connection_id='85234511-...' count=1 data='cba\n' event='echoed data!'
... peer='127.0.0.1' connection_id='1c6c0cb5-...' count=4 data='bar\n' event='echoed data!'
Since Twisted’s logging system is a bit peculiar, structlog
ships with an adapter
so it keeps behaving like you’d expect it to behave.
I’d also like to point out the Counter class that doesn’t do anything spectacular but gets bound once per connection to the logger and since its repr is the number itself, it’s logged out correctly for each event. This shows off the strength of keeping a dict of objects for context instead of passing around serialized strings.