Hello,

We need a little bit of help to understand what's wrong with our config.
We try to setup a reverse proxy cache using Nginx but somthing seems to be wrong with our configuration.
Behind the Nginx there is a tomcat server.

The problem is that Nginx doesn't cache at all.
Logs shows that the content isen't cacheable, but we diden't understand why !!

The config is:

nginx -V
nginx version: nginx/0.8.53
built by gcc 4.4.3 20100127 (Red Hat 4.4.3-4) (GCC)
configure arguments: --with-debug

nginx.conf
worker_processes 2;
error_log logs/error.log debug_core debug_http debug_alloc debug_mutex debug_event ;
worker_rlimit_nofile 8192;
events {
worker_connections 1024;
use epoll;
}


http {
include mime.types;
default_type application/octet-stream;
sendfile on;
client_body_buffer_size 1m;
proxy_buffering on;
proxy_buffer_size 4k;
proxy_buffers 8 32k;
tcp_nopush on;

#keepalive_timeout 0;
keepalive_timeout 65;

#gzip on;

proxy_cache_path /tmp/cache levels=1:2 keys_zone=tmpcache:15m;

server {
listen 8080;
server_name myservername;

#charset koi8-r;

#access_log logs/host.access.log main;

location / {
proxy_pass http://localhost:8085;
proxy_set_header Host $host;
proxy_set_header X-Real-IP $remote_addr;
proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
}

location /test/v1/ {
proxy_pass http://localhost:8085;
proxy_set_header Host $http_host;
proxy_set_header X-Real-IP $remote_addr;
proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
proxy_cache_valid 200 301 302 120m;
expires 864000;
proxy_cache tmpcache;
}
}
}

