[Varnish] #699: Varnishncsa Will Not Log Certain Requests Due to Out of Sequence (ReqEnd, SessionClose)

[Varnish]

#699: Varnishncsa Will Not Log Certain Requests Due to Out of Sequence (ReqEnd,
SessionClose)
----------------------+-----------------------------------------------------
 Reporter:  osterman  |        Type:  defect     
   Status:  new       |    Priority:  normal     
Milestone:            |   Component:  varnishncsa
  Version:  trunk     |    Severity:  major      
 Keywords:            |  
----------------------+-----------------------------------------------------
 Varnishncsa assumes that a ReqEnd will always happen before a
 SessionClose. Very frequently, a SessionClose happens after a ReqEnd,
 which casues lp->bogus to be set and the log event dropped. This has been
 a problem for us sometime.

 The fix we have implemented is to not rely on the ordering of
 ReqEnd/SessionClose, but instead rely on SessionOpen. When we get a
 SessionOpen, we initialize the *lp pointer, thereby resetting everything.
 Since I'm not that familiar with the varnish source code, I'm not
 submitting a patch as our solution might not be the best.

 Below, you will see ReqEnd before SessionClose. The output was generated
 using varnishlog.


    16 TxProtocol   c HTTP/1.1
    16 TxStatus     c 200
    16 TxResponse   c OK
    16 TxHeader     c Server: Varnish
    16 TxHeader     c Retry-After: 0
    16 TxHeader     c X-Cacheable-URL: /health_check.html
    16 TxHeader     c Content-Type: text/plain; charset=utf-8
    16 TxHeader     c Cache-Control: no-cache, must-revalidate
    16 TxHeader     c Expires: Mon, 26 Jul 1997 05:00:00 GMT
    16 TxHeader     c Content-Length: 2
    16 TxHeader     c Date: Tue, 11 May 2010 00:12:33 GMT
    16 TxHeader     c X-Varnish: 176572510
    16 TxHeader     c Age: 0
    16 TxHeader     c Via: 1.1 varnish
    16 TxHeader     c Connection: close
    16 TxHeader     c X-Served-By: domU-12-31-39-0E-41-C2
    16 TxHeader     c X-Cache: MISS
    16 ReqEnd       c 176572510 1273536753.646451950 1273536753.646547079
 0.000028849 0.000061035 0.000034094
    16 SessionClose c error
    16 StatSess     c 10.240.61.192 35698 0 1 1 0 0 0 387 2
     0 Backend_health - s3_varnish_prod Still healthy 4--X-RH 5 3 5
 0.008935 0.011059 HTTP/1.1 200 OK
    16 SessionOpen  c 127.0.0.1 33707 :80
    16 ReqStart     c 127.0.0.1 33707 176572511
    16 RxRequest    c GET
    16 RxURL        c /s2?q=test
    16 RxProtocol   c HTTP/1.1
    16 RxHeader     c Host: www-qa.host.com
    16 RxHeader     c User-Agent: Mozilla/5.0 (Macintosh; U; Intel Mac OS X
 10.6; en-US; rv:1.9.2.3) Gecko/20100401 Firefox/3.6.3
    16 RxHeader     c Accept:
 text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
    16 RxHeader     c Accept-Language: en-us,en;q=0.5
    16 RxHeader     c Accept-Encoding: gzip,deflate
    16 RxHeader     c Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
    16 RxHeader     c Keep-Alive: 115
    16 RxHeader     c Connection: keep-alive

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