Trying to find reason for 500 error when running a Django site in Nginx

Question

I have a Django site running being served by Nginx in a docker container, following the repository here.

The sample repo works great, but when I add my site, I get a 500 Internal Server Error. So now I am trying to debug this (or find any information about it at all).

I can log into the running docker instance and view the Nginx error.log file, which looks like:

2015/06/25 18:46:18 [debug] 15#0: epoll add event: fd:8 op:1 ev:00002001
2015/06/25 18:46:24 [debug] 15#0: post event 0000000000A2BDD0
2015/06/25 18:46:24 [debug] 15#0: delete posted event 0000000000A2BDD0
2015/06/25 18:46:24 [debug] 15#0: accept on 0.0.0.0:80, ready: 0
2015/06/25 18:46:24 [debug] 15#0: posix_memalign: 00000000009FB600:256 @16
2015/06/25 18:46:24 [debug] 15#0: *1 accept: 192.168.59.3 fd:11
2015/06/25 18:46:24 [debug] 15#0: posix_memalign: 0000000000A1C380:256 @16
2015/06/25 18:46:24 [debug] 15#0: *1 event timer add: 11: 60000:1435258044854
2015/06/25 18:46:24 [debug] 15#0: *1 reusable connection: 1
2015/06/25 18:46:24 [debug] 15#0: *1 epoll add event: fd:11 op:1 ev:80002001
2015/06/25 18:46:24 [debug] 15#0: *1 post event 0000000000A2BEA0
2015/06/25 18:46:24 [debug] 15#0: *1 delete posted event 0000000000A2BEA0
2015/06/25 18:46:24 [debug] 15#0: *1 http wait request handler
2015/06/25 18:46:24 [debug] 15#0: *1 malloc: 0000000000A1C490:1024
2015/06/25 18:46:24 [debug] 15#0: *1 recv: fd:11 370 of 1024
2015/06/25 18:46:24 [debug] 15#0: *1 reusable connection: 0
2015/06/25 18:46:24 [debug] 15#0: *1 posix_memalign: 0000000000A16140:4096 @16
2015/06/25 18:46:24 [debug] 15#0: *1 http process request line
2015/06/25 18:46:24 [debug] 15#0: *1 http request line: "GET / HTTP/1.1"
2015/06/25 18:46:24 [debug] 15#0: *1 http uri: "/"
2015/06/25 18:46:24 [debug] 15#0: *1 http args: ""
2015/06/25 18:46:24 [debug] 15#0: *1 http exten: ""
2015/06/25 18:46:24 [debug] 15#0: *1 posix_memalign: 0000000000A090A0:4096 @16
2015/06/25 18:46:24 [debug] 15#0: *1 http process request header line
2015/06/25 18:46:24 [debug] 15#0: *1 http header: "Host: 192.168.59.103:8888"
2015/06/25 18:46:24 [debug] 15#0: *1 http header: "User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.10; rv:38.0) Gecko/20100101 Firefox/38.0"
2015/06/25 18:46:24 [debug] 15#0: *1 http header: "Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8"
2015/06/25 18:46:24 [debug] 15#0: *1 http header: "Accept-Language: en-US,en;q=0.5"
2015/06/25 18:46:24 [debug] 15#0: *1 http header: "Accept-Encoding: gzip, deflate"
2015/06/25 18:46:24 [debug] 15#0: *1 http header: "Cookie: _ga=GA1.1.1071325028.1434557714"
2015/06/25 18:46:24 [debug] 15#0: *1 http header: "Connection: keep-alive"
2015/06/25 18:46:24 [debug] 15#0: *1 http header: "Cache-Control: max-age=0"
2015/06/25 18:46:24 [debug] 15#0: *1 http header done
2015/06/25 18:46:24 [debug] 15#0: *1 event timer del: 11: 1435258044854
2015/06/25 18:46:24 [debug] 15#0: *1 generic phase: 0
2015/06/25 18:46:24 [debug] 15#0: *1 rewrite phase: 1
2015/06/25 18:46:24 [debug] 15#0: *1 test location: "/"
2015/06/25 18:46:24 [debug] 15#0: *1 using configuration "/"
2015/06/25 18:46:24 [debug] 15#0: *1 http cl:-1 max:78643200
2015/06/25 18:46:24 [debug] 15#0: *1 rewrite phase: 3
2015/06/25 18:46:24 [debug] 15#0: *1 post rewrite phase: 4
2015/06/25 18:46:24 [debug] 15#0: *1 generic phase: 5
2015/06/25 18:46:24 [debug] 15#0: *1 generic phase: 6
2015/06/25 18:46:24 [debug] 15#0: *1 generic phase: 7
2015/06/25 18:46:24 [debug] 15#0: *1 access phase: 8
2015/06/25 18:46:24 [debug] 15#0: *1 access phase: 9
2015/06/25 18:46:24 [debug] 15#0: *1 access phase: 10
2015/06/25 18:46:24 [debug] 15#0: *1 access phase: 11
2015/06/25 18:46:24 [debug] 15#0: *1 post access phase: 12
2015/06/25 18:46:24 [debug] 15#0: *1 http init upstream, client timer: 0
2015/06/25 18:46:24 [debug] 15#0: *1 epoll add event: fd:11 op:3 ev:80002005
2015/06/25 18:46:24 [debug] 15#0: *1 http script copy: "QUERY_STRING"
2015/06/25 18:46:24 [debug] 15#0: *1 uwsgi param: "QUERY_STRING: "
2015/06/25 18:46:24 [debug] 15#0: *1 http script copy: "REQUEST_METHOD"
2015/06/25 18:46:24 [debug] 15#0: *1 http script var: "GET"
2015/06/25 18:46:24 [debug] 15#0: *1 uwsgi param: "REQUEST_METHOD: GET"
2015/06/25 18:46:24 [debug] 15#0: *1 http script copy: "CONTENT_TYPE"
2015/06/25 18:46:24 [debug] 15#0: *1 uwsgi param: "CONTENT_TYPE: "
2015/06/25 18:46:24 [debug] 15#0: *1 http script copy: "CONTENT_LENGTH"
2015/06/25 18:46:24 [debug] 15#0: *1 uwsgi param: "CONTENT_LENGTH: "
2015/06/25 18:46:24 [debug] 15#0: *1 http script copy: "REQUEST_URI"
2015/06/25 18:46:24 [debug] 15#0: *1 http script var: "/"
2015/06/25 18:46:24 [debug] 15#0: *1 uwsgi param: "REQUEST_URI: /"
2015/06/25 18:46:24 [debug] 15#0: *1 http script copy: "PATH_INFO"
2015/06/25 18:46:24 [debug] 15#0: *1 http script var: "/"
2015/06/25 18:46:24 [debug] 15#0: *1 uwsgi param: "PATH_INFO: /"
2015/06/25 18:46:24 [debug] 15#0: *1 http script copy: "DOCUMENT_ROOT"
2015/06/25 18:46:24 [debug] 15#0: *1 http script var: "/usr/share/nginx/html"
2015/06/25 18:46:24 [debug] 15#0: *1 uwsgi param: "DOCUMENT_ROOT: /usr/share/nginx/html"
2015/06/25 18:46:24 [debug] 15#0: *1 http script copy: "SERVER_PROTOCOL"
2015/06/25 18:46:24 [debug] 15#0: *1 http script var: "HTTP/1.1"
2015/06/25 18:46:24 [debug] 15#0: *1 uwsgi param: "SERVER_PROTOCOL: HTTP/1.1"
2015/06/25 18:46:24 [debug] 15#0: *1 http script copy: ""
2015/06/25 18:46:24 [debug] 15#0: *1 http script copy: "REMOTE_ADDR"
2015/06/25 18:46:24 [debug] 15#0: *1 http script var: "192.168.59.3"
2015/06/25 18:46:24 [debug] 15#0: *1 uwsgi param: "REMOTE_ADDR: 192.168.59.3"
2015/06/25 18:46:24 [debug] 15#0: *1 http script copy: "REMOTE_PORT"
2015/06/25 18:46:24 [debug] 15#0: *1 http script var: "64244"
2015/06/25 18:46:24 [debug] 15#0: *1 uwsgi param: "REMOTE_PORT: 64244"
2015/06/25 18:46:24 [debug] 15#0: *1 http script copy: "SERVER_PORT"
2015/06/25 18:46:24 [debug] 15#0: *1 http script var: "80"
2015/06/25 18:46:24 [debug] 15#0: *1 uwsgi param: "SERVER_PORT: 80"
2015/06/25 18:46:24 [debug] 15#0: *1 http script copy: "SERVER_NAME"
2015/06/25 18:46:24 [debug] 15#0: *1 http script var: ""
2015/06/25 18:46:24 [debug] 15#0: *1 uwsgi param: "SERVER_NAME: "
2015/06/25 18:46:24 [debug] 15#0: *1 uwsgi param: "HTTP_HOST: 192.168.59.103:8888"
2015/06/25 18:46:24 [debug] 15#0: *1 uwsgi param: "HTTP_USER_AGENT: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.10; rv:38.0) Gecko/20100101 Firefox/38.0"
2015/06/25 18:46:24 [debug] 15#0: *1 uwsgi param: "HTTP_ACCEPT: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8"
2015/06/25 18:46:24 [debug] 15#0: *1 uwsgi param: "HTTP_ACCEPT_LANGUAGE: en-US,en;q=0.5"
2015/06/25 18:46:24 [debug] 15#0: *1 uwsgi param: "HTTP_ACCEPT_ENCODING: gzip, deflate"
2015/06/25 18:46:24 [debug] 15#0: *1 uwsgi param: "HTTP_COOKIE: _ga=GA1.1.1071325028.1434557714"
2015/06/25 18:46:24 [debug] 15#0: *1 uwsgi param: "HTTP_CONNECTION: keep-alive"
2015/06/25 18:46:24 [debug] 15#0: *1 uwsgi param: "HTTP_CACHE_CONTROL: max-age=0"
2015/06/25 18:46:24 [debug] 15#0: *1 http cleanup add: 0000000000A17030
2015/06/25 18:46:24 [debug] 15#0: *1 get rr peer, try: 1
2015/06/25 18:46:24 [debug] 15#0: *1 socket 12
2015/06/25 18:46:24 [debug] 15#0: *1 epoll add connection: fd:12 ev:80002005
2015/06/25 18:46:24 [debug] 15#0: *1 connect to unix:/opt/django/app.sock, fd:12 #2
2015/06/25 18:46:24 [debug] 15#0: *1 connected
2015/06/25 18:46:24 [debug] 15#0: *1 http upstream connect: 0
2015/06/25 18:46:24 [debug] 15#0: *1 posix_memalign: 0000000000A1C8A0:128 @16
2015/06/25 18:46:24 [debug] 15#0: *1 http upstream send request
2015/06/25 18:46:24 [debug] 15#0: *1 chain writer buf fl:0 s:641
2015/06/25 18:46:24 [debug] 15#0: *1 chain writer in: 0000000000A17068
2015/06/25 18:46:24 [debug] 15#0: *1 writev: 641
2015/06/25 18:46:24 [debug] 15#0: *1 chain writer out: 0000000000000000
2015/06/25 18:46:24 [debug] 15#0: *1 event timer add: 12: 60000:1435258044854
2015/06/25 18:46:24 [debug] 15#0: *1 http finalize request: -4, "/?" a:1, c:2
2015/06/25 18:46:24 [debug] 15#0: *1 http request count:2 blk:0
2015/06/25 18:46:24 [debug] 15#0: *1 post event 0000000000A3F6B0
2015/06/25 18:46:24 [debug] 15#0: *1 post event 0000000000A3F718
2015/06/25 18:46:24 [debug] 15#0: *1 delete posted event 0000000000A3F718
2015/06/25 18:46:24 [debug] 15#0: *1 http upstream request: "/?"
2015/06/25 18:46:24 [debug] 15#0: *1 http upstream dummy handler
2015/06/25 18:46:24 [debug] 15#0: *1 delete posted event 0000000000A3F6B0
2015/06/25 18:46:24 [debug] 15#0: *1 http run request: "/?"
2015/06/25 18:46:24 [debug] 15#0: *1 http upstream check client, write event:1, "/"
2015/06/25 18:46:24 [debug] 15#0: *1 http upstream recv(): -1 (11: Resource temporarily unavailable)
2015/06/25 18:46:24 [debug] 15#0: *1 post event 0000000000A3F718
2015/06/25 18:46:24 [debug] 15#0: *1 delete posted event 0000000000A3F718
2015/06/25 18:46:24 [debug] 15#0: *1 http upstream request: "/?"
2015/06/25 18:46:24 [debug] 15#0: *1 http upstream dummy handler
2015/06/25 18:46:24 [debug] 15#0: *1 post event 0000000000A2BF08
2015/06/25 18:46:24 [debug] 15#0: *1 post event 0000000000A3F718
2015/06/25 18:46:24 [debug] 15#0: *1 delete posted event 0000000000A3F718
2015/06/25 18:46:24 [debug] 15#0: *1 http upstream request: "/?"
2015/06/25 18:46:24 [debug] 15#0: *1 http upstream dummy handler
2015/06/25 18:46:24 [debug] 15#0: *1 delete posted event 0000000000A2BF08
2015/06/25 18:46:24 [debug] 15#0: *1 http upstream request: "/?"
2015/06/25 18:46:24 [debug] 15#0: *1 http upstream process header
2015/06/25 18:46:24 [debug] 15#0: *1 malloc: 00000000009FFCF0:4096
2015/06/25 18:46:24 [debug] 15#0: *1 recv: fd:12 104 of 4096
2015/06/25 18:46:24 [debug] 15#0: *1 http uwsgi status 500 "500 Internal Server Error"
2015/06/25 18:46:24 [debug] 15#0: *1 http uwsgi header: "Connection: close"
2015/06/25 18:46:24 [debug] 15#0: *1 http uwsgi header: "Content-Type: text/plain"
2015/06/25 18:46:24 [debug] 15#0: *1 http uwsgi header done
2015/06/25 18:46:24 [debug] 15#0: *1 xslt filter header
2015/06/25 18:46:24 [debug] 15#0: *1 charset: "" > "utf-8"
2015/06/25 18:46:24 [debug] 15#0: *1 HTTP/1.1 500 Internal Server Error
Server: nginx/1.6.2
Date: Thu, 25 Jun 2015 18:46:24 GMT
Content-Type: text/plain; charset=utf-8
Transfer-Encoding: chunked
Connection: keep-alive

