[Varnish] #1692: Assert error in vep_emit_common
Varnish
varnish-bugs at varnish-cache.org
Fri Mar 20 14:09:02 CET 2015
#1692: Assert error in vep_emit_common
--------------------+---------------------
Reporter: martin | Owner:
Type: defect | Status: new
Priority: normal | Milestone:
Component: build | Version: unknown
Severity: normal | Keywords:
--------------------+---------------------
During varnish cache plus testing, we found that r01184.vtc would fail
occasionally in vep_emit_common.
Backtrace:
{{{
**** s1 0.6 macro undef s1_sock
**** v1 0.6 vsl| 1005 Begin c sess 0 HTTP/1
**** v1 0.6 vsl| 1005 SessOpen c 127.0.0.1 40315
127.0.0.1:0 127.0.0.1 43229 1426852631.268863 13
**** v1 0.6 vsl| 1005 Link c req 1006 rxreq
**** v1 0.6 vsl| 1007 Begin b bereq 1006 fetch
**** v1 0.6 vsl| 1007 Timestamp b Start: 1426852631.269114
0.000000 0.000000
**** v1 0.6 vsl| 1007 BereqMethod b GET
**** v1 0.6 vsl| 1007 BereqURL b /c
**** v1 0.6 vsl| 1007 BereqProtocol b HTTP/1.1
**** v1 0.6 vsl| 1007 BereqHeader b X-Forwarded-For:
127.0.0.1
**** v1 0.6 vsl| 1007 BereqHeader b Accept-Encoding: gzip
**** v1 0.6 vsl| 1007 BereqHeader b X-Varnish: 1007
**** v1 0.6 vsl| 1007 VCL_call b BACKEND_FETCH
**** v1 0.6 vsl| 1007 VCL_return b fetch
**** v1 0.6 vsl| 1007 BackendClose b 15 s1(127.0.0.1,,36613)
toolate
**** v1 0.6 vsl| 1007 BackendOpen b 15 s1(127.0.0.1,,36613)
127.0.0.1 37296
**** v1 0.6 vsl| 1007 Backend b 15 s1
s1(127.0.0.1,,36613)
**** v1 0.6 vsl| 1007 BereqHeader b Host: 127.0.0.1
**** v1 0.6 vsl| 1007 Timestamp b Bereq: 1426852631.269525
0.000411 0.000411
**** v1 0.6 vsl| 1007 Timestamp b Beresp: 1426852631.270038
0.000923 0.000512
**** v1 0.6 vsl| 1007 BerespProtocol b HTTP/1.1
**** v1 0.6 vsl| 1007 BerespStatus b 200
**** v1 0.6 vsl| 1007 BerespReason b OK
**** v1 0.6 vsl| 1007 BerespHeader b Content-Encoding: gzip
**** v1 0.6 vsl| 1007 BerespHeader b Transfer-Encoding:
Chunked
**** v1 0.6 vsl| 1007 BerespHeader b Date: Fri, 20 Mar 2015
11:57:11 GMT
**** v1 0.6 vsl| 1007 TTL b RFC 120 -1 -1 1426852631
1426852631 1426852631 0 0
**** v1 0.6 vsl| 1007 VCL_call b BACKEND_RESPONSE
**** v1 0.6 vsl| 1007 VCL_return b deliver
**** v1 0.6 vsl| 1007 STV_Alloc b 456 456 456 0 0
**** v1 0.6 vsl| 1007 Storage b malloc s0
**** v1 0.6 vsl| 1007 ObjProtocol b HTTP/1.1
**** v1 0.6 vsl| 1007 ObjStatus b 200
**** v1 0.6 vsl| 1007 ObjReason b OK
**** v1 0.6 vsl| 1007 ObjHeader b Content-Encoding: gzip
**** v1 0.6 vsl| 1007 ObjHeader b Date: Fri, 20 Mar 2015
11:57:11 GMT
**** v1 0.6 vsl| 1007 Fetch_Body b 2 chunked -
**** v1 0.6 vsl| 1007 STV_Alloc b 16384 16384 16384 0 0
**** v1 0.6 vsl| 1007 Gzip b Gunzip error: -3 (invalid
distance too far back)
**** v1 0.6 vsl| 1007 FetchError b Invalid Gzip data:
invalid distance too far back
**** v1 0.6 vsl| 1007 Gzip b U F - 99 81 80 80 0
*** v1 1.6 debug| Child (29250) died signal=6\n
*** v1 1.6 debug| Child (29250) Panic message:\n
*** v1 1.6 debug| Assert error in vep_emit_common(),
cache/cache_esi_parse.c line 300:\n
*** v1 1.6 debug| Condition(l > 0) not true.\n
*** v1 1.6 debug| thread = (cache-worker)\n
*** v1 1.6 debug| version = varnish-plus-4.0.3r1-rc1 revision
80f5e17\n
*** v1 1.6 debug| ident =
Linux,3.16.0-4-amd64,x86_64,-smalloc,-smalloc,-hcritbit,epoll\n
*** v1 1.6 debug| Backtrace:\n
*** v1 1.6 debug| 0x455bc9: pan_backtrace+0x19\n
*** v1 1.6 debug| 0x455ac0: pan_ic+0x330\n
*** v1 1.6 debug| 0x428b54: vep_emit_common+0x64\n
*** v1 1.6 debug| 0x4289f2: VEP_Finish+0x282\n
*** v1 1.6 debug| 0x424793: vfp_esi_end+0x1a3\n
*** v1 1.6 debug| 0x423d64: vfp_esi_gzip_pull+0x304\n
*** v1 1.6 debug| 0x436534: vfp_call+0xb4\n
*** v1 1.6 debug| 0x43641e: VFP_Suck+0x2ae\n
*** v1 1.6 debug| 0x4369b9: VFP_Fetch_Body+0x479\n
*** v1 1.6 debug| 0x433f2d: vbf_stp_fetch+0xe5d\n
*** v1 1.6 debug| busyobj = 0x7ff55dc8e020 {\n
*** v1 1.6 debug| ws = 0x7ff55dc8e0e0 {\n
*** v1 1.6 debug| id = "bo",\n
*** v1 1.6 debug| {s,f,r,e} =
{0x7ff55dc90008,+528,(nil),+57368},\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| refcnt = 2\n
*** v1 1.6 debug| retries = 0\n
*** v1 1.6 debug| failed = 1\n
*** v1 1.6 debug| state = 1\n
*** v1 1.6 debug| is_do_esi\n
*** v1 1.6 debug| is_is_gzip\n
*** v1 1.6 debug| bodystatus = 2 (chunked),\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| http[bereq] = {\n
*** v1 1.6 debug| ws = 0x7ff55dc8e0e0[bo]\n
*** v1 1.6 debug| "GET",\n
*** v1 1.6 debug| "/c",\n
*** v1 1.6 debug| "HTTP/1.1",\n
*** v1 1.6 debug| "X-Forwarded-For: 127.0.0.1",\n
*** v1 1.6 debug| "Accept-Encoding: gzip",\n
*** v1 1.6 debug| "X-Varnish: 1007",\n
*** v1 1.6 debug| "Host: 127.0.0.1",\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| http[beresp] = {\n
*** v1 1.6 debug| ws = 0x7ff55dc8e0e0[bo]\n
*** v1 1.6 debug| "HTTP/1.1",\n
*** v1 1.6 debug| "200",\n
*** v1 1.6 debug| "OK",\n
*** v1 1.6 debug| "Content-Encoding: gzip",\n
*** v1 1.6 debug| "Transfer-Encoding: Chunked",\n
*** v1 1.6 debug| "Date: Fri, 20 Mar 2015 11:57:11 GMT",\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| ws = 0x7ff55dc8e258 {\n
*** v1 1.6 debug| id = "obj",\n
*** v1 1.6 debug| {s,f,r,e} = {0x7ff56a13c368,+96,(nil),+96},\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| objcore (FETCH) = 0x7ff55c8100c0 {\n
*** v1 1.6 debug| refcnt = 2\n
*** v1 1.6 debug| flags = 0x2\n
*** v1 1.6 debug| objhead = 0x7ff55c80e0e0\n
*** v1 1.6 debug| }\n
*** v1 1.6 debug| obj (FETCH) = 0x7ff56a13c200 {\n
*** v1 1.6 debug| meta = 0x7ff56a13c238 {\n
*** v1 1.6 debug| vxid = 2147484655,\n
*** v1 1.6 debug| http[obj] = {\n
*** v1 1.6 debug| ws = (nil)[]\n
*** v1 1.6 debug| "HTTP/1.1",\n
*** v1 1.6 debug| "200",\n
*** v1 1.6 debug| "OK",\n
*** v1 1.6 debug| "Content-Encoding: gzip",\n
*** v1 1.6 debug| "Date: Fri, 20 Mar 2015 11:57:11 GMT",\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| len = 15,\n
*** v1 1.6 debug| }\n
*** v1 1.6 debug| store = {\n
*** v1 1.6 debug| 15 {\n
*** v1 1.6 debug| 1f 8b 08 00 00 00 00 00 00 03 00 00 00 ff ff
|...............|\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| }\n
*** v1 1.6 debug| \n
*** v1 1.6 debug| \n
}}}
varnishtest -j20 -n50 would usually trigger it.
We haven't been able to reproduce it on master/4.0, but changes in -plus
with regard to buffer handling could explain why it behaves differently.
Attached patch fixes the issue for us, and it looks to be applicable for
master/4.0 as well.
-Martin
--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1692>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator
More information about the varnish-bugs
mailing list