Using ajp_cache fails to return responses

[davidjb]

I'm attempting to use this module to talk to a backend AJP endpoint (Jetty) and so far so good with using a location block with ajp_pass and other associated options. However, I'm wanting to cache responses in Nginx using ajp_cache, much like you can with proxy_cache, and I'm experiencing the server closing the connection when requesting cached resources.

This happens for subsequent requests for an individual cached resource or URL. The first request for a given URL will succeed and be correctly returned to the client, but subsequent requests for the same resource cause the server to close the connection with no data (or headers) being sent. A manual inspection of the file structure shows that it appears the cache is being filled with requested resources. Clearing the cache manually allows the first request to a given URL to work again, but the same behaviour reoccurs with subsequent requests failing.

My example configuration, which naively caches all images and JS resources for an AJP backend looks like this:

http {
   ...
   ajp_cache_path     /var/cache/nginx/ajp_cache  levels=1:2
                       keys_zone=ajp_cache:60m
                       inactive=100m;
   ...
}
server {
    listen 80 default_server;
    listen 443 ssl default_server;
    location / {
       location ~ ^/.*\.(gif|jpg|png|js)$ {
           ajp_cache ajp_cache;
           ajp_cache_key     "$host$request_uri";
           ajp_cache_valid   any 1d;
           ajp_read_timeout 90s;
           ajp_ignore_headers "Set-Cookie";
           ajp_hide_header Server;
           ajp_pass localhost:8009;
       }
       ajp_read_timeout 90s;
       ajp_hide_header Server;
       ajp_pass localhost:8009;
    }

As a side note, responses that are always ignored for caching (eg responses with a Set-Cookie header by default), continue to be served - though this is probably because no attempt at caching or reading them from cache is attempted.

I'm using this plugin with Nginx 1.6.0. Nginx compiles correctly, though that's not to say there's been some incompatibility or difference introduced recently with the caching code in the Nginx's core.

[davidjb]

And looking at the server's error logs, the worker process is crashing:

2014/05/15 12:38:02 [alert] 9127#0: worker process 9129 exited on signal 11
2014/05/15 12:38:07 [alert] 9127#0: worker process 9131 exited on signal 11
2014/05/15 12:38:10 [alert] 9127#0: worker process 9134 exited on signal 11

Will debug this further shortly.

[yaoweibin]

Could you get the coredump and show me the backtrace?

[davidjb]

Right, here we go. Here's the debug log (https://gist.github.com/davidjb/c313816e81e902ad33aa) and the backtrace is below (using gdb /usr/sbin/nginx.debug /opt/nginx/nginx.core and backtrace):

Core was generated by `nginx: worke'.
Program terminated with signal 11, Segmentation fault.
#0  ngx_http_upstream_send_request_body (r=0x1ea88f0, u=0x1e95b00)
    at /root/rpmbuild/BUILD/nginx-1.6.0/nginx_ajp_module/ngx_http_ajp_handler.c:535
535     c->log->action = "sending request body again to upstream";
Missing separate debuginfos, use: debuginfo-install nginx-debug-1.6.0-1.el6.ngx.x86_64
(gdb) backtrace
#0  ngx_http_upstream_send_request_body (r=0x1ea88f0, u=0x1e95b00)
    at /root/rpmbuild/BUILD/nginx-1.6.0/nginx_ajp_module/ngx_http_ajp_handler.c:535
#1  0x00000000004a7a6a in ngx_http_ajp_process_header (r=0x1ea88f0)
    at /root/rpmbuild/BUILD/nginx-1.6.0/nginx_ajp_module/ngx_http_ajp_handler.c:362
#2  0x0000000000451a92 in ngx_http_upstream_cache_send (r=0x1ea88f0, u=0x1e95b00)
    at src/http/ngx_http_upstream.c:866
#3  0x00000000004548e1 in ngx_http_upstream_cache (r=0x1ea88f0) at src/http/ngx_http_upstream.c:780
#4  ngx_http_upstream_init_request (r=0x1ea88f0) at src/http/ngx_http_upstream.c:500
#5  0x0000000000449de7 in ngx_http_read_client_request_body (r=0x1ea88f0, 
    post_handler=0x455130 <ngx_http_upstream_init>) at src/http/ngx_http_request_body.c:176
#6  0x00000000004a65ca in ngx_http_ajp_handler (r=0x1ea88f0)
    at /root/rpmbuild/BUILD/nginx-1.6.0/nginx_ajp_module/ngx_http_ajp_handler.c:106
#7  0x000000000043aa14 in ngx_http_core_content_phase (r=0x1ea88f0, ph=0x1eb0a98)
    at src/http/ngx_http_core_module.c:1410
#8  0x0000000000434b5d in ngx_http_core_run_phases (r=0x1ea88f0) at src/http/ngx_http_core_module.c:888
#9  0x00000000004407e1 in ngx_http_process_request (r=0x1ea88f0) at src/http/ngx_http_request.c:1900
#10 0x00000000004416ac in ngx_http_process_request_line (rev=0x1eb3f80) at src/http/ngx_http_request.c:1012
#11 0x000000000042ad31 in ngx_epoll_process_events (cycle=0x1e89c80, timer=<value optimized out>, 
    flags=<value optimized out>) at src/event/modules/ngx_epoll_module.c:691
#12 0x00000000004213ae in ngx_process_events_and_timers (cycle=0x1e89c80) at src/event/ngx_event.c:248
#13 0x0000000000428985 in ngx_worker_process_cycle (cycle=0x1e89c80, data=<value optimized out>)
    at src/os/unix/ngx_process_cycle.c:816
#14 0x0000000000426d14 in ngx_spawn_process (cycle=0x1e89c80, proc=0x4288b0 <ngx_worker_process_cycle>, 
    data=0x0, name=0x4b2603 "worker process", respawn=-3) at src/os/unix/ngx_process.c:198
#15 0x0000000000427c7c in ngx_start_worker_processes (cycle=0x1e89c80, n=1, type=-3)
    at src/os/unix/ngx_process_cycle.c:364
#16 0x0000000000429124 in ngx_master_process_cycle (cycle=0x1e89c80) at src/os/unix/ngx_process_cycle.c:136
#17 0x0000000000408c96 in main (argc=<value optimized out>, argv=<value optimized out>) at src/core/nginx.c:407

I can post the backtrace full output as well if necessary. The first request succeeds correctly, and any subsequent requests cause the segfault as above. From a brief look at the code behind the innermost call, it looks as if Nginx is attempting to send the request body to the upstream server, when in fact it is/should have been cached.

From a client's perspective, this is what happens:

[vagrant@localhost ~]$ curl http://localhost/solr/admin/solr_small.png > /dev/null
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100  7926  100  7926    0     0   831k      0 --:--:-- --:--:-- --:--:-- 1290k
[vagrant@localhost ~]$ curl http://localhost/solr/admin/solr_small.png
curl: (52) Empty reply from server