varnishlog sometimes reports backend logs as client logs

[thoran]

under heavy load, some backend logs are reported as if they were coming from the client. Here is an example:

   10 RxProtocol   c HTTP/1.1
   10 RxStatus     c 200
   10 RxResponse   c OK
   10 RxHeader     c Date: Wed, 21 Jul 2010 13:38:20 GMT
   10 RxHeader     c Status: 200 OK
   10 RxHeader     c Connection: close
   10 RxHeader     c Vary: X-Ftn-Is-Logged,Host
   10 RxHeader     c ETag: "a23d4243273da489d81423ee54c17767"
   10 RxHeader     c p3p: CP="IDC DSP COR ADM DEVi TAIi PSA PSD IVAi IVDi CONi HIS OUR IND CNT"
   10 RxHeader     c X-Varnish-Browser-Cache-Control: no-cache, private
   10 RxHeader     c X-Runtime: 0.45694
   10 RxHeader     c Content-Type: text/html; charset=utf-8
   10 RxHeader     c Content-Length: 27925
   10 RxHeader     c X-Metacache-Key: /items/154r509v8jcbi-gJMQmBre_2Q#Host:www.fotopedia.com#X-Ftn-Is-Logged:yes#
   10 RxHeader     c Cache-Control: public, max-age=604800

This fragment was received from the backend, not from the client. By the way, it obviously looks like an HTTP response. So there is no way it could be an RxStatus?, at best we can see a TxStatus?, when talking to a client.

This bug is easy to reproduce:

• Setup an nginx to serve some static files on localhost:2223
• launch varnish with this:

     varnishd -a *:8543 -b localhost:2223 -F   
  

• hit varnish with apache-bench like this:

   ab -n 100000 -c 50  http://localhost:8543/i/test.html
  

• control for the presence of an absurd log with this:

  varnishlog   -c  -i RxStatus
  

• wait

---

Results:

on my linux vm, I approximately see 1 log every 1000 requests:

[10:14][infrabox] root@infrabox:~# varnishlog   -c  -i RxStatus
   14 RxStatus     c 200
   13 RxStatus     c 200
   13 RxStatus     c 200
   14 RxStatus     c 200
   15 RxStatus     c 200
   21 RxStatus     c 200
   18 RxStatus     c 200
   13 RxStatus     c 200
   13 RxStatus     c 200
   14 RxStatus     c 200
   13 RxStatus     c 200

[thoran]

I forgot to mention one important setting of the nginx configuration. Be sure that nginx answers with

Cache-Control: no-cache

otherwise, varnish will cache the response

[thoran]

on our server, in production, the bug happens much more frequently than here. For requests that hit our backends, 1/20 of their responses are logged as coming from the client.

By the way, we only observed the problem with the response, not with the request (which is correctly logged as being sent to a backend)

[martin]

(In [5160]) Add explicit log flushing when backend connections close to keep log chronology. This is to avoid log lines for the same (reused) FD coming before the closing connection when load is high.

Fixes #739