[Varnish] #1038: Assert error in ESI_DeliverChild

[Varnish]

#1038: Assert error in ESI_DeliverChild
----------------------+-----------------------------------------------------
 Reporter:  scoof     |       Owner:       
     Type:  defect    |      Status:  new  
 Priority:  normal    |   Milestone:       
Component:  varnishd  |     Version:  trunk
 Severity:  normal    |    Keywords:       
----------------------+-----------------------------------------------------
 Varnish with gzip and esi asserts when doing many ESI requests.

 To recreate, generate ESI files with many ESI includes:

 for a in `seq 1 1000`; do echo "<esi:include src='/esimany$a.html' />" >>
 esimany.html; echo abc$a > esimany$a.html; done

 When varnish is fetching esimany.html and fragments from the backend,
 everything works, but when fetching from cache, it asserts:

 Last panic at: Mon, 24 Oct 2011 14:51:10 GMT
 Assert error in ESI_DeliverChild(), cache_esi_deliver.c line 493:
   Condition((dbits) != 0) not true.
 thread = (cache-worker)
 ident = Linux,3.0.0-1-amd64,x86_64,-smalloc,-smalloc,-hcritbit,epoll
 Backtrace:
   0x42f2d5: pan_ic+d5
   0x41dac1: ESI_DeliverChild+491
   0x432508: RES_WriteObj+4a8
   0x4175f7: CNT_Session+697
   0x41d326: ESI_Deliver+896
   0x432308: RES_WriteObj+2a8
   0x4175f7: CNT_Session+697
   0x430cfd: Pool_Work_Thread+1bd
   0x43fca2: wrk_thread_real+202
   0x7f642bb89b40: _end+7f642b509e10
 sp = 0x7f6420c07040 {
   fd = 15, id = 15, xid = 2007150718,
   client = 127.0.0.1 47825,
   step = STP_DELIVER,
   handling = deliver,
   restarts = 0, esi_level = 1
   flags =
   bodystatus = 0
   ws = 0x7f6420c071a8 {
     id = "sess",
     {s,f,r,e} = {0x7f6420c07c48,+384,(nil),+65536},
   },
   http[req] = {
     ws = 0x7f6420c071a8[sess]
       "GET",
       "/esimany432.html",
       "HTTP/1.1",
       "User-Agent: curl/7.21.7 (x86_64-pc-linux-gnu) libcurl/7.21.7
 OpenSSL/1.0.0e zlib/1.2.3.4 libidn/1.22 libssh2/1.2.8 librtmp/2.3",
       "Host: localhost",
       "Accept: */*",
       "X-Forwarded-For: 127.0.0.1",
       "Accept-Encoding: gzip",
   },
   worker = 0x7f641c7eea20 {
     ws = 0x7f641c7eecf0 { overflow
       id = "wrk",
       {s,f,r,e} = {0x7f641c7dc9d0,+65536,(nil),+65536},
     },
     http[resp] = {
       ws = 0x7f641c7eecf0[wrk]
         "HTTP/1.1",
         "OK",
         "Server: Apache/2.2.21 (Debian)",
         "Last-Modified: Mon, 24 Oct 2011 14:49:56 GMT",
         "ETag: "8815a2-7-4b00c894c3d8e"",
         "Content-Type: text/html",
         "Content-Encoding: gzip",
         "Age: 1",
         "Via: 1.1 varnish",
     },
     },
     vcl = {
       srcname = {
         "input",
         "Default",
       },
     },
   obj = 0x7f641b6d3800 {
     xid = 2007150717,
     ws = 0x7f641b6d3818 {
       id = "obj",
       {s,f,r,e} = {0x7f641b6d39f0,+248,(nil),+280},
     },
     http[obj] = {
       ws = 0x7f641b6d3818[obj]
         "HTTP/1.1",
         "OK",
         "Date: Mon, 24 Oct 2011 14:51:08 GMT",
         "Server: Apache/2.2.21 (Debian)",
         "Last-Modified: Mon, 24 Oct 2011 14:49:56 GMT",
         "ETag: "8815a2-7-4b00c894c3d8e"",
         "Content-Type: text/html",
         "Content-Encoding: gzip",
         "Content-Length: 39",
     },
     len = 39,
     store = {
       39 {
         1f 8b 08 00 00 00 00 00 00 03 02 00 00 00 ff ff |................|
         4a 4c 4a 36 31 36 e2 02 00 00 00 ff ff 03 00 b3 |JLJ616..........|
         b2 c2 7f 07 00 00 00                            |.......|
       },
     },
   },
 },

 It looks like the assert happens at around the same time that varnishlog
 starts logging LostHeader.

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