Nginx keep crashes when it is used in uwsgi

In my setup, i have nginx proxy in different machine, nginx server and
uwsgi
service. Once Nginx server receives the request from the proxy, it
invokes
the uwsgi call to using uwsgi socket, uwsgi module replies the request,
after receiving the response from the uwsgi service nginx server
forwards
the response to the proxy, after transaction completes, nginx trying to
close the socket connection and it crashes…

Nginx is not generating the backtrace, it is getting killed and worker
threads are getting suspended… would you kindly help me out how to
proceed
further to debug the issue or fix the crash…

thanks
amaran

Posted at Nginx Forum:

Hello!

On Thu, Oct 30, 2014 at 08:17:41AM -0400, arulmarans wrote:

In my setup, i have nginx proxy in different machine, nginx server and uwsgi
service. Once Nginx server receives the request from the proxy, it invokes
the uwsgi call to using uwsgi socket, uwsgi module replies the request,
after receiving the response from the uwsgi service nginx server forwards
the response to the proxy, after transaction completes, nginx trying to
close the socket connection and it crashes…

Nginx is not generating the backtrace, it is getting killed and worker
threads are getting suspended… would you kindly help me out how to proceed
further to debug the issue or fix the crash…

Some debugging hints can be found here:


Maxim D.
http://nginx.org/

I have already gone through that link, still gdb was not catching core
dump…

Log snippet:

2014/10/30 13:54:07 [debug] 16259#0: *2 http static fd: 11
2014/10/30 13:54:07 [debug] 16259#0: *2 http set discard body
2014/10/30 13:54:07 [debug] 16259#0: *2 HTTP/1.1 200 OK^M
Server: nginx/1.7.6^M
Date: Thu, 30 Oct 2014 08:24:07 GMT^M
Content-Type: text/html^M
Content-Length: 1249^M
Last-Modified: Thu, 28 Aug 2014 12:20:24 GMT^M
Connection: keep-alive^M
ETag: “53ff1e88-4e1”^M
Access-Control-Allow-Origin: *^M
Access-Control-Allow-Methods: GET, OPTIONS, POST^M
Access-Control-Allow-Headers: origin, authorization, accept^M
Accept-Ranges: bytes^M

2014/10/30 13:54:07 [debug] 16259#0: *2 write new buf t:1 f:0
00000000025B6B50, pos 00000000025B6B50, size: 381 file: 0, size: 0
2014/10/30 13:54:07 [debug] 16259#0: *2 http write filter: l:0 f:0 s:381
2014/10/30 13:54:07 [debug] 16259#0: *2 http output filter
“/grafana_prod.html?”
2014/10/30 13:54:07 [debug] 16259#0: *2 http copy filter:
“/grafana_prod.html?”
2014/10/30 13:54:07 [debug] 16259#0: *2 http postpone filter
“/grafana_prod.html?” 00007FFFD64F0CB0
2014/10/30 13:54:07 [debug] 16259#0: *2 write old buf t:1 f:0
00000000025B6B50, pos 00000000025B6B50, size: 381 file: 0, size: 0
2014/10/30 13:54:07 [debug] 16259#0: *2 write new buf t:0 f:1
0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 1249
2014/10/30 13:54:07 [debug] 16259#0: *2 http write filter: l:1 f:0
s:1630
2014/10/30 13:54:07 [debug] 16259#0: *2 http write filter limit 0
2014/10/30 13:54:07 [debug] 16259#0: *2 writev: 381
2014/10/30 13:54:07 [debug] 16259#0: *2 sendfile: @0 1249
2014/10/30 13:54:07 [debug] 16259#0: *2 sendfile: 1249, @0 1249:1249
2014/10/30 13:54:07 [debug] 16259#0: *2 http write filter
0000000000000000
2014/10/30 13:54:07 [debug] 16259#0: *2 http copy filter: 0
“/grafana_prod.html?”
2014/10/30 13:54:07 [debug] 16259#0: *2 http finalize request: 0,
“/grafana_prod.html?” a:1, c:1
2014/10/30 13:54:07 [debug] 16259#0: *2 set http keepalive handler
2014/10/30 13:54:07 [debug] 16259#0: *2 http close request
2014/10/30 13:54:07 [debug] 16259#0: *2 http log handler
2014/10/30 13:54:07 [debug] 16259#0: *2 run cleanup: 00000000025BF6A0
2014/10/30 13:54:07 [debug] 16259#0: *2 file cleanup: fd:11
2014/10/30 13:54:07 [debug] 16259#0: *2 free: 00000000025BE6C0, unused:
8
2014/10/30 13:54:07 [debug] 16259#0: *2 free: 00000000025B6980, unused:
2899
2014/10/30 13:54:07 [debug] 16259#0: *2 free: 00000000025C8610