2015/06/25 18:46:24 [debug] 15#0: *1 write new buf t:1 f:0 0000000000A09C80, pos 0000000000A09C80, size: 189 file: 0, size: 0
2015/06/25 18:46:24 [debug] 15#0: *1 http write filter: l:0 f:0 s:189
2015/06/25 18:46:24 [debug] 15#0: *1 http cacheable: 0
2015/06/25 18:46:24 [debug] 15#0: *1 http upstream process upstream
2015/06/25 18:46:24 [debug] 15#0: *1 pipe read upstream: 1
2015/06/25 18:46:24 [debug] 15#0: *1 pipe preread: 21
2015/06/25 18:46:24 [debug] 15#0: *1 readv: 1:3992
2015/06/25 18:46:24 [debug] 15#0: *1 pipe recv chain: 0
2015/06/25 18:46:24 [debug] 15#0: *1 pipe buf free s:0 t:1 f:0 00000000009FFCF0, pos 00000000009FFD43, size: 21 file: 0, size: 0
2015/06/25 18:46:24 [debug] 15#0: *1 pipe length: -1
2015/06/25 18:46:24 [debug] 15#0: *1 input buf #0
2015/06/25 18:46:24 [debug] 15#0: *1 pipe write downstream: 1
2015/06/25 18:46:24 [debug] 15#0: *1 pipe write downstream flush in
2015/06/25 18:46:24 [debug] 15#0: *1 http output filter "/?"
2015/06/25 18:46:24 [debug] 15#0: *1 http copy filter: "/?"
2015/06/25 18:46:24 [debug] 15#0: *1 image filter
2015/06/25 18:46:24 [debug] 15#0: *1 xslt filter body
2015/06/25 18:46:24 [debug] 15#0: *1 http postpone filter "/?" 0000000000A17120
2015/06/25 18:46:24 [debug] 15#0: *1 http chunk: 21
2015/06/25 18:46:24 [debug] 15#0: *1 write old buf t:1 f:0 0000000000A09C80, pos 0000000000A09C80, size: 189 file: 0, size: 0
2015/06/25 18:46:24 [debug] 15#0: *1 write new buf t:1 f:0 0000000000A09F50, pos 0000000000A09F50, size: 4 file: 0, size: 0
2015/06/25 18:46:24 [debug] 15#0: *1 write new buf t:1 f:0 00000000009FFCF0, pos 00000000009FFD43, size: 21 file: 0, size: 0
2015/06/25 18:46:24 [debug] 15#0: *1 write new buf t:0 f:0 0000000000000000, pos 00000000004B2EBD, size: 2 file: 0, size: 0
2015/06/25 18:46:24 [debug] 15#0: *1 http write filter: l:0 f:0 s:216
2015/06/25 18:46:24 [debug] 15#0: *1 http copy filter: 0 "/?"
2015/06/25 18:46:24 [debug] 15#0: *1 pipe write downstream done
2015/06/25 18:46:24 [debug] 15#0: *1 event timer: 12, old: 1435258044854, new: 1435258044855
2015/06/25 18:46:24 [debug] 15#0: *1 http upstream exit: 0000000000000000
2015/06/25 18:46:24 [debug] 15#0: *1 finalize http upstream request: 0
2015/06/25 18:46:24 [debug] 15#0: *1 finalize http uwsgi request
2015/06/25 18:46:24 [debug] 15#0: *1 free rr peer 1 0
2015/06/25 18:46:24 [debug] 15#0: *1 close http upstream connection: 12
2015/06/25 18:46:24 [debug] 15#0: *1 free: 0000000000A1C8A0, unused: 48
2015/06/25 18:46:24 [debug] 15#0: *1 event timer del: 12: 1435258044854
2015/06/25 18:46:24 [debug] 15#0: *1 reusable connection: 0
2015/06/25 18:46:24 [debug] 15#0: *1 http upstream temp fd: -1
2015/06/25 18:46:24 [debug] 15#0: *1 http output filter "/?"
2015/06/25 18:46:24 [debug] 15#0: *1 http copy filter: "/?"
2015/06/25 18:46:24 [debug] 15#0: *1 image filter
2015/06/25 18:46:24 [debug] 15#0: *1 xslt filter body
2015/06/25 18:46:24 [debug] 15#0: *1 http postpone filter "/?" 00007FFF339BF280
2015/06/25 18:46:24 [debug] 15#0: *1 http chunk: 0
2015/06/25 18:46:24 [debug] 15#0: *1 posix_memalign: 0000000000A00D00:4096 @16
2015/06/25 18:46:24 [debug] 15#0: *1 write old buf t:1 f:0 0000000000A09C80, pos 0000000000A09C80, size: 189 file: 0, size: 0
2015/06/25 18:46:24 [debug] 15#0: *1 write old buf t:1 f:0 0000000000A09F50, pos 0000000000A09F50, size: 4 file: 0, size: 0
2015/06/25 18:46:24 [debug] 15#0: *1 write old buf t:1 f:0 00000000009FFCF0, pos 00000000009FFD43, size: 21 file: 0, size: 0
2015/06/25 18:46:24 [debug] 15#0: *1 write old buf t:0 f:0 0000000000000000, pos 00000000004B2EBD, size: 2 file: 0, size: 0
2015/06/25 18:46:24 [debug] 15#0: *1 write new buf t:0 f:0 0000000000000000, pos 00000000004B2EBA, size: 5 file: 0, size: 0
2015/06/25 18:46:24 [debug] 15#0: *1 http write filter: l:1 f:0 s:221
2015/06/25 18:46:24 [debug] 15#0: *1 http write filter limit 0
2015/06/25 18:46:24 [debug] 15#0: *1 writev: 221
2015/06/25 18:46:24 [debug] 15#0: *1 http write filter 0000000000000000
2015/06/25 18:46:24 [debug] 15#0: *1 http copy filter: 0 "/?"
2015/06/25 18:46:24 [debug] 15#0: *1 http finalize request: 0, "/?" a:1, c:1
2015/06/25 18:46:24 [debug] 15#0: *1 set http keepalive handler
2015/06/25 18:46:24 [debug] 15#0: *1 http close request
2015/06/25 18:46:24 [debug] 15#0: *1 http log handler
2015/06/25 18:46:24 [debug] 15#0: *1 free: 00000000009FFCF0
2015/06/25 18:46:24 [debug] 15#0: *1 free: 0000000000A16140, unused: 0
2015/06/25 18:46:24 [debug] 15#0: *1 free: 0000000000A090A0, unused: 56
2015/06/25 18:46:24 [debug] 15#0: *1 free: 0000000000A00D00, unused: 3790
2015/06/25 18:46:24 [debug] 15#0: *1 free: 0000000000A1C490
2015/06/25 18:46:24 [debug] 15#0: *1 hc free: 0000000000000000 0
2015/06/25 18:46:24 [debug] 15#0: *1 hc busy: 0000000000000000 0
2015/06/25 18:46:24 [debug] 15#0: *1 tcp_nodelay
2015/06/25 18:46:24 [debug] 15#0: *1 reusable connection: 1
2015/06/25 18:46:24 [debug] 15#0: *1 event timer add: 11: 65000:1435258049855
2015/06/25 18:46:24 [debug] 15#0: *1 post event 0000000000A2BEA0
2015/06/25 18:46:24 [debug] 15#0: *1 delete posted event 0000000000A2BEA0
2015/06/25 18:46:24 [debug] 15#0: *1 http keepalive handler
2015/06/25 18:46:24 [debug] 15#0: *1 malloc: 0000000000A1C490:1024
2015/06/25 18:46:24 [debug] 15#0: *1 recv: fd:11 -1 of 1024
2015/06/25 18:46:24 [debug] 15#0: *1 recv() not ready (11: Resource temporarily unavailable)
2015/06/25 18:46:24 [debug] 15#0: *1 free: 0000000000A1C490

I see the HTTP/1.1 500 Internal Server Error line, but there doesn't seem to be any more valuable information. I was expecting something more specific related to my Django app, etc.

Does anyone know where I can look to find where my 500 error is occurring? I am using the same Nginx configuration file that is found here, only I added the line error_log /var/log/nginx/mysite/error.log debug; to the server { } section.

Any advice would be greatly appreciated. I'm just beginning to learn Nginx.

Answer 1

You'll want to check the logs from your Django application, not nginx. Checkout the uwsgi logging documentation to learn how to specify where the logs are written to. Then do tail -f /tmp/mylog.log and refresh your browser.