How to see details of Django errors with Gunicorn?

Question

I just deployed my Django (1.6) project with gunicorn and Nginx.

It seems to be working fine but I have one page were I'm getting an HTTP 500 error and I can't find any details about the error anywhere.

How do I get gunicorn to show me errors?

Here's all I currently see in the log file when I hit the page giving me the error:

>tail gunicorn.errors 
2014-02-21 14:41:02 [22676] [INFO] Listening at: unix:/opt/djangoprojects/reports/bin/gunicorn.sock (22676)
2014-02-21 14:41:02 [22676] [INFO] Using worker: sync
2014-02-21 14:41:02 [22689] [INFO] Booting worker with pid: 22689
...
2014-02-21 19:41:10 [22691] [DEBUG] GET /reports/2/

Here's my bash script I use to start gunicorn:

>cat gunicorn_start
#!/bin/bash

NAME="reports"                                  # Name of the application
DJANGODIR=/opt/djangoprojects/reports          # Django project directory
SOCKFILE=/opt/djangoprojects/reports/bin/gunicorn.sock  # we will communicte using this unix socket
USER=reportsuser                                        # the user to run as
GROUP=webapps                                     # the group to run as
NUM_WORKERS=4                                     # how many worker processes should Gunicorn spawn
DJANGO_SETTINGS_MODULE=reports.settings             # which settings file should Django use
DJANGO_WSGI_MODULE=reports.wsgi                     # WSGI module name

#echo "Starting $NAME as `whoami`"

# Activate the virtual environment
cd $DJANGODIR
source pythonenv/bin/activate
export DJANGO_SETTINGS_MODULE=$DJANGO_SETTINGS_MODULE
export PYTHONPATH=$DJANGODIR:$PYTHONPATH

# Create the run directory if it doesn't exist
RUNDIR=$(dirname $SOCKFILE)
test -d $RUNDIR || mkdir -p $RUNDIR

# Start your Django Unicorn
# Programs meant to be run under supervisor should not daemonize themselves (do not use --daemon)
exec gunicorn ${DJANGO_WSGI_MODULE}:application \
  --name $NAME \
  --workers $NUM_WORKERS \
  --user=$USER --group=$GROUP \
  --log-level=debug \
  --bind=unix:$SOCKFILE \
  --error-logfile /opt/djangoprojects/reports/bin/gunicorn.errors \
  --log-file /opt/djangoprojects/reports/bin/gunicorn.errors

More info:

I'm starting/stopping gunicorn with this init.d script I copied and modified using sudo service reports start|stop|restart:

>cat /etc/init.d/reports
#!/bin/sh
### BEGIN INIT INFO
# Provides:          django_gunicorn
# Required-Start:    $local_fs $network $remote_fs
# Required-Stop:     $local_fs $network $remote_fs
# Default-Start:     2 3 4 5
# Default-Stop:      0 1 6
# Short-Description: Starts django_unicorn reports at boot time.
# Description:       Starts django_unicorn reports at boot time.
### END INIT INFO

name=`basename $0`
dir="/opt/djangoprojects/reports"
cmd="${dir}/bin/gunicorn_start"
pid_file="/var/run/$name.pid"
log_file="${dir}/bin/reports.log"

get_pid() {
    cat "$pid_file"    
}

is_running() {
    [ -f "$pid_file" ] && ps `get_pid` > /dev/null 2>&1
}

case "$1" in
    start)
    if is_running; then
        echo "Already running"
    else
        echo -n "Starting ${name}... "
        cd "$dir"
        #sudo -u "$user" $cmd &>> "$log_file"
        $cmd &>> "$log_file" &
        echo $! > "$pid_file"
        if ! is_running; then
            echo "Unable to start; see $log_file"
            exit 1
        else
            echo "[STARTED]"
        fi
    fi
    ;;
    stop)
    if is_running; then
        echo -n "Stopping ${name}... "
        kill `get_pid`
        for i in {1..10}
        do
            if ! is_running; then
                break
            fi

            echo -n "."
            sleep 1
        done
        echo

        if is_running; then
            echo "Not stopped; may still be shutting down or shutdown may have failed"
            exit 1
        else
            echo "[STOPPED]"
            if [ -f "$pid_file" ]; then
                rm "$pid_file"
            fi
        fi
    else
        echo "Not running"
    fi
    ;;
    restart)
    $0 stop
    if is_running; then
        echo "Unable to stop, will not attempt to start"
        exit 1
    fi
    $0 start
    ;;
    status)
    if is_running; then
        echo "[RUNNING]"
    else
        echo "[STOPPED]"
        exit 1
    fi
    ;;
    *)
    echo "Usage: $0 {start|stop|restart|status}"
    exit 1
    ;;
esac

exit 0

Answer 1

From your comment I think this is a config problem in your django site, not a matter of gunicorn log, logs will not show more than django send to it.

Here is an example of how you can configure django setting to send log to your file (instead of send it to admins by email as default):