2014/10/30 13:54:07 [debug] 16259#0: *2 free: 00000000025C8610
2014/10/30 13:54:07 [debug] 16259#0: *2 free: 00000000025B2640, unused:
0
2014/10/30 13:54:07 [debug] 16259#0: *2 free: 00000000025C8500, unused:
120
2014/10/30 13:54:07 [debug] 16259#0: timer delta: 1
2014/10/30 13:54:07 [debug] 16259#0: worker cycle
2014/10/30 13:54:07 [debug] 16259#0: epoll timer: -1
2014/10/30 13:54:17 [debug] 16392#0: bind() 0.0.0.0:80 #6
2014/10/30 13:54:17 [debug] 16392#0: bind() 0.0.0.0:8090 #7
2014/10/30 13:54:17 [notice] 16392#0: OS: Linux
2.6.32-358.18.1.el6.x86_64
2014/10/30 13:54:17 [notice] 16392#0: getrlimit(RLIMIT_NOFILE):
8192:8192
2014/10/30 13:54:17 [debug] 16393#0: write: 8, 00007FFF049D4300, 6, 0
2014/10/30 13:54:17 [debug] 16393#0: write: 8, 00007FFF049D4300, 6, 0
2014/10/30 13:54:17 [debug] 16393#0: setproctitle: “nginx: master
process
/idap/activeRelease/nginx/sbin/nginx -c
/idap/activeRelease/conf/nginx/idap_gp_nginx.conf”
2014/10/30 13:54:17 [notice] 16393#0: start worker processes
2014/10/30 13:54:17 [debug] 16393#0: channel 3:8
2014/10/30 13:54:17 [notice] 16393#0: start worker process 16394
2014/10/30 13:54:17 [debug] 16393#0: sigsuspend
2014/10/30 13:54:17 [debug] 16394#0: malloc: 0000000000D03EB0:6144
2014/10/30 13:54:17 [debug] 16394#0: malloc: 00007F9DCDD3E010:212992
2014/10/30 13:54:17 [debug] 16394#0: malloc: 0000000000D223C0:106496
2014/10/30 13:54:17 [debug] 16394#0: malloc: 0000000000D3C3D0:106496
2014/10/30 13:54:17 [debug] 16394#0: epoll add event: fd:6 op:1
ev:00002001
2014/10/30 13:54:17 [debug] 16394#0: epoll add event: fd:7 op:1
ev:00002001
2014/10/30 13:54:17 [debug] 16394#0: epoll add event: fd:8 op:1
ev:00002001
2014/10/30 13:54:17 [debug] 16394#0: setproctitle: “nginx: worker
process”
2014/10/30 13:54:17 [debug] 16394#0: worker cycle

Posted at Nginx Forum:

Hello!

On Thu, Oct 30, 2014 at 10:54:38AM -0400, arulmarans wrote:

Hi Maxim D.,

I have gone through those steps, still i was not able to catch the backtrace
in the gdb.

You may start with providing “nginx -V” output, as recommended at
Debugging | NGINX.

[…]

2014/10/30 13:54:07 [debug] 16259#0: *2 event timer del: 10: 1414657522682
2014/10/30 13:54:07 [debug] 16259#0: *2 reusable connection: 0
2014/10/30 13:54:07 [debug] 16259#0: *2 free: 00000000025C8610
2014/10/30 13:54:07 [debug] 16259#0: *2 free: 00000000025B2640, unused: 0
2014/10/30 13:54:07 [debug] 16259#0: *2 free: 00000000025C8500, unused: 120
2014/10/30 13:54:07 [debug] 16259#0: timer delta: 1
2014/10/30 13:54:07 [debug] 16259#0: worker cycle
2014/10/30 13:54:07 [debug] 16259#0: epoll timer: -1

… here nginx finishes processing of a connection, and goes to
the kernel, waiting for more connections…

2014/10/30 13:54:17 [debug] 16392#0: bind() 0.0.0.0:80 #6
2014/10/30 13:54:17 [debug] 16392#0: bind() 0.0.0.0:8090 #7
2014/10/30 13:54:17 [notice] 16392#0: using the “epoll” event method
2014/10/30 13:54:17 [debug] 16392#0: counter: 00007F9DCDF92080, 1
2014/10/30 13:54:17 [notice] 16392#0: nginx/1.7.6
2014/10/30 13:54:17 [notice] 16392#0: OS: Linux 2.6.32-358.18.1.el6.x86_64
2014/10/30 13:54:17 [notice] 16392#0: getrlimit(RLIMIT_NOFILE): 8192:8192
2014/10/30 13:54:17 [debug] 16393#0: write: 8, 00007FFF049D4300, 6, 0
===>Restarted (I have monitor proceess whenever it crashes it will be
restarted)