logs:
2010/11/09 17:08:35 [debug] 3900#0: *1 http request line: "GET /test/v1/lookup/?method=listConnectedCountries HTTP/1.1"
2010/11/09 17:08:35 [debug] 3900#0: *1 http uri: "/test/v1/lookup/"
2010/11/09 17:08:35 [debug] 3900#0: *1 http args: "method=listConnectedCountries"
2010/11/09 17:08:35 [debug] 3900#0: *1 http exten: ""
2010/11/09 17:08:35 [debug] 3900#0: *1 http process request header line
2010/11/09 17:08:35 [debug] 3900#0: *1 http header: "Host: myhostname:8080"
2010/11/09 17:08:35 [debug] 3900#0: *1 http header: "User-Agent: Mozilla/5.0 (Windows; U; Windows NT 6.0; fr; rv:1.9.2.12) Gecko/20101026 AskTbUT2V5/3.9.1.14019 Firefox/3.6.12 ( .NET CLR 3.5.30729)"
2010/11/09 17:08:35 [debug] 3900#0: *1 http header: "Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8"
2010/11/09 17:08:35 [debug] 3900#0: *1 http header: "Accept-Language: fr,fr-fr;q=0.8,en-us;q=0.5,en;q=0.3"
2010/11/09 17:08:35 [debug] 3900#0: *1 http header: "Accept-Encoding: gzip,deflate"
2010/11/09 17:08:35 [debug] 3900#0: *1 http header: "Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7"
2010/11/09 17:08:35 [debug] 3900#0: *1 http header: "Keep-Alive: 115"
2010/11/09 17:08:35 [debug] 3900#0: *1 http header: "Connection: keep-alive"
2010/11/09 17:08:35 [debug] 3900#0: *1 http header: "Cookie: __utma=38270632.803570674.1278490999.1288117398.1288363663.11; __utmz=38270632.1278490999.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none)"
2010/11/09 17:08:35 [debug] 3900#0: *1 http header: "Pragma: no-cache"
2010/11/09 17:08:35 [debug] 3900#0: *1 http header: "Cache-Control: no-cache"
2010/11/09 17:08:35 [debug] 3900#0: *1 http header done
2010/11/09 17:08:35 [debug] 3900#0: *1 event timer del: 11: 832387028
2010/11/09 17:08:35 [debug] 3900#0: *1 rewrite phase: 0
2010/11/09 17:08:35 [debug] 3900#0: *1 test location: "/"
2010/11/09 17:08:35 [debug] 3900#0: *1 test location: "test/v1/"
2010/11/09 17:08:35 [debug] 3900#0: *1 using configuration "/test/v1/"
2010/11/09 17:08:35 [debug] 3900#0: *1 http cl:-1 max:1048576
2010/11/09 17:08:35 [debug] 3900#0: *1 rewrite phase: 2
2010/11/09 17:08:35 [debug] 3900#0: *1 post rewrite phase: 3
2010/11/09 17:08:35 [debug] 3900#0: *1 generic phase: 4
2010/11/09 17:08:35 [debug] 3900#0: *1 generic phase: 5
2010/11/09 17:08:35 [debug] 3900#0: *1 access phase: 6
2010/11/09 17:08:35 [debug] 3900#0: *1 access phase: 7
2010/11/09 17:08:35 [debug] 3900#0: *1 post access phase: 8
2010/11/09 17:08:35 [debug] 3900#0: *1 http init upstream, client timer: 0
2010/11/09 17:08:35 [debug] 3900#0: *1 epoll add event: fd:11 op:3 ev:80000005
2010/11/09 17:08:35 [debug] 3900#0: *1 http cache key: "http://localhost:8085"
2010/11/09 17:08:35 [debug] 3900#0: *1 http cache key: "/test/v1/lookup/?method=listConnectedCountries"
2010/11/09 17:08:35 [debug] 3900#0: *1 add cleanup: 08CF0DD0
2010/11/09 17:08:35 [debug] 3900#0: slab alloc: 76 slot: 4
2010/11/09 17:08:35 [debug] 3900#0: slab alloc: B5A8C000
2010/11/09 17:08:35 [debug] 3900#0: *1 http file cache exists: -5 e:0
2010/11/09 17:08:35 [debug] 3900#0: *1 cache file: "/tmp/cache/9/3f/e20791cdfc84e7878b482605b9bdd3f9"
2010/11/09 17:08:35 [debug] 3900#0: *1 add cleanup: 08CF0E10
2010/11/09 17:08:35 [debug] 3900#0: *1 http upstream cache: -5
2010/11/09 17:08:35 [debug] 3900#0: *1 http script copy: "Host: "
2010/11/09 17:08:35 [debug] 3900#0: *1 http script var: "myhostname:8080"
2010/11/09 17:08:35 [debug] 3900#0: *1 http script copy: "
"
2010/11/09 17:08:35 [debug] 3900#0: *1 http script copy: "X-Real-IP: "
2010/11/09 17:08:35 [debug] 3900#0: *1 http script var: "myhostipaddr"
2010/11/09 17:08:35 [debug] 3900#0: *1 http script copy: "
"
2010/11/09 17:08:35 [debug] 3900#0: *1 http script copy: "X-Forwarded-For: "
2010/11/09 17:08:35 [debug] 3900#0: *1 http script var: "myhostipaddr"
2010/11/09 17:08:35 [debug] 3900#0: *1 http script copy: "
"
2010/11/09 17:08:35 [debug] 3900#0: *1 http script copy: "Connection: close
"
2010/11/09 17:08:35 [debug] 3900#0: *1 http proxy header: "User-Agent: Mozilla/5.0 (Windows; U; Windows NT 6.0; fr; rv:1.9.2.12) Gecko/20101026 AskTbUT2V5/3.9.1.14019 Firefox/3.6.12 ( .NET CLR 3.5.30729)"
2010/11/09 17:08:35 [debug] 3900#0: *1 http proxy header: "Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8"
2010/11/09 17:08:35 [debug] 3900#0: *1 http proxy header: "Accept-Language: fr,fr-fr;q=0.8,en-us;q=0.5,en;q=0.3"
2010/11/09 17:08:35 [debug] 3900#0: *1 http proxy header: "Accept-Encoding: gzip,deflate"
2010/11/09 17:08:35 [debug] 3900#0: *1 http proxy header: "Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7"
2010/11/09 17:08:35 [debug] 3900#0: *1 http proxy header: "Cookie: __utma=38270632.803570674.1278490999.1288117398.1288363663.11; __utmz=38270632.1278490999.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none)"
2010/11/09 17:08:35 [debug] 3900#0: *1 http proxy header: "Pragma: no-cache"
2010/11/09 17:08:35 [debug] 3900#0: *1 http proxy header: "Cache-Control: no-cache"
2010/11/09 17:08:35 [debug] 3900#0: *1 http proxy header:
"GET /test/v1/lookup/?method=listConnectedCountries HTTP/1.0
Host: myhostname:8080
X-Real-IP: myhostipaddr
X-Forwarded-For: myhostipaddr
Connection: close
User-Agent: Mozilla/5.0 (Windows; U; Windows NT 6.0; fr; rv:1.9.2.12) Gecko/20101026 AskTbUT2V5/3.9.1.14019 Firefox/3.6.12 ( .NET CLR 3.5.30729)
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Accept-Language: fr,fr-fr;q=0.8,en-us;q=0.5,en;q=0.3
Accept-Encoding: gzip,deflate
Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
Cookie: __utma=38270632.803570674.1278490999.1288117398.1288363663.11; __utmz=38270632.1278490999.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none)
Pragma: no-cache
Cache-Control: no-cache

