Logo Questions Linux Laravel Mysql Ubuntu Git Menu
 

Django with gunicorn and nginx: HTTP 500 not appearing in log files

I have a Django app running on a gunicorn server with an nginx up front. I need to diagnose a production failure with an HTTP 500 outcome, but the error log files do not contain the information I would expect. Thusly:

  • gunicorn has setting errorlog = "/somepath/gunicorn-errors.log"
  • nginx has setting error_log /somepath/nginx-errors.log;
  • My app has an InternalErrorView the dispatch of which does an unconditional raise Exception("Just for testing.") That view is mapped to URL /fail_now
  • I have not modified handler500
  • When I run my app with DEBUG=True and have my browser request /fail_now, I see the usual Django error screen alright, including the "Just for testing." message. Fine.
  • When I run my app with DEBUG=False, I get a response that consists merely of <h1>Server Error (500)</h1>, as expected. Fine.
  • However, when I look into gunicorn-errors.log, there is no entry for this HTTP 500 event at all. Why? How can I get it? I would like to get a traceback.
  • Likewise in nginx-errors.log: No trace of a 500 or the /fail_now URL. Why?

Bonus question: When I compare this to my original production problem, I am getting a different response there: a 9-line document with <h1><p>Internal Server Error</p></h1> as the central message. Why?

Bonus question 2: When I copy my database contents to my staging server (which is identical in configuration to the production server) and set DEBUG=True in Django there, /fail_now works as expected, but my original problem still shows up as <h1><p>Internal Server Error</p></h1>. WTF?

like image 808
Lutz Prechelt Avatar asked Aug 24 '16 09:08

Lutz Prechelt


1 Answers

OK, it took long, but I found it all out:

  • The <h1>Server Error (500)</h1> response comes from Django's django.views.defaults.server_error (if no 500.html template exists).
  • The <h1><p>Internal Server Error</p></h1> from the bonus question comes from gunicorn's gunicorn.workers.base.handle_error.
  • nginx logs the 500 error in the access log file, not the error log file; presumably because it was not nginx itself that failed.
  • For /fail_now, gunicorn will also log the problem in the access log, not the error log; again presumably because gunicorn as such has not failed, only the application has.
  • My original problem did actually appear in the gunicorn error log, but I had never searched for it there, because I had introduced the log file only freshly (I had relied on Docker logs output before, which is pretty confusing) and assumed it would be better to use the very explicit InternalErrorView for initial debugging. (This was an idea that was wrong in an interesting way.)
  • However, my actual programming error involved sending a response with a Content-Disposition header (generated in Django code) like this: attachment; filename="dag-wönnegården.pdf". The special characters are apparently capable of making gunicorn stumble when it processes this response.

Writing the question helped me considerably with diagnosing this situation. Now if this response helps somebody else, the StackOverflow magic has worked once again.

like image 132
Lutz Prechelt Avatar answered Oct 20 '22 00:10

Lutz Prechelt