Logging Flask requests with structure and colors

Logging is one of those things on which all developers agree, what we don't agree with is the format.

You can log using "free text", agree on a structure of use full JSON.

I tend to use a combination of free text and structured logging. My favorite logging library so far is lograge for Rails which funnily enough is described by the authors as "An attempt to tame Rails' default policy to log everything".

Flask definitely doesn't get logging right by default and I think it has to do also with how complicated Python's default logging which honestly I never completely understood.

Anyway, back on the scope of the article. Lograge is pretty neat because it turns this:

Started GET "/" for 127.0.0.1 at 2012-03-10 14:28:14 +0100
Processing by HomeController#index as HTML
  Rendered text template within layouts/application (0.0ms)
  Rendered layouts/_assets.html.erb (2.0ms)
  Rendered layouts/_top.html.erb (2.6ms)
  Rendered layouts/_about.html.erb (0.3ms)
  Rendered layouts/_google_analytics.html.erb (0.4ms)
Completed 200 OK in 79ms (Views: 78.8ms | ActiveRecord: 0.0ms)

into this:

method=GET path=/jobs/833552.json format=json controller=JobsController  action=show status=200 duration=58.33 view=40.43 db=15.26

I wanted to replicate that with the latest released version of Flask (v0.12.2) and add some coloring to get to this:

Info to collect

As you can see from the image we need:

• request method
• request path
• response status code
• request time
• time stamp in RFC339 format
• request ip
• request host
• request params

How to collect it in Flask

Flask has hooks to inject your code at different stages of requests. A bit like Rails request filters.

We're going to use before_request and after_request.

The first thing we're going to collect it the timestamp of the beginning of the request:

@app.before_request
def start_timer():
    g.start = time.time()

app is the Flask app, g is the flask global object and time.time() well... you know :-)

The rest of the information can be collected after the request is finished with:

@app.after_request
def log_request(response):
    if request.path == '/favicon.ico':
        return response
    elif request.path.startswith('/static'):
        return response

    now = time.time()
    duration = round(now - g.start, 2)
    dt = datetime.datetime.fromtimestamp(now)
    timestamp = rfc3339(dt, utc=True)

    ip = request.headers.get('X-Forwarded-For', request.remote_addr)
    host = request.host.split(':', 1)[0]
    args = dict(request.args)

• This does not log the favicon or requests for static files. You might want to keep them
• The timestamp is in UTC, you might want it in a specific timezone but I tend to like logs in UTC. I use rfc3339 library
• It retrieves the IP address from X-Forwarded-For to give precedence to proxied requests, defaults to Flask's remote address
• Host is retrieved without the optional port

The next step is to create the params and add coloring:

    log_params = [
        ('method', request.method, 'blue'),
        ('path', request.path, 'blue'),
        ('status', response.status_code, 'yellow'),
        ('duration', duration, 'green'),
        ('time', timestamp, 'magenta'),
        ('ip', ip, 'red'),
        ('host', host, 'red'),
        ('params', args, 'blue')
    ]
    request_id = request.headers.get('X-Request-ID')
    if request_id:
        log_params.append(('request_id', request_id, 'yellow'))

I also optionally log the request id which is set by Heroku.

The last part is actually building the line and outputting it:

    parts = []  # as any dev I hate naming temporary variables :-)
    for name, value, color in log_params:
        part = color("{}={}".format(name, value), fg=color)
        parts.append(part)
    line = " ".join(parts)

    app.logger.info(line)

color comes from the ansicolors library.

This is the whole snippet:

import datetime
import time

import colors
from flask import g, request
from rfc3339 import rfc3339

app = create_your_flask_app()


@app.before_request
def start_timer():
    g.start = time.time()


@app.after_request
def log_request(response):
    if request.path == '/favicon.ico':
        return response
    elif request.path.startswith('/static'):
        return response

    now = time.time()
    duration = round(now - g.start, 2)
    dt = datetime.datetime.fromtimestamp(now)
    timestamp = rfc3339(dt, utc=True)

    ip = request.headers.get('X-Forwarded-For', request.remote_addr)
    host = request.host.split(':', 1)[0]
    args = dict(request.args)

    log_params = [
        ('method', request.method, 'blue'),
        ('path', request.path, 'blue'),
        ('status', response.status_code, 'yellow'),
        ('duration', duration, 'green'),
        ('time', timestamp, 'magenta'),
        ('ip', ip, 'red'),
        ('host', host, 'red'),
        ('params', args, 'blue')
    ]

    request_id = request.headers.get('X-Request-ID')
    if request_id:
        log_params.append(('request_id', request_id, 'yellow'))

    parts = []
    for name, value, color in log_params:
        part = colors.color("{}={}".format(name, value), fg=color)
        parts.append(part)
    line = " ".join(parts)

    app.logger.info(line)

    return response

Comments

[Ramiro Savoie]

Man, this is lovely! Thanks!

[rhymes]

You're welcome!

[Tomasz Urbaszek]

Awesome!

[Reece Dunham]

Can I have permission to make a Flask extension out of a slightly modified this (with a credit towards you of course)? It's really cool what you've done here.

[rhymes]

Sure you can! Keep in mind that the colorless final version of the log_request is this one:

@app.after_request
def log_request(response):
    "Log HTTP request details"

    if (
        request.path == "/favicon.ico"
        or request.path.startswith("/static")
        or request.path.startswith("/admin/static")
    ):
        return response

    now = time.time()
    duration = round(now - g.start, 6)  # to the microsecond
    ip_address = request.headers.get("X-Forwarded-For", request.remote_addr)
    host = request.host.split(":", 1)[0]
    params = dict(request.args)

    request_id = request.headers.get("X-Request-ID", "")

    log_params = {
        "method": request.method,
        "path": request.path,
        "status": response.status_code,
        "duration": duration,
        "ip": ip_address,
        "host": host,
        "params": params,
        "request_id": request_id,
    }

    log.info("request", **log_params)

    return response

[Deuce]

Many thanks

[Jayme Davis]

Cheers! This is great, I love it.

One small issue I can't seem to work around... I am using the automatic pycharm requirements.txt plugin. In pycharm, I copy this exact code, and in order to resolve the "colors" dependency, I choose "add imported packages to requirements". This adds "MyApplication~=0.1.0" to my requirements, and everything works!... weird, right? I have tried to add in ansicolors in several different ways, but I can't quite get it.

Any idea what I'm doing wrong? I tried deleting and rebuilding my venv, installing ansicolors(~=1.1.8), etc, but I can't get this resolved without "MyApplication". I'm fairly new to python. I included a screenshot of what I see when I try to resolve colors. ansicolors is installed at this point as well.

[Jayme Davis]

So I've got this working passed the MyApplication mess now, at least! I deleted my venv and ansicolors from requirements.txt, and rebuilt the env. I'm left with this annoying bit in pycharm now (screenshot). My guess is it's using another libraries code for colors? ansicolors is not installed, but yet it works.

[Jayme Davis]

Nevermind. I'm overly tired, long day. Turns out I DID need ansicolors... everything works, I'm just left with this.

I am going to leave my thread here so if nothing else, it shows you how dedicated I was to getting this working, because I liked it so much. Thanks again!!