$request_time is 0.000 with gzip/chunked?

[Robert Coup]

Hey folks,

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.

curl -v --compressed http://192.168.56.101/big.html > /dev/null
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
> GET /big.html HTTP/1.1
> User-Agent: curl/7.30.0
> Host: 192.168.56.101
> Accept: */*
> Accept-Encoding: deflate, gzip
>
< HTTP/1.1 200 OK
< Server: nginx/1.5.9
< Date: Wed, 29 Jan 2014 19:13:48 GMT
< Content-Type: text/html
< Last-Modified: Thu, 28 Nov 2013 09:05:23 GMT
< Transfer-Encoding: chunked
< Connection: keep-alive
< Content-Encoding: gzip

curl -v http://192.168.56.101/big.html > /dev/null
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
> GET /big.html HTTP/1.1
> User-Agent: curl/7.30.0
> Host: 192.168.56.101
> Accept: */*
>
< HTTP/1.1 200 OK
< Server: nginx/1.5.9
< Date: Wed, 29 Jan 2014 19:14:19 GMT
< Content-Type: text/html
< Content-Length: 79645024
< Last-Modified: Thu, 28 Nov 2013 09:05:23 GMT
< Connection: keep-alive
< ETag: "52970753-4bf4960"
< Accept-Ranges: bytes

Happens on both OSX 10.9 and Linux/2.6 with latest master (498c331c).

Simplest steps to reproduce:
1. ./configure; make; make install
2. edit default nginx.conf and:
  - add "$request_time" to the main log_format (:23)
  - enable the access log (:25)
  - enable gzip (:33)
3. setup a decent sized file/symlink as html/big.html, it needs a .html
extension to get gzipped. Mine was 80MB.
4. start the server
5. curl -v --compressed http://localhost/big.html > /dev/null
6. curl -v http://localhost/big.html > /dev/null

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.

With "chunked_transfer_encoding off":

curl -v --compressed http://192.168.56.101/big.html > /dev/null
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
> GET /big.html HTTP/1.1
> User-Agent: curl/7.30.0
> Host: 192.168.56.101
> Accept: */*
> Accept-Encoding: deflate, gzip
>
< HTTP/1.1 200 OK
< Server: nginx/1.5.9
< Date: Wed, 29 Jan 2014 19:16:12 GMT
< Content-Type: text/html
< Last-Modified: Thu, 28 Nov 2013 09:05:23 GMT
< Connection: close
< Content-Encoding: gzip
<

(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)

Thoughts?

Rob :)
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.nginx.org/pipermail/nginx-devel/attachments/20140130/eebdff00/attachment-0001.html>