Setting up JSON logging for a production Django app requires the following steps:
- Configure JSON logging from the Django app
- Configure JSON logging from the application server (for example, uWSGI)
In the last article I covered how to configure JSON logging with Django. In this article, I'll show how to ensure that uWSGI server and request logs are formatted as JSON.
Let's get started.
Configure uWSGI with Django app
For code, you can pick up where you left off in the last article, or you can download and extract an archive of the project here.
From there, let's install uwsgi:
❯ pip install uwsgi==2.0.21
❯ pip freeze > requirements.txt
Configure uWSGI with JSON logging
For running a Django app in production, we'll use an application server that implements the WSGI interface. Though you have a bunch of options, we'll focus on uWSGI.
Run app with uWSGI
To run our app with uWSGI, let's first create a configuration file in the project root named uwsgi.ini:
[uwsgi]
http=0.0.0.0:80
module=django_json_logging.wsgi:application
master=true
pidfile=/tmp/pid.pid
vacuum=true
max-requests=5000
workers=2
enable-threads=true
single-interpreter=true
lazy-apps=true
And run the app with the following
uwsgi --ini uwsgi.ini
At startup, and upon making a request to localhost/log (notice the removal of port 8000), we should see the following:
[uWSGI] getting INI configuration from uwsgi.ini
*** Starting uWSGI 2.0.21 (64bit) on [Mon Nov 21 16:40:26 2022] ***
compiled with version: Apple LLVM 14.0.0 (clang-1400.0.29.102) on 08 November 2022 13:39:58
os: Darwin-21.6.0 Darwin Kernel Version 21.6.0: Thu Sep 29 20:13:56 PDT 2022; root:xnu-8020.240.7~1/RELEASE_ARM64_T6000
nodename: Chriss-MacBook-Pro.local
machine: arm64
clock source: unix
pcre jit disabled
detected number of CPU cores: 10
current working directory: /Users/rama/workspace/personal/django-json-logging
writing pidfile to /tmp/pid.pid
detected binary path: /Users/rama/.pyenv/versions/3.10.5/envs/django-json-logging/bin/uwsgi
your processes number limit is 2048
your memory page size is 16384 bytes
detected max file descriptor number: 524288
lock engine: OSX spinlocks
thunder lock: disabled (you can enable it with --thunder-lock)
uWSGI http bound on 0.0.0.0:80 fd 4
uwsgi socket 0 bound to TCP address 127.0.0.1:64862 (port auto-assigned) fd 3
Python version: 3.10.5 (main, Sep 21 2022, 09:41:39) [Clang 13.1.6 (clang-1316.0.21.2.5)]
Python main interpreter initialized at 0x139e04fe0
python threads support enabled
your server socket listen backlog is limited to 100 connections
your mercy for graceful operations on workers is 60 seconds
mapped 218688 bytes (213 KB) for 2 cores
*** Operational MODE: preforking ***
spawned uWSGI master process (pid: 38156)
spawned uWSGI worker 1 (pid: 38171, cores: 1)
spawned uWSGI worker 2 (pid: 38172, cores: 1)
spawned uWSGI http 1 (pid: 38173)
WSGI app 0 (mountpoint='') ready in 0 seconds on interpreter 0x139e04fe0 pid: 38171 (default app)
WSGI app 0 (mountpoint='') ready in 0 seconds on interpreter 0x139e04fe0 pid: 38172 (default app)
{"user": "me", "source": "django", "level": "INFO", "pathname": "/Users/rama/workspace/personal/django-json-logging/./django_json_logging/views.py", "lineno": 10, "message": "Sample info log", "time": "2022-11-21T22:40:32.638078"}
[pid: 38172|app: 0|req: 1/1] 127.0.0.1 () {52 vars in 1326 bytes} [Mon Nov 21 22:40:32 2022] GET /log/ => generated 16 bytes in 17 msecs (HTTP/1.1 200) 6 headers in 198 bytes (1 switches on core 0)
[pid: 38172|app: 0|req: 2/2] 127.0.0.1 () {50 vars in 1249 bytes} [Mon Nov 21 22:40:32 2022] GET /favicon.ico => generated 2222 bytes in 21 msecs (HTTP/1.1 404) 6 headers in 215 bytes (1 switches on core 0)
In the third-to-last message, we see our JSON log originating from our Django app. All other messages originate from uWSGI and not Django. Let's now turn our attention toward formatting those uWSGI log messages as JSON.
Server Logs vs Request Logs
A quick note on two different kinds of uWSGI logs before we dive into configuration. First, we have uWSGI server logs. These are logs produced by the running uWSGI process, and that refer to the state of threads and the server in general. Messages like these are server logs:
spawned uWSGI worker 1 (pid: 38171, cores: 1)
spawned uWSGI worker 2 (pid: 38172, cores: 1)
spawned uWSGI http 1 (pid: 38173)
WSGI app 0 (mountpoint='') ready in 0 seconds on interpreter 0x139e04fe0 pid: 38171 (default app)
The other kind of uWSGI logs are request logs. These are log messages spawned from the handling of individual requests to the underlying server. Messages like these are request logs:
[pid: 38172|app: 0|req: 1/1] 127.0.0.1 () {52 vars in 1326 bytes} [Mon Nov 21 22:40:32 2022] GET /log/ => generated 16 bytes in 17 msecs (HTTP/1.1 200) 6 headers in 198 bytes (1 switches on core 0)
[pid: 38172|app: 0|req: 2/2] 127.0.0.1 () {50 vars in 1249 bytes} [Mon Nov 21 22:40:32 2022] GET /favicon.ico => generated 2222 bytes in 21 msecs (HTTP/1.1 404) 6 headers in 215 bytes (1 switches on core 0)
When configuring uWSGI logging, we'll find that we need to configure these separately. In general, options including -req (for example logger-req) in their names refer to the configuration of request logs, while those that don't include -req (for example logger) refer to the configuration of server logs. One exception to this is log-format, which is used to define the format of request logs.
Configure uWSGI logging
Customizing logs in uWSGI is a matter of defining some loggers, routers, formatters and encoders. Let's start with the final outcome, and I'll step through each line:
; Defines logger to use for Django app logs
logger = djangologger stdio
; Defines logger to use for uWSGI server logs
logger = uwsgilogger stdio
; Route any message starting with { to the djangologger
log-route = djangologger ^{.*$
; Route any message NOT starting with a { to the uwsgilogger
log-route = uwsgilogger ^((?!\{).)*$
; Leave djangologger messages as-is
log-encoder = format:djangologger ${msg}
; Encode uWSGI server logs as JSON
log-encoder = json:uwsgilogger {"source": "uwsgi", "type": "server", "time": "${micros}", "message": "${msg}"}
; uWSGI request logs ---------------------------------------------------------------
logger-req = stdio
log-format = {"source": "uwsgi", "type": "request", "method": "%(method)", "path": "%(uri)", "user_agent": "%(uagent)", "duration_in_ms": %(msecs), "referer": "%(referer)", "host": "%(host)", "time": %(time), "remote_ip": "%(addr)", "lb_trace_id": "%(var.HTTP_X_FORWARDED_FOR)"}
; ----------------------------------------------------------------------------------
log-encoder = nl
Server Logs
Let's start with the definition of two different server loggers:
; Defines logger to use for Django app logs
logger = djangologger stdio
; Defines logger to use for uWSGI server logs
logger = uwsgilogger stdio
These loggers allow us to route messages to each logger based on rules we'll touch on in a moment, and they also allow us to format and encode them differently. Here's that routing:
; Route any message starting with { to the djangologger
log-route = djangologger ^{.*$
; Route any message NOT starting with a { to the uwsgilogger
log-route = uwsgilogger ^((?!\{).)*$
The first route we define is based on the assumption that any message hitting standard out (except a request log) that starts with a left curly brace ({) is a JSON-formatted log message originating from our Django app, and therefore should be routed to the djangologger. This will require no special encoding since it's already JSON-formatted. The second route specifies that all other messages be routed to the uwsgilogger, which will require a bit of encoding work.
Here's how we encode each of these:
; Leave djangologger messages as-is
log-encoder = format:djangologger ${msg}
; Encode uWSGI server logs as JSON
log-encoder = json:uwsgilogger {"source": "uwsgi", "type": "server", "time": "${micros}", "message": "${msg}"}
For the djangologger, we assume these messages are already JSON-encoded, so no special encoding is required; we only need to output the message (${msg}) itself.
For the uwsgilogger, we enlist the help of the JSON encoder, which is one of uWSGI's core log encoders. This encoder ensures that the output of the message is well-formed JSON. Refer to the uWSGI docs for all variables available for interpolation.
Request Logs
The next lines ensure that uWSGI request logs are output to standard out and formatted as JSON:
; uWSGI request logs ---------------------------------------------------------------
logger-req = stdio
log-format = {"source": "uwsgi", "type": "request", "method": "%(method)", "path": "%(uri)", "user_agent": "%(uagent)", "duration_in_ms": %(msecs), "referer": "%(referer)", "host": "%(host)", "time": %(time), "remote_ip": "%(addr)", "lb_trace_id": "%(var.HTTP_X_FORWARDED_FOR)"}
; ----------------------------------------------------------------------------------
Notice that I've chosen to use log-format for forming the JSON. I chose this approach because the list of variables for interpolation is much more extensive when formatting than when encoding. See the request log docs for all available options. Also, when using log-format, notice the syntactic difference of %(variable) instead of ${variable}.
The one drawback of this approach is that if any of the variables you've chosen for interpolation can include characters (such as double quotes) that result in malformed JSON, because we haven't used a JSON encoder, the final output will be that malformed JSON, which could potentially have negative downstream effects. One possible solution is to write (or use) a plugin that sanitizes this data, exposing it as a new variable. One such plugin is found at github.com/velebit-ai/uwsgi-json-logging-plugin.
Test uWSGI Log Configuration
With this configuration file in place, let's run the app again:
uwsgi --ini uwsgi.ini
The first few lines represent output from the loading of uWSGI configuration:
[uWSGI] getting INI configuration from uwsgi.ini
[log-encoder] registered format:djangologger ${msg}
[log-encoder] registered json:uwsgilogger {"source": "uwsgi", "type": "server", "time": "${micros}", "message": "${msg}"}
[log-encoder] registered nl
And then, we see all JSON-encoded messages:
{"source": "uwsgi", "type": "server", "time": "1669496080561750", "message": "*** Starting uWSGI 2.0.21 (64bit) on [Sat Nov 26 14:54:40 2022] ***"}
{"source": "uwsgi", "type": "server", "time": "1669496080561772", "message": "compiled with version: Apple LLVM 14.0.0 (clang-1400.0.29.102) on 08 November 2022 13:39:58"}
{"source": "uwsgi", "type": "server", "time": "1669496080561783", "message": "os: Darwin-21.6.0 Darwin Kernel Version 21.6.0: Thu Sep 29 20:13:56 PDT 2022; root:xnu-8020.240.7~1/RELEASE_ARM64_T6000"}
{"source": "uwsgi", "type": "server", "time": "1669496080561790", "message": "nodename: Chriss-MacBook-Pro.local"}
{"source": "uwsgi", "type": "server", "time": "1669496080561796", "message": "machine: arm64"}
{"source": "uwsgi", "type": "server", "time": "1669496080561801", "message": "clock source: unix"}
{"source": "uwsgi", "type": "server", "time": "1669496080561803", "message": "pcre jit disabled"}
{"source": "uwsgi", "type": "server", "time": "1669496080561806", "message": "detected number of CPU cores: 10"}
{"source": "uwsgi", "type": "server", "time": "1669496080561810", "message": "current working directory: /Users/rama/workspace/personal/django-json-logging"}
{"source": "uwsgi", "type": "server", "time": "1669496080561813", "message": "writing pidfile to /tmp/pid.pid"}
{"source": "uwsgi", "type": "server", "time": "1669496080561819", "message": "detected binary path: /Users/rama/.pyenv/versions/3.10.5/envs/django-json-logging/bin/uwsgi"}
{"source": "uwsgi", "type": "server", "time": "1669496080561821", "message": "your processes number limit is 2048"}
{"source": "uwsgi", "type": "server", "time": "1669496080561824", "message": "your memory page size is 16384 bytes"}
{"source": "uwsgi", "type": "server", "time": "1669496080561827", "message": "detected max file descriptor number: 524288"}
{"source": "uwsgi", "type": "server", "time": "1669496080561830", "message": "lock engine: OSX spinlocks"}
{"source": "uwsgi", "type": "server", "time": "1669496080561887", "message": "thunder lock: disabled (you can enable it with --thunder-lock)"}
{"source": "uwsgi", "type": "server", "time": "1669496080561895", "message": "uWSGI http bound on 0.0.0.0:80 fd 9"}
{"source": "uwsgi", "type": "server", "time": "1669496080561903", "message": "uwsgi socket 0 bound to TCP address 127.0.0.1:64999 (port auto-assigned) fd 8"}
{"source": "uwsgi", "type": "server", "time": "1669496080561910", "message": "Python version: 3.10.5 (main, Sep 21 2022, 09:41:39) [Clang 13.1.6 (clang-1316.0.21.2.5)]"}
{"source": "uwsgi", "type": "server", "time": "1669496080561916", "message": "Python main interpreter initialized at 0x1546048f0"}
{"source": "uwsgi", "type": "server", "time": "1669496080561920", "message": "python threads support enabled"}
{"source": "uwsgi", "type": "server", "time": "1669496080561926", "message": "your server socket listen backlog is limited to 100 connections"}
{"source": "uwsgi", "type": "server", "time": "1669496080561929", "message": "your mercy for graceful operations on workers is 60 seconds"}
{"source": "uwsgi", "type": "server", "time": "1669496080561933", "message": "mapped 218688 bytes (213 KB) for 2 cores"}
{"source": "uwsgi", "type": "server", "time": "1669496080561937", "message": "*** Operational MODE: preforking ***"}
{"source": "uwsgi", "type": "server", "time": "1669496080561940", "message": "spawned uWSGI master process (pid: 79884)"}
{"source": "uwsgi", "type": "server", "time": "1669496080561944", "message": "spawned uWSGI worker 1 (pid: 79897, cores: 1)"}
{"source": "uwsgi", "type": "server", "time": "1669496080561947", "message": "spawned uWSGI worker 2 (pid: 79898, cores: 1)"}
{"source": "uwsgi", "type": "server", "time": "1669496080561950", "message": "spawned uWSGI http 1 (pid: 79899)"}
{"source": "uwsgi", "type": "server", "time": "1669496080806324", "message": "WSGI app 0 (mountpoint='') ready in 0 seconds on interpreter 0x1546048f0 pid: 79898 (default app)"}
{"source": "uwsgi", "type": "server", "time": "1669496080806347", "message": "WSGI app 0 (mountpoint='') ready in 0 seconds on interpreter 0x1546048f0 pid: 79897 (default app)"}
And upon making a request to /log/, we see both our Django log message and the uWSGI request log, both JSON-encoded:
{"user": "me", "source": "django", "level": "INFO", "pathname": "/Users/rama/workspace/personal/django-json-logging/./django_json_logging/views.py", "lineno": 10, "message": "Sample info log", "time": "2022-11-26T20:55:03.512062"}
{"source": "uwsgi", "type": "request", "method": "GET", "path": "/log/", "user_agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/107.0.0.0 Safari/537.36", "duration_in_ms": 19, "referer": "-", "host": "localhost", "time": 1669496103, "remote_ip": "127.0.0.1", "lb_trace_id": "-"}
Conclusion and Next Steps
In this article we looked at how to configure uWSGI logs as JSON. This approach, in combination with the configuration of Django logs as JSON, results in a uWSGI process running in a deployed environment to produce all JSON log messages on standard out.
With JSON-formatted logs, all on standard out in accordance with 12factor.net/logs, we are now ready to forward and aggregate logs with a self-hosted or managed service for log management, such as OpenSearch, AWS CloudWatch, or SumoLogic.