Logging in Crossbar.io

Crossbar’s structured logging system is present in versions 0.11 and above.

Crossbar.io uses Twisted’s new Logger facilities to provide structured logging for Crossbar.io and components run inside of it.

Twisted Logger

Twisted Logger, introduced in Twisted 15.2, provides structured logging for Python applications. Crossbar.io integrates with this and uses it internally, and your components can take advantage of it. Crossbar.io also captures stdout, so print() statements will also be captured.

Writing Components that use Logger

A component that uses Logger is the hello example application.

To set your application up for logging, import Logger from twisted.logger and instantiate it. If you have classes, making it a class attribute allows Logger to store some more information (more on that later).

The Logger instance has several methods, relating to the levels of events:

  • critical: For unhandled/unhandleable errors.

  • error: For handled errors.

  • warn: For warnings which may affect the component but is not an error (for example: deprecated configuration, or having to make assumptions)

  • info: For general information messages.

  • debug: For debugging information.

These methods take at least one argument (the “format string”) which will be used to produce a textual representation of the log event. This argument follows the standard Python format string representation as in PEP-3101. Further keyword arguments can be given which will be used in the formatting.

The formatting may not be done straight away – if the log event is never observed (for example, if it is a debug message, and the log observer level is set to info) the event will never be formatted into a string. This can be more efficient, as it means debug calls essentially turn into no-ops when the log level of the listener is not on debug as well.

As an example, if we have a variable named counter which is set to 1, and a Logger instance at self.log, we could do the following:

self.log.info("published to 'oncounter' with counter {counter}", counter=counter)

This message would show up in the Crossbar logs as:

2015-08-17T13:45:10+0800 [Container    7326] published to 'oncounter' with counter 1

Log recovery at all costs

If your log message cannot be formatted, Logger will try and preserve as much as possible. For example, if you forgot to pass the counter keyword argument to the self.log.info call…

self.log.info("published to 'oncounter' with counter {counter}")

…it would produce the following in Crossbar’s log:

2015-08-17T14:22:47+0800 [Container    7676] Unable to format event {'log_logger': <Logger 'hello.hello.AppSession'>, 'log_time': 1439792567.720701, 'log_source': <hello.hello.AppSession object at 0x10af0e290>, 'log_format': "published to 'oncounter' with counter {counter}"}: u'counter'

Logger will try and preserve as much information as possible, no matter what errors may occur, rather than eating the message.

Class instance Loggers

If you make your Logger a class attribute (as in the hello example), it captures some extra information. The log_source attribute in the log event is set automatically when it is a class attribute, which points to the instance of the class that it was called from. This means that you can get information from the class instance without having to individually pass it into the log call. For example:

from twisted.logger import Logger
from autobahn.twisted.wamp import ApplicationSession

class AppSession(ApplicationSession):

    log = Logger()

    def onJoin(self, details):

        self.x = "Hello Crossbar!"
        self.log.info("x on self is {log_source.x}")

When this application component is run under Crossbar, it will produce the following log message:

2015-08-17T14:28:13+0800 [Container    7825] x on self is Hello Crossbar!

Plus, when Crossbar’s logger is set to debug, each log message comes with where it came from in the log, to help trace down where errors may be occurring:

2015-08-17T13:43:52+0800 [Container    7310 hello.hello.AppSession] published to 'oncounter' with counter 2

Configuring the Crossbar logger

For more information on configuring the Crossbar.io logging output (for example, to turn on debug, change the output format, or write to a file), see Configuring Crossbar.io’s Logging .