PK $;C#RF F + structlog-0.3.2/logging-best-practices.html
The best practice for you depends very much on your context. To give you some pointers nevertheless, here are a few scenarios that may be applicable to you.
Pull requests for further interesting approaches as well as refinements and more complete examples are very welcome.
Logging is not a new concept and in no way special to Python. Logfiles have existed for decades and there’s little reason to reinvent the wheel in our little world.
There are several concepts that are very well-solved in general and especially in heterogeneous environments, using special tooling for Python applications does more harm than good and makes the operations staff build dart board with your pictures.
Therefore let’s rely on proven tools as much as possible and do only the absolutely necessary inside of Python[*]. A very nice approach is to simply log to standard out and let other tools take care of the rest.
One runner that makes this very easy is the venerable runit project which made it a part of its design: server processes don’t detach but log to standard out instead. There it gets processed by other software – potentially by one of its own tools: svlogd. We use it extensively and it has proven itself extremely robust and capable; check out this tutorial if you’d like to try it.
If you’re not quite convinced and want an overview on running daemons, have a look at cue’s daemon showdown that discusses the most common ones.
There are basically two common ways to log to local logfiles: writing yourself into files and syslog.
The simplest approach to logging is to forward your entries to the syslogd. Twisted, uwsgi, and runit support it directly. It will happily add a timestamp and write wherever you tell it in its configuration. You can also log from multiple processes into a single file and use your system’s logrotate for log rotation.
The only downside is that syslog has some quirks that show itself under high load like rate limits (they can be switched off) and lost log entries.
Nowadays you usually don’t want your logfiles in compressed archives distributed over dozens – if not thousands – servers. You want them at a single location; parsed and easy to query.
The widely deployed syslog implementation rsyslog supports remote logging out-of-the-box. Have a look at this post by Revolution Systems on the how.
Since syslog is such a widespread solution, there are also ways to use it with basically any centralized product.
Logstash is a great way to parse, save, and search your logs.
The general modus operandi is that you have log shippers that parse your log files and forward the log entries to your Logstash server and store is in elasticsearch. If your log entries consist – as suggested – of a tai64n timestamp and a JSON dictionary, this is pretty easy and efficient.
If you can’t decide on a log shipper, Lumberjack works really well.
Graylog goes one step further. It not only supports everything those above do (and then some); you can also log directly JSON entries towards it – optionally even through an AMQP server (like RabbitMQ) for better reliability. Additionally, Graylog’s Extended Log Format (GELF) allows for structured data which makes it an obvious choice to use together with structlog.
[*] | This is obviously a privileged UNIX-centric view but even Windows has tools and means for log management although we won’t be able to discuss them here. |
You should call some functions with some arguments.
—David Reid
The behavior of copying itself, adding new values, and returning the result is useful for applications that keep somehow their own context using classes or closures. Twisted is a fine example for that. Another possible approach is passing wrapped loggers around or log only within your view where you gather errors and events using return codes and exceptions. If you are willing to do that, you should stick to it because immutable state is a very good thing[*]. Sooner or later, global state and mutable data lead to unpleasant surprises.
However, in the case of conventional web development, we realize that passing loggers around seems rather cumbersome, intrusive, and generally against the mainstream culture. And since it’s more important that people actually use structlog than to be pure and snobby, structlog contains a dirty but convenient trick: thread local context storage which you may already know from Flask:
Thread local storage makes your logger’s context global but only within the current thread[†]. In the case of web frameworks this usually means that your context becomes global to the current request.
The following explanations may sound a bit confusing at first but the Flask example illustrates how simple and elegant this works in practice.
In order to make your context thread local, structlog ships with a function that can wrap any dict-like class to make it usable for thread local storage: structlog.threadlocal.wrap_dict().
Within one thread, every instance of the returned class will have a common instance of the wrapped dict-like class:
>>> from structlog.threadlocal import wrap_dict
>>> WrappedDictClass = wrap_dict(dict)
>>> d1 = WrappedDictClass({'a': 1})
>>> d2 = WrappedDictClass({'b': 2})
>>> d3 = WrappedDictClass()
>>> d3['c'] = 3
>>> d1 is d3
False
>>> d1 == d2 == d3 == WrappedDictClass()
True
>>> d3
<WrappedDict-...({'a': 1, 'c': 3, 'b': 2})>
Then use an instance of the generated class as the context class:
configure(context_class=WrappedDictClass())
Note
Remember: the instance of the class doesn’t matter. Only the class type matters because all instances of one class share the same data.
structlog.threadlocal.wrap_dict() returns always a completely new wrapped class:
>>> from structlog.threadlocal import wrap_dict
>>> WrappedDictClass = wrap_dict(dict)
>>> AnotherWrappedDictClass = wrap_dict(dict)
>>> WrappedDictClass() != AnotherWrappedDictClass()
True
>>> WrappedDictClass.__name__
WrappedDict-41e8382d-bee5-430e-ad7d-133c844695cc
>>> AnotherWrappedDictClass.__name__
WrappedDict-e0fc330e-e5eb-42ee-bcec-ffd7bd09ad09
In order to be able to bind values temporarily to a logger, structlog.threadlocal comes with a context manager: tmp_bind():
>>> log.bind(x=42)
<BoundLogger(context=<WrappedDict-...({'x': 42})>, ...)>
>>> log.msg('event!')
x=42 event='event!'
>>> with tmp_bind(log, x=23, y='foo') as tmp_log:
... tmp_log.msg('another event!')
y='foo' x=23 event='another event!'
>>> log.msg('one last event!')
x=42 event='one last event!'
The state before the with statement is saved and restored once it’s left.
If you want to detach a logger from thread local data, there’s structlog.threadlocal.as_immutable().
The convenience of having a thread local context comes at a price though:
Warning
If you can’t rule out that your application re-uses threads, you must remember to initialize your thread local context at the start of each request using new() (instead of bind()). Otherwise you may start a new request with the context still filled with data from the request before.
Don’t stop assigning the results of your bind()s and new()s!
Do:
log = log.new(y=23)
log = log.bind(x=42)
Don’t:
log.new(y=23)
log.bind(x=42)
Although the state is saved in a global data structure, you still need the global wrapped logger produce a real bound logger. Otherwise each log call will result in an instantiation of a temporary BoundLogger. See Configuration for more details.
The general sentiment against thread locals is that they’re hard to test. In this case we feel like this is an acceptable trade-off. You can easily write deterministic tests using a call-capturing processor if you use the API properly (cf. warning above).
This big red box is also what separates immutable local from mutable global data.
[*] | In the spirit of Python’s ‘consenting adults’, structlog doesn’t enforce the immutability with technical means. However, if you don’t meddle with undocumented data, the objects can be safely considered immutable. |
[†] | Special care has been taken to detect and support greenlets properly. |
Convenience function that returns a logger according to configuration.
>>> from structlog import get_logger
>>> log = get_logger(y=23)
>>> log.msg('hello', x=42)
y=23 x=42 event='hello'
Parameters: | initial_values – Values that are used to pre-populate your contexts. |
---|---|
Return type: | A proxy that creates a correctly configured bound logger when necessary. |
See Configuration for details.
If you prefer CamelCase, there’s an alias for your reading pleasure: structlog.getLogger().
CamelCase alias for structlog.get_logger().
This function is supposed to be in every source file – we don’t want it to stick out like a sore thumb in frameworks like Twisted or Zope.
Create a new bound logger for an arbitrary logger.
Default values for processors, wrapper_class, and context_class can be set using configure().
If you set an attribute here, configure() calls have no effect for the respective attribute.
In other words: selective overwriting of the defaults while keeping some is possible.
Parameters: | initial_values – Values that are used to pre-populate your contexts. |
---|---|
Return type: | A proxy that creates a correctly configured bound logger when necessary. |
See configure() for the meaning of the rest of the arguments.
Configures the global defaults.
They are used if wrap_logger() has been called without arguments.
Also sets the global class attribute is_configured to True on first call. Can be called several times, keeping an argument at None leaves is unchanged from the current setting.
Use reset_defaults() to undo your changes.
Parameters: |
|
---|
Configures iff structlog isn’t configured yet.
It does not matter whether is was configured using configure() or configure_once() before.
Raises a RuntimeWarning if repeated configuration is attempted.
Resets global default values to builtins.
That means [format_exc_info(), KeyValueRenderer] for processors, BoundLogger for wrapper_class, OrderedDict for context_class, PrintLogger for logger_factory, and False for cache_logger_on_first_use.
Also sets the global class attribute is_configured to True.
A generic BoundLogger that can wrap anything.
Every unknown method will be passed to the wrapped logger. If that’s too much magic for you, try structlog.twisted.BoundLogger or :class:`structlog.twisted.BoundLogger which also take advantage of knowing the wrapped class which generally results in better performance.
Not intended to be instantiated by yourself. See wrap_logger() and get_logger().
Clear context and binds initial_values using bind().
Only necessary with dict implementations that keep global state like those wrapped by structlog.threadlocal.wrap_dict() when threads are re-used.
Return type: | self.__class__ |
---|
Return a new logger with new_values added to the existing ones.
Return type: | self.__class__ |
---|
Return a new logger with keys removed from the context.
Raises KeyError: | |
---|---|
If the key is not part of the context. | |
Return type: | self.__class__ |
Prints events into a file.
Parameters: | file (file) – File to print to. (default: stdout) |
---|
>>> from structlog import PrintLogger
>>> PrintLogger().msg('hello')
hello
Useful if you just capture your stdout with tools like runit or if you forward your stderr to syslog.
Also very useful for testing and examples since logging is sometimes finicky in doctests.
Print message.
Print message.
Print message.
Print message.
Print message.
Print message.
Print message.
Print message.
Returns the string that it’s called with.
>>> from structlog import ReturnLogger
>>> ReturnLogger().msg('hello')
'hello'
>>> ReturnLogger().msg('hello', when='again')
(('hello',), {'when': 'again'})
Useful for unit tests.
Changed in version 0.3.0: Allow for arbitrary arguments and keyword arguments to be passed in.
Return tuple of args, kw or just args[0] if only one arg passed
Return tuple of args, kw or just args[0] if only one arg passed
Return tuple of args, kw or just args[0] if only one arg passed
Return tuple of args, kw or just args[0] if only one arg passed
Return tuple of args, kw or just args[0] if only one arg passed
Return tuple of args, kw or just args[0] if only one arg passed
Return tuple of args, kw or just args[0] if only one arg passed
Return tuple of args, kw or just args[0] if only one arg passed
If raised by an processor, the event gets silently dropped.
Derives from BaseException because it’s technically not an error.
Immutable context carrier.
Doesn’t do any actual logging; examples for useful subclasses are:
- the generic BoundLogger that can wrap anything,
- structlog.twisted.BoundLogger,
- and structlog.stdlib.BoundLogger.
See also Custom Wrappers.
Clear context and binds initial_values using bind().
Only necessary with dict implementations that keep global state like those wrapped by structlog.threadlocal.wrap_dict() when threads are re-used.
Return type: | self.__class__ |
---|
Return a new logger with new_values added to the existing ones.
Return type: | self.__class__ |
---|
Return a new logger with keys removed from the context.
Raises KeyError: | |
---|---|
If the key is not part of the context. | |
Return type: | self.__class__ |
Wrapped logger.
Combines creates an event_dict and runs the chain.
Call it to combine your event and context into an event_dict and process using the processor chain.
Parameters: |
|
---|---|
Raises : | structlog.DropEvent if log entry should be dropped. |
Return type: | tuple of (*args, **kw) |
Run processor chain on event & call method_name on wrapped logger.
DRY convenience method that runs _process_event(), takes care of handling structlog.DropEvent, and finally calls method_name on _logger with the result.
Parameters: |
|
---|
Primitives to keep context global but thread (and greenlet) local.
Wrap a dict-like class and return the resulting class.
The wrapped class and used to keep global in the current thread.
Parameters: | dict_class (type) – Class used for keeping context. |
---|---|
Return type: | type |
Bind tmp_values to logger & memorize current state. Rewind afterwards.
>>> from structlog import wrap_logger, PrintLogger
>>> from structlog.threadlocal import tmp_bind, wrap_dict
>>> logger = wrap_logger(PrintLogger(), context_class=wrap_dict(dict))
>>> with tmp_bind(logger, x=5) as tmp_logger:
... logger = logger.bind(y=3)
... tmp_logger.msg('event')
y=3 x=5 event='event'
>>> logger.msg('event')
event='event'
Extract the context from a thread local logger into an immutable logger.
Parameters: | logger (BoundLogger) – A logger with possibly thread local state. |
---|---|
Return type: | BoundLogger with an immutable context. |
Processors useful regardless of the logging framework.
Render the event_dict using json.dumps(event_dict, **json_kw).
Parameters: | json_kw – Are passed unmodified to json.dumps(). |
---|
>>> from structlog.processors import JSONRenderer
>>> JSONRenderer(sort_keys=True)(None, None, {'a': 42, 'b': [1, 2, 3]})
'{"a": 42, "b": [1, 2, 3]}'
Bound objects are attempted to be serialize using a __structlog__` method. If none is defined, ``repr() is used:
>>> class C1(object):
... def __structlog__(self):
... return ['C1!']
... def __repr__(self):
... return '__structlog__ took precedence'
>>> class C2(object):
... def __repr__(self):
... return 'No __structlog__, so this is used.'
>>> from structlog.processors import JSONRenderer
>>> JSONRenderer(sort_keys=True)(None, None, {'c1': C1(), 'c2': C2()})
'{"c1": ["C1!"], "c2": "No __structlog__, so this is used."}'
Please note that additionally to strings, you can also return any type the standard library JSON module knows about – like in this example a list.
Changed in version 0.2.0: Added support for __structlog__ serialization method.
Render event_dict as a list of Key=repr(Value) pairs.
Parameters: |
|
---|
>>> from structlog.processors import KeyValueRenderer
>>> KeyValueRenderer(sort_keys=True)(None, None, {'a': 42, 'b': [1, 2, 3]})
'a=42 b=[1, 2, 3]'
>>> KeyValueRenderer(key_order=['b', 'a'])(None, None,
... {'a': 42, 'b': [1, 2, 3]})
'b=[1, 2, 3] a=42'
Replace an exc_info field by an exception string field:
If event_dict contains the key exc_info, there are two possible behaviors:
If there is no exc_info key, the event_dict is not touched. This behavior is analogue to the one of the stdlib’s logging.
>>> from structlog.processors import format_exc_info
>>> try:
... raise ValueError
... except ValueError:
... format_exc_info(None, None, {'exc_info': True})
{'exception': 'Traceback (most recent call last):...
Add a timestamp to event_dict.
Parameters: |
|
---|
>>> from structlog.processors import TimeStamper
>>> TimeStamper()(None, None, {})
{'timestamp': 1378994017}
>>> TimeStamper(fmt='iso')(None, None, {})
{'timestamp': '2013-09-12T13:54:26.996778Z'}
>>> TimeStamper(fmt='%Y')(None, None, {})
{'timestamp': '2013'}
Processors and helpers specific to the logging module from the Python standard library.
Python Standard Library version of structlog.BoundLogger. Works exactly like the generic one except that it takes advantage of knowing the logging methods in advance.
Use it like:
configure(
wrapper_class=structlog.stdlib.BoundLogger,
)
Build a standard library logger when an instance is called.
>>> from structlog import configure
>>> from structlog.stdlib import LoggerFactory
>>> configure(logger_factory=LoggerFactory())
Check whether logging is configured to accept messages from this log level.
Should be the first processor if stdlib’s filtering by level is used so possibly expensive processors like exception formatters are avoided in the first place.
>>> import logging
>>> from structlog.stdlib import filter_by_level
>>> logging.basicConfig(level=logging.WARN)
>>> logger = logging.getLogger()
>>> filter_by_level(logger, 'warn', {})
{}
>>> filter_by_level(logger, 'debug', {})
Traceback (most recent call last):
...
DropEvent
Processors and tools specific to the Twisted networking engine.
See also structlog’s Twisted support.
Twisted-specific version of structlog.BoundLogger.
Works exactly like the generic one except that it takes advantage of knowing the logging methods in advance.
Use it like:
configure(
wrapper_class=structlog.twisted.BoundLogger,
)
Return a new logger with new_values added to the existing ones.
Return type: | self.__class__ |
---|
Return a new logger with keys removed from the context.
Raises KeyError: | |
---|---|
If the key is not part of the context. | |
Return type: | self.__class__ |
Clear context and binds initial_values using bind().
Only necessary with dict implementations that keep global state like those wrapped by structlog.threadlocal.wrap_dict() when threads are re-used.
Return type: | self.__class__ |
---|
Build a Twisted logger when an instance is called.
>>> from structlog import configure
>>> from structlog.twisted import LoggerFactory
>>> configure(logger_factory=LoggerFactory())
Adapt an event_dict to Twisted logging system.
Particularly, make a wrapped twisted.python.log.err behave as expected.
Parameters: | dictRenderer (callable) – Renderer that is used for the actual log message. Please note that structlog comes with a dedicated JSONRenderer. |
---|
Must be the last processor in the chain and requires a dictRenderer for the actual formatting as an constructor argument in order to be able to fully support the original behaviors of log.msg() and log.err().
Behaves like structlog.processors.JSONRenderer except that it formats tracebacks and failures itself if called with err().
Not an adapter like EventAdapter but a real formatter. Nor does it require to be adapted using it.
Use together with a JSONLogObserverWrapper-wrapped Twisted logger like plainJSONStdOutLogger() for pure-JSON logs.
Return a logger that writes only the message to stdout.
Transforms non-JSONRenderer messages to JSON.
Ideal for JSONifying log entries from Twisted plugins and libraries that are outside of your control:
$ twistd -n --logger structlog.twisted.plainJSONStdOutLogger web
{"event": "Log opened.", "system": "-"}
{"event": "twistd 13.1.0 (python 2.7.3) starting up.", "system": "-"}
{"event": "reactor class: twisted...EPollReactor.", "system": "-"}
{"event": "Site starting on 8080", "system": "-"}
{"event": "Starting factory <twisted.web.server.Site ...>", ...}
...
Composes PlainFileLogObserver and JSONLogObserverWrapper to a usable logger.
New in version 0.2.0.
Wrap a log observer and render non-JSONRenderer entries to JSON.
Parameters: | observer (ILogObserver) – Twisted log observer to wrap. For example PlainFileObserver or Twisted’s stock FileLogObserver |
---|
New in version 0.2.0.
structlog is licensed under the permissive Apache License, Version 2. The full license text can be also found in the source code repository.
structlog is written and maintained by Hynek Schlawack. It’s inspired by previous work done by Jean-Paul Calderone and David Reid.
The development is kindly supported by Variomedia AG.
The following folks helped forming structlog into what it is now:
Some of them disapprove of the addition of thread local context data. :)
The compatibility code that makes this software run on both Python 2 and 3 is heavily inspired and partly copy and pasted from the MIT-licensed six by Benjamin Peterson. The only reason why it’s not used as a dependency is to avoid any runtime dependency in the first place.
The Sphinx (documentation) theme is an adapted version of the Write The Docs theme which in turn is an adapted version of the requests docs theme by Kenneth Reitz which in turn is an adapted version of the Flask docs theme by Armin Ronacher.
structlog comes with a generic bound logger called structlog.BoundLogger that can be used to wrap any logger class you fancy. It does so by intercepting unknown method names and proxying them to the wrapped logger.
This works fine, except that it has a performance penalty and the API of BoundLogger isn’t clear from reading the documentation because large parts depend on the wrapped logger. An additional reason is that you may want to have semantically meaningful log method names that add meta data to log entries as it is fit (see example below).
To solve that, structlog offers you to use an own wrapper class which you can configure using structlog.configure(). And to make it easier for you, it comes with the class structlog.BoundLoggerBase which takes care of all data binding duties so you just add your log methods if you choose to sub-class it.
It’s much easier to demonstrate with an example:
>>> from structlog import BoundLoggerBase, PrintLogger, wrap_logger
>>> class SemanticLogger(BoundLoggerBase):
... def msg(self, event, **kw):
... if not 'status' in kw:
... return self._proxy_to_logger('msg', event, status='ok', **kw)
... else:
... return self._proxy_to_logger('msg', event, **kw)
...
... def user_error(self, event, **kw):
... self.msg(event, status='user_error', **kw)
>>> log = wrap_logger(PrintLogger(), wrapper_class=SemanticLogger)
>>> log = log.bind(user='fprefect')
>>> log.user_error('user.forgot_towel')
user='fprefect' status='user_error' event='user.forgot_towel'
You can observe the following:
These two methods and one attribute is all you need to write own wrapper classes.
This chapter is intended to give you a taste of realistic usage of structlog.
In the simplest case, you bind a unique request ID to every incoming request so you can easily see which log entries belong to which request.
import uuid
import flask
import structlog
from .some_module import some_function
logger = structlog.get_logger()
app = flask.Flask(__name__)
@app.route('/login', methods=['POST', 'GET'])
def some_route():
log = logger.new(
request_id=str(uuid.uuid4()),
)
# do something
# ...
log.info('user logged in', user='test-user')
# gives you:
# event='user logged in' request_id='ffcdc44f-b952-4b5f-95e6-0f1f3a9ee5fd' user='test-user'
# ...
some_function()
# ...
if __name__ == "__main__":
structlog.configure(
processors=[
structlog.processors.KeyValueRenderer(
key_order=['event', 'request_id'],
),
],
context_class=structlog.threadlocal.wrap_dict(dict),
logger_factory=structlog.stdlib.LoggerFactory(),
)
app.run()
some_module.py
from structlog import get_logger
logger = get_logger()
def some_function():
# later then:
logger.error('user did something', something='shot_in_foot')
# gives you:
# event='user did something 'request_id='ffcdc44f-b952-4b5f-95e6-0f1f3a9ee5fd' something='shot_in_foot'
While wrapped loggers are immutable by default, this example demonstrates how to circumvent that using a thread local dict implementation for context data for convenience (hence the requirement for using new() for re-initializing the logger).
Please note that 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 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 structlog
import twisted
from twisted.internet import protocol, reactor
logger = structlog.getLogger()
class Counter(object):
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.
Processors are a both simple and powerful feature of structlog.
So you want timestamps as part of the structure of the log entry, censor passwords, filter out log entries below your log level before they even get rendered, and get your output as JSON for convenient parsing? Here you go:
>>> 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 – for a list of shipped processors, check out the API documentation.
s | ||
structlog | ||
structlog.processors | ||
structlog.stdlib | ||
structlog.threadlocal | ||
structlog.twisted |
Please activate JavaScript to enable the search functionality.
From here you can search these documents. Enter your search words into the box below and click "search". Note that the search function will automatically search for all of the words. Pages containing fewer words won't appear in the result list.
Warning
Currently, the Twisted-specific code is not tested against Python 3.3. This is caused by this Twisted bug and will remedied once that bug is fixed.
To make structlog’s behavior less magicy, it ships with a Twisted-specific wrapper class that has an explicit API instead of improvising: structlog.twisted.BoundLogger. It behaves exactly like the generic structlog.BoundLogger except:
In order to structlog not disturbing your CamelCase harmony, it comes with an alias for structlog.get_logger() calls structlog.getLogger().
structlog comes with two Twisted-specific processors:
This is useful if you have an existing Twisted application and just want to wrap your loggers for now. It takes care of transforming your event dictionary into something twisted.python.log.err can digest.
For example:
def onError(fail):
failure = fail.trap(MoonExploded)
log.err(failure, _why='event-that-happend')
will still work as expected.
Needs to be put at the end of the processing chain. It formats the event using a renderer that needs to be passed into the constructor:
configure(processors=[EventAdapter(KeyValueRenderer()])
The drawback of this approach is that Twisted will format your exceptions as multi-line log entries which is painful to parse. Therefore structlog comes with:
structlog comes with a wrapper for Twisted’s log observers to ensure the rest of your logs are in JSON too: JSONLogObserverWrapper().
What it does is determining whether a log entry has been formatted by JSONRenderer and if not, converts the log entry to JSON with event being the log message and putting Twisted’s system into a second key.
So for example:
2013-09-15 22:02:18+0200 [-] Log opened.
becomes:
2013-09-15 22:02:18+0200 [-] {"event": "Log opened.", "system": "-"}
There is obviously some redundancy here. Also, I’m presuming that if you write out JSON logs, you’re going to let something else parse them which makes the human-readable date entries more trouble than they’re worth.
To get a clean log without timestamps and additional system fields ([-]), structlog comes with PlainFileLogObserver that writes only the plain message to a file and plainJSONStdOutLogger() that composes it with the aforementioned JSONLogObserverWrapper() and gives you a pure JSON log without any timestamps or other noise straight to standard out:
$ twistd -n --logger structlog.twisted.plainJSONStdOutLogger web
{"event": "Log opened.", "system": "-"}
{"event": "twistd 13.1.0 (python 2.7.3) starting up.", "system": "-"}
{"event": "reactor class: twisted...EPollReactor.", "system": "-"}
{"event": "Site starting on 8080", "system": "-"}
{"event": "Starting factory <twisted.web.server.Site ...>", ...}
...
import structlog
structlog.configure(
processors=[structlog.twisted.JSONRenderer()],
context_class=dict,
logger_factory=structlog.twisted.LoggerFactory(),
wrapper_class=structlog.twisted.BoundLogger,
cache_logger_on_first_use=True,
)
See also Logging Best Practices.
To make logging as unintrusive and straight-forward to use as possible, structlog comes with a plethora of configuration options and convenience functions. Let me start at the end and introduce you to the ultimate convenience function that relies purely on configuration: structlog.get_logger() (and its Twisted-friendly alias structlog.getLogger()).
The goal is to reduce your per-file logging boilerplate to:
from structlog.stdlib import get_logger
logger = get_logger()
while still giving you the full power via configuration.
To achieve that you’ll have to call structlog.configure() on app initialization (of course, only if you’re not content with the defaults). The previous example could thus have been written as following:
>>> configure(processors=[proc], context_class=dict)
>>> log = wrap_logger(PrintLogger())
>>> log.msg('hello world')
I got called with {'event': 'hello world'}
{'event': 'hello world'}
In fact, it could even be written like
>>> configure(processors=[proc], context_class=dict)
>>> log = get_logger()
>>> log.msg('hello world')
I got called with {'event': 'hello world'}
{'event': 'hello world'}
because PrintLogger is the default LoggerFactory used (see Logger Factories).
structlog tries to behave in the least surprising way when it comes to handling defaults and configuration:
If necessary, you can always reset your global configuration back to default values using structlog.reset_defaults(). That can be handy in tests.
Note
Since you will call structlog.wrap_logger() (or one of the get_logger() functions) most likely at import time and thus before you had a chance to configure structlog, they return a proxy that returns a correct wrapped logger on first bind()/new().
Therefore, you must not call new() or bind() in module scope! Use get_logger()‘s initial_values to achieve pre-populated contexts.
To enable you to log with the module-global logger, it will create a temporary BoundLogger and relay the log calls to it on each call. Therefore if you have nothing to bind but intend to do lots of log calls in a function, it makes sense performance-wise to create a local logger by calling bind() or new() without any parameters. See also Performance.
To make structlog.get_logger() work, one needs one more option that hasn’t been discussed yet: logger_factory.
It is a callable that returns the logger that gets wrapped and returned. In the simplest case, it’s a function that returns a logger – or just a class. But you can also pass in an instance of a class with a __call__ method for more complicated setups.
For the common cases of standard library logging and Twisted logging, structlog comes with two factories built right in:
So all it takes to use structlog with standard library logging is this:
>>> from structlog import get_logger, configure
>>> from structlog.stdlib import LoggerFactory
>>> configure(logger_factory=LoggerFactory())
>>> log = get_logger()
>>> log.critical('this is too easy!')
event='this is too easy!'
The Twisted example shows how easy it is for Twisted.
Note
LoggerFactory()-style factories always need to get passed as instances like in the examples above. While neither allows for customization using parameters yet, they may do so in the future.
Calling structlog.get_logger() without configuration gives you a perfectly useful structlog.PrintLogger with the default values exaplained above. I don’t believe silent loggers are a sensible default.
The best place to perform your configuration varies with applications and frameworks. Ideally as late as possible but before non-framework (i.e. your) code is executed. If you use standard library’s logging, it makes sense to configure them next to each other.
If you have no choice but have to configure on import time in module-global scope, or can’t rule out for other reasons that that your structlog.configure() gets called more than once, structlog offers structlog.configure_once() that raises a warning if structlog has been configured before (no matter whether using structlog.configure() or configure_once()) but doesn’t change anything.
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:
structlog comes with one standard library-specific processor:
import structlog
structlog.configure(
processors=[structlog.stdlib.filter_by_level,
structlog.processors.format_exc_info,
structlog.processors.JSONRenderer()],
context_class=dict,
logger_factory=structlog.stdlib.LoggerFactory(),
wrapper_class=structlog.stdlib.BoundLogger,
cache_logger_on_first_use=True,
)
See also Logging Best Practices.
structlog can be easily installed using:
$ pip install structlog
If you’re running Python 2.6 and want to use OrderedDicts for your context (which is the default), you also have to install the respective compatibility package:
$ pip install ordereddict
If the order of the keys of your context doesn’t matter (e.g. if you’re logging JSON that gets parsed anyway), simply use a vanilla dict to avoid this dependency. See Configuration on how to achieve that.
A lot of effort went into making structlog accessible without reading pages of documentation. And indeed, the simplest possible usage looks like this:
>>> import structlog
>>> log = structlog.get_logger()
>>> log.msg('greeted', whom='world', more_than_a_string=[1, 2, 3])
whom='world' more_than_a_string=[1, 2, 3] event='greeted'
Here, structlog takes full advantage of its hopefully useful default settings:
It should be noted that even in most complex logging setups the example would still look just like that thanks to Configuration.
There you go, structured logging! However, this alone wouldn’t warrant its own package. After all, there’s even a recipe on structured logging for the standard library. So let’s go a step further.
Imagine a hypothetical web application that wants to log out all relevant data with just the API from above:
from structlog import get_logger
log = get_logger()
def view(request):
user_agent = request.get('HTTP_USER_AGENT', 'UNKNOWN')
peer_ip = request.client_addr
if something:
log.msg('something', user_agent=user_agent, peer_ip=peer_ip)
return 'something'
elif something_else:
log.msg('something_else', user_agent=user_agent, peer_ip=peer_ip)
return 'something_else'
else:
log.msg('else', user_agent=user_agent, peer_ip=peer_ip)
return 'else'
The calls themselves are nice and straight to the point, however you’re repeating yourself all over the place. At this point, you’ll be tempted to write a closure like
def log_closure(event):
log.msg(event, user_agent=user_agent, peer_ip=peer_ip)
inside of the view. Problem solved? Not quite. What if the parameters are introduced step by step? Do you really want to have a logging closure in each of your views?
Let’s have a look at a better approach:
from structlog import get_logger
logger = get_logger()
def view(request):
log = logger.bind(
user_agent=request.get('HTTP_USER_AGENT', 'UNKNOWN'),
peer_ip=request.client_addr,
)
foo = request.get('foo')
if foo:
log = log.bind(foo=foo)
if something:
log.msg('something')
return 'something'
elif something_else:
log.msg('something_else')
return 'something_else'
else:
log.msg('else')
return 'else'
Suddenly your logger becomes your closure!
For structlog, a log entry is just a dictionary called event dict[ionary]:
structlog’s primary application isn’t printing though. Instead, it’s intended to wrap your existing loggers and add structure and incremental context building to them. For that, structlog is completely agnostic of your underlying logger – you can use it with any logger you like.
The most prominent example of such an ‘existing logger’ is without doubt the logging module in the standard library. To make this common case as simple as possible, structlog comes with some tools to help you:
>>> import logging
>>> logging.basicConfig()
>>> from structlog import get_logger, configure
>>> from structlog.stdlib import LoggerFactory
>>> configure(logger_factory=LoggerFactory())
>>> log = get_logger()
>>> log.warn('it works!', difficulty='easy')
WARNING:structlog...:difficulty='easy' event='it works!'
In other words, you tell structlog that you would like to use the standard library logger factory and keep calling get_logger() like before.
Since structlog is mainly used together with standard library’s logging, there’s more goodness to make it as fast and convenient as possible.
Now you’re all set for the rest of the user’s guide. If you want to see more code, make sure to check out the Examples!
[*] | In production, you’re more likely to use JSONRenderer that can also be customized using a __structlog__ method so you don’t have to change your repr methods to something they weren’t originally intended for. |
Every open source project lives from the generous help by contributors that sacrifice their time and structlog is no different.
To make participation as pleasant as possible, this project adheres to the Code of Conduct by the Python Software Foundation.
Here are a few hints and rules to get you started:
Note
If you have something great but aren’t sure whether it adheres – or even can adhere – to the rules above: please submit a pull request anyway!
In the best case, we can mold it into something, in the worst case the pull request gets politely closed. There’s absolutely nothing to fear.
Thank you for considering to contribute to structlog! If you have any question or concerns, feel free to reach out to me – there is also a #structlog channel on freenode.
structlog makes structured logging in Python easy by augmenting your existing logger. It allows you to split your log entries up into key/value pairs and build them incrementally without annoying boilerplate code.
It’s licensed under Apache License, version 2, available from PyPI, the source code can be found on GitHub, the documentation at http://www.structlog.org/.
structlog targets Python 2.6, 2.7, 3.2, and 3.3 as well as PyPy with no additional dependencies for core functionality.
If you need any help, visit us on #structlog on Freenode!
The true power of structlog lies in its combinable log processors. A log processor is a regular callable, i.e. a function or an instance of a class with a __call__() method.
The processor chain is a list of processors. Each processors receives three positional arguments:
The return value of each processor is passed on to the next one as event_dict until finally the return value of the last processor gets passed into the wrapped logging method.
If you set up your logger like:
from structlog import BoundLogger, PrintLogger
wrapped_logger = PrintLogger()
logger = BoundLogger.wrap(wrapped_logger, processors=[f1, f2, f3, f4])
log = logger.new(x=42)
and call log.msg('some_event', y=23), it results in the following call chain:
wrapped_logger.msg(
f4(wrapped_logger, 'msg',
f3(wrapped_logger, 'msg',
f2(wrapped_logger, 'msg',
f1(wrapped_logger, 'msg', {'event': 'some_event', 'x': 42, 'y': 23})
)
)
)
)
In this case, f4 has to make sure it returns something wrapped_logger.msg can handle (see Adapting and Rendering).
The simplest modification a processor can make is adding new values to the event_dict. Parsing human-readable timestamps is tedious, not so UNIX timestamps – let’s add one to each log entry!
import calendar
import time
def timestamper(logger, log_method, event_dict):
event_dict['timestamp'] = calendar.timegm(time.gmtime())
return event_dict
Easy, isn’t it? Please note, that structlog comes with such an processor built in: TimeStamper.
If a processor raises structlog.DropEvent, the event is silently dropped.
Therefore, the following processor drops every entry:
from structlog import DropEvent
def dropper(logger, method_name, event_dict):
raise DropEvent
But we can do better than that!
How about dropping only log entries that are marked as coming from a certain peer (e.g. monitoring)?
from structlog import DropEvent
class ConditionalDropper(object):
def __init__(self, peer_to_ignore):
self._peer_to_ignore = peer_to_ignore
def __call__(self, logger, method_name, event_dict):
"""
>>> cd = ConditionalDropper('127.0.0.1')
>>> cd(None, None, {'event': 'foo', 'peer': '10.0.0.1'})
{'peer': '10.0.0.1', 'event': 'foo'}
>>> cd(None, None, {'event': 'foo', 'peer': '127.0.0.1'})
Traceback (most recent call last):
...
DropEvent
"""
if event_dict.get('peer') == self._peer_to_ignore:
raise DropEvent
else:
return event_dict
An important role is played by the last processor because its duty is to adapt the event_dict into something the underlying logging method understands. With that, it’s also the only processor that needs to know anything about the underlying system.
For that, it can either return a string that is passed as the first (and only) positional argument to the underlying logger or a tuple of (args, kwargs) that are passed as log_method(*args, **kwargs). Therefore return 'hello world' is a shortcut for return (('hello world',), {}) (the example in Chains assumes this shortcut has been taken).
This should give you enough power to use structlog with any logging system while writing agnostic processors that operate on dictionaries.
The probably most useful formatter for string based loggers is JSONRenderer. Advanced log aggregation and analysis tools like logstash offer features like telling them “this is JSON, deal with it” instead of fiddling with regular expressions.
More examples can be found in the examples chapter. For a list of shipped processors, check out the API documentation.
structlog’s default configuration tries to be as unsurprising and not confusing to new developers as possible. Some of the choices made come with an avoidable performance price tag – although its impact is debatable.
Here are a few hints how to get most out of structlog in production:
Use plain dicts as context classes. Python is full of them and they are highly optimized:
configure(context_class=dict)
If you don’t use automated parsing (you should!) and need predicable order of your keys for some reason, use the key_order argument of KeyValueRenderer.
Use a specific wrapper class instead of the generic one. structlog comes with ones for the Python Standard Library and for Twisted:
configure(wrapper_class=structlog.stdlib.BoundLogger)
Writing own wrapper classes is straightforward too.
Avoid (frequently) calling log methods on loggers you get back from structlog.wrap_logger() and structlog.get_logger(). Since those functions are usually called in module scope and thus before you are able to configure them, they return a proxy that assembles the correct logger on demand.
Create a local logger if you expect to log frequently without binding:
logger = structlog.get_logger()
def f():
log = logger.bind()
for i in range(1000000000):
log.info('iterated', i=i)
Set the cache_logger_on_first_use option to True so the aforementioned on-demand loggers will be assembled only once and cached for future uses:
configure(cache_logger_on_first_use=True)
This has the only drawback is that later calls on configure() don’t have any effect on already cached loggers – that shouldn’t matter outside of testing though.
The center of structlog is the immutable log wrapper BoundLogger.
All it does is:
You won’t be instantiating it yourself though. For that there is the structlog.wrap_logger() function (or the convenience function structlog.get_logger() we’ll discuss in a minute):
>>> from structlog import wrap_logger
>>> class PrintLogger(object):
... def msg(self, message):
... print message
>>> def proc(logger, method_name, event_dict):
... print 'I got called with', event_dict
... return repr(event_dict)
>>> log = wrap_logger(PrintLogger(), processors=[proc], context_class=dict)
>>> log2 = log.bind(x=42)
>>> log == log2
False
>>> log.msg('hello world')
I got called with {'event': 'hello world'}
{'event': 'hello world'}
>>> log2.msg('hello world')
I got called with {'x': 42, 'event': 'hello world'}
{'x': 42, 'event': 'hello world'}
>>> log3 = log2.unbind('x')
>>> log == log3
True
>>> log3.msg('nothing bound anymore', foo='but you can structure the event too')
I got called with {'foo': 'but you can structure the event too', 'event': 'nothing bound anymore'}
{'foo': 'but you can structure the event too', 'event': 'nothing bound anymore'}
As you can see, it accepts one mandatory and a few optional arguments:
A list of callables that can filter, mutate, and format the log entry before it gets passed to the wrapped logger.
Default is [format_exc_info(), KeyValueRenderer].
The class to save your context in. Particularly useful for thread local context storage.
Default is OrderedDict.
Additionally, the following arguments are allowed too:
Note
Free your mind from the preconception that log entries have to be serialized to strings eventually. All structlog cares about is a dictionary of keys and values. What happens to it depends on the logger you wrap and your processors alone.
This gives you the power to log directly to databases, log aggregation servers, web services, and whatnot.
To save you the hassle of using standard library logging for simple standard out logging, structlog ships a PrintLogger that can log into arbitrary files – including standard out (which is the default if no file is passed into the constructor):
>>> from structlog import PrintLogger
>>> PrintLogger().info('hello world!')
hello world!
It’s handy for both examples and in combination with tools like runit or stdout/stderr-forwarding.
Additionally – mostly for unit testing – structlog also ships with a logger that just returns whatever it gets passed into it: ReturnLogger.
>>> from structlog import ReturnLogger
>>> ReturnLogger().msg(42) == 42
True
>>> obj = ['hi']
>>> ReturnLogger().msg(obj) is obj
True
>>> ReturnLogger().msg('hello', when='again')
(('hello',), {'when': 'again'})
[*] | Since this is slightly magicy, structlog comes with concrete loggers for the Python Standard Library and Twisted that offer you explicit APIs for the supported logging methods but behave identically like the generic BoundLogger otherwise. |
Release v0.3.2 (What’s new?).
structlog makes structured logging in Python easy by augmenting your existing logger. It allows you to split your log entries up into key/value pairs and build them incrementally without annoying boilerplate code.
It’s licensed under Apache License, version 2, available from PyPI, the source code can be found on GitHub, the documentation at http://www.structlog.org/.
structlog targets Python 2.6, 2.7, 3.2, and 3.3 as well as PyPy with no additional dependencies for core functionality.
If you need any help, visit us on #structlog on Freenode!
I believe the widespread use of format strings in logging is based on two presumptions:
- The first level consumer of a log message is a human.
- The programmer knows what information is needed to debug an issue.
I believe these presumptions are no longer correct in server side software.
Structured logging means that you don’t write hard-to-parse and hard-to-keep-consistent prose in your logs but that you log events that happen in a context instead.
Because it’s easy and you don’t have to replace your underlying logger – you just add structure to your log entries and format them to strings before they hit your real loggers.
structlog supports you with building your context as you go (e.g. if a user logs in, you bind their user name to your current logger) and log events when they happen (i.e. the user does something log-worthy):
>>> from structlog import get_logger
>>> log = get_logger()
>>> log = log.bind(user='anonymous', some_key=23)
>>> log = log.bind(user='hynek', another_key=42)
>>> log.info('user.logged_in', happy=True)
some_key=23 user='hynek' another_key=42 happy=True event='user.logged_in'
This ability to bind key/values pairs to a logger frees you from using conditionals, closures, or boilerplate methods to log out all relevant data.
Additionally, structlog offers you a flexible way to filter and modify your log entries using so called processors before the entry is passed to your real logger. The possibilities include logging in JSON, adding arbitrary meta data like timestamps, counting events as metrics, or dropping log entries caused by your monitoring system. structlog is also flexible enough to allow transparent thread local storage for your context if you don’t like the idea of local bindings as in the example above.
Since structlog avoids monkey-patching and events are fully free-form, you can start using it today!
Intrigued? Get started now or have a look at more realistic examples and be completely convinced!
structlog can be used immediately with any existing logger. However it comes with special wrappers for the Python standard library and Twisted that are optimized for their respective underlying loggers and contain less magic.
# Copyright 2013 Hynek Schlawack
#
# Licensed under the Apache License, Version 2.0 (the "License");
# you may not use this file except in compliance with the License.
# You may obtain a copy of the License at
#
# http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.
"""
Painless structured logging.
"""
from __future__ import absolute_import, division, print_function
__version__ = '0.3.2'
from structlog import (
processors,
stdlib,
threadlocal,
)
from structlog._base import (
BoundLoggerBase,
)
from structlog._config import (
configure,
configure_once,
getLogger,
get_logger,
reset_defaults,
wrap_logger,
)
from structlog._exc import (
DropEvent,
)
from structlog._generic import (
BoundLogger
)
from structlog._loggers import (
PrintLogger,
ReturnLogger,
)
try:
from structlog import twisted
except ImportError: # pragma: nocover
twisted = None
__all__ = [
BoundLogger,
BoundLoggerBase,
DropEvent,
PrintLogger,
ReturnLogger,
configure,
configure_once,
getLogger,
get_logger,
processors,
reset_defaults,
stdlib,
threadlocal,
twisted,
wrap_logger,
]
# Copyright 2013 Hynek Schlawack
#
# Licensed under the Apache License, Version 2.0 (the "License");
# you may not use this file except in compliance with the License.
# You may obtain a copy of the License at
#
# http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.
"""
Processors and tools specific to the `Twisted <http://twistedmatrix.com/>`_
networking engine.
See also :doc:`structlog's Twisted support <twisted>`.
"""
from __future__ import absolute_import, division, print_function
import json
import sys
from twisted.python.failure import Failure
from twisted.python import log
from twisted.python.log import ILogObserver, textFromEventDict
from zope.interface import implementer
from structlog._base import BoundLoggerBase
from structlog._compat import PY2, string_types
from structlog._utils import until_not_interrupted
from structlog.processors import (
KeyValueRenderer,
# can't import processors module without risking circular imports
JSONRenderer as GenericJSONRenderer
)
[docs]class BoundLogger(BoundLoggerBase):
"""
Twisted-specific version of :class:`structlog.BoundLogger`.
Works exactly like the generic one except that it takes advantage of
knowing the logging methods in advance.
Use it like::
configure(
wrapper_class=structlog.twisted.BoundLogger,
)
"""
[docs] def msg(self, event=None, **kw):
"""
Process event and call ``log.msg()`` with the result.
"""
return self._proxy_to_logger('msg', event, **kw)
[docs] def err(self, event=None, **kw):
"""
Process event and call ``log.err()`` with the result.
"""
return self._proxy_to_logger('err', event, **kw)
[docs]class LoggerFactory(object):
"""
Build a Twisted logger when an *instance* is called.
>>> from structlog import configure
>>> from structlog.twisted import LoggerFactory
>>> configure(logger_factory=LoggerFactory())
"""
def __call__(self, name=None):
"""
:rvalue: A new Twisted logger.
"""
return log
_FAIL_TYPES = (BaseException, Failure)
def _extractStuffAndWhy(eventDict):
"""
Removes all possible *_why*s and *_stuff*s, analyzes exc_info and returns
a tuple of `(_stuff, _why, eventDict)`.
**Modifies** *eventDict*!
"""
_stuff = eventDict.pop('_stuff', None)
_why = eventDict.pop('_why', None)
event = eventDict.pop('event', None)
if (
isinstance(_stuff, _FAIL_TYPES) and
isinstance(event, _FAIL_TYPES)
):
raise ValueError('Both _stuff and event contain an Exception/Failure.')
# `log.err('event', _why='alsoEvent')` is ambiguous.
if _why and isinstance(event, string_types):
raise ValueError('Both `_why` and `event` supplied.')
# Two failures are ambiguous too.
if not isinstance(_stuff, _FAIL_TYPES) and isinstance(event, _FAIL_TYPES):
_why = _why or 'error'
_stuff = event
if isinstance(event, string_types):
_why = event
if not _stuff and sys.exc_info() != (None, None, None):
_stuff = Failure()
# Either we used the error ourselves or the user supplied one for
# formatting. Avoid log.err() to dump another traceback into the log.
if isinstance(_stuff, BaseException):
_stuff = Failure(_stuff)
if PY2:
sys.exc_clear()
return _stuff, _why, eventDict
[docs]class JSONRenderer(GenericJSONRenderer):
"""
Behaves like :class:`structlog.processors.JSONRenderer` except that it
formats tracebacks and failures itself if called with `err()`.
*Not* an adapter like :class:`EventAdapter` but a real formatter. Nor does
it require to be adapted using it.
Use together with a :class:`JSONLogObserverWrapper`-wrapped Twisted logger
like :func:`plainJSONStdOutLogger` for pure-JSON logs.
"""
def __call__(self, logger, name, eventDict):
_stuff, _why, eventDict = _extractStuffAndWhy(eventDict)
if name == 'err':
eventDict['event'] = _why
if isinstance(_stuff, Failure):
eventDict['exception'] = _stuff.getTraceback(detail='verbose')
_stuff.cleanFailure()
else:
eventDict['event'] = _why
return ((GenericJSONRenderer.__call__(self, logger, name, eventDict),),
{'_structlog': True})
@implementer(ILogObserver)
[docs]class PlainFileLogObserver(object):
"""
Write only the the plain message without timestamps or anything else.
Great to just print JSON to stdout where you catch it with something like
runit.
:param file file: File to print to.
.. versionadded:: 0.2.0
"""
def __init__(self, file):
self._write = file.write
self._flush = file.flush
def __call__(self, eventDict):
until_not_interrupted(self._write, textFromEventDict(eventDict) + '\n')
until_not_interrupted(self._flush)
@implementer(ILogObserver)
[docs]class JSONLogObserverWrapper(object):
"""
Wrap a log *observer* and render non-:class:`JSONRenderer` entries to JSON.
:param ILogObserver observer: Twisted log observer to wrap. For example
:class:`PlainFileObserver` or Twisted's stock `FileLogObserver
<http://twistedmatrix.com/documents/current/api/twisted.python.log.
FileLogObserver.html>`_
.. versionadded:: 0.2.0
"""
def __init__(self, observer):
self._observer = observer
def __call__(self, eventDict):
if '_structlog' not in eventDict:
eventDict['message'] = (json.dumps({
'event': textFromEventDict(eventDict),
'system': eventDict.get('system'),
}),)
eventDict['_structlog'] = True
return self._observer(eventDict)
[docs]def plainJSONStdOutLogger():
"""
Return a logger that writes only the message to stdout.
Transforms non-:class:`~structlog.twisted.JSONRenderer` messages to JSON.
Ideal for JSONifying log entries from Twisted plugins and libraries that
are outside of your control::
$ twistd -n --logger structlog.twisted.plainJSONStdOutLogger web
{"event": "Log opened.", "system": "-"}
{"event": "twistd 13.1.0 (python 2.7.3) starting up.", "system": "-"}
{"event": "reactor class: twisted...EPollReactor.", "system": "-"}
{"event": "Site starting on 8080", "system": "-"}
{"event": "Starting factory <twisted.web.server.Site ...>", ...}
...
Composes :class:`PlainFileLogObserver` and :class:`JSONLogObserverWrapper`
to a usable logger.
.. versionadded:: 0.2.0
"""
return JSONLogObserverWrapper(PlainFileLogObserver(sys.stdout))
[docs]class EventAdapter(object):
"""
Adapt an ``event_dict`` to Twisted logging system.
Particularly, make a wrapped `twisted.python.log.err
<http://twistedmatrix.com/documents/current/
api/twisted.python.log.html#err>`_ behave as expected.
:param callable dictRenderer: Renderer that is used for the actual
log message. Please note that structlog comes with a dedicated
:class:`JSONRenderer`.
**Must** be the last processor in the chain and requires a `dictRenderer`
for the actual formatting as an constructor argument in order to be able to
fully support the original behaviors of ``log.msg()`` and ``log.err()``.
"""
def __init__(self, dictRenderer=None):
"""
:param dictRenderer: A processor used to format the log message.
"""
self._dictRenderer = dictRenderer or KeyValueRenderer()
def __call__(self, logger, name, eventDict):
if name == 'err':
# This aspires to handle the following cases correctly:
# - log.err(failure, _why='event', **kw)
# - log.err('event', **kw)
# - log.err(_stuff=failure, _why='event', **kw)
_stuff, _why, eventDict = _extractStuffAndWhy(eventDict)
eventDict['event'] = _why
return ((), {
'_stuff': _stuff,
'_why': self._dictRenderer(logger, name, eventDict),
})
else:
return self._dictRenderer(logger, name, eventDict)
# Copyright 2013 Hynek Schlawack
#
# Licensed under the Apache License, Version 2.0 (the "License");
# you may not use this file except in compliance with the License.
# You may obtain a copy of the License at
#
# http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.
"""
Processors useful regardless of the logging framework.
"""
from __future__ import absolute_import, division, print_function
import calendar
import datetime
import json
import operator
import sys
import time
import traceback
from structlog._compat import StringIO, unicode_type
[docs]class KeyValueRenderer(object):
"""
Render `event_dict` as a list of ``Key=repr(Value)`` pairs.
:param bool sort_keys: Whether to sort keys when formatting.
:param list key_order: List of keys that should be rendered in this exact
order. Missing keys will be rendered as `None`, extra keys depending
on *sort_keys* and the dict class.
.. versionadded:: 0.2.0
>>> from structlog.processors import KeyValueRenderer
>>> KeyValueRenderer(sort_keys=True)(None, None, {'a': 42, 'b': [1, 2, 3]})
'a=42 b=[1, 2, 3]'
>>> KeyValueRenderer(key_order=['b', 'a'])(None, None,
... {'a': 42, 'b': [1, 2, 3]})
'b=[1, 2, 3] a=42'
"""
def __init__(self, sort_keys=False, key_order=None):
# Use an optimized version for each case.
if key_order and sort_keys:
def ordered_items(event_dict):
items = []
for key in key_order:
value = event_dict.pop(key, None)
items.append((key, value))
items += sorted(event_dict.items())
return items
elif key_order:
def ordered_items(event_dict):
items = []
for key in key_order:
value = event_dict.pop(key, None)
items.append((key, value))
items += event_dict.items()
return items
elif sort_keys:
def ordered_items(event_dict):
return sorted(event_dict.items())
else:
ordered_items = operator.methodcaller('items')
self._ordered_items = ordered_items
def __call__(self, _, __, event_dict):
return ' '.join(k + '=' + repr(v)
for k, v in self._ordered_items(event_dict))
class UnicodeEncoder(object):
"""
Encode unicode values in `event_dict`.
:param str encoding: Encoding to encode to (default: ``'utf-8'``.
:param str errors: How to cope with encoding errors (default
``'backslashreplace'``).
Useful for :class:`KeyValueRenderer` if you don't want to see u-prefixes:
>>> from structlog.processors import KeyValueRenderer, UnicodeEncoder
>>> KeyValueRenderer()(None, None, {'foo': u'bar'})
"foo=u'bar'"
>>> KeyValueRenderer()(None, None,
... UnicodeEncoder()(None, None, {'foo': u'bar'}))
"foo='bar'"
Just put it in the processor chain before `KeyValueRenderer`.
"""
def __init__(self, encoding='utf-8', errors='backslashreplace'):
self._encoding = encoding
self._errors = errors
def __call__(self, logger, name, event_dict):
for key, value in event_dict.items():
if isinstance(value, unicode_type):
event_dict[key] = value.encode(self._encoding, self._errors)
return event_dict
[docs]class JSONRenderer(object):
"""
Render the `event_dict` using `json.dumps(event_dict, **json_kw)`.
:param json_kw: Are passed unmodified to `json.dumps()`.
>>> from structlog.processors import JSONRenderer
>>> JSONRenderer(sort_keys=True)(None, None, {'a': 42, 'b': [1, 2, 3]})
'{"a": 42, "b": [1, 2, 3]}'
Bound objects are attempted to be serialize using a ``__structlog__`
method. If none is defined, ``repr()`` is used:
>>> class C1(object):
... def __structlog__(self):
... return ['C1!']
... def __repr__(self):
... return '__structlog__ took precedence'
>>> class C2(object):
... def __repr__(self):
... return 'No __structlog__, so this is used.'
>>> from structlog.processors import JSONRenderer
>>> JSONRenderer(sort_keys=True)(None, None, {'c1': C1(), 'c2': C2()})
'{"c1": ["C1!"], "c2": "No __structlog__, so this is used."}'
Please note that additionally to strings, you can also return any type
the standard library JSON module knows about -- like in this example
a list.
.. versionchanged:: 0.2.0
Added support for ``__structlog__`` serialization method.
"""
def __init__(self, **dumps_kw):
self._dumps_kw = dumps_kw
def __call__(self, logger, name, event_dict):
return json.dumps(event_dict, cls=_JSONFallbackEncoder,
**self._dumps_kw)
class _JSONFallbackEncoder(json.JSONEncoder):
"""
Serialize custom datatypes and pass the rest to __structlog__ & repr().
"""
def default(self, obj):
"""
Serialize obj with repr(obj) as fallback.
"""
# circular imports :(
from structlog.threadlocal import _ThreadLocalDictWrapper
if isinstance(obj, _ThreadLocalDictWrapper):
return obj._dict
else:
try:
return obj.__structlog__()
except AttributeError:
return repr(obj)
[docs]def format_exc_info(logger, name, event_dict):
"""
Replace an `exc_info` field by an `exception` string field:
If *event_dict* contains the key ``exc_info``, there are two possible
behaviors:
- If the value is a tuple, render it into the key ``exception``.
- If the value true but no tuple, obtain exc_info ourselves and render
that.
If there is no ``exc_info`` key, the *event_dict* is not touched.
This behavior is analogue to the one of the stdlib's logging.
>>> from structlog.processors import format_exc_info
>>> try:
... raise ValueError
... except ValueError:
... format_exc_info(None, None, {'exc_info': True})# doctest: +ELLIPSIS
{'exception': 'Traceback (most recent call last):...
"""
exc_info = event_dict.pop('exc_info', None)
if exc_info:
if not isinstance(exc_info, tuple):
exc_info = sys.exc_info()
event_dict['exception'] = _format_exception(exc_info)
return event_dict
def _format_exception(exc_info):
"""
Prettyprint an `exc_info` tuple.
Shamelessly stolen from stdlib's logging module.
"""
sio = StringIO()
traceback.print_exception(exc_info[0], exc_info[1], exc_info[2], None, sio)
s = sio.getvalue()
sio.close()
if s[-1:] == "\n":
s = s[:-1]
return s
[docs]class TimeStamper(object):
"""
Add a timestamp to `event_dict`.
:param str format: strftime format string, or ``"iso"`` for `ISO 8601
<http://en.wikipedia.org/wiki/ISO_8601>`_, or `None` for a `UNIX
timestamp <http://en.wikipedia.org/wiki/Unix_time>`_.
:param bool utc: Whether timestamp should be in UTC or local time.
>>> from structlog.processors import TimeStamper
>>> TimeStamper()(None, None, {}) # doctest: +SKIP
{'timestamp': 1378994017}
>>> TimeStamper(fmt='iso')(None, None, {}) # doctest: +SKIP
{'timestamp': '2013-09-12T13:54:26.996778Z'}
>>> TimeStamper(fmt='%Y')(None, None, {}) # doctest: +SKIP
{'timestamp': '2013'}
"""
def __new__(cls, fmt=None, utc=True):
if fmt is None and not utc:
raise ValueError('UNIX timestamps are always UTC.')
now_method = getattr(datetime.datetime, 'utcnow' if utc else 'now')
if fmt is None:
def stamper(self, _, __, event_dict):
event_dict['timestamp'] = calendar.timegm(time.gmtime())
return event_dict
elif fmt.upper() == 'ISO':
if utc:
def stamper(self, _, __, event_dict):
event_dict['timestamp'] = now_method().isoformat() + 'Z'
return event_dict
else:
def stamper(self, _, __, event_dict):
event_dict['timestamp'] = now_method().isoformat()
return event_dict
else:
def stamper(self, _, __, event_dict):
event_dict['timestamp'] = now_method().strftime(fmt)
return event_dict
return type('TimeStamper', (object,), {'__call__': stamper})()
# Copyright 2013 Hynek Schlawack
#
# Licensed under the Apache License, Version 2.0 (the "License");
# you may not use this file except in compliance with the License.
# You may obtain a copy of the License at
#
# http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.
"""
Primitives to keep context global but thread (and greenlet) local.
"""
from __future__ import absolute_import, division, print_function
import contextlib
import uuid
from structlog._config import BoundLoggerLazyProxy
try:
from greenlet import getcurrent
except ImportError: # pragma: nocover
from threading import local as ThreadLocal
else:
class ThreadLocal(object): # pragma: nocover
"""
threading.local() replacement for greenlets.
"""
def __init__(self):
self.__dict__["_prefix"] = str(id(self))
def __getattr__(self, name):
return getattr(getcurrent(), self._prefix + name)
def __setattr__(self, name, val):
setattr(getcurrent(), self._prefix + name, val)
def __delattr__(self, name):
delattr(getcurrent(), self._prefix + name)
[docs]def wrap_dict(dict_class):
"""
Wrap a dict-like class and return the resulting class.
The wrapped class and used to keep global in the current thread.
:param type dict_class: Class used for keeping context.
:rtype: `type`
"""
Wrapped = type('WrappedDict-' + str(uuid.uuid4()),
(_ThreadLocalDictWrapper,), {})
Wrapped._tl = ThreadLocal()
Wrapped._dict_class = dict_class
return Wrapped
[docs]def as_immutable(logger):
"""
Extract the context from a thread local logger into an immutable logger.
:param BoundLogger logger: A logger with *possibly* thread local state.
:rtype: :class:`~structlog.BoundLogger` with an immutable context.
"""
if isinstance(logger, BoundLoggerLazyProxy):
logger = logger.bind()
try:
ctx = logger._context._tl.dict_.__class__(logger._context._dict)
bl = logger.__class__(
logger._logger,
processors=logger._processors,
context={},
)
bl._context = ctx
return bl
except AttributeError:
return logger
@contextlib.contextmanager
[docs]def tmp_bind(logger, **tmp_values):
"""
Bind *tmp_values* to *logger* & memorize current state. Rewind afterwards.
>>> from structlog import wrap_logger, PrintLogger
>>> from structlog.threadlocal import tmp_bind, wrap_dict
>>> logger = wrap_logger(PrintLogger(), context_class=wrap_dict(dict))
>>> with tmp_bind(logger, x=5) as tmp_logger:
... logger = logger.bind(y=3)
... tmp_logger.msg('event')
y=3 x=5 event='event'
>>> logger.msg('event')
event='event'
"""
saved = as_immutable(logger)._context
yield logger.bind(**tmp_values)
logger._context.clear()
logger._context.update(saved)
class _ThreadLocalDictWrapper(object):
"""
Wrap a dict-like class and keep the state *global* but *thread-local*.
Attempts to re-initialize only updates the wrapped dictionary.
Useful for short-lived threaded applications like requests in web app.
Use :func:`wrap` to instantiate and use
:func:`structlog._loggers.BoundLogger.new` to clear the context.
"""
def __init__(self, *args, **kw):
"""
We cheat. A context dict gets never recreated.
"""
if args and isinstance(args[0], self.__class__):
# our state is global, no need to look at args[0] if it's of our
# class
self._dict.update(**kw)
else:
self._dict.update(*args, **kw)
@property
def _dict(self):
"""
Return or create and return the current context.
"""
try:
return self.__class__._tl.dict_
except AttributeError:
self.__class__._tl.dict_ = self.__class__._dict_class()
return self.__class__._tl.dict_
def __repr__(self):
return '<{0}({1!r})>'.format(self.__class__.__name__, self._dict)
def __eq__(self, other):
# Same class == same dictionary
return self.__class__ == other.__class__
def __ne__(self, other):
return not self.__eq__(other)
# Proxy methods necessary for structlog.
# Dunder methods don't trigger __getattr__ so we need to proxy by hand.
def __iter__(self):
return self._dict.__iter__()
def __setitem__(self, key, value):
self._dict[key] = value
def __delitem__(self, key):
self._dict.__delitem__(key)
def __len__(self):
return self._dict.__len__()
def __getattr__(self, name):
method = getattr(self._dict, name)
setattr(self, name, method)
return method
# Copyright 2013 Hynek Schlawack
#
# Licensed under the Apache License, Version 2.0 (the "License");
# you may not use this file except in compliance with the License.
# You may obtain a copy of the License at
#
# http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.
"""
Processors and helpers specific to the `logging module
<http://docs.python.org/2/library/logging.html>`_ from the `Python standard
library <http://docs.python.org/>`_.
"""
from __future__ import absolute_import, division, print_function
import logging
import sys
from structlog._base import BoundLoggerBase
from structlog._exc import DropEvent
[docs]class BoundLogger(BoundLoggerBase):
"""
Python Standard Library version of :class:`structlog.BoundLogger`.
Works exactly like the generic one except that it takes advantage of
knowing the logging methods in advance.
Use it like::
configure(
wrapper_class=structlog.stdlib.BoundLogger,
)
"""
def debug(self, event=None, **kw):
"""
Process event and call ``Logger.debug()`` with the result.
"""
return self._proxy_to_logger('debug', event, **kw)
def info(self, event=None, **kw):
"""
Process event and call ``Logger.info()`` with the result.
"""
return self._proxy_to_logger('info', event, **kw)
def warning(self, event=None, **kw):
"""
Process event and call ``Logger.warning()`` with the result.
"""
return self._proxy_to_logger('warning', event, **kw)
warn = warning
def error(self, event=None, **kw):
"""
Process event and call ``Logger.error()`` with the result.
"""
return self._proxy_to_logger('error', event, **kw)
def critical(self, event=None, **kw):
"""
Process event and call ``Logger.critical()`` with the result.
"""
return self._proxy_to_logger('critical', event, **kw)
[docs]class LoggerFactory(object):
"""
Build a standard library logger when an *instance* is called.
>>> from structlog import configure
>>> from structlog.stdlib import LoggerFactory
>>> configure(logger_factory=LoggerFactory())
"""
[docs] def __call__(self):
"""
Deduces the caller's module name and create a stdlib logger.
:rtype: `logging.Logger`
"""
f = sys._getframe()
name = f.f_globals['__name__']
# We skip all frames that originate from within structlog.
while name.startswith('structlog.'):
f = f.f_back
name = f.f_globals['__name__']
return logging.getLogger(name)
# Adapted from the stdlib
CRITICAL = 50
FATAL = CRITICAL
ERROR = 40
WARNING = 30
WARN = WARNING
INFO = 20
DEBUG = 10
NOTSET = 0
_nameToLevel = {
'critical': CRITICAL,
'error': ERROR,
'warn': WARNING,
'warning': WARNING,
'info': INFO,
'debug': DEBUG,
'notset': NOTSET,
}
[docs]def filter_by_level(logger, name, event_dict):
"""
Check whether logging is configured to accept messages from this log level.
Should be the first processor if stdlib's filtering by level is used so
possibly expensive processors like exception formatters are avoided in the
first place.
>>> import logging
>>> from structlog.stdlib import filter_by_level
>>> logging.basicConfig(level=logging.WARN)
>>> logger = logging.getLogger()
>>> filter_by_level(logger, 'warn', {})
{}
>>> filter_by_level(logger, 'debug', {})
Traceback (most recent call last):
...
DropEvent
"""
if logger.isEnabledFor(_nameToLevel[name]):
return event_dict
else:
raise DropEvent