:LastChangedDate: $LastChangedDate$ :LastChangedRevision: $LastChangedRevision$ :LastChangedBy: $LastChangedBy$ .. _core-howto-logger-main: Logging with twisted.logger =========================== The Basics ---------- Logging consists of two main endpoints: applications that emit events, and observers that receive and handle those events. An event is simply a ``dict`` object containing the relevant data that describes something interesting that has occurred in the application. For example: a web server might emit an event after handling each request that includes the URI of requested resource, the response's status code, a count of bytes transferred, and so on. All of that information might be contained in a pair of objects representing the request and response, so logging this event could be as simple as: .. code-block:: python log.info(request=request, response=response) The above API would seem confusing to users of many logging systems, which are built around the idea of emitting strings to a file. There is, after all, no string in the above call. In such systems, one might expect the API to look like this instead: .. code-block:: python log.info( "{uri}: status={status}, bytes={size}, etc..." .format(uri=request.uri, status=response.code, size=response.size) ) Here, a string is rendered by formatting data from our request and response objects. The string can be easily appended to a log file, to be later read by an administrator, or perhaps teased out via some scripts or log gathering tools. One disadvantage to this is that a strings meant to be human-readable are not necessarily easy (or even possible) for software to handle reliably. While text files are a common medium for storing logs, one might want to write code that notices certain types of events and does something other than store the event. In the web server example, if many requests from a given IP address are resulting in failed authentication, someone might be trying to break in to the server. Perhaps blocking requests from that IP address would be useful. An observer receiving the above event as a string would have to resort to parsing the string to extract the relevant information, which may perform poorly and, depending on how well events are formatted, it may also be difficult to avoid bugs. Additionally, any information not encoded into the string is simply unavailable; if the IP address isn't in the string, it cannot be obtained from the event. However, if the ``request`` and ``response`` objects are available to the observer, as in the first example, it would be possible to write an observer that accessed any attributes of those objects. It would also be a lot easier to write an observer that emitted structured information by serializing these objects into a format such as JSON, rows in a database, etc. Events-as-strings do have the advantage that it's obvious what an observer that writes strings, for example to a file, would emit. We can solve this more flexibly by providing an optional format string in events that can be used for this purpose: .. code-block:: python log.info( "{request.uri}: status={response.status}, bytes={response.size}, etc...", request=request, response=response ) Note that this looks very much like the events-as-strings version of the API, except that the string is not rendered by the caller; we leave that to the observer, *if and when it is needed* . The observer also has direct access to the request and response objects, as well as their attributes. Now a text-based observer can format the text in a prescribed way, and an observer that wants to handle these events in some other manner can do so as well. Usage for emitting applications ------------------------------- The first thing that an application that emits logging events needs to do is to instantiate a :api:`twisted.logger.Logger ` object, which provides the API to emit events. A :api:`twisted.logger.Logger ` may be created globally for a module: .. code-block:: python from twisted.logger import Logger log = Logger() def handleData(data): log.debug("Got data: {data!r}.", data=data) A :api:`twisted.logger.Logger ` can also be associated with a class: .. code-block:: python from twisted.logger import Logger class Foo(object): log = Logger() def oops(self, data): self.log.error( "Oops! Invalid data from server: {data!r}", data=data ) When associated with a class in this manner, the ``"log_source"`` key is set in the event. For example: :download:`logsource.py ` .. literalinclude:: listings/logger/logsource.py This example will show the string "object with value 7 doing a task" because the ``log_source`` key is automatically set to the ``MyObject`` instance that the ``Logger`` is retrieved from. Capturing Failures ~~~~~~~~~~~~~~~~~~ :api:`twisted.logger.Logger ` provides a :api:`twisted.logger.Logger.failure ` method, which allows one to capture a :api:`twisted.python.failure.Failure ` object conveniently: .. code-block:: python from twisted.logger import Logger log = Logger() try: 1 / 0 except: log.failure("Math is hard!") The emitted event will have the ``"log_failure"`` key set, which is a :api:`twisted.python.failure.Failure ` that captures the exception. This can be used by my observers to obtain a traceback. For example, :api:`twisted.logger.FileLogObserver ` will append the traceback to it's output:: Math is hard! Traceback (most recent call last): --- --- File "/tmp/test.py", line 8, in 1/0 exceptions.ZeroDivisionError: integer division or modulo by zero Note that this API is meant to capture unexpected and unhandled errors (that is: bugs, which is why tracebacks are preserved). As such, it defaults to logging at the :api:`twisted.logger.LogLevel.critical ` level. It is generally more appropriate to instead use `log.error()` when logging an expected error condition that was appropriately handled by the software. Namespaces ~~~~~~~~~~ All :api:`twisted.logger.Logger ` s have a namespace, which can be used to categorize events. Namespaces may be specified by passing in a ``namespace`` argument to :api:`twisted.logger.Logger ` 's initializer, but if none is given, the logger will derive its namespace from the module name of the callable that instantiated it, or, in the case of a class, from the fully qualified name of the class. A :api:`twisted.logger.Logger ` will add a ``log_namespace`` key to the events it emits. In the first example above, the namespace would be ``some.module`` , and in the second example, it would be ``some.module.Foo`` . Log levels ~~~~~~~~~~ :api:`twisted.logger.Logger ` s provide a number of methods for emitting events. These methods all have the same signature, but each will attach a specific ``log_level`` key to events. Log levels are defined by the :api:`twisted.logger.LogLevel ` constants container. These are: :api:`twisted.logger.LogLevel.debug ` Debugging events: Information of use to a developer of the software, not generally of interest to someone running the software unless they are attempting to diagnose a software issue. :api:`twisted.logger.LogLevel.info ` Informational events: Routine information about the status of an application, such as incoming connections, startup of a subsystem, etc. :api:`twisted.logger.LogLevel.warn ` Warning events: Events that may require greater attention than informational events but are not a systemic failure condition, such as authorization failures, bad data from a network client, etc. Such events are of potential interest to system administrators, and should ideally be phrased in such a way, or documented, so as to indicate an action that an administrator might take to mitigate the warning. :api:`twisted.logger.LogLevel.error ` Error conditions: Events indicating a systemic failure. For example, resource exhaustion, or the loss of connectivity to an external system, such as a database or API endpoint, without which no useful work can proceed. Similar to warnings, errors related to operational parameters may be actionable to system administrators and should provide references to resources which an administrator might use to resolve them. :api:`twisted.logger.LogLevel.critical ` Critical failures: Errors indicating systemic failure (ie. service outage), data corruption, imminent data loss, etc. which must be handled immediately. This includes errors unanticipated by the software, such as unhandled exceptions, wherein the cause and consequences are unknown. In the first example above, the call to ``log.debug`` will add a ``log_level`` key to the emitted event with a value of :api:`twisted.logger.LogLevel.debug ` . In the second example, calling ``self.log.error`` would use a value of :api:`twisted.logger.LogLevel.error ` . The above descriptions are simply guidance, but it is worth noting that log levels have a reduced value if they are used inconsistently. If one module in an application considers a message informational, and another module considers a similar message an error, then filtering based on log levels becomes harder. This is increasingly likely if the modules in question are developed by different parties, as will often be the case with externally source libraries and frameworks. (If a module tends to use higher levels than another, namespaces may be used to calibrate the relative use of log levels, but that is obviously suboptimal.) Sticking to the above guidelines will hopefully help here. Emitter method signatures ~~~~~~~~~~~~~~~~~~~~~~~~~ The emitter methods (:api:`twisted.logger.Logger.debug ` , :api:`twisted.logger.Logger.info ` , :api:`twisted.logger.Logger.warn ` , etc.) all take an optional format string as a first argument, followed by keyword arguments that will be included in the emitted event. Note that all three examples in the opening section of this HOWTO fit this signature. The first omits the format, which doesn't lend itself well to text logging. The second omits the keyword arguments, which hostile to anything other than text logging, and is therefore ill-advised. Finally, the third provides both, which is the recommended usage. These methods are all convenience wrappers around the :api:`twisted.logger.Logger.emit ` method, which takes a :api:`twisted.logger.LogLevel ` as its first argument. Format strings ~~~~~~~~~~~~~~ Format strings provide observers with a standard way to format an event as text suitable for a human being to read, via the function :api:`twisted.logger.formatEvent ` . When writing a format string, take care to present it in a manner which would make as much sense as possible to a human reader. Particularly, format strings need not be written with an eye towards parseability or machine-readability. If you want to save your log events along with their structure and then analyze them later, see the next section, on :ref:`"saving events for later" ` . Format strings should be ``unicode`` , and use `PEP 3101 `_ syntax to describe how the event should be rendered as human-readable text. For legacy support and convenience in python 2, UTF-8-encoded ``bytes`` are also accepted for format strings, but unicode is preferred. There are two variations from PEP 3101 in the format strings used by this module: #. Positional (numerical) field names (eg. ``{0}`` ) are not permitted. Event keys are not ordered, which means positional field names do not make sense in this context. However, this is not an accidental limitation, but an intentional design decision. As software evolves, log messages often grow to include additional information, while still logging the same conceptual event. By using meaningful names rather than opaque indexes for event keys, these identifiers are more robust against future changes in the format of messages and the information provided. #. Field names ending in parentheses (eg. ``{foo()}`` ) will call the referenced object with no arguments, then call ``str`` on the result, rather than calling ``str`` on the referenced object directly. This extension to PEP 3101 format syntax is provided to make it as easy as possible to defer potentially expensive work until a log message must be emitted. For example, let's say that we wanted to log a message with some useful, but potentially expensive information from the 'request' object: .. code-block:: python log.info("{request.uri} useful, but expensive: {request.usefulButExpensive()}", request=request) In the case where this log message is filtered out as uninteresting and not saved, no formatting work is done *at all* ; and since we can use PEP3101 attribute-access syntax in conjunction with this parenthesis extension, the caller does not even need to build a function or bound method object to pass as a separate key. There is no support for specifying arguments in the format string; the goal is to make it idiomatic to express that work be done later, not to implement a full Python expression evaluator. Event keys added by the system ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ The logging system will add keys to emitted events. All event keys that are inserted by the logging system with have a ``log_`` prefix, to avoid namespace collisions with application-provided event keys. Applications should therefore not insert event keys using the ``log_`` prefix, as that prefix is reserved for the logging system. System-provided event keys include: ``log_logger`` :api:`twisted.logger.Logger ` object that the event was emitted to. ``log_source`` The source object that emitted the event. When a :api:`twisted.logger.Logger ` is accessed as an attribute of a class, the class is the source. When accessed as an attribute of an instance, the instance is the source. In other cases, the source is ``None`` . ``log_level`` The :api:`twisted.logger.LogLevel ` associated with the event. ``log_namespace`` The namespace associated with the event. ``log_format`` The format string provided for use by observers that wish to render the event as text. This may be ``None`` , if no format string was provided. ``log_time`` The time that the event was emitted, as returned by :api:`time.time