[Varnish] #228: Varnish crashes on assert error in Tcheck

[Varnish]

#228: Varnish crashes on assert error in Tcheck
----------------------+-----------------------------------------------------
 Reporter:  anders    |       Owner:  phk                              
     Type:  defect    |      Status:  new                              
 Priority:  high      |   Milestone:                                   
Component:  varnishd  |     Version:  trunk                            
 Severity:  normal    |    Keywords:  varnish crash assert error Tcheck
----------------------+-----------------------------------------------------
 I am running Varnish trunk/2629 on FreeBSD/amd64 7.0-RELEASE (with
 SCHED_ULE), on Intel hardware. After running for around half an hour, I
 got a crash:

 {{{
 Child said (2, 880): <<Assert error in Tcheck(), cache.h line 661:>>
 Child said (2, 880): <<  Condition((t.b) != 0) not true.>>
 Child said (2, 880): <<  errno = 35 (Resource temporarily unavailable)>>
 }}}

 Backtrace:

 {{{
 (gdb) bt
 #0  0x0000000800d0cfec in thr_kill () from /lib/libc.so.7
 #1  0x0000000800d96c5b in abort () from /lib/libc.so.7
 #2  0x000000080066dcaf in lbv_assert (func=Variable "func" is not
 available.
 ) at assert.c:65
 #3  0x0000000000412fe3 in Tcheck (t={b = 0x0, e = 0x0}) at cache.h:661
 #4  0x0000000000413674 in http_findhdr (hp=0x8f92268b8, l=Variable "l" is
 not available.
 ) at cache_http.c:210
 #5  0x000000000041375b in http_GetHdr (hp=0x8f92268b8,
     hdr=0x539456 "\bExpires:", ptr=0x7ffff399b9f8) at cache_http.c:232
 #6  0x00000000004289c8 in RFC2616_Ttl (sp=0x8215f6008, hp=0x8f92268b8,
     obj=0x8f9226800) at rfc2616.c:138
 #7  0x0000000000428c1e in RFC2616_cache_policy (sp=0x8215f6008,
 hp=0x8f92268b8)
     at rfc2616.c:195
 #8  0x000000000040c77c in cnt_fetch (sp=0x8215f6008) at cache_center.c:342
 #9  0x000000000040d462 in CNT_Session (sp=0x8215f6008) at steps.h:41
 #10 0x00000000004172c8 in wrk_do_one (w=0x7ffff399dad0) at
 cache_pool.c:194
 #11 0x000000000041758d in wrk_thread (priv=0x800f11240) at
 cache_pool.c:247
 #12 0x0000000800a94a88 in pthread_getprio () from /lib/libthr.so.3
 #13 0x0000000000000000 in ?? ()
 Cannot access memory at address 0x7ffff399e000
 (gdb) frame 3
 #3  0x0000000000412fe3 in Tcheck (t={b = 0x0, e = 0x0}) at cache.h:661
 661             AN(t.b);
 (gdb) print t.b
 $1 = 0x0
 (gdb) frame 4
 #4  0x0000000000413674 in http_findhdr (hp=0x8f92268b8, l=Variable "l" is
 not available.
 ) at cache_http.c:210
 210                     Tcheck(hp->hd[u]);
 (gdb) print *hp
 $2 = {magic = 1680389577, ws = 0x8f9226828, conds = 0 '\0', logtag =
 HTTP_Obj,
   status = 301, hd = {{b = 0x0, e = 0x0}, {b = 0x0, e = 0x0}, {
       b = 0x8f9226b48 "HTTP/1.1", e = 0x8f9226b50 ""}, {b = 0x8f9226b51
 "301",
       e = 0x8f9226b54 ""}, {b = 0x8f9226b55 "Moved Permanently",
       e = 0x8f9226b66 ""}, {
       b = 0x8f9226b67 "Date: Fri, 18 Apr 2008 12:20:45 GMT",
       e = 0x8f9226b8a ""}, {
       b = 0x8f9226b8b "Server: Apache/2.2.3 (Debian) Resin/3.0.25",
       e = 0x8f9226bb5 ""}, {b = 0x8f9226bb6 "Pragma: no-cache",
       e = 0x8f9226bc6 ""}, {b = 0x8f9226bc7 "Cache-Control: no-cache",
       e = 0x8f9226bde ""}, {
       b = 0x8f9226bdf "Location:
 /finn/gojsp/gojsp/gojsp/gojsp/gojsp/gojsp/gojsp/gojsp/gojsp/gojsp/gojsp/gojsp/gojsp/gojsp/gojsp/gojsp/gojsp/gojsp/gojsp/gojsp/gojsp/gojsp/gojsp/gojsp/gojsp/gojsp/gojsp/gojsp/gojsp/gojsp/gojs"...,
       e = 0x8f9226fe6 ""}, {b = 0x0, e = 0x0}, {
       b = 0x8f9226fe7 "Content-Type: text/plain", e = 0x8f9226fff ""}, {
       b = 0x0, e = 0x0} <repeats 20 times>}, hdf = '\0' <repeats 31
 times>,
   nhd = 12}
 }}}

 This happened after reducing obj.workspace from 4K to 2K, so it might be
 an object that is too big?

 It would be very nice to be able to log the objects that are too big. The
 one I see here in *hp seems to be have bogus Location field, and should be
 fixed.

-- 
Ticket URL: <http://varnish.projects.linpro.no/ticket/228>
Varnish <http://varnish.projects.linpro.no/>
The Varnish HTTP Accelerator