Django View logging is back-the-front
Have you ever looked through your Django log files and console messages, felt something was out of order and didn’t make sense, but couldn’t quite put your finger on it?
Here is an example of what I mean. Here is some view code:
def diagramz_list(request, template_name="list.html"):
log.info("diagramz_list has been called")
...
return render(request, template_name, {"object_list": diagrams})that gets routed via url(r”^listz$”, views.diagramz_list, name=”listall”).
Let’s look at the log file and console messages that get generated when you do the usual python manage.py runserver and using the browser, visit endpoint /listz:
[2018–10–20 14:42:50] [INFO] diagramz_list has been called
[2018–10–20 14:42:51] [INFO] “GET /listz HTTP/1.1” 200 119585Can you see the problem?
Right — the hit on the endpoint /listz gets logged after the output of the logging statement which says “diagramz_list has been called”.
That’s counterintuitive for me when I do logfile analysis.
IMO — the Django endpoint call should be logged immediately.
Anything that happens during the execution of that request should be logged afterwards.
Django logging via runserver has it arse-about. Even running in production, which doesn’t use Django’s local runserver technology, this problem still occurs (and we’ll see how to fix it, later).
Basically Django logs the endpoint “hit” at the end of the request processing view function, rather than at the beginning of it. For those of us trying to make sense of a sequence of events in the log file — this is confusing.
The solution
My solution is to use some “middleware code” to output a log message at the very, very start of each view function.
I found this old snippet and modified it to be Django 2/Python 3 compatible using this guide, then added the magic logging code I wanted — see line 27 below.
Most of the above code is about formatting a useful, pretty log message. The essential thing is that we are defining a class RequestLoggingMiddleware(MiddlewareMixin): and defining process_request and process_response methods. You can do what you want inside these methods — I choose to log.
Add the above file request-logging-middleware.py to some path in your project. Then add the following line of config to your middleware (in settings.py) like this:
MIDDLEWARE = [
...
"SOMEPATH.request-logging-middleware.RequestLoggingMiddleware",
...For example if you choose to put request-logging-middleware.py in a package of your project called lib.extras then the entry should be “lib.extras.request-logging-middleware.RequestLoggingMiddleware”. If you choose to put the file in the root of your Django project, then the path need only be “request-logging-middleware.RequestLoggingMiddleware”.
Now, after restarting your Django server and visiting some urls of your Django project, your log output should look like:
[2018-10-21 14:48:21] [INFO] Endpoint /listz request 127.0.0.1
[2018-10-21 14:48:21] [INFO] diagramz_list has been called
[2018-10-21 14:48:22] [INFO] Endpoint completed, 127.0.0.1 GET /listz 200 119585 (0.26 seconds) (39 SQL queries, 1.0 ms)
[21/Oct/2018 14:48:22] "GET /listz HTTP/1.1" 200 119585Notice that we can now see where the endpoint hit first begins.
Result!
Production out of sequence issues too!
I tend to host a lot of my work using Heroku, or its free little brother, Dokku, on a Digital Ocean droplet (VM). With these deployment technologies, logging to file is disabled (forcibly, by Heroku) and all log messages go to stdout. These days I install a Datadog agent and forward these log messages to Datadog for monitoring.
It turns out that in such a deployment scenario:
all Python and Django log messages go to stderr
and all gunicorn log messages that deal with view hits and static file serving go to stdout.
This phenomenon may cause ‘out of sequence’ log messages, too!
For example the Datadog Agent scans my docker containers in my Digital Ocean droplet (VM) and sends them to the lovely Datadog service. I think that the way the agent grabs those separate message streams, timestamps them and sends them to Datadog can result in stdout messages getting a slight priority over Django’s error messages — thus causing the gunicorn view requests to be logged first — as we want. A quirk of fate, perhaps, but at least it’s in our favour.
If we want to eliminate the stdout/stderr timing problems, this stackoverflow post and also perhaps this one discuss how we can configure our logging so that everything goes to stdout. This would eliminate this possible area of log ordering confusion.
However when viewing the log messages from my deployed app in a dokku managed docker container via a terminal, e.g.dokku logs appnamethen interestingly, the sequence is the same as my local machine — the gunicorn view requests are logged last, and thus suffer the same out of sequence problem as the first part of this article.
Thankfully our middleware generated log messages give us the correct sequence all the time.
Conclusion
Use my middleware logging solution above. Then in all situations, local and production, whether its via terminal or via an agent like datadog, look at the middleware generated log messages not the gunicorn generated log messages, to follow the real time sequence.
I hope this article was useful. I rely on this solution for making sense of the log files in my web apps below.
My Other Cool Software
- GitUML — generate UML diagrams instantly from any GitHub repository containing Python code (web app)
- Pynsource — UML for Python (desktop app)
- Python to RPN — Run Python 3 on vintage HP calculators (web app)
- Print42 — Electron-Python app, non-invasive log file annotation tool that supports thermal printers
About Andy Bulka
- Main website and blog www.andypatterns.com
- Medium article: Building a deployable Python-Electron App — Using Electron as a GUI toolkit for Python.
- Medium article: Async/await for wxPython — Python 3 GUI apps with asynchronous functionality.
- Medium article: Getting Python and wxPython apps into the Ubuntu app store
- Github https://github.com/abulka