MyFancyRequestHandler extends the werkzeug BaseRequestHandler to provide HTTP request execution time to the server log. NB: The associated tutorial is: http://jaytaylor.com/blog/?p=305

serving.py

import time
from werkzeug.serving import BaseRequestHandler

class MyFancyRequestHandler(BaseRequestHandler):
    """Extend werkzeug request handler to suit our needs."""
    def handle(self):
        self.fancyStarted = time.time()
        rv = super(MyFancyRequestHandler, self).handle()
        return rv

    def send_response(self, *args, **kw):
        self.fancyProcessed = time.time()
        super(MyFancyRequestHandler, self).send_response(*args, **kw)

    def log_request(self, code='-', size='-'):
        duration = int((self.fancyProcessed - self.fancyStarted) * 1000)
        self.log('info', '"{0}" {1} {2} [{3}ms]'.format(self.requestline, code, size, duration))

Shouldn't the timer be after the send_response()? While the sending is taking place, the socket is "still busy", so I think the timing would be more accurate if the processed time is logged after all data has been sent.

This also brings the question of "how good" the timing is. Perhaps it should be done at a lower layer for better accuracy (don't know if this is really needed in your application) :-?

I thought about that and it's certainly a valid consideration, but I ultimately decided the primary concern is how long it takes to generate the response rather than including transmission time.

Thanks, this was very timely for me as I just did the same thing with a secondary log using @before_request and @after_request, but this is more what I was looking for - directly appending to the access.log entries.

However, I'm trying to figure out how to override the request handler in a hosted wsgi situation where app.run() is not called directly by my code. Flask does not appear to have a way to pass in werkzeug options to the Flask() constructor. Any ideas on how to tackle that?

Like @noise, I'm trying to accomplish this from gunicorn, which doesn't app.run. The Heroku Procfile doesn't help either. There doesn't seem to be a way to set this handler after/before the call to run.