[Varnish] #739: varnishlog sometimes reports backend logs as client logs

[Varnish]

#739: varnishlog sometimes reports backend logs as client logs
------------------------+---------------------------------------------------
 Reporter:  thoran      |       Owner:  phk  
     Type:  defect      |      Status:  new  
 Priority:  normal      |   Milestone:       
Component:  varnishlog  |     Version:  2.1.2
 Severity:  major       |    Keywords:       
------------------------+---------------------------------------------------
 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 at 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
 }}}

-- 
Ticket URL: <http://varnish-cache.org/ticket/739>
Varnish <http://varnish-cache.org/>
The Varnish HTTP Accelerator