[Varnish] #1001: Varnish 3.0.1 crashes in http_GetHdr

Varnish varnish-bugs at varnish-cache.org
Wed Aug 31 21:33:11 CEST 2011


#1001: Varnish 3.0.1 crashes in http_GetHdr
----------------------+-----------------------------------------------------
 Reporter:  anders    |       Owner:       
     Type:  defect    |      Status:  new  
 Priority:  high      |   Milestone:       
Component:  varnishd  |     Version:  3.0.1
 Severity:  critical  |    Keywords:       
----------------------+-----------------------------------------------------

Comment(by anders):

 When this happens, the last lines outputted by varnishlog -O was:

 {{{
   395 RxHeader     c Accept-Encoding: gzip, deflate
   395 RxHeader     c Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
   395 RxHeader     c Connection: keep-alive
   395 RxHeader     c Referer: http://www.aftenbladet.no/
   395 RxHeader     c Cookie: rsi_segs=; xtvrn=$398888$
   395 RxHeader     c If-Modified-Since: Wed, 31 Aug 2011 18:07:49 GMT
   395 RxHeader     c Cache-Control: max-age=0
   395 VCL_call     c recv
   395 VCL_acl      c NO_MATCH nocacheclients
   395 VCL_return   c lookup
   395 VCL_call     c hash
   395 Hash         c
 /incoming/article2857960.ece/ALTERNATES/w680c169/halltoll.jpg
   395 Hash         c www.aftenbladet.no
   395 VCL_return   c hash
   395 VCL_call     c miss
   395 VCL_return   c fetch
   398 BackendOpen  b sa 80.91.37.197 64009 80.91.41.74 80
   395 Backend      c 398 sa sa
   398 TxRequest    b GET
   398 TxURL        b
 /incoming/article2857960.ece/ALTERNATES/w680c169/halltoll.jpg
   398 TxProtocol   b HTTP/1.1
   398 TxHeader     b Host: mediahash2.aftenbladet.no
   398 TxHeader     b User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64;
 rv:6.0) Gecko/20100101 Firefox/6.0
   398 TxHeader     b Accept: image/png,image/*;q=0.8,*/*;q=0.5
   398 TxHeader     b Accept-Language: nb-no,nb;q=0.9,no-no;q=0.8,no;q=0.6
 ,nn-no;q=0.5,nn;q=0.4,en-us;q=0.3,en;q=0.1
   398 TxHeader     b Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
   398 TxHeader     b Referer: http://www.aftenbladet.no/
   398 TxHeader     b Cookie: rsi_segs=; xtvrn=$398888$
   398 TxHeader     b X-Varnish: 534089652
   398 TxHeader     b Accept-Encoding: gzip
 }}}

 The last request from Varnish as seen from ngrep:

 {{{
 T 80.91.37.197:64009 -> 80.91.41.74:80 [AP]
 GET /incoming/article2857960.ece/ALTERNATES/w680c169/halltoll.jpg
 HTTP/1.1.
 Host: mediahash2.aftenbladet.no.
 User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:6.0) Gecko/20100101
 Firefox/6
 .0.
 Accept: image/png,image/*;q=0.8,*/*;q=0.5.
 Accept-Language: nb-no,nb;q=0.9,no-no;q=0.8,no;q=0.6,nn-no;q=0.5,nn;q=0.4
 ,en-us;
 q=0.3,en;q=0.1.
 Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7.
 Referer: http://www.aftenbladet.no/.
 Cookie: rsi_segs=; xtvrn=$398888$.
 X-Varnish: 534089652.
 Accept-Encoding: gzip.
 }}}

 And the response:

 {{{
 T 80.91.41.74:80 -> 80.91.37.197:64009 [A]
 HTTP/1.1 200 OK.
 Date: Wed, 31 Aug 2011 19:12:11 GMT.
 Server: Apache-Coyote/1.1.
 Last-Modified: Wed, 31 Aug 2011 18:10:15 GMT.
 Cache-Control: public, max-age=31536000.
 Content-Type: image/jpeg.
 Content-Length: 38891.
 Set-Cookie: JSESSIONID=E5FBDEB1DA51A5C3431A9520E31385D6; Path=/sa.
 X-Backend: saweb3.
 Connection: close.
 .
 ......JFIF.............C.
 (picture data..)
 }}}

 A gdb trace (gdb attached to process) with this particular crash:

 {{{
 Program received signal SIGSEGV, Segmentation fault.
 [Switching to Thread 806640b80 (LWP 101300)]
 0x00000008008c9e7f in getframeaddr (level=Variable "level" is not
 available.
 ) at execinfo.c:273
 273         case 2: return __builtin_frame_address(3);
 (gdb) bt
 #0  0x00000008008c9e7f in getframeaddr (level=Variable "level" is not
 available.
 ) at execinfo.c:273
 #1  0x00000008008c9ebc in backtrace (buffer=Variable "buffer" is not
 available.
 ) at execinfo.c:53
 #2  0x000000000042d849 in pan_ic (func=0x455df0 "http_GetHdr",
     file=0x4557f0 "cache_http.c", line=266, cond=0x455900 "l == strlen(hdr
 + 1)",
     err=Variable "err" is not available.
 ) at cache_panic.c:283
 #3  0x0000000000429afc in http_GetHdr (hp=0x80907b3e8,
     hdr=0x807060e42 ".91.37.197", ptr=0x7ffff3b8b4c8) at cache_http.c:266
 #4  0x000000000043339f in VRY_Match (sp=0x80907b008,
     vary=0x807060e40 "80.91.37.197") at cache_vary.c:192
 #5  0x000000000042630b in HSH_Lookup (sp=0x80907b008, poh=0x7ffff3b8b580)
     at cache_hash.c:358
 #6  0x0000000000414592 in cnt_lookup (sp=0x80907b008) at
 cache_center.c:1088
 #7  0x0000000000417aaf in CNT_Session (sp=0x80907b008) at steps.h:38
 #8  0x0000000000430221 in wrk_do_cnt_sess (w=0x7ffff3b9ec80, priv=Variable
 "priv" is not available.
 )
     at cache_pool.c:301
 #9  0x000000000042f3ba in wrk_thread_real (qp=0x801213600,
 shm_workspace=Variable "shm_workspace" is not available.
 )
     at cache_pool.c:184
 #10 0x0000000800e61511 in pthread_getprio () from /lib/libthr.so.3
 #11 0x0000000000000000 in ?? ()
 Error accessing memory address 0x7ffff3b9f000: Bad address.
 (gdb) frame 4
 #4  0x000000000043339f in VRY_Match (sp=0x80907b008,
     vary=0x807060e40 "80.91.37.197") at cache_vary.c:192
 192                             i = http_GetHdr(sp->http, (const
 char*)(vary+2), &h);
 (gdb) print sp->http
 $1 = (struct http *) 0x80907b3e8
 (gdb) print *sp->http
 $2 = {magic = 1680389577, logtag = HTTP_Rx, ws = 0x80907b080, hd =
 0x80907b410,
   hdf = 0x80907b810 "", shd = 64, nhd = 14, status = 0, protover = 11
 '\v',
   conds = 0 '\0'}
 (gdb) print vary
 $3 = (const uint8_t *) 0x807060e40 "80.91.37.197"
 (gdb) print *vary
 $4 = 56 '8'
 (gdb) print *sp
 $5 = {magic = 741317722, fd = 384, id = 384, xid = 534089653, restarts =
 0,
   esi_level = 0, disable_esi = 0, hash_ignore_busy = 0 '\0',
   hash_always_miss = 0 '\0', wrk = 0x7ffff3b9ec80, sockaddrlen = 16,
   mysockaddrlen = 128, sockaddr = 0x80907b2e8, mysockaddr = 0x80907b368,
   mylsock = 0x8012224f0, addr = 0x80907bcb8 "80.202.232.18",
   port = 0x80907bcc8 "3166", client_identity = 0x0, doclose = 0x0,
   http = 0x80907b3e8, http0 = 0x80907b850, ws = {{magic = 905626964,
 overflow = 0,
       id = 0x453366 "sess", s = 0x80907bcb8 "80.202.232.18", f =
 0x80907bfa8 "",
       r = 0x80908bcb8 "", e = 0x80908bcb8 ""}}, ws_ses = 0x80907bcd0
 "GET",
   ws_req = 0x80907bf78 "Accept-Encoding: gzip",
   digest = "A�f\201Lw�-p\031/�hq*�\032\210l\202\213^�*Vp\217�xJqO",
   vary_b = 0x80907bfa8 "", vary_l = 0x0, vary_e = 0x80908bcb8 "", htc = {{
       magic = 1041886673, fd = 384, maxbytes = 32768, maxhdr = 4096,
       ws = 0x80907b080, rxbuf = {b = 0x80907bcd0 "GET", e = 0x80907bf75
 ""},
       pipeline = {b = 0x0, e = 0x0}}}, t_open = 1314817931.3116455,
   t_req = 1314817931.3199937, t_resp = nan(0x8000000000000),
   t_end = 1314817931.3116455, exp = {ttl = -1, grace = 21600, keep = -1,
 age = 0,
     entered = 0}, step = STP_LOOKUP, cur_method = 0, handling = 3,
   sendbody = 0 '\0', wantbody = 1 '\001', err_code = 0, err_reason = 0x0,
 list = {
     vtqe_next = 0x0, vtqe_prev = 0x0}, director = 0x801213978, vbc = 0x0,
   obj = 0x0, objcore = 0x0, vcl = 0x80139ee28, hash_objhead = 0x0,
   mem = 0x80907b000, workreq = {list = {vtqe_next = 0x0, vtqe_prev = 0x0},
     func = 0x430160 <wrk_do_cnt_sess>, priv = 0x80907b008}, acct_tmp =
 {first = 0,
     sess = 1, req = 1, pipe = 0, pass = 0, fetch = 0, hdrbytes = 0,
 bodybytes = 0},
   acct_req = {first = 0, sess = 0, req = 0, pipe = 0, pass = 0, fetch = 0,
     hdrbytes = 0, bodybytes = 0}, acct_ses = {first = 1314817931.3116455,
 sess = 0,
     req = 0, pipe = 0, pass = 0, fetch = 0, hdrbytes = 0, bodybytes = 0}}
 (gdb) print h
 $8 = 0x42d295 "�E\020\001"
 (gdb) print *h
 $9 = -57 '�'
 }}}

 So it doesn't seem to be a Vary header?

-- 
Ticket URL: <http://www.varnish-cache.org/trac/ticket/1001#comment:8>
Varnish <http://varnish-cache.org/>
The Varnish HTTP Accelerator




More information about the varnish-bugs mailing list