Hi,

I'm having trouble setting up Nginx as my frontend cache to a tomcat backend...

My main problem is that I have a webservice that has special headers for authentication and I need to benchmark it.

Whenever I user a REST client lik cREST ( http://groups.google.com/group/crest-client ) the content that I ask for gets cached in nginx cache and everything is fine...

But whenever I use a benchmark tool like Jmeter or ApacheBench, none of my requests get cached.
I've looked all over the debug error_log for any Cache-Control or Pragma no-cache headers but that doesnt seen to be the case. I've even tried to add the ignore_header...


That's my nginx.conf

user www;
worker_processes 1;

events {
worker_connections 1024;
}

http {
include /etc/nginx/mime.types;
error_log /var/log/nginx/error.log debug;
proxy_buffering on;
proxy_cache_valid any 10m;
proxy_cache_path /tmp/api-cache levels=1:2 keys_zone=api:8m max_size=400m inactive=600m;
proxy_temp_path /tmp/api-temp;
proxy_buffer_size 4k;
proxy_buffers 100 8k;

sendfile on;
keepalive_timeout 65;
tcp_nodelay on;

server {
listen 80;
server_name api.host.com;
proxy_buffering on;
proxy_set_header X-Real-IP $remote_addr;
proxy_ignore_headers Cache-control;

location / {
proxy_pass http://api.host.com:8080;
proxy_cache api;
proxy_cache_key "$request_uri";
proxy_cache_valid 200;
proxy_ignore_headers Cache-control;
}

}
}






That's my access.log from nginx

10.1.0.190 - - [30/Apr/2011:18:09:11 -0300] "GET /v1/category/4 HTTP/1.1" 200 700 "-" "Java/1.6.0_22"
10.1.0.190 - - [30/Apr/2011:18:09:12 -0300] "GET /v1/category/4 HTTP/1.1" 200 700 "-" "Java/1.6.0_22"
10.1.0.190 - - [30/Apr/2011:18:09:12 -0300] "GET /v1/category/4 HTTP/1.1" 200 700 "-" "Java/1.6.0_22"




and the access.log from tomcat

api.host.com:8080 - 10.1.0.95 - - [30/Apr/2011:18:09:11 -0300] "GET /v1/category/4 HTTP/1.0" 200 700 - "Java/1.6.0_22"
api.host.com:8080 - 10.1.0.95 - - [30/Apr/2011:18:09:12 -0300] "GET /v1/category/4 HTTP/1.0" 200 700 - "Java/1.6.0_22"
api.host.com:8080 - 10.1.0.95 - - [30/Apr/2011:18:09:12 -0300] "GET /v1/category/4 HTTP/1.0" 200 700 - "Java/1.6.0_22"
api.host.com:8080 - 10.1.0.95 - - [30/Apr/2011:18:17:52 -0300] "GET /v1/category/4 HTTP/1.0" 200 700 - "Mozilla/5.0 (X11; Linux i686) AppleWebKit/534.24 (KHTML, like Gecko) Chrome/11.0.696.57 Safari/534.24"




with the last request (from chrome cREST) the content gets cached and everything runs smooth for this URI.

and the debug log from error_log (nginx - 1 request only)




2011/04/30 18:12:36 [debug] 18628#0: *46 http process request line
2011/04/30 18:12:36 [debug] 18628#0: *46 http request line: "GET /v1/category/4 HTTP/1.1"
2011/04/30 18:12:36 [debug] 18628#0: *46 http uri: "/v1/category/4"
2011/04/30 18:12:36 [debug] 18628#0: *46 http args: ""
2011/04/30 18:12:36 [debug] 18628#0: *46 http exten: ""
2011/04/30 18:12:36 [debug] 18628#0: *46 http process request header line
2011/04/30 18:12:36 [debug] 18628#0: *46 http header: "Connection: close"
2011/04/30 18:12:36 [debug] 18628#0: *46 http header: "Accept: application/xml"
2011/04/30 18:12:36 [debug] 18628#0: *46 http header: "X-QB-Key: 3dcc84dbf452e063cdc88256f9987fd3"
2011/04/30 18:12:36 [debug] 18628#0: *46 http header: "User-Agent: Java/1.6.0_22"
2011/04/30 18:12:36 [debug] 18628#0: *46 http header: "Host: api.host.com"
2011/04/30 18:12:36 [debug] 18628#0: *46 http header done
2011/04/30 18:12:36 [debug] 18628#0: *46 rewrite phase: 0
2011/04/30 18:12:36 [debug] 18628#0: *46 test location: "/"
2011/04/30 18:12:36 [debug] 18628#0: *46 using configuration "/"
2011/04/30 18:12:36 [debug] 18628#0: *46 http cl:-1 max:1048576
2011/04/30 18:12:36 [debug] 18628#0: *46 rewrite phase: 2
2011/04/30 18:12:36 [debug] 18628#0: *46 post rewrite phase: 3
2011/04/30 18:12:36 [debug] 18628#0: *46 generic phase: 4
2011/04/30 18:12:36 [debug] 18628#0: *46 generic phase: 5
2011/04/30 18:12:36 [debug] 18628#0: *46 access phase: 6
2011/04/30 18:12:36 [debug] 18628#0: *46 access phase: 7
2011/04/30 18:12:36 [debug] 18628#0: *46 post access phase: 8
2011/04/30 18:12:36 [debug] 18628#0: *46 http init upstream, client timer: 0
2011/04/30 18:12:36 [debug] 18628#0: *46 http script var: "/v1/category/4"
2011/04/30 18:12:36 [debug] 18628#0: *46 http cache key: "/v1/category/4"
2011/04/30 18:12:36 [debug] 18628#0: *46 http file cache exists: -5 e:0
2011/04/30 18:12:36 [debug] 18628#0: *46 cache file: "/tmp/api-cache/4/05/5d456f91ba858b3ba58616cbf7d9a054"
2011/04/30 18:12:36 [debug] 18628#0: *46 http upstream cache: -5
2011/04/30 18:12:36 [debug] 18628#0: *46 http script copy: "X-Real-IP: "
2011/04/30 18:12:36 [debug] 18628#0: *46 http script var: "10.1.0.190"
2011/04/30 18:12:36 [debug] 18628#0: *46 http script copy: "
"
2011/04/30 18:12:36 [debug] 18628#0: *46 http script copy: "Host: "
2011/04/30 18:12:36 [debug] 18628#0: *46 http script var: "api.host.com:8080"
2011/04/30 18:12:36 [debug] 18628#0: *46 http script copy: "
"
2011/04/30 18:12:36 [debug] 18628#0: *46 http script copy: "Connection: close
"
2011/04/30 18:12:36 [debug] 18628#0: *46 http proxy header: "Accept: application/xml"
2011/04/30 18:12:36 [debug] 18628#0: *46 http proxy header: "X-QB-Key: 3dcc84dbf452e063cdc88256f9987fd3"
2011/04/30 18:12:36 [debug] 18628#0: *46 http proxy header: "User-Agent: Java/1.6.0_22"
2011/04/30 18:12:36 [debug] 18628#0: *46 http proxy header:
"GET /v1/category/4 HTTP/1.0
X-Real-IP: 10.1.0.190
Host: api.host.com:8080
Connection: close
Accept: application/xml
X-QB-Key: 3dcc84dbf452e063cdc88256f9987fd3
User-Agent: Java/1.6.0_22

"
2011/04/30 18:12:36 [debug] 18628#0: *46 http cleanup add: 0000000002F3A158
2011/04/30 18:12:36 [debug] 18628#0: *46 get rr peer, try: 1
2011/04/30 18:12:36 [debug] 18628#0: *46 http upstream connect: -2
2011/04/30 18:12:36 [debug] 18628#0: *46 http finalize request: -4, "/v1/category/4?" a:1, c:2
2011/04/30 18:12:36 [debug] 18628#0: *46 http request count:2 blk:0
2011/04/30 18:12:36 [debug] 18628#0: *46 http upstream request: "/v1/category/4?"
2011/04/30 18:12:36 [debug] 18628#0: *46 http upstream send request handler
2011/04/30 18:12:36 [debug] 18628#0: *46 http upstream send request
2011/04/30 18:12:36 [debug] 18628#0: *46 http run request: "/v1/category/4?"
2011/04/30 18:12:36 [debug] 18628#0: *46 http upstream check client, write event:1, "/v1/category/4"
2011/04/30 18:12:36 [debug] 18628#0: *46 http upstream recv(): -1 (11: Resource temporarily unavailable)
2011/04/30 18:12:36 [debug] 18628#0: *46 http upstream request: "/v1/category/4?"
2011/04/30 18:12:36 [debug] 18628#0: *46 http upstream process header
2011/04/30 18:12:36 [debug] 18628#0: *46 http proxy status 200 "200 OK"
2011/04/30 18:12:36 [debug] 18628#0: *46 http proxy header: "Access-Control-Allow-Origin: *"
2011/04/30 18:12:36 [debug] 18628#0: *46 http proxy header: "Access-Control-Allow-Headers: Content-Type, Accept, X-QB-Key"
2011/04/30 18:12:36 [debug] 18628#0: *46 http proxy header: "Access-Control-Allow-Credentials: true"
2011/04/30 18:12:36 [debug] 18628#0: *46 http proxy header: "X-QB-RateLimit-Remaining: 99999159"
2011/04/30 18:12:36 [debug] 18628#0: *46 http proxy header: "Set-Cookie: JSESSIONID=2D14DE3353DCCF99B9443591A4701580; Path=/"
2011/04/30 18:12:36 [debug] 18628#0: *46 http proxy header: "Content-Type: application/xml;charset=UTF-8"
2011/04/30 18:12:36 [debug] 18628#0: *46 http proxy header: "Content-Length: 520"
2011/04/30 18:12:36 [debug] 18628#0: *46 http proxy header: "Date: Sat, 30 Apr 2011 21:12:36 GMT"
2011/04/30 18:12:36 [debug] 18628#0: *46 http proxy header: "Connection: close"
2011/04/30 18:12:36 [debug] 18628#0: *46 http proxy header: "Server: Host 2.0"
2011/04/30 18:12:36 [debug] 18628#0: *46 http proxy header done
2011/04/30 18:12:36 [debug] 18628#0: *46 HTTP/1.1 200 OK
Server: nginx/0.8.54
Date: Sat, 30 Apr 2011 21:12:36 GMT
Content-Type: application/xml;charset=UTF-8
Connection: close
Access-Control-Allow-Origin: *
Access-Control-Allow-Headers: Content-Type, Accept, X-QB-Key
Access-Control-Allow-Credentials: true
X-QB-RateLimit-Remaining: 99999159
Set-Cookie: JSESSIONID=2D14DE3353DCCF99B9443591A4701580; Path=/
Content-Length: 520

2011/04/30 18:12:36 [debug] 18628#0: *46 http write filter: l:0 f:0 s:398
2011/04/30 18:12:36 [debug] 18628#0: *46 http cacheable: 0
2011/04/30 18:12:36 [debug] 18628#0: *46 http file cache free, fd: -1
2011/04/30 18:12:36 [debug] 18628#0: *46 http upstream process upstream
2011/04/30 18:12:36 [debug] 18628#0: *46 http upstream request: "/v1/category/4?"
2011/04/30 18:12:36 [debug] 18628#0: *46 http upstream dummy handler
2011/04/30 18:12:36 [debug] 18628#0: *46 http upstream request: "/v1/category/4?"
2011/04/30 18:12:36 [debug] 18628#0: *46 http upstream process upstream
2011/04/30 18:12:36 [debug] 18628#0: *46 http output filter "/v1/category/4?"
2011/04/30 18:12:36 [debug] 18628#0: *46 http copy filter: "/v1/category/4?"
2011/04/30 18:12:36 [debug] 18628#0: *46 http postpone filter "/v1/category/4?" 0000000002F3AA28
2011/04/30 18:12:36 [debug] 18628#0: *46 http write filter: l:0 f:0 s:918
2011/04/30 18:12:36 [debug] 18628#0: *46 http copy filter: 0 "/v1/category/4?"
2011/04/30 18:12:36 [debug] 18628#0: *46 http upstream exit: 0000000000000000
2011/04/30 18:12:36 [debug] 18628#0: *46 finalize http upstream request: 0
2011/04/30 18:12:36 [debug] 18628#0: *46 finalize http proxy request
2011/04/30 18:12:36 [debug] 18628#0: *46 free rr peer 1 0
2011/04/30 18:12:36 [debug] 18628#0: *46 close http upstream connection: 10
2011/04/30 18:12:36 [debug] 18628#0: *46 http upstream temp fd: -1
2011/04/30 18:12:36 [debug] 18628#0: *46 http output filter "/v1/category/4?"
2011/04/30 18:12:36 [debug] 18628#0: *46 http copy filter: "/v1/category/4?"
2011/04/30 18:12:36 [debug] 18628#0: *46 http postpone filter "/v1/category/4?" 00007FFF94380080
2011/04/30 18:12:36 [debug] 18628#0: *46 http write filter: l:1 f:0 s:918
2011/04/30 18:12:36 [debug] 18628#0: *46 http write filter limit 0
2011/04/30 18:12:36 [debug] 18628#0: *46 http write filter 0000000000000000
2011/04/30 18:12:36 [debug] 18628#0: *46 http copy filter: 0 "/v1/category/4?"
2011/04/30 18:12:36 [debug] 18628#0: *46 http finalize request: 0, "/v1/category/4?" a:1, c:1
2011/04/30 18:12:36 [debug] 18628#0: *46 http request count:1 blk:0
2011/04/30 18:12:36 [debug] 18628#0: *46 http close request
2011/04/30 18:12:36 [debug] 18628#0: *46 http log handler
2011/04/30 18:12:36 [debug] 18628#0: *46 close http connection: 9



one response from the log that I do not understand is the:

"http file cache exists: -5 e:0" (minus 5)


I'm totally lost since nginx cache has been working for plenty of other projects that I have...

Anyone have any clue to what might be happening to nginx not cache from ab e jmeter requests ?