Logbook setup example

logbook_example.py

"""
API request logger:
    One record per each API request received
    1) Logs to a file in logstash format.

App logger:
    Your usual logger that just writes down what the code is doing.
    Mostly quiet on production except when errors happen.
    Includes stack traces.

    1) Writes to stderr during development.
    2) Writes to basic log file on all environments.
    3) Errors and Exceptions are also logged to a logstash file (different than the file used by API request logger).
"""
import json
import time

import logbook
import pytz
import sys
from logbook.base import Logger, NestedSetup, Processor
from logbook.handlers import StderrHandler, NullHandler, FileHandler, StringFormatter, StreamHandler


req_log = Logger('api_request')
app_log = Logger('app')


class LogstashFormatter(StringFormatter):
    def __call__(self, record, handler):
        s = {
            'log_level': logbook.get_level_name(record.level),
            'log_name': record.channel,
            'datetime': record.time.replace(tzinfo=pytz.utc).strftime('%Y-%m-%dT%H:%M:%S%z'),
        }
        if isinstance(record.message, dict):
            s.update(record.message)
        else:
            s.update(message=record.message)
        if record.extra:
            s.update(record.extra)
        return json.dumps(s)


class ApiRequestLogFileHandler(FileHandler):
    formatter_class = LogstashFormatter

    def should_handle(self, record):
        return super(ApiRequestLogFileHandler, self).should_handle(record) and record.channel == 'api_request'


class AppLogFileHandler(FileHandler):
    formatter_class = LogstashFormatter


class AppLogStreamHandler(StreamHandler):
    formatter_class = LogstashFormatter


def inject_app_info(record):
    # Inject things like app version
    pass


def inject_request_info(record):
    """
    This is called on every logging call
    """
    record.extra['request_time'] = time.time()


setup = NestedSetup([
    # This must be read bottom-up. Records handled by a lower handled and not bubbled upwards will not
    # reach the handlers above.
    # That's why ApiRequestLogFileHandler needs to go in the bottom.
    # Processor lets through everything.
    NullHandler(),
    AppLogFileHandler('/tmp/app.log', level=logbook.INFO),
    AppLogStreamHandler(stream=sys.stderr, level=logbook.DEBUG, bubble=True),  # This would only be enabled in development
    ApiRequestLogFileHandler('/tmp/api_requests.log', level=logbook.INFO),
    Processor(inject_app_info),
])


with setup.applicationbound():
    app_log.info('Starting up application')

    with Processor(inject_request_info).threadbound():
        app_log.info('Starting request processing')
        req_log.info('API request processed', extra={'response_time': 13})
        app_log.info('Completing request processing')

    app_log.info('We are outside of injectors context')

    app_log.info('Shutting down application')