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-Forto 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