How to enrich logging messages with request information in flask?

Question

I have a small Flask app that's used like a REST API that implements many methods like this:

@route('/do/something', methods=['POST'])
def something():
    app.logger.debug("got request to /do/something")
    result = something_implementation(request.json())
    app.logger.debug("result was %s", str(result))
    return flask.Response(result)

I would like to enrich these log messages automatically with information from the request object such as header information, parts of the body and whatever else is convenient.

How do I do that in an elegant and pythonic way?

Of course I could just wrap app.logger in my own function and pass the request object and the message along, but there's got to be a nicer and easier way I'm missing.

Answer 1

I usually include something like this in my app.py file to log debug information for each request, along with handling standard errors:

# Useful debugging interceptor to log all values posted to the endpoint
@app.before_request
def before():
    values = 'values: '
    if len(request.values) == 0:
        values += '(None)'
    for key in request.values:
        values += key + ': ' + request.values[key] + ', '
    app.logger.debug(values)

# Useful debugging interceptor to log all endpoint responses
@app.after_request
def after(response):
    app.logger.debug('response: ' + response.status + ', ' + response.data.decode('utf-8'))
    return response

# Default handler for uncaught exceptions in the app
@app.errorhandler(500)
def internal_error(exception):
    app.logger.error(exception)
    return flask.make_response('server error', 500)

# Default handler for all bad requests sent to the app
@app.errorhandler(400)
def handle_bad_request(e):
    app.logger.info('Bad request', e)
    return flask.make_response('bad request', 400)v

Answer 2

I have solved this by subclassing logging.Filter and adding it to my handler.

Something like this:

class ContextFilter(logging.Filter):
    '''Enhances log messages with contextual information'''
    def filter(self, record):
        try:
            record.rid = request.rid
        except RuntimeError as exc:
            if str(exc.message) == 'working outside of request context':
                record.rid = ''
            else:
                raise exc
        return True

The try/except clause is necessary for log messages outside of a request context to work. And then use it like this:

fileHandler = RotatingFileHandler(app.config['LOGFILE'], maxBytes=20971520,
                                  backupCount=5, encoding='utf-8')
fileHandler.setLevel(logging.DEBUG)
fileHandler.addFilter(ContextFilter())
filefmt = '%(asctime)s [%(filename)s:%(lineno)d] %(rid)s: %(message)s'
fileFormatter = logging.Formatter(filefmt)
fileHandler.setFormatter(fileFormatter)
app.logger.addHandler(fileHandler)

In the future I can add more fields in the ContextFilter.filter() method and use them however I please in the formatter configuration.