Middleware error framework, high level logging for database queries

[Rishi Gupta]

Hi django-developers,

Hope things are going well! I work on an open-source group chat product
called zulip [1], written in python and javascript and based on Django, and
we have two small enhancements that we were thinking of contributing
upstream. Before making pull requests, we wanted to get a feel for what the
community thinks in terms of whether/how useful the features might be, and
any suggestions on how we should go about integrating them into the Django
codebase.

I realize many of you may be busy with DjangoCon US; I'll be at the sprints
on Thursday and Friday, and would be happy to talk to people then! We would
also love to get one or both of these into a merge-able state during that
time, or have a clear path forward.

(1) Middleware error framework.

Zulip has some exception middleware to allow 40x errors to be returned
to the user from anywhere within the view code via raising a special
exception, which we’ve found to be a really nice, convenient
programming style. With this model, validation code called anywhere
from within a view can pass nice, clear user-facing errors up to the
frontend. You can do this by writing something like:

def my_function(duration):
if duration < 0:
raise JsonableError(‘Negative durations are not valid’, status_code=400)

and the error message is passed back to the user via an HttpResponse
containing the error message in our own JSON format.

To implement this, our middleware code looks like the following (with
some logging and error checking):

class JsonErrorHandler(object):
def process_exception(self, request, exception):
if hasattr(exception, 'to_json_error_msg') and
callable(exception.to_json_error_msg):
# json_error just dumps the arguments as JSON and puts it
into an HttpResponse
return json_error(exception.to_json_error_msg(),
status=exception.status_code)
if request.error_format == "JSON":
logging.error(traceback.format_exc())
return json_error("Internal server error", status=500)
return None

class JsonableError(Exception):
def __init__(self, error, status_code=400):
self.error = error
self.status_code = status_code
def to_json_error_msg(self):
return self.error

For merging into Django, we'd want to generalize this a bit to not
hardcode the way to
marshall the data, but hopefully the snippets above give a sense of
how this works and might be useful.

(2) High level logging for database queries.

We've currently monkey-patched a system to add the following
information to our log lines:

... 52ms (db: 4ms/8q) /url ...

Where 52ms is the total time spent in views code, during which 8
database queries were made, which took a total of 4ms.

Our developers use this as a light-weight performance debugging tool;
it helps in a few ways:
a) It highlights when one is accidentally making database calls in a
loop (common Django newbie mistake!).
b) It makes it possible to rule out possibilities for why performance
was poor for a specific request in production. E.g. one can know if
it was slow due to too many database queries, a really slow database
query, or some other potentially expensive code in the application.

Currently there isn't a great way to do this "natively"; Django’s
database cursors either logs the whole query (in DEBUG mode) or
nothing at all.

We do it by wrapping the psycopg2 connection and cursor classes with
something that keeps track of these basic stats, along with middleware
that then logs the summary for the entire request.

(We’ve implemented similar logging for memcached as well; I think it’d
eventually make sense to do this sort of tracking for all of the major
network services that Django has hooks to RPC to).

Thanks!
Rishi

[1] https://github.com/zulip/zulip and https://zulip.org

[Tim Graham]

For 1, I'm wondering if there's anything preventing that from being implemented as a third-party package? It seems that could be a first step toward getting a better sense of the idea and whether or not it should be included in core.

For 2, a first step could be to add proper hooks in Django so that you don't need to do monkey-patching to achieve your use case. I imagine that others have similar needs that would benefit from that.

[Curtis Maloney]

On 19/07/16 05:16, Rishi Gupta wrote:
> Hi django-developers,
>

> (1) Middleware error framework.
>
> Zulip has some exception middleware to allow 40x errors to be returned
> to the user from anywhere within the view code via raising a special
> exception, which we’ve found to be a really nice, convenient
> programming style. With this model, validation code called anywhere
> from within a view can pass nice, clear user-facing errors up to the
> frontend. You can do this by writing something like:

I did something like this [actually, the code was handed to me by Matt
Schinckel]... which I use in django-nap.

It's HtppResponse melded with Exception so you can raise it.

I submitted it for consideration some time ago, and it was rejected
because it bound source and action too tightly.

However, it looks like your solution doesn't suffer from this shortcoming.

As was mentioned by Tim, I think this can readily grow outside django,
until it's matured.

> (2) High level logging for database queries.
>
> We've currently monkey-patched a system to add the following
> information to our log lines:
>
> ... 52ms (db: 4ms/8q) /url ...

Some years back I wrote some middleware to do just this.... originally
logging the count / total time, and later sending it to the browser in a
cookie with a 0 time to live.

> Currently there isn't a great way to do this "natively"; Django’s
> database cursors either logs the whole query (in DEBUG mode) or
> nothing at all.

In debug mode the queries [and their execution times] are kept on the
connection.

import time

class CookieDebugMiddleware(object):
'''Show query counts, times, and view timing in Cookies'''

def process_request(self, request):
request.start_time = time.time()

def process_response(self, request, response):
response.set_cookie('QueryCount', '%d (%s s)' % (
len(connection.queries),
sum([float(q['time']) for q in connection.queries])
), max_age=0)
response.set_cookie('ViewTime', '%s s' % (time.time() -
request.start_time), max_age=0)
return response


--
Curtis