DEV Community

loading...

Logging Flask requests with structure and colors

rhymes profile image rhymes ・4 min read

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)
Enter fullscreen mode Exit fullscreen mode

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
Enter fullscreen mode Exit fullscreen mode

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

colorized logging

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()
Enter fullscreen mode Exit fullscreen mode

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)
Enter fullscreen mode Exit fullscreen mode
  • 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'))
Enter fullscreen mode Exit fullscreen mode

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)

Enter fullscreen mode Exit fullscreen mode

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
Enter fullscreen mode Exit fullscreen mode

Discussion (6)

pic
Editor guide
Collapse
turbaszek profile image
Collapse
rsavoie profile image
Ramiro Savoie

Man, this is lovely! Thanks!

Collapse
rhymes profile image
rhymes Author

You're welcome!

Collapse
rdil profile image
Reece Dunham • Edited

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.

Collapse
rhymes profile image
rhymes Author

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
Collapse
khunpisit profile image
Deuce

Many thanks