Panic message: Assert error in VRT_IP_string()
Thiago Figueiro
TFigueiro at au.westfield.com
Tue Nov 30 09:05:20 CET 2010
(long message - heaps of debug goodies - sorry about the length)
Hi there! I've run into some varnish crashes and was hoping someone
could help.
As our site gets busier I have seen Varnish crashing. One thing in
common between the requests was the presence of long Cookies.
I've googled for the errors we get and the best I could come up with was
to increase sess_workspace to 32k and upgrade to 2.1.4 (we were running
2.1.2 when I started seeing the errors about 3 weeks ago).
We're starting varnish with:
/usr/sbin/varnishd -P /var/run/varnish.pid -f /etc/varnish/default.vcl
-T 127.0.0.1:6082 -t 120 -p thread_pools 6 -w 150,3000,120 -u varnish -g
varnish -h classic,91193 -s
file,/var/lib/varnish/varnish_storage.bin,25G -p listen_depth 4096 -p
session_linger 50/100/150 -p sess_workspace 32768 -p lru_interval 60
This is the latest crash message in /var/log/messages:
2010-11-30T12:31:47.093463+11:00 rp1 varnishd[3174]:
Child (3178) Panic message: Assert error in VRT_IP_string(), cache_vrt.c
line 888:
Condition((p = WS_Alloc(sp->http->ws, len)) != 0) not true.
thread = (cache-worker)
ident = Linux,2.6.18-194.26.1.el5,x86_64,-sfile,-hclassic,epoll
Backtrace:
0x423aa6: pan_ic+b6
0x42b8fc: VRT_IP_string+11c
0x2ab0eb904cb8: _end+2ab0eb2916b0
0x428ab3: VCL_recv_method+43
0x41450a: CNT_Session+5ca
0x425e68: wrk_do_cnt_sess+b8
0x42516e: wrk_thread_real+32e
0x2b2c2611573d: _end+2b2c25aa2135
0x2b2c26899f6d: _end+2b2c26226965
sp = 0x2ab0ec07c008 {
fd = 30, id = 30, xid = 508103012,
client = 208.80.194.26 57092,
step = STP_RECV,
handling = deliver,
err_code = 400, err_reason = (null),
restarts = 4, esis = 0
ws = 0x2ab0ec07c080 { overflow
id = "sess",
{s,f,r,e} = {0x2ab0ec07ccd8,+32760,(nil),+32768},
},
http[req] = {
ws = 0x2ab0ec07c080[sess]
"GET",
"/derby/images/derby/downloads/Car_Park_Map_Jan2010.pdf",
"HTTP/1.0",
"User-Agent: Mozilla/4.0 (compatible; MSIE 6.0; America Online
Browser 1.1; rev1.2; Windows NT 5.1; SV1; Fu
nWebProducts; hbtools 4.7.0)",
"Cookie:
%BC%C3%C4%FE%C8%FD%BA%C5%C3%BA%BF%F3%B9%A4%BB%E1=ViewUrl=%2Findex%2Easp;
.ASPXANONYMOUS=S9gNy_-uzAEkAAAAYTQ5ODM3NzgtNDgxYy00ZWQ0LTgyNzAtNjBhZDUyM
2ZjZWI40; 20gp=R3954494786; 240plan=R3762637933; 300gp=R3396056608;
60gp=R525209263;
7c4cd48b6985de8e58134182f87d9d92=b4e9c9c9dcff9b856004afc652d5a0ac;
82690c47ee3cca07192225ab40e9b146=a84911870bc1f0a803596001388321ef;
91489bd6ed9a2e2903386db3df6e1458=3a22e5281e6bbd2adcf9c91aba899fc1;
AA002=001291080700-8970232; ANON_CONFIRM=TRUE; ARPT=LWYXXLSSm2CYLU;
ASP.NET_SessionId=suavbzndghxhvg55fgyfyl55;
ASPSESSIONIDAAABSRDB=AAFEEIMBEICDABKPHIKMKBPH;
ASPSESSIONIDAAADBRDS=CFCEJBCCAAKMDHPLMMBLJMCG;
ASPSESSIONIDAABCQRBD=HHGOAKNBJPADCIICAEEOBBCP;
ASPSESSIONIDAABCSBCR=JFGFLMPBKDAJAMOMJBJJFNHJ;
ASPSESSIONIDAADTCQBD=GKMAFAMBIMBAIFECLGFCHJBL; ASPSESSIO
(entry seems truncated - perhaps maximum syslog message size?)
I managed to find the request in varnishlog:
30 SessionOpen c 208.80.194.26 57092 :80
30 Debug c "herding"
30 ReqStart c 208.80.194.26 57092 508103012
30 RxRequest c GET
30 RxURL c
/derby/images/derby/downloads/Car_Park_Map_Jan2010.pdf
30 RxProtocol c HTTP/1.0
30 RxHeader c Host: uk.westfield.com
30 RxHeader c User-Agent: Mozilla/4.0 (compatible; MSIE 6.0;
America Online Browser 1.1; rev1.2; Windows NT 5.1; SV1; FunWebProducts;
hbtools 4.7.0)
30 RxHeader c Cookie:
%BC%C3%C4%FE%C8%FD%BA%C5%C3%BA%BF%F3%B9%A4%BB%E1=ViewUrl=%2Findex%2Easp;
.ASPXANONYMOUS=S9gNy_-uzAEkAAAAYTQ5ODM3NzgtNDgxYy00ZWQ0LTgyNzAtNjBhZDUyM
2ZjZWI40; 20gp=R3954494786; 240plan=R3762637933; 300gp=R3396056608;
60gp=R525209263; 7c4cd48b6985de8e5
30 VCL_call c recv
30 VCL_return c lookup
30 VCL_call c hash
30 VCL_return c hash
30 VCL_call c miss
30 VCL_return c fetch
30 Backend c 49 centre_rails centre_rail_uschi_app01
49 TxRequest b GET
49 TxURL b
/derby/images/derby/downloads/Car_Park_Map_Jan2010.pdf
49 TxProtocol b HTTP/1.1
49 TxHeader b User-Agent: Mozilla/4.0 (compatible; MSIE 6.0;
America Online Browser 1.1; rev1.2; Windows NT 5.1; SV1; FunWebProducts;
hbtools 4.7.0)
49 TxHeader b X-Forwarded-For: 208.80.194.26
49 TxHeader b X-Forwarded-Host: uk.westfield.com
49 TxHeader b Host: premium.prod.dbg.westfield.com
49 TxHeader b Cookie:
%BC%C3%C4%FE%C8%FD%BA%C5%C3%BA%BF%F3%B9%A4%BB%E1=ViewUrl=%2Findex%2Easp;
.ASPXANONYMOUS=S9gNy_-uzAEkAAAAYTQ5ODM3NzgtNDgxYy00ZWQ0LTgyNzAtNjBhZDUyM
2ZjZWI40; 20gp=R3954494786; 240plan=R3762637933; 300gp=R3396056608;
60gp=R525209263; 7c4cd48b6985de8e5
49 TxHeader b X-Varnish: 508103012
49 RxProtocol b HTTP/1.1
49 RxStatus b 400
49 RxResponse b Bad Request
49 RxHeader b Date: Tue, 30 Nov 2010 01:31:47 GMT
49 RxHeader b Server: Apache
49 RxHeader b Content-Length: 7573
49 RxHeader b Connection: close
49 RxHeader b Content-Type: text/html; charset=iso-8859-1
30 TTL c 508103012 RFC 120 1291080707 0 0 0 0
30 VCL_call c fetch
30 VCL_return c restart
30 ObjProtocol c HTTP/1.1
30 ObjStatus c 400
30 ObjResponse c Bad Request
30 ObjHeader c Date: Tue, 30 Nov 2010 01:31:47 GMT
30 ObjHeader c Content-Type: text/html; charset=iso-8859-1
30 ObjHeader c Server: Apache
49 Length b 7573
49 BackendClose b centre_rail_uschi_app01
30 VCL_call c recv
30 LostHeader c Cookie:
30 VCL_return c lookup
30 VCL_call c hash
30 VCL_return c hash
30 VCL_call c miss
30 VCL_return c fetch
30 Backend c 41 centre_rails centre_rail_uschi_app02
(repeats x4 until varnish crashes and restarts)
30 TTL c 508103012 RFC 120 1291080707 0 0 0 0
30 VCL_call c fetch
30 VCL_return c restart
30 ObjProtocol c HTTP/1.1
30 ObjStatus c 400
30 ObjResponse c Bad Request
30 ObjHeader c Date: Tue, 30 Nov 2010 01:31:47 GMT
30 ObjHeader c Content-Type: text/html; charset=iso-8859-1
30 ObjHeader c Server: Apache
18 Length b 7679
18 BackendClose b centre_rail_uschi_app03
0 WorkThread - 0x420e2e50 start
0 CLI - Rd vcl.load "boot" ./vcl.jCxU17wG.so
I can see all backends Varnish tried to use returned 400. I could
probably fix the request by stripping the whole Cookie (it's in my
backlog) or passing the 400 to the client but that doesn't change the
fact that Varnish crashed.
We collect statistics every 5 minutes and the ones below collected about
2 minutes before Varnish crashed (it had been running for about 4 hours
since the last restart).
2010-11-30T12:30:05.379422+11:00 297136-rp1 varnishd[3174]: (...)
136842 Client connections accepted
159246 Client requests received
115849 Cache hits
39311 Cache misses
16038 Backend conn. success
26600 Backend conn. reuses
14285 Backend conn. was closed
40921 Backend conn. recycles
2 Fetch head
31677 Fetch with Length
10592 Fetch chunked
170 Fetch wanted close
78 N struct sess_mem
26 N struct sess
31448 N struct object
31491 N struct objectcore
30457 N struct objecthead
62889 N struct smf
1 N large free smf
37 N struct vbe_conn
900 N worker threads
900 N worker threads created
48 N overflowed work requests
31 N backends
5030 N expired objects
20571 N LRU moved objects
154544 Objects sent with write
136840 Total Sessions
159246 Total Requests
4517 Total pass
41102 Total fetch
49574908 Total header bytes
2419039389 Total body bytes
99858 Session Closed
131864 Session Linger
58812 Session herd
7607244 SHM records
766387 SHM writes
77 SHM MTX contention
2 SHM cycles through buffer
78841 allocator requests
62888 outstanding allocations
1381466112 bytes allocated
25462079488 bytes free
1721 SMS allocator requests
1667264 SMS bytes allocated
1667264 SMS bytes freed
42635 Backend requests made
1 N vcl total
1 N vcl available
5383 N total active purges
5394 N new purges added
11 N old purges deleted
44017 N objects tested
10261150 N regexps tested against
2716 N duplicate purges rem
Did you read until here? Wow. Thanks! What do you think then?
Cheers,
Thiago Figueiro
Technical Operations Manager
Westfield Digital Business
T +61 (0)2 9358 7123
F +61 (0)2 9357 7866
W westfield.com.au
E tfigueiro at au.westfield.com
______________________________________________________
CONFIDENTIALITY NOTICE
This electronic mail message, including any and/or all attachments, is for the sole use of the intended recipient(s), and may contain confidential and/or privileged information, pertaining to business conducted under the direction and supervision of the sending organization. All electronic mail messages, which may have been established as expressed views and/or opinions (stated either within the electronic mail message or any of its attachments), are left to the sole responsibility of that of the sender, and are not necessarily attributed to the sending organization. Unauthorized interception, review, use, disclosure or distribution of any such information contained within this electronic mail message and/or its attachment(s), is (are) strictly prohibited. If you are not the intended recipient, please contact the sender by replying to this electronic mail message, along with the destruction all copies of the original electronic mail message (along with any attachments).
______________________________________________________
More information about the varnish-misc
mailing list