"
2010/11/09 17:08:35 [debug] 3900#0: *1 http cleanup add: 08CF1164
2010/11/09 17:08:35 [debug] 3900#0: *1 get rr peer, try: 2
2010/11/09 17:08:35 [debug] 3900#0: *1 get rr peer, current: 1 1
2010/11/09 17:08:35 [debug] 3900#0: *1 socket 12
2010/11/09 17:08:35 [debug] 3900#0: *1 epoll add connection: fd:12 ev:80000005
2010/11/09 17:08:35 [debug] 3900#0: *1 connect to 127.0.0.1:8085, fd:12 #2
2010/11/09 17:08:35 [debug] 3900#0: *1 http upstream connect: -2
2010/11/09 17:08:35 [debug] 3900#0: *1 event timer add: 12: 60000:832387049
2010/11/09 17:08:35 [debug] 3900#0: *1 http finalize request: -4, "/test/v1/lookup/?method=listConnectedCountries" a:1, c:2
2010/11/09 17:08:35 [debug] 3900#0: *1 http request count:2 blk:0
2010/11/09 17:08:35 [debug] 3900#0: posted event 00000000
2010/11/09 17:08:35 [debug] 3900#0: worker cycle
2010/11/09 17:08:35 [debug] 3900#0: accept mutex locked
2010/11/09 17:08:35 [debug] 3900#0: epoll timer: 60000
2010/11/09 17:08:35 [debug] 3900#0: epoll: fd:11 ev:0004 d:08D00B78
2010/11/09 17:08:35 [debug] 3900#0: *1 post event 08D23B40
2010/11/09 17:08:35 [debug] 3900#0: epoll: fd:12 ev:0004 d:08D00BD0
2010/11/09 17:08:35 [debug] 3900#0: *1 post event 08D23B74
2010/11/09 17:08:35 [debug] 3900#0: timer delta: 1
2010/11/09 17:08:35 [debug] 3900#0: posted events 08D23B74
2010/11/09 17:08:35 [debug] 3900#0: posted event 08D23B74
2010/11/09 17:08:35 [debug] 3900#0: *1 delete posted event 08D23B74
2010/11/09 17:08:35 [debug] 3900#0: *1 http upstream request: "/test/v1/lookup/?method=listConnectedCountries"
2010/11/09 17:08:35 [debug] 3900#0: *1 http upstream send request handler
2010/11/09 17:08:35 [debug] 3900#0: *1 http upstream send request
2010/11/09 17:08:35 [debug] 3900#0: *1 chain writer buf fl:1 s:713
2010/11/09 17:08:35 [debug] 3900#0: *1 chain writer in: 08CF1180
2010/11/09 17:08:35 [debug] 3900#0: *1 writev: 713
2010/11/09 17:08:35 [debug] 3900#0: *1 chain writer out: 00000000
2010/11/09 17:08:35 [debug] 3900#0: *1 event timer del: 12: 832387049
2010/11/09 17:08:35 [debug] 3900#0: *1 event timer add: 12: 60000:832387050
2010/11/09 17:08:35 [debug] 3900#0: posted event 08D23B40
2010/11/09 17:08:35 [debug] 3900#0: *1 delete posted event 08D23B40
2010/11/09 17:08:35 [debug] 3900#0: *1 http run request: "/test/v1/lookup/?method=listConnectedCountries"
2010/11/09 17:08:35 [debug] 3900#0: *1 http upstream check client, write event:1, "/test/v1/lookup/"
2010/11/09 17:08:35 [debug] 3900#0: *1 http upstream recv(): -1 (11: Resource temporarily unavailable)
2010/11/09 17:08:35 [debug] 3900#0: posted event 00000000
2010/11/09 17:08:35 [debug] 3900#0: worker cycle
2010/11/09 17:08:35 [debug] 3900#0: accept mutex locked
2010/11/09 17:08:35 [debug] 3900#0: epoll timer: 60000
2010/11/09 17:08:35 [debug] 3900#0: epoll: fd:12 ev:0005 d:08D00BD0
2010/11/09 17:08:35 [debug] 3900#0: *1 post event 08D16B6C
2010/11/09 17:08:35 [debug] 3900#0: *1 post event 08D23B74
2010/11/09 17:08:35 [debug] 3900#0: timer delta: 7
2010/11/09 17:08:35 [debug] 3900#0: posted events 08D23B74
2010/11/09 17:08:35 [debug] 3900#0: posted event 08D23B74
2010/11/09 17:08:35 [debug] 3900#0: *1 delete posted event 08D23B74
2010/11/09 17:08:35 [debug] 3900#0: *1 http upstream request: "/test/v1/lookup/?method=listConnectedCountries"
2010/11/09 17:08:35 [debug] 3900#0: *1 http upstream dummy handler
2010/11/09 17:08:35 [debug] 3900#0: posted event 08D16B6C
2010/11/09 17:08:35 [debug] 3900#0: *1 delete posted event 08D16B6C
2010/11/09 17:08:35 [debug] 3900#0: *1 http upstream request: "/test/v1/lookup/?method=listConnectedCountries"
2010/11/09 17:08:35 [debug] 3900#0: *1 http upstream process header
2010/11/09 17:08:35 [debug] 3900#0: *1 malloc: 08CF1508:4096
2010/11/09 17:08:35 [debug] 3900#0: *1 recv: fd:12 354 of 3998
2010/11/09 17:08:35 [debug] 3900#0: *1 http proxy status 200 "200 OK"
2010/11/09 17:08:35 [debug] 3900#0: *1 http proxy header: "Server: Apache-Coyote/1.1"
2010/11/09 17:08:35 [debug] 3900#0: *1 http proxy header: "Pragma: no-cache"
2010/11/09 17:08:35 [debug] 3900#0: *1 http proxy header: "Expires: Thu, 01 Jan 1970 00:00:00 GMT"
2010/11/09 17:08:35 [debug] 3900#0: *1 http proxy header: "Cache-Control: no-cache"
2010/11/09 17:08:35 [debug] 3900#0: *1 http proxy header: "Cache-Control: no-store"
2010/11/09 17:08:35 [debug] 3900#0: *1 http proxy header: "Date: Tue, 09 Nov 2010 17:08:35 GMT"
2010/11/09 17:08:35 [debug] 3900#0: *1 http proxy header: "Connection: close"
2010/11/09 17:08:35 [debug] 3900#0: *1 http proxy header done
2010/11/09 17:08:35 [debug] 3900#0: *1 HTTP/1.1 200 OK
Server: nginx/0.8.53
Date: Tue, 09 Nov 2010 17:08:35 GMT
Transfer-Encoding: chunked
Connection: keep-alive
Expires: Fri, 19 Nov 2010 17:08:35 GMT
Cache-Control: max-age=864000

