Examples

Simple Usage

The following snippet uses sprockets.logging.ContextFilter to insert context information into a message using a logging.LoggerAdapter instance.

import logging
import sys

import sprockets.logging


formatter = logging.Formatter('%(levelname)s %(message)s {%(context)s}')
handler = logging.StreamHandler(sys.stdout)
handler.setFormatter(formatter)
handler.addFilter(sprockets.logging.ContextFilter(properties=['context']))
logging.Logger.root.addHandler(handler)
logging.Logger.root.setLevel(logging.DEBUG)

# Outputs: INFO Hi there {None}
logging.info('Hi there')

# Outputs: INFO No KeyError {bah}
logging.info('No KeyError', extra={'context': 'bah'})

# Outputs: INFO Now with context! {foo}
adapted = logging.LoggerAdapter(logging.Logger.root, extra={'context': 'foo'})
adapted.info('Now with context!')

Dictionary-based Configuration

This package begins to shine if you use the dictionary-based logging configuration offered by logging.config.dictConfig(). You can insert the custom filter and format string into the logging infrastructure and insert context easily with logging.LoggerAdapter.

import logging.config
import signal
import uuid

from tornado import ioloop, web
import sprockets.logging


LOG_CONFIG = {
   'version': 1,
   'handlers': {
      'console': {
         'class': 'logging.StreamHandler',
         'stream': 'ext://sys.stdout',
         'formatter': 'simple',
         'filters': ['context'],
      },
   },
   'formatters': {
      'simple': {
         'class': 'logging.Formatter',
         'format': '%(levelname)s %(name)s: %(message)s [%(context)s]',
      },
   },
   'filters': {
      'context': {
         '()': 'sprockets.logging.ContextFilter',
         'properties': ['context'],
      },
   },
   'loggers': {
      'tornado': {
         'level': 'DEBUG',
      },
   },
   'root': {
      'handlers': ['console'],
      'level': 'DEBUG',
   },
   'incremental': False,
}


class RequestHandler(web.RequestHandler):

   def __init__(self, *args, **kwargs):
      self.parent_log = kwargs.pop('parent_log')
      super(RequestHandler, self).__init__(*args, **kwargs)

   def prepare(self):
      uniq_id = self.request.headers.get('X-UniqID', uuid.uuid4().hex)
      self.logger = logging.LoggerAdapter(
         self.parent_log.getChild('RequestHandler'),
         extra={'context': uniq_id})

   def get(self, object_id):
      self.logger.debug('fetchin %s', object_id)
      self.set_status(200)
      return self.finish()

def sig_handler(signo, frame):
   logging.info('caught signal %d, stopping IO loop', signo)
   iol = ioloop.IOLoop.instance()
   iol.add_callback_from_signal(iol.stop)

if __name__ == '__main__':
   logging.config.dictConfig(LOG_CONFIG)
   logger = logging.getLogger('app')
   app = web.Application([
      web.url('/(?P<object_id>\w+)', RequestHandler,
              kwargs={'parent_log': logger}),
   ])
   app.listen(8000)
   signal.signal(signal.SIGINT, sig_handler)
   signal.signal(signal.SIGTERM, sig_handler)
   ioloop.IOLoop.instance().start()
   logger.info('IO loop stopped, exiting')

Tornado Application JSON Logging

If you’re looking to log Tornado requests as JSON, the sprockets.logging.JSONRequestFormatter class works in conjunction with the tornado_log_function() method to output all Tornado log entries as JSON objects. In the following example, the dictionary-based configuration is expanded upon to include specify the sprockets.logging.JSONRequestFormatter as the formatter and passes tornado_log_function() in as the log_function when creating the Tornado application.

import logging.config
import signal
import uuid

from tornado import ioloop, web
import sprockets.logging


LOG_CONFIG = {
   'version': 1,
   'handlers': {
      'console': {
         'class': 'logging.StreamHandler',
         'stream': 'ext://sys.stdout',
         'formatter': 'simple',
         'filters': ['context']
      }
   },
   'formatters': {
      'simple': {
         '()': sprockets.logging.JSONRequestFormatter
      }
   },
   'filters': {
      'context': {
         '()': 'sprockets.logging.ContextFilter',
         'properties': ['context']
      }
   },
   'loggers': {
      'tornado': {
         'level': 'DEBUG'
      }
   },
   'root': {
      'handlers': ['console'],
      'level': 'DEBUG'
   },
   'incremental': False
}


class RequestHandler(web.RequestHandler):

   def __init__(self, *args, **kwargs):
      self.parent_log = kwargs.pop('parent_log')
      super(RequestHandler, self).__init__(*args, **kwargs)

   def prepare(self):
      uniq_id = self.request.headers.get('X-UniqID', uuid.uuid4().hex)
      self.logger = logging.LoggerAdapter(
         self.parent_log.getChild('RequestHandler'),
         extra={'context': uniq_id})

   def get(self, object_id):
      self.logger.debug('fetchin %s', object_id)
      self.set_status(200)
      return self.finish()

def sig_handler(signo, frame):
   logging.info('caught signal %d, stopping IO loop', signo)
   iol = ioloop.IOLoop.instance()
   iol.add_callback_from_signal(iol.stop)

if __name__ == '__main__':
   logging.config.dictConfig(LOG_CONFIG)
   logger = logging.getLogger('app')
   app = web.Application([
      web.url('/(?P<object_id>\w+)', RequestHandler,
              kwargs={'parent_log': logger}),
   ], log_function=sprockets.logging.tornado_log_function)
   app.listen(8000)
   signal.signal(signal.SIGINT, sig_handler)
   signal.signal(signal.SIGTERM, sig_handler)
   ioloop.IOLoop.instance().start()
   logger.info('IO loop stopped, exiting')