HTTP Application Logging in AL2023

Logging the HTTP request pipeline

We are running a typical Nginx / Gunicorn / Django HTTP request pipeline, with the Gunicorn / Django application running as a Docker container.

Nginx logs HTTP requests to files. Those files are rotated and uploaded to the logging storage on a regular basis. We are using OpenTelemetry to fast-track errors.

Gunicorn / Django logs to stdout and stderr. Docker is configured to send logs to journald. Journald forwards events to syslog so we are able to write logs to standard text files, thus using the same aggregator pipeline we do for Nginx logs.

Here is a summary of the important config files

...
ForwardToSyslog=yes
...

...
OPTIONS='--selinux-enabled --log-driver=journald --log-opt tag="{{.Name}}/{{.ID}}"'

...
errorlog="-"
accesslog="-"
loglevel="info"
access_log_format='%(h)s %({Host}i)s %({User-Session}o)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s" "%({X-Forwarded-For}i)s"'

...
LOGGING = {
  'formatters': {
    'request_format': {
      'format':
        "%(remote_addr)s %(http_host)s %(username)s [%(asctime)s]"\
        " %(levelname)s %(message)s",
        'datefmt': "%d/%b/%Y:%H:%M:%S %z"
    }
  },
  'handlers': {
    'log': {
      'level': "DEBUG",
      'formatter': "request_format",
      'class': "logging.StreamHandler",
    }
  },
  'loggers': {
...
    # This is the root logger.
    # The level will only be taken into account if the record is not
    # propagated from a child logger.
    #https://docs.python.org/2/library/logging.html#logging.Logger.propagate
    '': {
      'handlers': ["log"],
      'level': "INFO"
    },
  },
}
...

What changed?

We originally configured Logging of Docker containers output through journald to syslog-ng, but with the migration from Amazon Linux 2 to AL2023, syslog-ng is not readily available as a package. There is an experimental AL2023 syslog-ng package. Still at this point we decided to go the rsyslog route.

$ sudo dnf install rsyslog

We create a rsyslog config file to separate the application log events into their own file. Note that if the filter doesn't seem to be taken into account, it might be because of interaction with previous rules. We thus use a 00- prefix for the config filename here so it is the first to be loaded by rsyslog.

# logs app messages in a separate file
if $programname == 'app' then /var/log/gunicorn/app.log

We check there is no syntax error.

$ sudo rsyslogd -N1

The expected lines do not always appear in the logfile. It might be a combination of different services needing to be restarted.

$ sudo systemctl start rsyslog.service
$ sudo systemctl force-reload systemd-journald
$ sudo systemctl reload rsyslog.service

For debugging, we use a few journalctl commands to track log events through the stack.

# tailing output of docker itself (should show messages from all containers)
$ sudo journalctl -l _SYSTEMD_UNIT=docker.service -f

# showing json formatted of all metadata in the output of app container log
$ journalctl --since "5 min ago" CONTAINER_NAME=app -o json-pretty

If the $programname is not set correctly by Docker, or not passed through properly by jounald, it is sometimes easier to start filtering based on the $msg rsyslog property.

At this point, the output of the application makes it to the logfile, but each line is prefixed by sysload information. Since we are interested to have the same output recorded in the logfile as the ones a developer would see when they run python manage.py runserver on the their development machine, we are only going to write the raw message to the logfile.

# logs app messages in a separate file
template(name="rawMsgFormat" type="string" string="%msg%\n")

if $programname == 'app' then action(type="omfile" file="/var/log/gunicorn/app.log" template="rawMsgFormat")

Et voila! There is no distinction between the logfiles generated in production and the standard output a developer would record on its own development machine.

More to read

You might also like to read Shipping ssh login events through OpenTelemetry, or Fast-tracking server errors to a log aggregator on S3.

More technical posts are also available on the DjaoDjin blog, as well as business lessons we learned running a SaaS application hosting platform.