1

I am running Python2.7, djangoappengine and AppEngine 1.6.5

My problem is that my logging.debug() messages aren't being consistently printed to the output. I've stripped my code back to a really simple homepage view

def home(request):
    logging.debug("Serving homepage")
    if request.user.is_authenticated():
        template = 'home-loggedin.html'
    else:
        template = 'home.html'
    return render_to_response(template, locals(), RequestContext(request))

The idea is that I would see "Serving homepage" consistently in the log output. However, it is only logged the first time and not on subsequent hits.

DEBUG    2012-04-27 17:33:02,616 views.py:8] Serving homepage
INFO     2012-04-27 17:33:02,711 dev_appserver.py:2891] "GET / HTTP/1.1" 200 -
INFO     2012-04-27 17:33:02,848 dev_appserver.py:2891] "GET /static/bootstrap/css/bootstrap.css HTTP/1.1" 200 -
[ .. Lots of 200 responses for my JS and CSS ..]
>> LOOK NO DEBUGGING LINE :(
INFO     2012-04-27 17:33:10,758 dev_appserver.py:2891] "GET / HTTP/1.1" 200 -
INFO     2012-04-27 17:33:10,844 dev_appserver.py:2891] "GET /static/bootstrap/css/bootstrap.css HTTP/1.1" 304 -
INFO     2012-04-27 17:33:10,854 dev_appserver.py:2891] "GET /static/bootstrap/css/bootstrap-responsive.css HTTP/1.1" 304 -
[ .. Lots of 304 Not Modified for my JS and CSS ..]

I'm not caching the view in my urlconf, I have memcached enabled in my settings.py but I'm not using it yet.

The actual pain I am feeling is in a module with more advanced logic where I am unable to follow the execution of the code due to the debug not being logged.

Any help appreciated

SimonMorris
  • 127
  • 1
  • 10
  • I haven't seen this problem - most likly the logging.debug() line is not executing. Is it possible memcache is actually working? Have you tried using a debugger to make sure that line is actually running? – dragonx Apr 27 '12 at 17:59
  • @dragonx Well - it does run that debug() line on the first load of the page. My guess was caching but I can't see any configuration where this would be enabled. I grepped through my settings.py and I haven't seen any evidence that it is being used, unless djangoappengine enables it by default. Debugging not my strong point but I think I'll be going there next. Thanks – SimonMorris Apr 27 '12 at 18:34
  • Interesting, I'm debugging in Eclipse/PyDev and the debugger is stopping inside my home() function so I reckon the problem is deeper into the logging library... I'll keep digging. – SimonMorris Apr 27 '12 at 19:01
  • ...and using the debugger I can see that something (appengine or djangoappengine) is forcing the logging level from 10 (logging.DEBUG) to 20 (logging.INFO) which is making me lose my lines. Simples! Thank you @dragonx – SimonMorris Apr 27 '12 at 19:08
  • learn to love the debugger! glad you figured it out! – dragonx Apr 28 '12 at 04:30

0 Answers0