Logging in Django on Heroku not appearing

Question

I have created an app on Heroku and I push my Django app to it.

I monitor the logs using heroku logs --tail to see them in real time.

Then, in my settings.py, I have the following:

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'verbose': {
            'format': ('%(asctime)s [%(process)d] [%(levelname)s] ' +
                       'pathname=%(pathname)s lineno=%(lineno)s ' +
                       'funcname=%(funcName)s %(message)s'),
            'datefmt': '%Y-%m-%d %H:%M:%S'
        },
        'simple': {
            'format': '%(levelname)s %(message)s'
        }
    },
    'handlers': {
        'null': {
            'level': 'DEBUG',
            'class': 'logging.NullHandler',
        },
        'console': {
            'level': 'INFO',
            'class': 'logging.StreamHandler',
            'formatter': 'verbose',
            'stream': sys.stdout,
        }
    },
    'loggers': {
        'MYAPP': {
            'handlers': ['console'],
            'level': 'INFO',
        }
    }
}

Then, when I want to log something, I use the following:

import logging
import sys 

logger = logging.getLogger('MYAPP')
logger.info('My message here...')
sys.stdout.flush()

but it isn't reflected in my logs.

My Procfile:

web: gunicorn myapp.wsgi --log-file=-

EDIT: Curiously, I can actually change "myapp" to "django" when I define my logging config and also logging.getLogger('django') and that allows me to see anything using print in my logs, but nothing from the formatted logger I've defined.

I even have PYTHONUNBUFFERED=true and DEBUG=1 set for my staging environment, but I don't see any of the logs that I see when using my local version with foreman start web.

What is causing this and how do I see my logs live in Heroku?

Refusal

what is you Procfile ? With Gunicorn you can specify the log level and the log file. – Vladikavkaz

How do you run your app on Heroku? With uWSGI or Gunicorn or something else? – Rudderhead

my Procfile is: web: gunicorn myapp.wsgi --log-file - – Refusal

Did you try changing the level option of console to DEBUG? – Excrescency

No, but I'm sending out at INFO level which should be higher – Refusal

Answer 1

Your Procfile is probably at fault here:

If you want to have gunicorn log to stdout you have to use the --logfile=- command line option (you are missing the = !) according to this answer.

So your entire Procfile should look like this:

web: gunicorn myapp.wsgi --log-file=-

EDIT:

Since print statements are working for you, but logging is not, your logging setup is probably at fault. Make sure that you set up logging during the startup of your app (where are you calling dictConfig in your code?):

import logging
logging.config.dictConfig(LOGGING)
logger = logging.getLogger('MYAPP')
logger.info("Just testing")

Rudderhead

Hmm, this doesn't seem to help. I still don't see the live logged output in the heroku logs --tail shell. – Refusal

@Refusal which version of Gunicorn are you using? Starting from version R20 it is logging to stdout by default again. So then you would not need the command line flag at all. Also try adding --log-level=debug, just to make sure that this is not the problem. – Rudderhead

I'm using gunicorn==19.3.0, which is what heroku uses for django stack. – Refusal

The --log-level=debug thing seems to show more messages, but not the ones I'm logging, so it doesn't solve the problem. What I see in addition now are some kind of Heroku heartbeat updates every second on the second like 2015-09-07T18:57:05.712965+00:00 app[web.1]: [2015-09-07 18:57:05 +0000] [3] [DEBUG] 2 workers. But nothing that I'm logging in my app. – Refusal

@Refusal hm strange. Try this as a sanity check: Put 'print "Just testing"' somewhere at the startup of your app and see if that shows up in the Heroku logs. If it does, then you know that your logging setup is somehow broken. If it doesn't it is probably something else. – Rudderhead

yes, inserting a print statement in settings.py does show up in the logs. In fact I see it twice which I assume must be some other system Heroku dyno starting up that I don't define in my Procfile? Which is strange. – Refusal

@Refusal I updated my answer. Can you show the code that you are using to setup logging? Ideally also add the files where you are doing this. – Rudderhead

Newer Gunicorn doesn't seem to have a --logfile argument, just --access-logfile and --error-logfile (the latter of which defaults to stdout). – Placard

Answer 2

Your Procfile and LOGGING configuration looks fine. Django configures the logger just before the apps are imported, so if you try to log even before than (for. e.g. from settings.py file), it will not work.

EDIT:

LOGGING config:

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'verbose': {
            'format': ('%(asctime)s [%(process)d] [%(levelname)s] '
                       'pathname=%(pathname)s lineno=%(lineno)s '
                       'funcname=%(funcName)s %(message)s'),
            'datefmt': '%Y-%m-%d %H:%M:%S'
        },
        'simple': {
            'format': '%(levelname)s %(message)s'
        }
    },
    'handlers': {
    'null': {
            'level': 'DEBUG',
            'class': 'logging.NullHandler',
    },
        'console': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
            'formatter': 'verbose'
        }
    },
    'loggers': {
    'ex_logger': {
            'handlers': ['console', ],
            'level': 'INFO',
        }
    }
}

adding following to settings.py won't log:

import logging
logger = logging.getLogger('ex_logger')
logger.info("core.settings logger")  # won't work 

adding to views.py should log:

from django.http import HttpResponse
import logging

logger = logging.getLogger('ex_logger')
logger.info("core.views logger")  # should work                                                                                                         

def url_please(request):
    logger.info("path: %s" % request.path)  # should work                                                                                               
    return HttpResponse(request.path)

Bowie

Answer 3

As stated in previous replies, the logger should be set up in the entry point to your app. In the case of a django based web server using gunicorn, that entry point is most likely the wsgi.py file. Try adding the required configuration to that file, e.g. setting the global basic logger:

import logging
import os

from dj_static import Cling

from django.core.wsgi import get_wsgi_application

os.environ.setdefault("DJANGO_SETTINGS_MODULE", "path.to.settings.py")

logging.basicConfig(
    level=logging.INFO,
    format="%(asctime)s %(name)s %(levelname)-8s %(message)s",
)

Deacon

Answer 4

I think if you drop a logger.error you would see something.

I had the same problem and it turns out heroku's settings tool breaks the pre-existing LOGGING setup. The logger you are using is not registered with django but is making its own way to the console using python's standard logging system.

Try doing:

django_heroku.settings(locals(), logging=False)

Or better yet, don't use it at all anymore since this package is no longer maintained anyway.

Helmholtz