<div dir="ltr">Hey folks,<div><br></div><div>I get a zero $request_time in the access log for gzipped+chunked transfer requests if nothing else is running (ie. ngx_time_update() doesn't get called for another request or something else). If I don't send Accept-Encoding with my request I get the expected time.</div>
<div><br></div><div>curl -v --compressed <a href="http://192.168.56.101/big.html">http://192.168.56.101/big.html</a> > /dev/null<br></div><div>192.168.56.1 - - [30/Jan/2014:07:56:24 +1300] "GET /big.html HTTP/1.1" 200 77859237 "-" "curl/7.30.0" "-" reqtime=0.000<br>
</div><div><div>> GET /big.html HTTP/1.1</div><div>> User-Agent: curl/7.30.0</div><div>> Host: 192.168.56.101</div><div>> Accept: */*</div><div>> Accept-Encoding: deflate, gzip</div><div>></div><div>< HTTP/1.1 200 OK</div>
<div>< Server: nginx/1.5.9<br></div><div>< Date: Wed, 29 Jan 2014 19:13:48 GMT</div><div>< Content-Type: text/html</div><div>< Last-Modified: Thu, 28 Nov 2013 09:05:23 GMT</div><div>< Transfer-Encoding: chunked</div>
<div>< Connection: keep-alive</div><div>< Content-Encoding: gzip</div></div><div><br></div><div>curl -v <a href="http://192.168.56.101/big.html">http://192.168.56.101/big.html</a> > /dev/null<br></div><div>192.168.56.1 - - [29/Jan/2014:17:18:29 +1300] "GET /big.html HTTP/1.1" 200 79645024 "-" "curl/7.30.0" "-" reqtime=2.550<br>
</div><div><div>> GET /big.html HTTP/1.1</div><div>> User-Agent: curl/7.30.0</div><div>> Host: 192.168.56.101</div><div>> Accept: */*</div><div>></div><div>< HTTP/1.1 200 OK</div><div>< Server: nginx/1.5.9<br>
</div><div>< Date: Wed, 29 Jan 2014 19:14:19 GMT</div><div>< Content-Type: text/html</div><div>< Content-Length: 79645024</div><div>< Last-Modified: Thu, 28 Nov 2013 09:05:23 GMT</div><div>< Connection: keep-alive</div>
<div>< ETag: "52970753-4bf4960"</div><div>< Accept-Ranges: bytes</div></div><div><br></div><div>Happens on both OSX 10.9 and Linux/2.6 with latest master (498c331c).<br></div><div><br></div><div>Simplest steps to reproduce:</div>
<div>1. ./configure; make; make install</div><div>2. edit default nginx.conf and:</div><div>  - add "$request_time" to the main log_format (:23)</div><div>  - enable the access log (:25)<br></div><div>  - enable gzip (:33)</div>
<div>3. setup a decent sized file/symlink as html/big.html, it needs a .html extension to get gzipped. Mine was 80MB.<br></div><div>4. start the server</div><div>5. curl -v --compressed <a href="http://localhost/big.html">http://localhost/big.html</a> > /dev/null</div>
<div>6. curl -v <a href="http://localhost/big.html">http://localhost/big.html</a> > /dev/null</div><div><br></div><div>If I set chunked_transfer_encoding off then I get non-zero request times again, so I suspect it's more something to do with that, and gzip is enabling chunked by default.</div>
<div><br></div><div>With "chunked_transfer_encoding off":</div><div><br></div><div>curl -v --compressed <a href="http://192.168.56.101/big.html">http://192.168.56.101/big.html</a> > /dev/null<br></div><div>192.168.56.1 - - [30/Jan/2014:08:16:24 +1300] "GET /big.html HTTP/1.1" 200 77839928 "-" "curl/7.30.0" "-" reqtime=11.8<br>
</div><div><div>> GET /big.html HTTP/1.1</div><div>> User-Agent: curl/7.30.0</div><div>> Host: 192.168.56.101</div><div>> Accept: */*</div><div>> Accept-Encoding: deflate, gzip</div><div>></div><div>< HTTP/1.1 200 OK</div>
<div>< Server: nginx/1.5.9<br></div><div>< Date: Wed, 29 Jan 2014 19:16:12 GMT</div><div>< Content-Type: text/html</div><div>< Last-Modified: Thu, 28 Nov 2013 09:05:23 GMT</div><div>< Connection: close</div>
<div>< Content-Encoding: gzip</div><div><</div></div><div><br></div><div>(the file happens to be symlinked from a host share on a linux VM in this case, hence the slow times, but I get the same results on my local OSX box)</div>
<div><br></div><div>Thoughts?</div><div><br></div><div>Rob :)</div></div>