Empty logging with Django, Nginx, Gunicorn and supervisor

Question

I have a problem with my django logging in my production environment. I am using Nginx+Gunicorn+Supervisorctl to run my Django website. I have tried almost everything for two days without any result.

My idea is to have two log files as I have defined in my Django app. One to store all log records (messages.log) and the other to store WARNING, ERROR and CRITICAL log records (errors.log)

LOGGING = {
'version': 1,
'disable_existing_loggers': True,
'formatters': {
    'verbose': {
        'format': ' [%(asctime)s] [%(levelname)s] [%(name)s] %(message)s'
    },
    'simple': {
        'format': ' %(levelname)s %(message)s'
    },
},
'handlers': {
    'console': {
        'level': 'DEBUG',
        'class': 'logging.StreamHandler',
        'formatter': 'verbose'
    },
    'file': {
        'level': 'DEBUG',
        'class': 'logging.FileHandler',
        'formatter': 'verbose',
        'filename': '/home/myuser/logs/messages.log'
    },
    'file_errors': {
        'level': 'WARNING',
        'class': 'logging.FileHandler',
        'formatter': 'verbose',
        'filename': '/home/myuser/logs/errors.log'
    },
    'mail_admins': {
        'level': 'ERROR',
        'class': 'django.utils.log.AdminEmailHandler',
        'include_html': True
    }
},
'loggers': {
    'main': {
        'handlers': ['console', 'file', 'file_errors', 'mail_admins'],
        'level': 'DEBUG'
    },
    'caching': {
        'handlers': ['console', 'file', 'file_errors'],
        'level': 'DEBUG'
    }
}

With this logging configuration, I am registering log records in my django app with commands like follows:

logger = logging.getLogger("main")
logger.info("INFO message")
logger.critical("CRITICAL message")

This commands are registered well in messages.log and errors.log in my development environment. Now, time to upload the app to production.

In production I am running gunicorn with supervisor. This is my configuration to run gunicorn using supervisor:

[program:gunicorn_app]
command=gunicorn --bind 172.31.19.71:8000 -c /home/myuser/app/gunicorn.conf.py -p /home/myuser/app/gunicorn.pid wsgi:application
directory=/home/myuser/app
user=myuser
autostart=true
stdout_logfile = /home/myuser/logs/app_supervisor
stderr_logfile = /home/myuser/logs/app_error_supervisor
autorestart=true
redirect_stderr=true

As you can see, I am using a config file for gunicorn which content is as follows:

from __future__ import unicode_literals 
import multiprocessing

bind = "unix:%(proj_path)s/gunicorn.sock"
workers = 4
proc_name = "app_proc"

Finally Nginx is configured as follows:

server {

    listen 80;
    server_name www.myapp.com;
    client_max_body_size 10M;
    keepalive_timeout    15;
    error_log /home/myser/logs/app_error_nginx.log info;

    ...
}

When I run my application the only log file generated is /home/myuser/logs/app_supervisor, which is the one generated by supervisor and only containing information about the process starting up. It is the only file contained in /home/myuser/logs.

However, HTTP requests are displayed on /var/log/nginx/access.log but even /var/log/nginx/errors.log does not display any error or warning message coming from my app.

Any idea?

Answer 1

I think it is good to understand all the components and what they are actually logging.

• nginx - access.log

  This will will log any request that comes to nginx, irrespective of the nature or kind of request.

• nginx - error.log

  This will log errors that come from any backend ("upstream" in nginx language) servers that you have configured; if they are not handling these errors. In other words, if the upstream server has no logging configured and is sending all logs to stderr - it will finally be caught and logged in error.log.

• supervisor - stdout_logfile setting

  The file mentioned here logs any messages generated by supervisor when starting this entry.

• supervisor - stderr_logfile setting

  If supervisor faces an error launching the process configured, it is logged here.

• gunicorn

  gunicorn has two error loggers gunicorn.error and gunicorn.access which will log any error or stdout/access messages for the application being run under gunicorn.

• django logging

  This is the first place error messages are generated and then "moved up the chain".

So as error are generated at each level of your stack, they are either handled by that component, or simply passed through to the next component up until in the end, if nothing catches the error messages, they may be caught by the global OS error logger or - in most cases - silently discarded.

The reason in your app your errors are not doing what they should is because you have disabled all other loggers in your django configuration with 'disable_existing_loggers': True,.

This also disabled gunicorn.error and gunicorn.access - your error logs are now being discarded as they are actually being handled by gunicorn, but the loggers are disabled by your django configuration.

Simply add the appropriate configuration for those two loggers to your settings.py, or set disable_existing_loggers to False and then restart the gunicorn process and everything should work.