varnishncsa bad Time taken to serve the request

[César Sepúlveda]

Hi guys!.

we are using varnish 3.0.5 and have an issue with Time taken to serve the
request parameter (%D)

we realized that the varnishncsa log is written before the download is
complete: example


the download:
imac-de-cesar:~ csepulveda$ wget --limit-rate=100k
http://xxx.xxx.com/assets/img/promo-win.jpg
--2014-08-08 09:55:27--  http://xxxx.xxxx.com/assets/img/promo-win.jpg
Resolving xxx.xxx.com... xx.xx.xx.xx.
Connecting to xxx. xxx.com|xx.xx.xx.xx|:80... connected.
HTTP request sent, awaiting response... 200 OK
Length: 383810 (375K) [image/jpeg]
Saving to: ‘promo-win.jpg.2’

100%[=========================================================================>]
383,810      101KB/s   in 3.7s

2014-08-08 09:55:31 (101 KB/s) - ‘promo-win.jpg.2’ saved [383810/383810]


The log:
xx.xx.xx.xx "xx.xx.xx.xx" - [08/Aug/2014:13:55:33 +0000] "GET
http://xxx.xxxx.com/assets/img/promo-win.jpg HTTP/1.0" 200 383810 "-"
"Wget/UNKNOWN (darwin12.2.0)" 0.401839018 miss 0.785520

The download take 3.7 seconds but varnishncsa show 0.785520.watching this
with tail -f we see the log is writen when the download go on 5 or 8
percent.

The varnishncsa format is this:
FORMAT="%h \"%{X-Forwarded-For}i\" %u %t \"%r\" %s %b \"%{Referer}i\"
\"%{User-agent}i\" %{Varnish:time_firstbyte}x %{Varnish:handling}x %D"

what we are doing wrong?
can you help us?

Thanks!.

--
César Sepúlveda
Jefe de Plataforma
Mediastream Chile

Email: csepulveda at mediastre.am
Teléfono: +56 2 24029750
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20140808/df5200e6/attachment.html>