[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