… and then it’s magically restarted, including master process
which does mostly nothing but monitors worker process - in
particular, to restart them if needed.

From the log I suspect that it’s your monitor process which does
the wrong thing. You may want to try switching it off.


Maxim D.
http://nginx.org/

Thanks a lot Maxim,you identified the issue (Monitd is the issue), after
stopping the monit i have not faced the issue. Thanks for the prompt and
trust on the Nginx…

I have used following configurations:

server
{
listen 8090;
server_name uwsgi;

   add_header Access-Control-Allow-Origin "*";
   add_header Access-Control-Allow-Methods "GET, OPTIONS, POST";
   add_header Access-Control-Allow-Headers "origin, authorization,

accept";
# Django media
location /media
{
alias
/usr/lib/python2.6/site-packages/django/contrib/admin/media;
}
location /static
{
alias /idap/Release/build/gp/webapp/content;
}
# Finally, send all non-media requests to the Django server.
location /
{
uwsgi_pass unix:/var/uwsgi/app.sock;
include /idap/activeRelease/conf/uwsgi/uwsgi_params;
}
}


[root@Stage03 ~]# /idap/activeRelease/nginx/sbin/nginx -V -c
/idap/activeRelease/conf/nginx/idap_gp_nginx.conf
nginx version: nginx/1.7.6
configure arguments: --prefix=/home/amaran/src/idap/build
–error-log-path=/ilogs/nginx/error.log
–http-log-path=/ilogs/nginx/access/access.log
–http-client-body-temp-path=/ilogs/nginx/cbdy
–http-proxy-temp-path=/ilogs/nginx/proxy
–http-fastcgi-temp-path=/ilogs/nginx/fastcgi
–http-uwsgi-temp-path=/ilogs/nginx/uwsgi
–http-scgi-temp-path=/ilogs/nginx/scgi
–pid-path=/idap/activeRelease/tmp/pid
–lock-path=/idap/activeRelease/tmp/lock --with-pcre=…/pcre-8.36
–with-debug --add-module=nginx-backtrace-master/
[root@Stage03 ~]# /idap/activeRelease/nginx/sbin/nginx -V -c
/idap/activeRelease/conf/nginx/idap_gp_nginx.conf

Posted at Nginx Forum:

Hi Maxim D.,

I have gone through those steps, still i was not able to catch the
backtrace
in the gdb.

log snippet:
014/10/30 13:54:07 [debug] 16259#0: *2 posix_memalign:
00000000025B6980:4096
@16
2014/10/30 13:54:07 [debug] 16259#0: *2 add cleanup: 00000000025BF6A0
2014/10/30 13:54:07 [debug] 16259#0: *2 http static fd: 11
2014/10/30 13:54:07 [debug] 16259#0: *2 http set discard body
2014/10/30 13:54:07 [debug] 16259#0: *2 HTTP/1.1 200 OK^M
Server: nginx/1.7.6^M
Date: Thu, 30 Oct 2014 08:24:07 GMT^M
Content-Type: text/html^M
Content-Length: 1249^M
Last-Modified: Thu, 28 Aug 2014 12:20:24 GMT^M
Connection: keep-alive^M
ETag: “53ff1e88-4e1”^M
Access-Control-Allow-Origin: *^M
Access-Control-Allow-Methods: GET, OPTIONS, POST^M
Access-Control-Allow-Headers: origin, authorization, accept^M
Accept-Ranges: bytes^M

