Structured log files in Python using python-json-logger

‹ Structured log files | Testing Ansible roles with test-kitchen and Docker using the Ansible Role Tester ›

One approach for transferring events from your software into a log indexer software like logstash or splunk is to output them to disk in a structured format like JSON. Structured logs have some advantages over plain text logs, and the API of the Python logging module is flexible enough to output them with a custom Formatter.

In Python's log system, there are multiple logger objects organized into a tree that represent different parts of your system and different 3rd party libraries that you have installed. When you send a message into one of the loggers, the message gets output on all of that logger's handlers, using a formatter that's attached to each handler. The mesage then propagates up the logger tree until it hits one that is configured with propagate=False

There is a pypi package for python called python-json-logger which provides a Formatter class for outputting JSON on one or more of your handlers. Usage looks like this:

handler = logging.StreamHandler()  # Or FileHandler or anything else
# Configure the fields to include in the JSON output. message is the main log string itself
format_str = '%(message)%(levelname)%(name)%(asctime)'
formatter = pythonjsonlogger.jsonlogger.JsonFormatter(format_str)
handler.setFormatter(formatter)
logger = logging.getLogger('my_module_name')
logger.addHandler(handler)
# logger.setLevel(logging.DEBUG)
# Normally we would attach the handler to the root logger, and this would be unnecessary
logger.propagate = False

Other possible values for format_str can be found in the LogRecord documentation. The above example causes log messages such as the following to be output. Note the ability (bolded) to include extra keys:

Python codeOutput
logger.warning("Plain str"){"message": "Plain str", "levelname": "WARNING", "name": "pjlogger_full", "asctime": "2016-06-30 23:04:16,414"}
logger.error(u"Unicode string \U0001F4A9"){"message": "Unicode string \ud83d\udca9", "levelname": "ERROR", "name": "pjlogger_full", "asctime": "2016-06-30 23:04:16,414"}
logger.critical("String with extra=dict", extra={'foo': frozenset((u'\u0001f4a9',))}){"message": "String with extra=dict", "levelname": "CRITICAL", "name": "pjlogger_full", "asctime": "2016-06-30 23:08:17,928", "foo": "frozenset([u'\\x01f4a9'])"}
logger.warning("Default Setup Str+Param %d", logging.DEBUG){"message": "Default Setup Str+Param 10", "levelname": "WARNING", "name": "pjlogger_full", "asctime": "2016-06-30 23:04:16,414"}
logger.error({u'randomkey': set((logging.DEBUG,))}){"message": null, "levelname": "ERROR", "name": "pjlogger_full", "asctime": "2016-06-30 23:04:16,414", "randomkey": "set([10])"}
logger.critical("conflict", {u'message': set((logging.DEBUG,))}){"message": "conflict", "levelname": "CRITICAL", "name": "pjlogger_full", "asctime": "2016-06-30 23:04:16,414"}
logger.exception("exc_info")
logger.error("exc_info", exc_info=True)
{"message": "exc_info", "levelname": "ERROR", "name": "pjlogger_full", "asctime": "2016-10-30 15:49:51,039", "exc_info": "Traceback (most recent call last):\n File \"test.py\", line 24, in main\n raise Exception(\"MyException\")\nException: MyException"}
logger.warning("String with extra=set", extra=set(("foo",)))TypeError
logger.error("String with extra=str", extra="a")TypeError
logger.critical("kwargs", foo='foo', baz='baz', level=logging.CRITICAL)TypeError

Comments

May I suggest to add examples of log.exception and log.smth(exc_info=True)?

Added, thanks for the suggestion!

Subscribe to All Posts - Wesley Tanaka