nginx page caching not working for responses with valid (rfc 1123 compliant) Expires header

Kunal Pariani kpariani at zimbra.com
Tue Mar 10 19:42:41 UTC 2015 

Hello, 
I am on nginx-1.7.1 & trying to use nginx's page caching feature but run into an issue for responses with a valid 'Expires' header which seem to be in the correct rfc 1123 compliant format. Nginx somehow doesn't like it & hence doesn't cache such responses. Is this a bug ? 

---------------------------------------------------------- 
Config in http block to enable page caching 
---------------------------------------------------------- 
proxy_cache_path /opt/zimbra/data/tmp/nginx/cache keys_zone=zimbra:10m; 
proxy_cache zimbra; 
proxy_cache_key "$scheme$request_method$host$request_uri"; 
proxy_cache_valid 200 302 10m; 
add_header X-Proxy-Cache $upstream_cache_status; 

------------------------------------------------------------------------------------------------------ 
Logs showing that a .css with a valid Expires header doesn't get cached because of header parsing failure 
------------------------------------------------------------------------------------------------------ 
2015/03/10 13:58:29 [debug] 17311#0: *7 http upstream request: "/css/images,common,dwt,msgview,login,zm,spellcheck,skin.css?v=150302053859&debug=false&skin=harmony&locale=en_US" 
2015/03/10 13:58:29 [debug] 17311#0: *7 http upstream send request handler 
2015/03/10 13:58:29 [debug] 17311#0: *7 http upstream send request 
2015/03/10 13:58:29 [debug] 17311#0: *7 chain writer in: 0000000000000000 
2015/03/10 13:58:29 [debug] 17311#0: *7 event timer: 21, old: 1426013969478, new: 1426013969533 
2015/03/10 13:58:29 [debug] 17311#0: *7 http upstream process header 
2015/03/10 13:58:29 [debug] 17311#0: *7 SSL_read: 3904 
2015/03/10 13:58:29 [debug] 17311#0: *7 http proxy status 200 "200 OK" 
2015/03/10 13:58:29 [debug] 17311#0: *7 http proxy header: "Date: Tue, 10 Mar 2015 18:58:29 GMT" 
2015/03/10 13:58:29 [debug] 17311#0: *7 http proxy header: "X-Frame-Options: SAMEORIGIN" 
2015/03/10 13:58:29 [debug] 17311#0: *7 ngx_http_parse_time failed: h->value.data = Thu, 9 Apr 2015 19:58:29 GMT, h->value.len = 28 
2015/03/10 13:58:29 [debug] 17311#0: *7 http proxy header: "Expires: Thu, 9 Apr 2015 19:58:29 GMT" 
2015/03/10 13:58:29 [debug] 17311#0: *7 http proxy header: "Cache-Control: public, max-age=2595600" 
2015/03/10 13:58:29 [debug] 17311#0: *7 http proxy header: "Vary: User-Agent" 
2015/03/10 13:58:29 [debug] 17311#0: *7 http proxy header: "Content-Type: text/css" 
2015/03/10 13:58:29 [debug] 17311#0: *7 http proxy header: "Vary: Accept-Encoding, User-Agent" 
2015/03/10 13:58:29 [debug] 17311#0: *7 http proxy header: "Content-Length: 295693" 
2015/03/10 13:58:29 [debug] 17311#0: *7 http proxy header done 
2015/03/10 13:58:29 [debug] 17311#0: *7 http script var: "MISS" 
2015/03/10 13:58:29 [debug] 17311#0: *7 spdy header filter 
2015/03/10 13:58:29 [debug] 17311#0: *7 malloc: 00000000025EB460:385 
2015/03/10 13:58:29 [debug] 17311#0: *7 spdy deflate out: ni:00000000025EB5C8 no:00000000025D780E ai:0 ao:56 rc:0 
2015/03/10 13:58:29 [debug] 17311#0: *7 spdy:3 create SYN_REPLY frame 00000000025D7858: len:374 
2015/03/10 13:58:29 [debug] 17311#0: *7 http cleanup add: 00000000025D7898 
2015/03/10 13:58:29 [debug] 17311#0: *7 http cacheable: 0 