2014/10/30 13:54:07 [debug] 16259#0: *2 write new buf t:1 f:0
00000000025B6B50, pos 00000000025B6B50, size: 381 file: 0, size: 0
2014/10/30 13:54:07 [debug] 16259#0: *2 http write filter: l:0 f:0 s:381
2014/10/30 13:54:07 [debug] 16259#0: *2 http output filter
“/grafana_prod.html?”
2014/10/30 13:54:07 [debug] 16259#0: *2 http copy filter:
“/grafana_prod.html?”
2014/10/30 13:54:07 [debug] 16259#0: *2 http postpone filter
“/grafana_prod.html?” 00007FFFD64F0CB0
2014/10/30 13:54:07 [debug] 16259#0: *2 write old buf t:1 f:0
00000000025B6B50, pos 00000000025B6B50, size: 381 file: 0, size: 0
2014/10/30 13:54:07 [debug] 16259#0: *2 write new buf t:0 f:1
0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 1249
2014/10/30 13:54:07 [debug] 16259#0: *2 http write filter: l:1 f:0
s:1630
2014/10/30 13:54:07 [debug] 16259#0: *2 http write filter limit 0
2014/10/30 13:54:07 [debug] 16259#0: *2 writev: 381
2014/10/30 13:54:07 [debug] 16259#0: *2 sendfile: @0 1249
2014/10/30 13:54:07 [debug] 16259#0: *2 sendfile: 1249, @0 1249:1249
2014/10/30 13:54:07 [debug] 16259#0: *2 http write filter
0000000000000000
2014/10/30 13:54:07 [debug] 16259#0: *2 http copy filter: 0
“/grafana_prod.html?”
2014/10/30 13:54:07 [debug] 16259#0: *2 set http keepalive handler
2014/10/30 13:54:07 [debug] 16259#0: *2 http close request
2014/10/30 13:54:07 [debug] 16259#0: *2 http log handler
2014/10/30 13:54:07 [debug] 16259#0: *2 run cleanup: 00000000025BF6A0
2014/10/30 13:54:07 [debug] 16259#0: *2 file cleanup: fd:11
2014/10/30 13:54:07 [debug] 16259#0: *2 free: 00000000025BE6C0, unused:
8
2014/10/30 13:54:07 [debug] 16259#0: *2 free: 00000000025B6980, unused:
2899
2014/10/30 13:54:07 [debug] 16259#0: *2 free: 00000000025C8610
2014/10/30 13:54:07 [debug] 16259#0: *2 hc free: 0000000000000000 0
2014/10/30 13:54:07 [debug] 16259#0: *2 hc busy: 0000000000000000 0
2014/10/30 13:54:07 [debug] 16259#0: *2 tcp_nodelay
2014/10/30 13:54:07 [debug] 16259#0: *2 reusable connection: 1
2014/10/30 13:54:07 [debug] 16259#0: *2 event timer add: 10:
75000:1414657522682
2014/10/30 13:54:07 [debug] 16259#0: *2 post event 00000000025DB560
2014/10/30 13:54:07 [debug] 16259#0: timer delta: 1
2014/10/30 13:54:07 [debug] 16259#0: posted event 00000000025DB560
2014/10/30 13:54:07 [debug] 16259#0: *2 delete posted event
00000000025DB560
2014/10/30 13:54:07 [debug] 16259#0: *2 http keepalive handler
2014/10/30 13:54:07 [debug] 16259#0: *2 malloc: 00000000025C8610:1024
2014/10/30 13:54:07 [debug] 16259#0: *2 recv: fd:10 -1 of 1024
2014/10/30 13:54:07 [debug] 16259#0: *2 recv() not ready (11: Resource
temporarily unavailable)
2014/10/30 13:54:07 [debug] 16259#0: *2 free: 00000000025C8610
2014/10/30 13:54:07 [debug] 16259#0: worker cycle
2014/10/30 13:54:07 [debug] 16259#0: epoll timer: 74999
2014/10/30 13:54:07 [debug] 16259#0: epoll: fd:3 ev:2001
d:00007F1E6E9F1280
2014/10/30 13:54:07 [debug] 16259#0: *1 http keepalive handler
2014/10/30 13:54:07 [debug] 16259#0: *1 malloc: 00000000025C8610:1024
2014/10/30 13:54:07 [debug] 16259#0: *1 recv: fd:3 0 of 1024
2014/10/30 13:54:07 [info] 16259#0: *1 client 172.27.5.166 closed
keepalive
connection
2014/10/30 13:54:07 [debug] 16259#0: *1 close http connection: 3
2014/10/30 13:54:07 [debug] 16259#0: *1 event timer del: 3:
1414657522681
2014/10/30 13:54:07 [debug] 16259#0: *1 reusable connection: 0
2014/10/30 13:54:07 [debug] 16259#0: *1 free: 00000000025C8610
2014/10/30 13:54:07 [debug] 16259#0: *1 free: 00000000025B23D0, unused:
0
2014/10/30 13:54:07 [debug] 16259#0: *1 free: 00000000025B2530, unused:
120
2014/10/30 13:54:07 [debug] 16259#0: timer delta: 2
2014/10/30 13:54:07 [debug] 16259#0: worker cycle
2014/10/30 13:54:07 [debug] 16259#0: *1 malloc: 00000000025C8610:1024
2014/10/30 13:54:07 [debug] 16259#0: *1 recv: fd:3 0 of 1024
2014/10/30 13:54:07 [info] 16259#0: *1 client 172.27.5.166 closed
keepalive
connection
2014/10/30 13:54:07 [debug] 16259#0: *1 close http connection: 3
2014/10/30 13:54:07 [debug] 16259#0: *1 event timer del: 3:
1414657522681
2014/10/30 13:54:07 [debug] 16259#0: *1 reusable connection: 0
2014/10/30 13:54:07 [debug] 16259#0: *1 free: 00000000025C8610
2014/10/30 13:54:07 [debug] 16259#0: *1 free: 00000000025B23D0, unused:
0
2014/10/30 13:54:07 [debug] 16259#0: *1 free: 00000000025B2530, unused:
120
2014/10/30 13:54:07 [debug] 16259#0: timer delta: 2
2014/10/30 13:54:07 [debug] 16259#0: worker cycle
2014/10/30 13:54:07 [debug] 16259#0: epoll timer: 74998
2014/10/30 13:54:07 [debug] 16259#0: epoll: fd:10 ev:2001
d:00007F1E6E9F1350
2014/10/30 13:54:07 [debug] 16259#0: *2 http keepalive handler
2014/10/30 13:54:07 [debug] 16259#0: *2 malloc: 00000000025C8610:1024
2014/10/30 13:54:07 [debug] 16259#0: *2 recv: fd:10 0 of 1024
2014/10/30 13:54:07 [info] 16259#0: *2 client 172.27.5.166 closed
keepalive
connection
2014/10/30 13:54:07 [debug] 16259#0: *2 close http connection: 10
2014/10/30 13:54:07 [debug] 16259#0: *2 event timer del: 10:
1414657522682
2014/10/30 13:54:07 [debug] 16259#0: *2 reusable connection: 0
2014/10/30 13:54:07 [debug] 16259#0: *2 free: 00000000025C8610
2014/10/30 13:54:07 [debug] 16259#0: *2 free: 00000000025B2640, unused:
0
2014/10/30 13:54:07 [debug] 16259#0: *2 free: 00000000025C8500, unused:
120
2014/10/30 13:54:07 [debug] 16259#0: timer delta: 1
2014/10/30 13:54:07 [debug] 16259#0: worker cycle
2014/10/30 13:54:07 [debug] 16259#0: epoll timer: -1
2014/10/30 13:54:17 [debug] 16392#0: bind() 0.0.0.0:80 #6
2014/10/30 13:54:17 [debug] 16392#0: bind() 0.0.0.0:8090 #7
2014/10/30 13:54:17 [notice] 16392#0: using the “epoll” event method
2014/10/30 13:54:17 [debug] 16392#0: counter: 00007F9DCDF92080, 1
2014/10/30 13:54:17 [notice] 16392#0: nginx/1.7.6
2014/10/30 13:54:17 [notice] 16392#0: OS: Linux
2.6.32-358.18.1.el6.x86_64
2014/10/30 13:54:17 [notice] 16392#0: getrlimit(RLIMIT_NOFILE):
8192:8192
2014/10/30 13:54:17 [debug] 16393#0: write: 8, 00007FFF049D4300, 6, 0
===>Restarted (I have monitor proceess whenever it crashes it will be
restarted)
2014/10/30 13:54:17 [debug] 16393#0: setproctitle: “nginx: master
process
/idap/activeRelease/nginx/sbin/nginx -c
/idap/activeRelease/conf/nginx/idap_gp_nginx.conf”
2014/10/30 13:54:17 [notice] 16393#0: start worker processes
2014/10/30 13:54:17 [debug] 16393#0: channel 3:8
2014/10/30 13:54:17 [notice] 16393#0: start worker process 16394
2014/10/30 13:54:17 [debug] 16393#0: sigsuspend
2014/10/30 13:54:17 [debug] 16394#0: malloc: 0000000000D03EB0:6144
2014/10/30 13:54:17 [debug] 16394#0: malloc: 00007F9DCDD3E010:212992
2014/10/30 13:54:17 [debug] 16394#0: malloc: 0000000000D223C0:106496
2014/10/30 13:54:17 [debug] 16394#0: malloc: 0000000000D3C3D0:106496
2014/10/30 13:54:17 [debug] 16394#0: epoll add event: fd:6 op:1
ev:00002001
2014/10/30 13:54:17 [debug] 16394#0: epoll add event: fd:7 op:1
ev:00002001
2014/10/30 13:54:17 [debug] 16394#0: epoll add event: fd:8 op:1
ev:00002001
2014/10/30 13:54:17 [debug] 16394#0: setproctitle: “nginx: worker
process”
2014/10/30 13:54:17 [debug] 16394#0: worker cycle

Thanks
amaran

Posted at Nginx Forum: