[Varnish] #583: child process crash and restart

Varnish varnish-bugs at projects.linpro.no
Wed Nov 18 14:37:22 CET 2009


#583: child process crash and restart
----------------------+-----------------------------------------------------
 Reporter:  nidosaur  |       Owner:  phk              
     Type:  defect    |      Status:  new              
 Priority:  normal    |   Milestone:  After Varnish 2.1
Component:  varnishd  |     Version:  2.0              
 Severity:  normal    |    Keywords:  2.0.4 2.0.5      
----------------------+-----------------------------------------------------
 Debian Lenny kernel 2.6.26-2-686-bigmem #1 SMP on DELL R710 8Go RAM

 Varnish was installed in 2.0.5 in production. Memory Consumption was 1.2Go
 / 8Go and regulary we got message sayinhg child died
 /var/log/messages
 {{{
 Nov 18 11:01:38 front1 varnishd[2533]: child (2540) Started
 Nov 18 11:01:38 front1 varnishd[2533]: Child (2540) said Closed fds: 3 5 6
 7 10 11 13 14
 Nov 18 11:01:38 front1 varnishd[2533]: Child (2540) said Child starts
 Nov 18 11:01:38 front1 varnishd[2533]: Child (2540) said managed to mmap
 2147479552 bytes of 2147479552
 Nov 18 11:01:38 front1 varnishd[2533]: Child (2540) said Ready
 Nov 18 11:11:57 front1 varnishd[2533]: Child (2540) died signal=3
 Nov 18 11:11:57 front1 varnishd[2533]: child (4201) Started
 Nov 18 11:11:57 front1 varnishd[2533]: Child (4201) said Closed fds: 3 5 6
 7 10 11 13 14
 Nov 18 11:11:57 front1 varnishd[2533]: Child (4201) said Child starts
 Nov 18 11:11:57 front1 varnishd[2533]: Child (4201) said managed to mmap
 2147479552 bytes of 2147479552
 Nov 18 11:11:57 front1 varnishd[2533]: Child (4201) said Ready
 Nov 18 11:18:23 front1 varnishd[2533]: CLI 8 open from telnet
 127.0.0.1:44949 127.0.0.1:6082
 Nov 18 11:18:29 front1 varnishd[2533]: CLI 8 result 200 "help"
 Nov 18 11:18:41 front1 varnishd[2533]: CLI 8 result 200 "param.show"
 Nov 18 11:19:24 front1 varnishd[2533]: Child (4201) died signal=6
 Nov 18 11:19:24 front1 varnishd[2533]: child (5212) Started
 Nov 18 11:19:25 front1 varnishd[2533]: Child (5212) said Closed fds: 3 5 6
 7 8 11 12 14 16
 Nov 18 11:19:25 front1 varnishd[2533]: Child (5212) said Child starts
 Nov 18 11:19:25 front1 varnishd[2533]: Child (5212) said managed to mmap
 2147479552 bytes of 2147479552
 Nov 18 11:19:25 front1 varnishd[2533]: Child (5212) said Ready
 Nov 18 11:23:13 front1 varnishd[2533]: CLI 8 result 500 "quit"
 Nov 18 11:23:13 front1 varnishd[2533]: CLI 8 closed
 Nov 18 11:26:48 front1 varnishd[2533]: Child (5212) said Memory
 exhaustedCLI result = 106
 Nov 18 11:26:51 front1 varnishd[2533]: Child (5212) said Memory
 exhaustedCLI result = 106
 Nov 18 11:26:53 front1 varnishd[2533]: Child (5212) said Memory
 exhaustedCLI result = 106
 Nov 18 11:27:08 front1 varnishd[2533]: Child (5212) said Memory
 exhaustedCLI result = 106
 Nov 18 11:27:13 front1 varnishd[2533]: Child (5212) said Memory
 exhaustedCLI result = 106
 Nov 18 11:27:24 front1 varnishd[2533]: Child (5212) said Memory
 exhaustedCLI result = 106
 Nov 18 11:27:36 front1 varnishd[2533]: Child (5212) died signal=6
 Nov 18 11:27:36 front1 varnishd[2533]: child (6344) Started
 Nov 18 11:27:36 front1 varnishd[2533]: Child (6344) said Closed fds: 3 5 6
 7 10 11 13 14
 Nov 18 11:27:36 front1 varnishd[2533]: Child (6344) said Child starts
 Nov 18 11:27:36 front1 varnishd[2533]: Child (6344) said managed to mmap
 2147479552 bytes of 2147479552
 Nov 18 11:27:36 front1 varnishd[2533]: Child (6344) said Ready
 Nov 18 11:40:31 front1 varnishd[2533]: Child (6344) died signal=6
 Nov 18 11:40:31 front1 varnishd[2533]: child (8013) Started
 Nov 18 11:40:31 front1 varnishd[2533]: Child (8013) said Closed fds: 3 5 6
 7 10 11 13 14
 Nov 18 11:40:31 front1 varnishd[2533]: Child (8013) said Child starts
 Nov 18 11:40:31 front1 varnishd[2533]: Child (8013) said managed to mmap
 2147479552 bytes of 2147479552
 Nov 18 11:40:31 front1 varnishd[2533]: Child (8013) said Ready

 }}}
 /var/log/syslog with varnish 2.0.5

 {{{
 Nov 18 08:45:59 front1 varnishd[8364]: Child (8365) Panic message: Assert
 error in add_objexp(), cache_expire.c line 114:#012  Condition((o->objexp)
 != 0) not true.#012errno = 12 (Cannot allocate memory)#012thread = (cache-
 worker)#012Backtrace:#012  0x80693b1: pan_ic+13a#012  0x805e63d:
 add_objexp
 +1b9#012  0x805eb86: EXP_Insert+12b#012  0x805a17e: cnt_fetch+550#012
 0x805c121: CNT_Session+665#012  0x806ae57: wrk_do_cnt_sess+158#012
 0x806a89a:
  wrk_thread+51c#012  0xb7ec24c0: _end+afe0c4f8#012sp = 0x22d15004 {#012
 fd = 321, id = 321, xid = 1406669065,#012  client =
 195.93.102.42:44774,#012
   step = STP_FETCH,#012  handling = pass,#012  err_code = 200, err_reason
 = (null),#012  restarts = 0, esis = 0#012  ws = 0x22d15050 { #012    id =
 "
 sess",#012    {s,f,r,e} = {0x22d15544,+419,(nil),+16384},#012  },#012
 http[req] = {#012    ws = 0x22d15050[sess]#012      "HEAD",#012
 "/img/blo
 gs/ico_cine.jpg",#012      "HTTP/1.1",#012      "User-Agent: Mozilla/4.0
 (compatible; MSIE 7.0; AOL 9.0; Windows NT 5.1; Trident/4.0; .NET CLR
 1.1.43
 22; MSN Optimized;FR; .NET CLR 2.0.50727; .NET CLR 3.0.4506.2152; .NET CLR
 3.5.30729)",#012      "Accept-Encoding: gzip, deflate",#012      "Via: HTT
 P/1.1 cache-prs-ab10.proxy.aol.com[C35D662A] (Traffic-Server/6.1.5
 [uScM])",#012      "Host: ANONYMOUS"",#012  },#012  worker = 0x403f138#01
 2    vcl = {#012      srcname = {#012        "input",#012
 "Default",#012      },#012    },#012  obj = 0x8f7d8000 {#012    refcnt =
 2, xid = 14
 06669065,#012    ws = 0x8f7d8018 { #012      id = "obj",#012
 {s,f,r,e} = {0x8f7d81f4,+192,(nil),+7692},#012    },#012    http[obj] =
 {#012
 ws = 0x8f7d8018[obj]#012        "HTTP/1.1",#012        "200",#012
 "OK",#012        "Date: Wed, 18 Nov 2009 07:45:59 GMT",#012
 "Server:
 Apache",#012        "Last-Modified: Wed, 09 Jul 2008 10:05:20 GMT",#012
 "ETag: "24a9a0-1972-4519472361800"",#012        "Content-Type: image/j
 peg",#012        "Content-Length: 6514",#012    },#012    len = 6514,#012
 store = {#012      6514 {#012
 Nov 18 08:45:59 front1 varnishd[8364]: Child cleanup complete


 Panic message: Missing errorhandling code in alloc_smf(), storage_file.c
 line 427:#012  Condition((sp2) != 0) not true.errno = 12 (Cannot allocate
 memory)#012thread = (cache-worker)#012Backtrace:#012  0x80693b1:
 pan_ic+13a#012  0x80846c9: alloc_
 smf+255#012  0x80857a2: smf_alloc+c9#012  0x8082cd1: STV_alloc+7d#012
 0x8061a46: HSH_Prealloc+38c#012  0x8062599: HSH_Lookup+299#012  0x805a7f8:
 cnt
 _lookup+1a6#012  0x805c079: CNT_Session+5bd#012  0x806ae57:
 wrk_do_cnt_sess+158#012  0x806a89a: wrk_thread+51c#012sp = 0x1b810004
 {#012  fd = 104, id
  = 104, xid = 899199840,#012  client = 83.193.205.241:53623,#012  step =
 STP_LOOKUP,#012  handling = hash,#012  err_code = 200, err_reason =
 (null),#
 012  restarts = 0, esis = 0#012  ws = 0x1b810050 { #012    id =
 "sess",#012    {s,f,r,e} = {0x1b810544,+935,(nil),+16384},#012  },#012
 http[req] = {
 #012    ws = 0x1b810050[sess]#012      "GET",#012
 "bottom_bloc_bleu_long.gif",#012      "HTTP/1.1",#012      "Accept:
 */*",#012
    "Referer: http://ANONYMOUS",#012      "Accept-Language: fr",#012
 "User-Agent: Mozilla/4.0 (compatible; MSIE 8.0; Wi
 ndows NT 6.0; Trident/4.0; SLCC1; .NET CLR 2.0.50727; Media Center PC 5.0;
 .NET CLR 3.5.30729; .NET CLR 3.0.30618)",#012      "Accept-Encoding: gzip,
  deflate",#012      "Host: www.ANONYMOUS",#012      "Connection: Keep-
 Alive",#012  },#012  worker = 0x230fb138#012    vcl = {#012      srcname
 = {#012        "input",#012        "Default",#012      },#012
 },#012},#012
 Nov 18 08:58:32 front1 varnishd[8364]: Child cleanup complete
 Nov 18 08:58:32 front1 varnishd[8364]: child (16931) Started
 Nov 18 08:58:32 front1 varnishd[8364]: Child (16931) said Closed fds: 3 5
 6 7 10 11 13 14
 Nov 18 08:58:32 front1 varnishd[8364]: Child (16931) said Child starts
 Nov 18 08:58:32 front1 varnishd[8364]: Child (16931) said managed to mmap
 2147479552 bytes of 2147479552
 Nov 18 08:58:32 front1 varnishd[8364]: Child (16931) said Ready
 Nov 18 09:07:09 front1 varnishd[8364]: Child (16931) died signal=6
 Nov 18 09:07:09 front1 varnishd[8364]: Child (16931) Panic message:
 Missing errorhandling code in VBE_NewConn(), cache_backend.c line 214:#012
 Condi
 tion((vc) != 0) not true.errno = 12 (Cannot allocate memory)#012thread =
 (cache-worker)#012Backtrace:#012  0x80693b1: pan_ic+13a#012  0x8052f70:
 VBE_
 NewConn+123#012  0x80538d4: VBE_GetVbe+373#012  0x805dffa:
 vdi_simple_getfd+1ca#012  0x8053550: VBE_GetFd+17e#012  0x8060e90:
 Fetch+38d#012  0x8059e2
 e: cnt_fetch+200#012  0x805c121: CNT_Session+665#012  0x806ae57:
 wrk_do_cnt_sess+158#012  0x806a89a: wrk_thread+51c#012sp = 0x20b6f004
 {#012  fd = 32
 9, id = 329, xid = 1613131390,#012  client = 90.1.41.205:2341,#012  step =
 STP_FETCH,#012  handling = fetch,#012  err_code = 200, err_reason = (null)
 ,#012  restarts = 0, esis = 0#012  ws = 0x20b6f050 { #012    id =
 "sess",#012    {s,f,r,e} = {0x20b6f544,+1162,(nil),+16384},#012  },#012
 http[req]
 = {#012    ws = 0x20b6f050[sess]#012      "GET",#012
 "86.jpg.jpg",#012      "HTTP/1.1",#012      "Host: www.ANONYMOUS",#012
 "User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; fr; rv:1.9.0.1
 5) Gecko/2009101601 Firefox/3.0.15",#012      "Accept:
 image/png,image/*;q=0.8,*/*;q=0.5",#012      "Accept-Language: fr,fr-
 fr;q=0.8,en-us;q=0.5,en;q
 =0.3",#012      "Accept-Encoding: gzip,deflate",#012      "Accept-Charset:
 ISO-8859-1,utf-8;q=0.7,*;q=0.7",#012      "Keep-Alive: 300",#012      "Con
 nection: keep-alive",#012      "Referer: http://www.ANONYMOUS",#012
 },#012  worker = 0x1a4fc138#012    v
 cl = {#012      srcname = {#012        "input",#012        "Default",#012
 },#012    },#012  obj = 0x82ff8000 {#012    refcnt = 1, xid = 16131313
 90,#012    ws = 0x82ff8018 { #012      id = "obj",#012      {s,f,r,e} =
 {0x82ff81f4,0x82ff81f4,(nil),+7692},#012    },#012    http[obj] = {#012
 ws = 0x82ff8018[obj]#012    },#012    len = 0,#012    store = {#012
 },#012  },#012},#012
 Nov 18 09:07:09 front1 varnishd[8364]: Child cleanup complete
 Nov 18 09:07:09 front1 varnishd[8364]: child (18071) Started

 }}}


 /var/log/syslog with varnish 2.0.4
 {{{
 Nov 18 13:36:41 front1 varnishd[2809]: Child (2810) Panic message: Assert
 error in add_objexp(), cache_expire.c line 114:#012  C
 ondition((o->objexp) != 0) not true.  errno = 12 (Cannot allocate memory)
 thread = (cache-worker)sp = 0x16756004 {#012  fd = 11  7, id = 117, xid =
 1158858687,#012  client = 90.34.68.204:49789,#012  step = STP_FETCH,#012
 handling = deliver,#012  err_code =   200, err_reason = (null),#012  ws =
 0x1675604c { #012    id = "sess",#012    {s,f,r,e} =
 {0x16756534,,+1348,(nil),+16384},#012    },#012    worker = 0x8047138
 {#012    },#012    vcl = {#012      srcname = {#012        "input",#012
 "Default",#012        },#012    },#012  obj = 0x71db0000 {#012    refcnt =
 2, xid = 1158858687,#012    ws = 0x71db0018 { #012      id = "obj",#012
 {s,f,r,e} = {0x71db01ec,,+191,(nil),+7700},#012    },#012    http = {#012
 ws = 0x71db0018 { #012        id = "obj",#012          {s,f,r,e} =
 {0x71db01ec,,+191,(nil),+7700},#012      },#012      hd = {#012
 "Date: Wed, 18 Nov 2009 12:36:41 GMT",  #012        "Server: Apache",#012
 "Last-Modified: Wed, 18 Nov 2009 05:42:34 GMT",#012        "ETag:
 "55f751-db8-4789eb59d  6680"",#012        "Content-Type: image/jpeg",#012
 "Content-Length: 3512",#012      },#012    },#012    len = 3512,#012
 store = {#012      3512 {#012        ff d8 ff e0 00 10 4a 46 49 46 00 01
 01 00 00 01 |......JFIF......|#012        00 01 00 00   ff fe 00 3b 43 52
 45 41 54 4f 52 3a |.......;CREATOR:|#012        20 67 64 2d 6a 70 65 67 20
 76 31 2e 30 20 28 75 | gd-jpeg v1.  0 (u|#012        73 69 6e 67 20 49 4a
 47 20 4a 50 45 47 20 76 36 |sing IJG JPEG v6|#012        [3448 more]#012
 },#012    },  #012  },#012},#012


 Nov 18 13:40:27 front1 varnishd[2809]: Child (6271) died signal=6
 Nov 18 13:40:27 front1 varnishd[2809]: Child (6271) Panic message: Missing
 errorhandling code in HSH_Copy(), cache_hash.c line 1  60:#012
 Condition((oh->hash) != 0) not true.  errno = 12 (Cannot allocate memory)
 thread = (cache-worker)sp = 0x1b74c004 {#012    fd = 418, id = 418, xid =
 373195725,#012  client = 195.5.200.5:3803,#012  step = STP_LOOKUP,#012
 handling = hash,#012  ws = 0  x1b74c04c { #012    id = "sess",#012
 {s,f,r,e} = {0x1b74c534,,+1286,(nil),+16384},#012  },#012    worker =
 0xbe7ff138 {#012      },#012    vcl = {#012      srcname = {#012
 "input",#012        "Default",#012      },#012    },#012},#012
 Nov 18 13:40:27 front1 varnishd[2809]: Child cleanup complete
 Nov 18 13:40:27 front1 varnishd[2809]: child (6754) Started

 }}}

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


More information about the varnish-bugs mailing list