Gunicorn: Can't see errors in log

[gregpinero]

I realized I should have posted here instead of StackOverflow. I'm starting to think it's a bug since I've followed all of the instructions as far as I can tell.

I'm running Django 1.6 and Gunicorn / Nginx on Scientific Linux and I'm getting log messages from Gunicorn for page access, and start up information, but nothing at all for django server errors.

Let me know what you guys think:

Full details:
http://stackoverflow.com/questions/21943962/how-to-see-details-of-django-errors-with-gunicorn

[SeanHayes]

Same here: http://stackoverflow.com/questions/21340049/how-to-use-django-logging-with-gunicorn

When running ./manage.py runserver logs show up on my console just fine, but not when running gunicorn in the foreground. gunicorn is disposing of them somehow.

[tilgovi]

What does your Django LOGGING configuration look like?

[SeanHayes]

LOGGING = {
    'version': 1,
    'disable_existing_loggers': True,
    'filters': {
        'require_debug_false': {
            '()': 'django.utils.log.RequireDebugFalse'
        },
        'filter_celery': {
            '()': 'meridian.logutils.ModuleFilter',
            'module': 'celery',
        }
    },
    'formatters': {
        'verbose': {
            'format': '%(levelname)s %(asctime)s %(process)d %(thread)d %(name)s:%(lineno)s %(funcName)s() %(message)s'
        },
        'verbose_sql': {
            'format': '%(levelname)s %(asctime)s %(process)d %(thread)d %(name)s:%(lineno)s %(funcName)s() %(sql)s\n%(params)s\n%(duration)ss'
        },
    },
    'handlers': {
        'mail_admins': {
            'level': 'ERROR',
            'filters': [],
            'class': 'meridian.logutils.AdminEmailHandler'
        },
        'real_console': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
            'formatter': 'verbose',
        },
        'real_console_sql': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
            'formatter': 'verbose_sql',
        },
        'console': {
            'class': 'logging.handlers.MemoryHandler',
            'target': 'real_console',
            'capacity': 8192,
            'filters': ['filter_celery'],
        },
        'console_sql': {
            'class': 'logging.handlers.MemoryHandler',
            'target': 'real_console_sql',
            'capacity': 8192,
        },
    },
    'loggers': {
        'django.request': {
            'handlers': ['mail_admins'],
            'level': 'ERROR',
            'propagate': True,
        },
        'django': {
            'handlers': ['console'],
            'level': 'INFO',
            'propagate': False,
        },
        'django.db.backends': {
            'handlers': ['console_sql'],
            'level': 'WARNING',
            'propagate': False,
        },
        'boto': {
            'level': 'WARNING',
        },
        'requests': {
            'level': 'WARNING',
        },
        'meridian': {
            'level': 'DEBUG',
        },
        'celery': {
            'level': 'WARNING',
        },
        'south': {
            'level': 'INFO',
        },
        'py.warnings': {
            'level': 'ERROR',# change to WARNING to show DeprecationWarnings, etc.
        },
    },
    'root': {
        'handlers': ['console'],
        'level': 'DEBUG',
    }
}

"filter_celery" just removes celery log lines.

Thanks for the quick response!

[tilgovi]

For @gregpinero it sounds like maybe Django catches the exception and returns an exception view. With Django's DEBUG setting, it shows the traceback in that page. Gunicorn will only log a traceback if it raises all the way into Gunicorn. If it is caught by Django, it will not be logged.

I don't know enough about Django internals to say whether it is caught by Django.

@SeanHayes your problem is different. Since you have passed disable_existing_loggers the Gunicorn loggers are disabled when Django loads your logging configuration. If you are setting this because you want to disable some default Django logging configuration, make sure you add back the gunicorn loggers, gunicorn.error and gunicorn.access with whatever handlers you want.

[benoitc]

@tilgovi what should we do with this issue?

[tilgovi]

I would like to hear some response from @gregpinero and @SeanHayes

But I think we can push to R19.1

[SeanHayes]

Setting 'disable_existing_loggers': False worked for me.

[tilgovi]

From the discussion here and SO it sounds like there is no problem for gunicorn.

[akshar-raaj]

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.

[NaitikShah]

Thanks @SeanHayes .. it worked :+1: !!!