Code added in src/http/ngx_http_upstream.c to throw the 'ngx_http_parse_time failed' debug 


expires = ngx_http_parse_time(h->value.data, h->value.len); ---> Returns NGX_ERROR 




if (expires == NGX_ERROR || expires < ngx_time()) { 

ngx_log_debug2(NGX_LOG_DEBUG_HTTP, r->connection->log, 0, 

"ngx_http_parse_time failed: h->value.data = %s, h->value.len = %d" , 

h->value.data, h->value.len); 

u->cacheable = 0; ---> sets cacheable to 0 here & hence does not gets cached 

return NGX_OK; 

} 


------------------------------------------------------------------------------------------------------ 
Logs showing that a gif image without Expires header gets cached correctly 
------------------------------------------------------------------------------------------------------ 
2015/03/10 13:58:35 [debug] 17311#0: *7 http upstream request: "/service/zimlet/com_zimbra_email/img/EmailZimlet_busy.gif?" 
2015/03/10 13:58:35 [debug] 17311#0: *7 http upstream process header 
2015/03/10 13:58:35 [debug] 17311#0: *7 SSL_read: 899 
2015/03/10 13:58:35 [debug] 17311#0: *7 SSL_read: -1 
2015/03/10 13:58:35 [debug] 17311#0: *7 SSL_get_error: 2 
2015/03/10 13:58:35 [debug] 17311#0: *7 http proxy status 200 "200 OK" 
2015/03/10 13:58:35 [debug] 17311#0: *7 http proxy header: "Date: Tue, 10 Mar 2015 18:58:35 GMT" 
2015/03/10 13:58:35 [debug] 17311#0: *7 http proxy header: "Content-Type: image/gif" 
2015/03/10 13:58:35 [debug] 17311#0: *7 http proxy header: "Last-Modified: Tue, 03 Mar 2015 01:41:21 GMT" 
2015/03/10 13:58:35 [debug] 17311#0: *7 http proxy header: "Accept-Ranges: bytes" 
2015/03/10 13:58:35 [debug] 17311#0: *7 http proxy header: "Content-Length: 729" 
2015/03/10 13:58:35 [debug] 17311#0: *7 http proxy header done 
2015/03/10 13:58:35 [debug] 17311#0: *7 http ims:1425346881 lm:1425346881 
2015/03/10 13:58:35 [debug] 17311#0: *7 http script var: "MISS" 
2015/03/10 13:58:35 [debug] 17311#0: *7 spdy header filter 
2015/03/10 13:58:35 [debug] 17311#0: *7 malloc: 00000000025C92B0:181 
2015/03/10 13:58:35 [debug] 17311#0: *7 spdy deflate out: ni:00000000025C9365 no:000000000260ECBB ai:0 ao:31 rc:0 
2015/03/10 13:58:35 [debug] 17311#0: *7 spdy:39 create SYN_REPLY frame 000000000260ECF0: len:195 
2015/03/10 13:58:35 [debug] 17311#0: *7 http cleanup add: 000000000260ED30 
2015/03/10 13:58:35 [debug] 17311#0: *7 spdy frame out: 000000000260ECF0 sid:39 prio:5 bl:1 len:195 
2015/03/10 13:58:35 [debug] 17311#0: *7 SSL buf copy: 203 
2015/03/10 13:58:35 [debug] 17311#0: *7 SSL to write: 203 
2015/03/10 13:58:35 [debug] 17311#0: *7 SSL_write: 203 
2015/03/10 13:58:35 [debug] 17311#0: *7 spdy:39 SYN_REPLY frame 000000000260ECF0 was sent 
2015/03/10 13:58:35 [debug] 17311#0: *7 spdy frame sent: 000000000260ECF0 sid:39 bl:1 len:195 
2015/03/10 13:58:35 [debug] 17311#0: *7 http file cache set header 
2015/03/10 13:58:35 [debug] 17311#0: *7 http cacheable: 1 

Thanks 
-Kunal 
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.nginx.org/pipermail/nginx/attachments/20150310/9dcd028e/attachment-0001.html>

More information about the nginx mailing list