I’m running an older version of nginx (0.7.67) with mod_zip 1.1.6. I
believe we have a found a rare bug, I’m trying to figure out of it is
with mod_zip or with nginx, and if upgrading nginx will potentially
resolve it.
The symptom is a worker process getting “stuck” at 100% CPU, leaving
all connections in CLOSE_WAIT, and servicing no requests. It appears
that the trigger for this is downloading an archive from mod_zip, but
we have never been able to reproduce it, only observe it in
production.
I was finally able to catch one of the workers and get a backtrace from
gdb:
$ cat backtrace.log | addr2line -e /usr/lib/debug/usr/sbin/nginx -f
ngx_http_postpone_filter
/build/buildd/nginx-0.7.67/src/http/ngx_http_postpone_filter_module.c:125
ngx_http_ssi_body_filter
/build/buildd/nginx-0.7.67/src/http/modules/ngx_http_ssi_filter_module.c:430
ngx_http_charset_body_filter
/build/buildd/nginx-0.7.67/src/http/modules/ngx_http_charset_filter_module.c:643
ngx_http_zip_body_filter
/build/buildd/nginx-0.7.67/modules/mod_zip-1.1.6/ngx_http_zip_module.c:336
ngx_output_chain
/build/buildd/nginx-0.7.67/src/core/ngx_output_chain.c:58
ngx_http_copy_filter
/build/buildd/nginx-0.7.67/src/http/ngx_http_copy_filter_module.c:114
ngx_http_range_body_filter
/build/buildd/nginx-0.7.67/src/http/modules/ngx_http_range_filter_module.c:549
ngx_http_output_filter
/build/buildd/nginx-0.7.67/src/http/ngx_http_core_module.c:1716
ngx_event_pipe_write_to_downstream
/build/buildd/nginx-0.7.67/src/event/ngx_event_pipe.c:627
ngx_http_upstream_process_upstream
/build/buildd/nginx-0.7.67/src/http/ngx_http_upstream.c:2509
ngx_http_upstream_handler
/build/buildd/nginx-0.7.67/src/http/ngx_http_upstream.c:844
ngx_event_process_posted
/build/buildd/nginx-0.7.67/src/event/ngx_event_posted.c:30
ngx_worker_process_cycle
/build/buildd/nginx-0.7.67/src/os/unix/ngx_process_cycle.c:793
ngx_spawn_process
/build/buildd/nginx-0.7.67/src/os/unix/ngx_process.c:201
ngx_reap_children
/build/buildd/nginx-0.7.67/src/os/unix/ngx_process_cycle.c:612
main
/build/buildd/nginx-0.7.67/src/core/nginx.c:396
??
??:0
_start
??:0
??
??:0
??
??:0
??
??:0
??
??:0
??
??:0
??
??:0
I also had the log in debug mode (it is incredibly large ~ 150GB
uncompressed) and it is completely filled with the following little
loop:
2012/02/17 11:58:45 [debug] 10150#0: *1888 mod_zip: entering
subrequest body filter
2012/02/17 11:58:45 [debug] 10150#0: *1888 http postpone filter
“/s3/bucket/key” 0000000000000000
2012/02/17 11:58:45 [debug] 10150#0: *1888 copy filter: 0
“/s3/bucket/key”
2012/02/17 11:58:45 [debug] 10150#0: *1888 pipe write busy: 8192
2012/02/17 11:58:45 [debug] 10150#0: *1888 pipe write:
out:0000000000000000, f:1
2012/02/17 11:58:45 [debug] 10150#0: *1888 http output filter
“/s3/bucket/key”
2012/02/17 11:58:45 [debug] 10150#0: *1888 copy filter: “/s3/bucket/key”
2012/02/17 11:58:45 [debug] 10150#0: *1888 mod_zip: entering
subrequest body filter
2012/02/17 11:58:45 [debug] 10150#0: *1888 http postpone filter
“/s3/bucket/key” 0000000000000000
2012/02/17 11:58:45 [debug] 10150#0: *1888 copy filter: 0
“/s3/bucket/key”
2012/02/17 11:58:45 [debug] 10150#0: *1888 pipe write busy: 8192
2012/02/17 11:58:45 [debug] 10150#0: *1888 pipe write:
out:0000000000000000, f:1
2012/02/17 11:58:45 [debug] 10150#0: *1888 http output filter
“/s3/bucket/key”
2012/02/17 11:58:45 [debug] 10150#0: *1888 copy filter: “/s3/bucket/key”
2012/02/17 11:58:45 [debug] 10150#0: *1888 mod_zip: entering
subrequest body filter
2012/02/17 11:58:45 [debug] 10150#0: *1888 http postpone filter
“/s3/bucket/key” 0000000000000000
2012/02/17 11:58:45 [debug] 10150#0: *1888 copy filter: 0
“/s3/bucket/key”
2012/02/17 11:58:45 [debug] 10150#0: *1888 pipe write busy: 8192
2012/02/17 11:58:45 [debug] 10150#0: *1888 pipe write:
out:0000000000000000, f:1
2012/02/17 11:58:45 [debug] 10150#0: *1888 http output filter
“/s3/bucket/key”
2012/02/17 11:58:45 [debug] 10150#0: *1888 copy filter: “/s3/bucket/key”
Am I right in assuming this is a bug in mod_zip, it looks like a
buffer is never being drained to the client?