2010/11/09 17:08:35 [debug] 3900#0: *1 write new buf t:1 f:0 08CF13B8, pos 08CF13B8, size: 201 file: 0, size: 0
2010/11/09 17:08:35 [debug] 3900#0: *1 http write filter: l:0 f:0 s:201
2010/11/09 17:08:35 [debug] 3900#0: *1 http cacheable: 0
2010/11/09 17:08:35 [debug] 3900#0: *1 http file cache free, fd: -1
2010/11/09 17:08:35 [debug] 3900#0: slab free: B5A8C000
2010/11/09 17:08:35 [debug] 3900#0: *1 posix_memalign: 08D30AE0:4096 @16
2010/11/09 17:08:35 [debug] 3900#0: *1 http upstream process upstream
2010/11/09 17:08:35 [debug] 3900#0: *1 pipe read upstream: 1
2010/11/09 17:08:35 [debug] 3900#0: *1 pipe preread: 144
2010/11/09 17:08:35 [debug] 3900#0: *1 readv: 1:3644
2010/11/09 17:08:35 [debug] 3900#0: *1 pipe recv chain: 0
2010/11/09 17:08:35 [debug] 3900#0: *1 pipe buf free s:0 t:1 f:0 08CF1508, pos 08CF163C, size: 144 file: 0, size: 0
2010/11/09 17:08:35 [debug] 3900#0: *1 input buf #0
2010/11/09 17:08:35 [debug] 3900#0: *1 pipe write downstream: 1
2010/11/09 17:08:35 [debug] 3900#0: *1 pipe write downstream flush in
2010/11/09 17:08:35 [debug] 3900#0: *1 http output filter "/test/v1/lookup/?method=listConnectedCountries"
2010/11/09 17:08:35 [debug] 3900#0: *1 http copy filter: "/test/v1/lookup/?method=listConnectedCountries"
2010/11/09 17:08:35 [debug] 3900#0: *1 http postpone filter "/test/v1/lookup/?method=listConnectedCountries" 08CF14C8
2010/11/09 17:08:35 [debug] 3900#0: *1 http chunk: 144
2010/11/09 17:08:35 [debug] 3900#0: *1 write old buf t:1 f:0 08CF13B8, pos 08CF13B8, size: 201 file: 0, size: 0
2010/11/09 17:08:35 [debug] 3900#0: *1 write new buf t:1 f:0 00000000, pos 08CF14D8, size: 4 file: 0, size: 0
2010/11/09 17:08:35 [debug] 3900#0: *1 write new buf t:1 f:0 08CF1508, pos 08CF163C, size: 144 file: 0, size: 0
2010/11/09 17:08:35 [debug] 3900#0: *1 write new buf t:0 f:0 00000000, pos 080AE7E1, size: 2 file: 0, size: 0
2010/11/09 17:08:35 [debug] 3900#0: *1 http write filter: l:0 f:0 s:351
2010/11/09 17:08:35 [debug] 3900#0: *1 http copy filter: 0 "/test/v1/lookup/?method=listConnectedCountries"
2010/11/09 17:08:35 [debug] 3900#0: *1 pipe write downstream done
2010/11/09 17:08:35 [debug] 3900#0: *1 event timer: 12, old: 832387050, new: 832387057
2010/11/09 17:08:35 [debug] 3900#0: *1 http upstream exit: 00000000
2010/11/09 17:08:35 [debug] 3900#0: *1 finalize http upstream request: 0
2010/11/09 17:08:35 [debug] 3900#0: *1 finalize http proxy request
2010/11/09 17:08:35 [debug] 3900#0: *1 free rr peer 2 0
2010/11/09 17:08:35 [debug] 3900#0: *1 close http upstream connection: 12
2010/11/09 17:08:35 [debug] 3900#0: *1 event timer del: 12: 832387050
2010/11/09 17:08:35 [debug] 3900#0: *1 http upstream temp fd: -1
2010/11/09 17:08:35 [debug] 3900#0: *1 http output filter "/test/v1/lookup/?method=listConnectedCountries"
2010/11/09 17:08:35 [debug] 3900#0: *1 http copy filter: "/test/v1/lookup/?method=listConnectedCountries"
2010/11/09 17:08:35 [debug] 3900#0: *1 http postpone filter "/test/v1/lookup/?method=listConnectedCountries" BF969EE8
2010/11/09 17:08:35 [debug] 3900#0: *1 http chunk: 0
2010/11/09 17:08:35 [debug] 3900#0: *1 write old buf t:1 f:0 08CF13B8, pos 08CF13B8, size: 201 file: 0, size: 0
2010/11/09 17:08:35 [debug] 3900#0: *1 write old buf t:1 f:0 00000000, pos 08CF14D8, size: 4 file: 0, size: 0
2010/11/09 17:08:35 [debug] 3900#0: *1 write old buf t:1 f:0 08CF1508, pos 08CF163C, size: 144 file: 0, size: 0
2010/11/09 17:08:35 [debug] 3900#0: *1 write old buf t:0 f:0 00000000, pos 080AE7E1, size: 2 file: 0, size: 0
2010/11/09 17:08:35 [debug] 3900#0: *1 write new buf t:0 f:0 00000000, pos 080AE7DE, size: 5 file: 0, size: 0
2010/11/09 17:08:35 [debug] 3900#0: *1 http write filter: l:1 f:0 s:356
2010/11/09 17:08:35 [debug] 3900#0: *1 http write filter limit 0
2010/11/09 17:08:35 [debug] 3900#0: *1 writev: 356
2010/11/09 17:08:35 [debug] 3900#0: *1 http write filter 00000000
2010/11/09 17:08:35 [debug] 3900#0: *1 http copy filter: 0 "/test/v1/lookup/?method=listConnectedCountries"
2010/11/09 17:08:35 [debug] 3900#0: *1 http finalize request: 0, "/test/v1/lookup/?method=listConnectedCountries" a:1, c:1
2010/11/09 17:08:35 [debug] 3900#0: *1 set http keepalive handler
2010/11/09 17:08:35 [debug] 3900#0: *1 http close request


Thank you in advance for your help.