[Varnish] #1307: Multiple StatSess records in varnishlog (3.0.3plus)

[Varnish]

#1307: Multiple StatSess records in varnishlog (3.0.3plus)
----------------------+-------------------
 Reporter:  scoof     |      Owner:
     Type:  defect    |     Status:  new
 Priority:  normal    |  Milestone:
Component:  varnishd  |    Version:  3.0.3
 Severity:  normal    |   Keywords:  plus
----------------------+-------------------
 I think there's one StatSess record too many here.

 {{{
    13 BackendOpen  b default 127.0.0.1 58234 127.0.0.1 8080
    13 TxRequest    b GET
    13 TxURL        b /
    13 TxProtocol   b HTTP/1.1
    13 TxHeader     b Host: localhost
    13 TxHeader     b User-Agent: lwp-request/6.03 libwww-perl/6.04
    13 TxHeader     b X-Forwarded-For: 127.0.0.1
    13 TxHeader     b X-Varnish: 1565817040
    13 TxHeader     b Accept-Encoding: gzip
    13 RxProtocol   b HTTP/1.1
    13 RxStatus     b 200
    13 RxResponse   b OK
    13 RxHeader     b Date: Thu, 23 May 2013 09:15:11 GMT
    13 RxHeader     b Accept-Ranges: bytes
    13 RxHeader     b Content-Type: text/html
    13 RxHeader     b Content-Length: 1082
    13 RxHeader     b Last-Modified: Wed, 25 Apr 2012 08:55:37 GMT
    13 RxHeader     b Server: Jetty(6.1.24)
    13 Fetch_Body   b 4(length) cls 0 mklen 1
    13 Length       b 1082
    13 BackendReuse b default
     0 WorkThread   - 0x7f41d9efeb10 start
    11 SessionOpen  c 127.0.0.1 42319 :80
    11 ReqStart     c 127.0.0.1 42319 1565817040
    11 RxRequest    c GET
    11 RxURL        c /
    11 RxProtocol   c HTTP/1.1
    11 RxHeader     c TE: deflate,gzip;q=0.3
    11 RxHeader     c Connection: TE, close
    11 RxHeader     c Host: localhost
    11 RxHeader     c User-Agent: lwp-request/6.03 libwww-perl/6.04
    11 VCL_call     c recv lookup
    11 VCL_call     c hash
    11 Hash         c /
    11 Hash         c localhost
    11 VCL_return   c hash
    11 VCL_call     c miss fetch
    11 Backend      c 13 default default
    11 TTL          c 1565817040 RFC 86400 -1 -1 1369300511 0 1369300511 0
 0
    11 VCL_call     c fetch deliver
    11 ObjProtocol  c HTTP/1.1
    11 ObjResponse  c OK
    11 ObjHeader    c Date: Thu, 23 May 2013 09:15:11 GMT
    11 ObjHeader    c Content-Type: text/html
    11 ObjHeader    c Last-Modified: Wed, 25 Apr 2012 08:55:37 GMT
    11 ObjHeader    c Server: Jetty(6.1.24)
    11 VCL_call     c deliver deliver
    11 TxProtocol   c HTTP/1.1
    11 TxStatus     c 200
    11 TxResponse   c OK
    11 TxHeader     c Content-Type: text/html
    11 TxHeader     c Last-Modified: Wed, 25 Apr 2012 08:55:37 GMT
    11 TxHeader     c Server: Jetty(6.1.24)
    11 TxHeader     c Content-Length: 1082
    11 TxHeader     c Accept-Ranges: bytes
    11 TxHeader     c Date: Thu, 23 May 2013 09:15:11 GMT
    11 TxHeader     c X-Varnish: 1565817040
    11 TxHeader     c Age: 0
    11 TxHeader     c Via: 1.1 varnish
    11 TxHeader     c Connection: close
    11 TxHeader     c Content-Length: 1082
    11 Length       c 1082
    11 ReqEnd       c 1565817040 1369300511.216991901 1369300511.222213268
 0.000102758 0.005040407 0.000180960
    11 SessionClose c Connection: close
    11 StatSess     c 127.0.0.1 42319 0 0 0 0 0 0 284 1082
    11 StatSess     c - - 0 1 1 0 0 0 0 0
 }}}

 VCL:

 {{{
 backend default {
  .host = "127.0.0.1";
  .port = "8080";
 }

 sub vcl_fetch {
 set beresp.do_stream=true;
 }
 }}}

 This was found when trying to troubleshoot an issue with thierr1, where it
 seems like the extra StatSess comes earlier, and cuts the log short.
 He's trying to create a reproducible case, and will append to this case if
 successful.

-- 
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1307>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator