[Varnish] #633: varnishncsa segfaults

[Varnish]

#633: varnishncsa segfaults
---------------------+------------------------------------------------------
 Reporter:  victori  |       Owner:  kristian
     Type:  defect   |      Status:  assigned
 Priority:  normal   |   Milestone:          
Component:  build    |     Version:  trunk   
 Severity:  normal   |    Keywords:          
---------------------+------------------------------------------------------

Comment(by jdzst):

 Hello,

 I think both tickets #633 and #685 are related with same problem.

 I have tested again the problem in production with enviroment:
   => I am testing Varnish (r4576) in Solaris 10 5.10 Generic_120011-14
 sun4v sparc SUNW,Sun-Fire-T2000.

 the problem is that in this Request '''lp->df_m , lp->df_Uq, lp->df_H and
 lp->df_s are NULL'''

 I have Removing the #if 0/#endif around line 390 and segfaults stopped as
 a workaround

 After that, I have changed varnishncsa.c to retrieve more information and
 print all BOGUS requests in log with "BOGUS REQUEST INFO [%s] XID [%u]\n"
 , my testing file is in the previous attachment, and those are the
 results:

 (example)

 varnishncsa output:
 {{{
 87.111.62.154 - - [31/May/2010:16:04:48 +0200] "GET <REQUEST>" 304 0
 - - - [31/May/2010:16:04:49 +0200] BOGUS REQUEST INFO [-] XID [0]
 ====> ERROR (This trace is print in my varnishncsa.c code when bogus==1,
 see attachment)
 85.112.8.250 - - [31/May/2010:16:04:49 +0200] "GET <NEXT REQUEST>" 200
 13715
 }}}

 varnishlog output (extract):
 {{{
    15 SessionOpen  c 87.111.62.154 50132 :8000
    15 ReqStart     c 87.111.62.154 50132 397508944
    15 RxRequest    c GET

 <REQUEST.....>

    15 VCL_call     c recv
    15 VCL_return   c lookup
    15 VCL_call     c hash
    15 VCL_return   c hash
    15 Hit          c 397508913
    15 VCL_call     c hit
    15 VCL_return   c deliver
    15 Length       c 0
    15 VCL_call     c deliver
    15 VCL_return   c deliver
    15 TxProtocol   c HTTP/1.1
    15 TxStatus     c 304
    15 TxResponse   c Not Modified
    15 TxHeader     c Date: Mon, 31 May 2010 14:04:48 GMT
    15 TxHeader     c Last-Modified: Wed, 17 Sep 2008 14:19:30 GMT
    15 TxHeader     c Cache-Control: max-age=345600
    15 TxHeader     c Expires: Fri, 04 Jun 2010 14:04:48 GMT
    15 TxHeader     c Connection: keep-alive
    15 TxHeader     c X-Cache: HIT
    15 ReqEnd       c 397508944 1275314688.964520454 1275314688.965110540
 0.000231504 0.000289917 0.000300169
    15 SessionClose c EOF
    15 ReqEnd       c 0 1275314689.074620008 1275314689.074620008
 0.109509468 0.000000000 0.000000000
    15 StatSess     c 87.111.62.154 50132 0 1 1 0 0 0 285 0
    15 SessionOpen  c 85.112.8.250 60478 :8000
    15 ReqStart     c 85.112.8.250 60478 397508952
    15 RxRequest    c GET

 <NEXT REQUEST.....>

    15 VCL_call     c recv
    15 VCL_return   c lookup
 }}}

 It seems that the root of all problems is when a session is closed because
 of a "SessionClose c EOF" there is always a second "ReqEnd" but empty,
 without XID:

 {{{
    15 ReqEnd       c 397508944 1275314688.964520454 1275314688.965110540
 0.000231504 0.000289917 0.000300169
    15 SessionClose c EOF
    15 ReqEnd       c 0 1275314689.074620008 1275314689.074620008
 0.109509468 0.000000000 0.000000000
 }}}

 I think it must be changed the "varnishncsa" logic, retrieve the XID from
 ReqEnd and ignore request if the xid== 0 avoiding print bad ReqEnd
 entries.

 It would be interesting to print (in standard error) wrong request that
 has bogus==1 but xid!=0

 I will prepare some code and post it in this ticket in order to fix
 varnishncsa ignoring ReqEnd without xid and dumping wrong request in
 stderr.

 The real problem, (when a session is closed because of a "SessionClose c
 EOF" there is always a second "ReqEnd") it is opened in a new ticket #709

-- 
Ticket URL: <http://varnish-cache.org/ticket/633#comment:4>
Varnish <http://varnish-cache.org/>
The Varnish HTTP Accelerator