LOGGING = {
    'version': 1,
    'disable_existing_loggers': True,
    'formatters': {
        'verbose': {
            'format': '%(asctime)s %(levelname)s [%(name)s:%(lineno)s] %(module)s %(process)d %(thread)d %(message)s'
        }
    },
    'handlers': {
        'gunicorn': {
            'level': 'DEBUG',
            'class': 'logging.handlers.RotatingFileHandler',
            'formatter': 'verbose',
            'filename': '/opt/djangoprojects/reports/bin/gunicorn.errors',
            'maxBytes': 1024 * 1024 * 100,  # 100 mb
        }
    },
    'loggers': {
        'gunicorn.errors': {
            'level': 'DEBUG',
            'handlers': ['gunicorn'],
            'propagate': True,
        },
    }
}

Read configuring logging (it provide a very well explanations of log settings options) and study the file django/utils/log.py to configure django loggin to appears more detailed on gunicorn logs.

Also check this answer and this which provide setting examples to send logs errors directly to a file. And consider to use Sentry to handle log errors, as is recomended by django guys.

Hope this helps.

Answer 2

This configuration worked for me. Add --capture-output --enable-stdio-inheritance with gunicorn command like below.

/home/ubuntu/inside-env/bin/gunicorn --access-logfile /var/log/access_file_g.log --error-logfile /var/log/error_file_g.log --capture-output --enable-stdio-inheritance --workers 3 --bind unix:/home/ubuntu/path-to-project/webapp.sock project.wsgi:application

With this setup, do enable logging in this way

import logging 
logging.basicConfig(level='DEBUG')

logging.info('hello world')

This way you will get to see the errors in the App as well.

Answer 3

Short answer:

With following logging configuration, your errors will start showing up in Gunicorn output(undaemonized) or runserver even when DEBUG is False. They anyways should be showing up when DEBUG is True.

LOGGING = {
'version': 1,
'disable_existing_loggers': False,
'filters': {
    'require_debug_false': {
        '()': 'django.utils.log.RequireDebugFalse',
    },
    'require_debug_true': {
        '()': 'django.utils.log.RequireDebugTrue',
    },
},
'formatters': {
    'django.server': {
        '()': 'django.utils.log.ServerFormatter',
        'format': '[%(server_time)s] %(message)s',
    }
},
'handlers': {
    'console': {
        'level': 'INFO',
        'filters': ['require_debug_true'],
        'class': 'logging.StreamHandler',
    },
    # Custom handler which we will use with logger 'django'.
    # We want errors/warnings to be logged when DEBUG=False
    'console_on_not_debug': {
        'level': 'WARNING',
        'filters': ['require_debug_false'],
        'class': 'logging.StreamHandler',
    },
    'django.server': {
        'level': 'INFO',
        'class': 'logging.StreamHandler',
        'formatter': 'django.server',
    },
    'mail_admins': {
        'level': 'ERROR',
        'filters': ['require_debug_false'],
        'class': 'django.utils.log.AdminEmailHandler'
    }
},
'loggers': {
    'django': {
        'handlers': ['console', 'mail_admins', 'console_on_not_debug'],
        'level': 'INFO',
    },
    'django.server': {
        'handlers': ['django.server'],
        'level': 'INFO',
        'propagate': False,
    },
}
}

If you want to see the Django errors in gunicorn error log, run gunicorn with --capture-output.

http://docs.gunicorn.org/en/stable/settings.html#capture-output

Long answer

There are two confusions involved when logging:

1. Whether runserver provide better log than gunicorn
2. Does settings.DEBUG=True provide better log than settings.DEBUG=False

Any log record you see with runserver can be seen with Gunicorn too as long as you have appropriate logging configuration.

Any log record you see with DEBUG=True can be seen while DEBUG=False too as long as you have appropriate logging configuration.

You can see default Django logging configuration at:

https://github.com/django/django/blob/1.10.8/django/utils/log.py#L18

It looks like: (I have stripped out parts which don't concern this answer)

DEFAULT_LOGGING = {
'version': 1,
'disable_existing_loggers': False,
'filters': {
    'require_debug_false': {
        '()': 'django.utils.log.RequireDebugFalse',
    },
    'require_debug_true': {
        '()': 'django.utils.log.RequireDebugTrue',
    },
},
'handlers': {
    'console': {
        'level': 'INFO',
        'filters': ['require_debug_true'],
        'class': 'logging.StreamHandler',
    },
    'mail_admins': {
        'level': 'ERROR',
        'filters': ['require_debug_false'],
        'class': 'django.utils.log.AdminEmailHandler'
    }
},
'loggers': {
    'django': {
        'handlers': ['console', 'mail_admins'],
        'level': 'INFO',
    },
}
}

What this says is:

1. Send django logger log record to handlers console and mail_admins.

2. Handler console has a filter require_debug_true on it. When settings.DEBUG is True, then handler console sends/prints the log on the Stream (because of logging.StreamHandler).

When settings.DEBUG is False, then handler console ignores the log message sent to it by logger django.

If you want logs to be printed with DEBUG=False too, then add a handler and make logger django use it.

Handler would look like:

    'console_on_not_debug': {
        'level': 'WARNING',
        'filters': ['require_debug_false'],
        'class': 'logging.StreamHandler',
    },

And use this handler with logger django:

    'django': {
        'handlers': ['console', 'mail_admins', 'console_on_not_debug'],
        'level': 'INFO',
    },

You can see the entire snippet in short answer.

With this, the logs will be printed on stream irrespective of if you are using runserver or gunicorn.

If you want the logs to be shown in gunicorn error log, then you need to run gunicorn with --capture-output.