[Varnish] #1440: e00019.vtc occasionally trips an assert
Varnish
varnish-bugs at varnish-cache.org
Wed Feb 26 11:30:37 CET 2014
#1440: e00019.vtc occasionally trips an assert
----------------------+-------------------
Reporter: martin | Owner:
Type: defect | Status: new
Priority: normal | Milestone:
Component: varnishd | Version: trunk
Severity: normal | Keywords:
----------------------+-------------------
Command to reproduce:
{{{
$ ./varnishtest -n100 -j8 -i tests/e00019.vtc
}}}
Backtrace:
{{{
*** v1 1.6 debug| Child (25308) died signal=6\n
*** v1 1.6 debug| Child (25308) Panic message: Assert error in
V1D_Deliver(), cache/cache_http1_deliver.c line 297:\n
*** v1 1.6 debug| Condition((req->obj->objcore->busyobj) == 0) not
true.\n
*** v1 1.6 debug| thread = (cache-worker)\n
*** v1 1.6 debug| ident =
Linux,3.2.0-4-amd64,x86_64,-smalloc,-smalloc,-hcritbit,epoll\n
*** v1 1.6 debug| Backtrace:\n
*** v1 1.6 debug| 0x445969: pan_backtrace+0x19\n
*** v1 1.6 debug| 0x44585d: pan_ic+0x23d\n
*** v1 1.6 debug| 0x44f071: V1D_Deliver+0x801\n
*** v1 1.6 debug| 0x44da84: cnt_deliver+0x944\n
*** v1 1.6 debug| 0x44a07d: CNT_Request+0x64d\n
*** v1 1.6 debug| 0x43c8b6: HTTP1_Session+0x536\n
*** v1 1.6 debug| 0x452425: ses_req_pool_task+0x1c5\n
*** v1 1.6 debug| 0x451f2c: ses_sess_pool_task+0x20c\n
*** v1 1.6 debug| 0x451611: SES_pool_accept_task+0x251\n
*** v1 1.6 debug| 0x448416: Pool_Work_Thread+0x576\n
*** v1 1.6 debug| req = 0x1d7b8e0 {\n
*** v1 1.6 debug| sp = 0x7feb7c00b9f0, vxid = 1073742825, step =
R_STP_DELIVER,\n
*** v1 1.6 debug| req_body = R_BODY_NONE,\n
*** v1 1.6 debug| err_code = 200, err_reason = (null),\n
*** v1 1.6 debug| restarts = 0, esi_level = 0\n
*** v1 1.6 debug| sp = 0x7feb7c00b9f0 {\n
*** v1 1.6 debug| fd = 11, vxid = 1000,\n
*** v1 1.6 debug| client = 127.0.0.1 36626,\n
*** v1 1.6 debug| step = S_STP_WORKING,\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| worker = 0x7feb8071fc60 {\n
*** v1 1.6 debug| ws = 0x7feb8071fe60 {\n
*** v1 1.6 debug| id = "wrk",\n
*** v1 1.6 debug| {s,f,r,e} =
{0x7feb8071f420,+80,+2048,+2048},\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| VCL::method = 0x0,\n
*** v1 1.6 debug| VCL::return = deliver,\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| ws = 0x1d7ba60 {\n
*** v1 1.6 debug| id = "req",\n
*** v1 1.6 debug| {s,f,r,e} = {0x1d7d8b0,+160,(nil),+57392},\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| http[req] = {\n
*** v1 1.6 debug| ws = 0x1d7ba60[req]\n
*** v1 1.6 debug| "GET",\n
*** v1 1.6 debug| "bar",\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| },\n
*** v1 1.6 debug| http[resp] = {\n
*** v1 1.6 debug| ws = 0x1d7ba60[req]\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| "Date: Wed, 26 Feb 2014 10:27:16 GMT",\n
*** v1 1.6 debug| "X-Varnish: 1001",\n
*** v1 1.6 debug| "Age: 0",\n
*** v1 1.6 debug| "Via: 1.1 varnish",\n
*** v1 1.6 debug| "Transfer-Encoding: chunked",\n
*** v1 1.6 debug| "Connection: keep-alive",\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| vcl = {\n
*** v1 1.6 debug| srcname = {\n
*** v1 1.6 debug| "input",\n
*** v1 1.6 debug| "Default",\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| busyobj = 0x1d5b880 {\n
*** v1 1.6 debug| ws = 0x1d5b948 {\n
*** v1 1.6 debug| id = "bo",\n
*** v1 1.6 debug| {s,f,r,e} = {0x1d5d840,+464,(nil),+57408},\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| is_do_esi\n
*** v1 1.6 debug| is_is_gunzip\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 = 0x1d5b948[bo]\n
*** v1 1.6 debug| "GET",\n
*** v1 1.6 debug| "bar",\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: 1002",\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 = 0x1d5b948[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| "Transfer-encoding: chunked",\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| ws = 0x1d5bac8 {\n
*** v1 1.6 debug| id = "obj",\n
*** v1 1.6 debug| {s,f,r,e} = {0x1d8bce0,+32,(nil),+32},\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| obj (FETCH) = 0x1d8bb90 {\n
*** v1 1.6 debug| vxid = 2147484650,\n
*** v1 1.6 debug| http[obj] = {\n
*** v1 1.6 debug| ws = 0x1d5bac8[obj]\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| },\n
*** v1 1.6 debug| len = 131837,\n
*** v1 1.6 debug| store = {\n
*** v1 1.6 debug| 131072 {\n
*** v1 1.6 debug| 3c 31 3e 3c 2f 65 73 69 3a 63 6f 6d 6d 65 6e
74 |<1></esi:comment|\n
*** v1 1.6 debug| 20 66 6f 6f 3e 3c 31 3e 3c 32 3e 3c 65 73 69
3a | foo><1><2><esi:|\n
*** v1 1.6 debug| 63 6f 6d 6d 65 6e 74 20 2f 20 3e 3c 65 73 69
3a |comment / ><esi:|\n
*** v1 1.6 debug| 63 6f 6d 6d 65 6e 74 20 64 6f 6f 3e 3c 32 3e
3c |comment doo><2><|\n
*** v1 1.6 debug| [131008 more]\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| 765 {\n
*** v1 1.6 debug| 31 32 33 34 35 36 37 30 31 32 33 34 35 36 37
30 |1234567012345670|\n
*** v1 1.6 debug| 31 32 33 34 35 36 37 30 31 32 33 34 35 36 37
30 |1234567012345670|\n
*** v1 1.6 debug| 31 32 33 34 35 36 37 30 31 32 33 34 35 36 37
30 |1234567012345670|\n
*** v1 1.6 debug| 31 32 33 34 35 36 37 30 31 32 33 34 35 36 37
30 |1234567012345670|\n
*** v1 1.6 debug| [701 more]\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| obj (REQ) = 0x1d8bb90 {\n
*** v1 1.6 debug| vxid = 2147484650,\n
*** v1 1.6 debug| http[obj] = {\n
*** v1 1.6 debug| ws = 0x1d5bac8[obj]\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| },\n
*** v1 1.6 debug| len = 131837,\n
*** v1 1.6 debug| store = {\n
*** v1 1.6 debug| 131072 {\n
*** v1 1.6 debug| 3c 31 3e 3c 2f 65 73 69 3a 63 6f 6d 6d 65 6e
74 |<1></esi:comment|\n
*** v1 1.6 debug| 20 66 6f 6f 3e 3c 31 3e 3c 32 3e 3c 65 73 69
3a | foo><1><2><esi:|\n
*** v1 1.6 debug| 63 6f 6d 6d 65 6e 74 20 2f 20 3e 3c 65 73 69
3a |comment / ><esi:|\n
*** v1 1.6 debug| 63 6f 6d 6d 65 6e 74 20 64 6f 6f 3e 3c 32 3e
3c |comment doo><2><|\n
*** v1 1.6 debug| [131008 more]\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| 765 {\n
*** v1 1.6 debug| 31 32 33 34 35 36 37 30 31 32 33 34 35 36 37
30 |1234567012345670|\n
*** v1 1.6 debug| 31 32 33 34 35 36 37 30 31 32 33 34 35 36 37
30 |1234567012345670|\n
*** v1 1.6 debug| 31 32 33 34 35 36 37 30 31 32 33 34 35 36 37
30 |1234567012345670|\n
*** v1 1.6 debug| 31 32 33 34 35 36 37 30 31 32 33 34 35 36 37
30 |1234567012345670|\n
*** v1 1.6 debug| [701 more]\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
}}}
Full test log:
{{{
**** top 0.0 macro def varnishd=varnishd
**** top 0.0 macro def varnishadm=varnishadm
**** top 0.0 macro def varnishstat=varnishstat
**** top 0.0 macro def varnishhist=varnishhist
**** top 0.0 macro def varnishlog=varnishlog
**** top 0.0 macro def varnishncsa=varnishncsa
**** top 0.0 macro def vmod_std=std from "/home/martin/varnish/git
/varnish-cache/lib/libvmod_std/.libs/libvmod_std.so"
**** top 0.0 macro def vmod_debug=debug from "/home/martin/varnish/git
/varnish-cache/lib/libvmod_debug/.libs/libvmod_debug.so"
**** top 0.0 macro def vmod_directors=directors from
"/home/martin/varnish/git/varnish-
cache/lib/libvmod_directors/.libs/libvmod_directors.so"
**** top 0.0 macro def pwd=/home/martin/varnish/git/varnish-
cache/bin/varnishtest
**** top 0.0 macro def topbuild=/home/martin/varnish/git/varnish-cache
**** top 0.0 macro def bad_ip=192.0.2.255
**** top 0.0 macro def tmpdir=/tmp/vtc.24902.1ade685f
* top 0.0 TEST tests/e00019.vtc starting
*** top 0.0 varnishtest
* top 0.0 TEST Push corners in new ESI parser
*** top 0.0 server
** s1 0.0 Starting server
**** s1 0.0 macro def s1_addr=127.0.0.1
**** s1 0.0 macro def s1_port=48509
**** s1 0.0 macro def s1_sock=127.0.0.1 48509
* s1 0.0 Listen on 127.0.0.1 48509
*** top 0.0 varnish
** s1 0.0 Started on 127.0.0.1 48509
** v1 0.0 Launch
*** v1 0.0 CMD: cd ${pwd} && ${varnishd} -d -d -n
/tmp/vtc.24902.1ade685f/v1 -l 2m,1m,- -p auto_restart=off -p
syslog_cli_traffic=off -p sigsegv_handler=on -a '127.0.0.1:0' -M
'127.0.0.1 60677' -P /tmp/vtc.24902.1ade685f/v1/varnishd.pid
*** v1 0.0 CMD: cd /home/martin/varnish/git/varnish-
cache/bin/varnishtest && varnishd -d -d -n /tmp/vtc.24902.1ade685f/v1 -l
2m,1m,- -p auto_restart=off -p syslog_cli_traffic=off -p
sigsegv_handler=on -a '127.0.0.1:0' -M '127.0.0.1 60677' -P
/tmp/vtc.24902.1ade685f/v1/varnishd.pid
*** v1 0.0 PID: 24943
*** v1 0.0 debug| Platform:
Linux,3.2.0-4-amd64,x86_64,-smalloc,-smalloc,-hcritbit\n
*** v1 0.0 debug| 200 276 \n
*** v1 0.0 debug| -----------------------------\n
*** v1 0.0 debug| Varnish Cache CLI 1.0\n
*** v1 0.0 debug| -----------------------------\n
*** v1 0.0 debug|
Linux,3.2.0-4-amd64,x86_64,-smalloc,-smalloc,-hcritbit\n
*** v1 0.0 debug| varnish-4.0.0-tp2 revision 3f79aa1\n
*** v1 0.0 debug| \n
*** v1 0.0 debug| Type 'help' for command list.\n
*** v1 0.0 debug| Type 'quit' to close CLI session.\n
*** v1 0.0 debug| Type 'start' to launch worker process.\n
*** v1 0.0 debug| \n
**** v1 0.1 CLIPOLL 1 0x1 0x0
*** v1 0.1 CLI connection fd = 9
*** v1 0.1 CLI RX 107
**** v1 0.1 CLI RX| xboxfbvjiipmfvqsjxftgytmhkmsffgc\n
**** v1 0.1 CLI RX| \n
**** v1 0.1 CLI RX| Authentication required.\n
**** v1 0.1 CLI TX| auth
9fdf0e9d724a784a17d8bd203361ae311ddbb0a86b8a2c05963812aa8cbb64fc\n
*** v1 0.1 CLI RX 200
**** v1 0.1 CLI RX| -----------------------------\n
**** v1 0.1 CLI RX| Varnish Cache CLI 1.0\n
**** v1 0.1 CLI RX| -----------------------------\n
**** v1 0.1 CLI RX|
Linux,3.2.0-4-amd64,x86_64,-smalloc,-smalloc,-hcritbit\n
**** v1 0.1 CLI RX| varnish-4.0.0-tp2 revision 3f79aa1\n
**** v1 0.1 CLI RX| \n
**** v1 0.1 CLI RX| Type 'help' for command list.\n
**** v1 0.1 CLI RX| Type 'quit' to close CLI session.\n
**** v1 0.1 CLI RX| Type 'start' to launch worker process.\n
**** v1 0.1 CLI TX| vcl.inline vcl1 << %XJEIFLH|)Xspa8P\n
**** v1 0.1 CLI TX| vcl 4.0;\n
**** v1 0.1 CLI TX| backend s1 { .host = "127.0.0.1"; .port = "48509";
}\n
**** v1 0.1 CLI TX| \n
**** v1 0.1 CLI TX| \n
**** v1 0.1 CLI TX| \tsub vcl_backend_response {\n
**** v1 0.1 CLI TX| \t\tif (bereq.url == "bar") {\n
**** v1 0.1 CLI TX| \t\t\tset beresp.do_esi = true;\n
**** v1 0.1 CLI TX| \t\t}\n
**** v1 0.1 CLI TX| \t}\n
**** v1 0.1 CLI TX| \n
**** v1 0.1 CLI TX| %XJEIFLH|)Xspa8P\n
*** v1 0.2 CLI RX 200
**** v1 0.2 CLI RX| Message from VCC-compiler:\n
**** v1 0.2 CLI RX| Not running as root, no priv-sep\n
**** v1 0.2 CLI RX| Message from C-compiler:\n
**** v1 0.2 CLI RX| Not running as root, no priv-sep\n
**** v1 0.2 CLI RX| Message from dlopen:\n
**** v1 0.2 CLI RX| Not running as root, no priv-sep\n
**** v1 0.2 CLI RX| \n
**** v1 0.2 CLI RX| VCL compiled.
**** v1 0.2 CLI TX| vcl.use vcl1
*** v1 0.2 CLI RX 200
**** v1 0.2 CLI RX| VCL 'vcl1' now active
** v1 0.2 Start
**** v1 0.2 CLI TX| start
*** v1 0.2 debug| child (25308) Started\n
*** v1 0.3 CLI RX 200
*** v1 0.3 wait-running
**** v1 0.3 CLI TX| status
*** v1 0.3 debug| Child (25308) said Not running as root, no priv-
sep\n
*** v1 0.3 debug| Child (25308) said Child starts\n
*** v1 0.3 CLI RX 200
**** v1 0.3 CLI RX| Child in state running
**** v1 0.3 CLI TX| debug.xid 999
*** v1 0.3 CLI RX 200
**** v1 0.3 CLI RX| XID is 999
**** v1 0.3 CLI TX| debug.listen_address
**** v1 0.3 vsl| 0 CLI - Rd debug.xid 999
**** v1 0.3 vsl| 0 CLI - Wr 200 10 XID is 999
*** v1 0.4 CLI RX 200
**** v1 0.4 CLI RX| 127.0.0.1 46370\n
** v1 0.4 Listen on 127.0.0.1 46370
**** v1 0.4 macro def v1_addr=127.0.0.1
**** v1 0.4 macro def v1_port=46370
**** v1 0.4 macro def v1_sock=127.0.0.1 46370
*** top 0.4 varnish
**** v1 0.4 CLI TX| param.set debug +esi_chop
**** v1 0.4 vsl| 0 CLI - Rd debug.listen_address
**** v1 0.4 vsl| 0 CLI - Wr 200 16 127.0.0.1 46370
*** v1 0.4 CLI RX 200
** v1 0.4 CLI 200 <param.set debug +esi_chop>
*** top 0.4 varnish
**** v1 0.4 CLI TX| param.set debug +syncvsl
*** v1 0.4 CLI RX 200
** v1 0.4 CLI 200 <param.set debug +syncvsl>
*** top 0.4 client
** c1 0.4 Starting client
** c1 0.4 Waiting for client
*** c1 0.4 Connect to 127.0.0.1 46370
*** c1 0.4 connected fd 10 from 127.0.0.1 36626 to 127.0.0.1 46370
*** c1 0.4 txreq
**** c1 0.4 txreq| GET bar HTTP/1.1\r\n
**** c1 0.4 txreq| \r\n
*** s1 0.4 accepted fd 4
*** s1 0.4 rxreq
*** c1 0.4 rxresp
**** s1 0.4 rxhdr| GET bar HTTP/1.1\r\n
**** s1 0.4 rxhdr| X-Forwarded-For: 127.0.0.1\r\n
**** s1 0.4 rxhdr| Accept-Encoding: gzip\r\n
**** s1 0.4 rxhdr| X-Varnish: 1002\r\n
**** s1 0.4 rxhdr| Host: 127.0.0.1\r\n
**** s1 0.4 rxhdr| \r\n
**** s1 0.4 http[ 0] | GET
**** s1 0.4 http[ 1] | bar
**** s1 0.4 http[ 2] | HTTP/1.1
**** s1 0.4 http[ 3] | X-Forwarded-For: 127.0.0.1
**** s1 0.4 http[ 4] | Accept-Encoding: gzip
**** s1 0.4 http[ 5] | X-Varnish: 1002
**** s1 0.4 http[ 6] | Host: 127.0.0.1
**** s1 0.4 bodylen = 0
*** s1 0.4 txresp
**** s1 0.4 txresp| HTTP/1.1 200 Ok\r\n
**** s1 0.4 txresp| Transfer-encoding: chunked\r\n
**** s1 0.4 txresp| \r\n
*** s1 0.4 chunked
**** s1 0.4 chunked| 18\r\n
**** s1 0.4 chunked| <1></esi:comment foo><1>\r\n
*** s1 0.4 chunked
**** s1 0.4 chunked| 27\r\n
**** s1 0.4 chunked| <2><esi:comment / ><esi:comment doo><2>\r\n
*** s1 0.4 chunked
**** s1 0.4 chunked| 29\r\n
**** s1 0.4 chunked| <3><esi:remove foo="bar"></esi:remove><3>\r\n
*** s1 0.4 chunked
**** s1 0.4 chunked| 27\r\n
**** s1 0.4 chunked| <4><esi:include src="foo"><esi:incl><4>\r\n
*** s1 0.4 chunked
**** s1 0.4 chunked| 10\r\n
**** s1 0.4 chunked| <H1><esi:remove>\r\n
*** s1 0.4 chunkedlen
**** s1 0.4 chunked| 100\r\n
**** s1 0.4 chunked|
0123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567\r\n
*** s1 0.4 chunked
**** s1 0.4 chunked| 12\r\n
**** s1 0.4 chunked| </esi:remove></H1>\r\n
*** s1 0.4 chunked
**** s1 0.4 chunked| 10\r\n
**** s1 0.4 chunked| <H2><esi:remove>\r\n
*** s1 0.4 chunkedlen
**** s1 0.5 chunked| 10000\r\n
**** s1 0.5 chunked|
01234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701...
*** s1 0.5 chunked
**** s1 0.5 chunked| 12\r\n
**** s1 0.5 chunked| </esi:remove></H2>\r\n
*** s1 0.5 chunked
**** s1 0.5 chunked| e\r\n
**** s1 0.5 chunked| <esi:comment/>\r\n
*** s1 0.5 chunkedlen
**** s1 0.5 chunked| 100\r\n
**** s1 0.5 chunked|
0123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567\r\n
*** s1 0.5 chunked
**** s1 0.5 chunked| e\r\n
**** s1 0.5 chunked| <esi:comment/>\r\n
*** s1 0.5 chunkedlen
**** s1 0.5 chunked| 10000\r\n
**** s1 0.5 chunked|
01234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701234567012345670123456701...
*** s1 0.5 chunked
**** s1 0.5 chunked| e\r\n
**** s1 0.5 chunked| <esi:comment/>\r\n
*** s1 0.5 chunkedlen
**** s1 0.5 chunked| 0\r\n
**** s1 0.5 chunked| \r\n
*** s1 0.5 rxreq
**** v1 0.5 vsl| 1000 Begin c sess 0 HTTP/1
**** v1 0.5 vsl| 1000 SessOpen c 127.0.0.1 36626
127.0.0.1:0 127.0.0.1 46370 1393410436.813103 11
**** v1 0.5 vsl| 1001 Begin c req 1000 rxreq
**** v1 0.5 vsl| 1000 Link c req 1001 rxreq
**** v1 0.5 vsl| 1001 ReqStart c 127.0.0.1 36626
**** v1 0.5 vsl| 1001 ReqMethod c GET
**** v1 0.5 vsl| 1001 ReqURL c bar
**** v1 0.5 vsl| 1001 ReqProtocol c HTTP/1.1
**** v1 0.5 vsl| 1001 VCL_call c RECV
**** v1 0.5 vsl| 1001 ReqHeader c X-Forwarded-For:
127.0.0.1
**** v1 0.5 vsl| 1001 VCL_return c hash
**** v1 0.5 vsl| 1001 VCL_call c HASH
**** v1 0.5 vsl| 1001 VCL_return c lookup
**** v1 0.5 vsl| 1001 Debug c XXXX MISS
**** v1 0.5 vsl| 1001 VCL_call c MISS
**** v1 0.5 vsl| 1001 VCL_return c fetch
**** v1 0.5 vsl| 1002 Begin b bereq 1001 fetch
**** v1 0.5 vsl| 1001 Link c bereq 1002 fetch
**** v1 0.5 vsl| 1002 BereqMethod b GET
**** v1 0.5 vsl| 1002 BereqURL b bar
**** v1 0.5 vsl| 1002 BereqProtocol b HTTP/1.1
**** v1 0.5 vsl| 1002 BereqHeader b X-Forwarded-For:
127.0.0.1
**** v1 0.5 vsl| 1002 BereqHeader b Accept-Encoding: gzip
**** v1 0.5 vsl| 1002 VCL_call b BACKEND_FETCH
**** v1 0.5 vsl| 1002 VCL_return b fetch
**** v1 0.5 vsl| 1002 BereqHeader b X-Varnish: 1002
**** v1 0.5 vsl| 1002 Debug b XXX BOS: 0 -> 1
**** v1 0.5 vsl| 1002 BackendOpen b 15 s1(127.0.0.1,,48509)
127.0.0.1 55107
**** v1 0.5 vsl| 1002 Backend b 15 s1
s1(127.0.0.1,,48509)
**** v1 0.5 vsl| 1002 BereqHeader b Host: 127.0.0.1
**** v1 0.5 vsl| 1002 BerespProtocol b HTTP/1.1
**** v1 0.5 vsl| 1002 BerespStatus b 200
**** v1 0.5 vsl| 1002 BerespResponse b Ok
**** v1 0.5 vsl| 1002 BerespHeader b Transfer-encoding:
chunked
**** v1 0.5 vsl| 1002 TTL b RFC 20 -1 -1 1393410437
1393410437 0 0 0
**** v1 0.5 vsl| 1002 VCL_call b BACKEND_RESPONSE
**** v1 0.5 vsl| 1002 VCL_return b deliver
**** v1 0.5 vsl| 1002 Storage b malloc s0
**** v1 0.5 vsl| 1002 ObjProtocol b HTTP/1.1
**** v1 0.5 vsl| 1002 ObjStatus b 200
**** v1 0.5 vsl| 1002 ObjResponse b Ok
**** v1 0.5 vsl| 1002 ESI_xmlerror b ERR at 14 ESI 1.0
</esi:comment> illegal end-tag
**** v1 0.5 vsl| 1002 ESI_xmlerror b ERR at 39 XML 1.0 '>'
does not follow '/' in tag
**** v1 0.5 vsl| 1002 ESI_xmlerror b ERR at 60 ESI 1.0
<esi:comment> needs final '/'
**** v1 0.5 vsl| 1002 ESI_xmlerror b WARN at 130 ESI 1.0
<esi:include> lacks final '/'
**** v1 0.5 vsl| 1002 ESI_xmlerror b ERR at 139 ESI 1.0
<esi:bogus> element
---- c1 0.6 HTTP rx EOF (fd:10 read: Success)
---- s1 0.6 HTTP rx EOF (fd:4 read: Success)
* top 0.6 RESETTING after tests/e00019.vtc
** s1 0.6 Waiting for server
**** s1 0.6 macro undef s1_addr
**** s1 0.6 macro undef s1_port
**** s1 0.6 macro undef s1_sock
**** v1 0.6 vsl| 1002 Fetch_Body b 2(chunked)
**** v1 0.6 vsl| 1002 Length b 131837
**** v1 0.6 vsl| 1002 Debug b XXX BOS: 1 -> 3
**** v1 0.6 vsl| 0 ExpKill - EXP_Inbox p=0x1d8b980
e=0.000000000 f=0x1c10
**** v1 0.6 vsl| 1001 RespProtocol c HTTP/1.1
**** v1 0.6 vsl| 0 ExpKill - EXP_When p=0x1d8b980
e=1393410466.813253164 f=0x1c10
**** v1 0.6 vsl| 1001 RespStatus c 200
**** v1 0.6 vsl| 1001 RespResponse c Ok
**** v1 0.6 vsl| 1001 RespHeader c Date: Wed, 26 Feb 2014
10:27:16 GMT
**** v1 0.6 vsl| 1001 RespHeader c X-Varnish: 1001
**** v1 0.6 vsl| 1001 RespHeader c Age: 0
**** v1 0.6 vsl| 1001 RespHeader c Via: 1.1 varnish
**** v1 0.6 vsl| 1001 VCL_call c DELIVER
**** v1 0.6 vsl| 1001 VCL_return c deliver
**** v1 0.6 vsl| 1001 Debug c RES_MODE 18
**** v1 0.6 vsl| 1001 RespHeader c Transfer-Encoding:
chunked
**** v1 0.6 vsl| 1001 RespHeader c Connection: keep-alive
*** v1 1.6 debug| Child (25308) died signal=6\n
*** v1 1.6 debug| Child (25308) Panic message: Assert error in
V1D_Deliver(), cache/cache_http1_deliver.c line 297:\n
*** v1 1.6 debug| Condition((req->obj->objcore->busyobj) == 0) not
true.\n
*** v1 1.6 debug| thread = (cache-worker)\n
*** v1 1.6 debug| ident =
Linux,3.2.0-4-amd64,x86_64,-smalloc,-smalloc,-hcritbit,epoll\n
*** v1 1.6 debug| Backtrace:\n
*** v1 1.6 debug| 0x445969: pan_backtrace+0x19\n
*** v1 1.6 debug| 0x44585d: pan_ic+0x23d\n
*** v1 1.6 debug| 0x44f071: V1D_Deliver+0x801\n
*** v1 1.6 debug| 0x44da84: cnt_deliver+0x944\n
*** v1 1.6 debug| 0x44a07d: CNT_Request+0x64d\n
*** v1 1.6 debug| 0x43c8b6: HTTP1_Session+0x536\n
*** v1 1.6 debug| 0x452425: ses_req_pool_task+0x1c5\n
*** v1 1.6 debug| 0x451f2c: ses_sess_pool_task+0x20c\n
*** v1 1.6 debug| 0x451611: SES_pool_accept_task+0x251\n
*** v1 1.6 debug| 0x448416: Pool_Work_Thread+0x576\n
*** v1 1.6 debug| req = 0x1d7b8e0 {\n
*** v1 1.6 debug| sp = 0x7feb7c00b9f0, vxid = 1073742825, step =
R_STP_DELIVER,\n
*** v1 1.6 debug| req_body = R_BODY_NONE,\n
*** v1 1.6 debug| err_code = 200, err_reason = (null),\n
*** v1 1.6 debug| restarts = 0, esi_level = 0\n
*** v1 1.6 debug| sp = 0x7feb7c00b9f0 {\n
*** v1 1.6 debug| fd = 11, vxid = 1000,\n
*** v1 1.6 debug| client = 127.0.0.1 36626,\n
*** v1 1.6 debug| step = S_STP_WORKING,\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| worker = 0x7feb8071fc60 {\n
*** v1 1.6 debug| ws = 0x7feb8071fe60 {\n
*** v1 1.6 debug| id = "wrk",\n
*** v1 1.6 debug| {s,f,r,e} =
{0x7feb8071f420,+80,+2048,+2048},\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| VCL::method = 0x0,\n
*** v1 1.6 debug| VCL::return = deliver,\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| ws = 0x1d7ba60 {\n
*** v1 1.6 debug| id = "req",\n
*** v1 1.6 debug| {s,f,r,e} = {0x1d7d8b0,+160,(nil),+57392},\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| http[req] = {\n
*** v1 1.6 debug| ws = 0x1d7ba60[req]\n
*** v1 1.6 debug| "GET",\n
*** v1 1.6 debug| "bar",\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| },\n
*** v1 1.6 debug| http[resp] = {\n
*** v1 1.6 debug| ws = 0x1d7ba60[req]\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| "Date: Wed, 26 Feb 2014 10:27:16 GMT",\n
*** v1 1.6 debug| "X-Varnish: 1001",\n
*** v1 1.6 debug| "Age: 0",\n
*** v1 1.6 debug| "Via: 1.1 varnish",\n
*** v1 1.6 debug| "Transfer-Encoding: chunked",\n
*** v1 1.6 debug| "Connection: keep-alive",\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| vcl = {\n
*** v1 1.6 debug| srcname = {\n
*** v1 1.6 debug| "input",\n
*** v1 1.6 debug| "Default",\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| busyobj = 0x1d5b880 {\n
*** v1 1.6 debug| ws = 0x1d5b948 {\n
*** v1 1.6 debug| id = "bo",\n
*** v1 1.6 debug| {s,f,r,e} = {0x1d5d840,+464,(nil),+57408},\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| is_do_esi\n
*** v1 1.6 debug| is_is_gunzip\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 = 0x1d5b948[bo]\n
*** v1 1.6 debug| "GET",\n
*** v1 1.6 debug| "bar",\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: 1002",\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 = 0x1d5b948[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| "Transfer-encoding: chunked",\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| ws = 0x1d5bac8 {\n
*** v1 1.6 debug| id = "obj",\n
*** v1 1.6 debug| {s,f,r,e} = {0x1d8bce0,+32,(nil),+32},\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| obj (FETCH) = 0x1d8bb90 {\n
*** v1 1.6 debug| vxid = 2147484650,\n
*** v1 1.6 debug| http[obj] = {\n
*** v1 1.6 debug| ws = 0x1d5bac8[obj]\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| },\n
*** v1 1.6 debug| len = 131837,\n
*** v1 1.6 debug| store = {\n
*** v1 1.6 debug| 131072 {\n
*** v1 1.6 debug| 3c 31 3e 3c 2f 65 73 69 3a 63 6f 6d 6d 65 6e
74 |<1></esi:comment|\n
*** v1 1.6 debug| 20 66 6f 6f 3e 3c 31 3e 3c 32 3e 3c 65 73 69
3a | foo><1><2><esi:|\n
*** v1 1.6 debug| 63 6f 6d 6d 65 6e 74 20 2f 20 3e 3c 65 73 69
3a |comment / ><esi:|\n
*** v1 1.6 debug| 63 6f 6d 6d 65 6e 74 20 64 6f 6f 3e 3c 32 3e
3c |comment doo><2><|\n
*** v1 1.6 debug| [131008 more]\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| 765 {\n
*** v1 1.6 debug| 31 32 33 34 35 36 37 30 31 32 33 34 35 36 37
30 |1234567012345670|\n
*** v1 1.6 debug| 31 32 33 34 35 36 37 30 31 32 33 34 35 36 37
30 |1234567012345670|\n
*** v1 1.6 debug| 31 32 33 34 35 36 37 30 31 32 33 34 35 36 37
30 |1234567012345670|\n
*** v1 1.6 debug| 31 32 33 34 35 36 37 30 31 32 33 34 35 36 37
30 |1234567012345670|\n
*** v1 1.6 debug| [701 more]\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| obj (REQ) = 0x1d8bb90 {\n
*** v1 1.6 debug| vxid = 2147484650,\n
*** v1 1.6 debug| http[obj] = {\n
*** v1 1.6 debug| ws = 0x1d5bac8[obj]\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| },\n
*** v1 1.6 debug| len = 131837,\n
*** v1 1.6 debug| store = {\n
*** v1 1.6 debug| 131072 {\n
*** v1 1.6 debug| 3c 31 3e 3c 2f 65 73 69 3a 63 6f 6d 6d 65 6e
74 |<1></esi:comment|\n
*** v1 1.6 debug| 20 66 6f 6f 3e 3c 31 3e 3c 32 3e 3c 65 73 69
3a | foo><1><2><esi:|\n
*** v1 1.6 debug| 63 6f 6d 6d 65 6e 74 20 2f 20 3e 3c 65 73 69
3a |comment / ><esi:|\n
*** v1 1.6 debug| 63 6f 6d 6d 65 6e 74 20 64 6f 6f 3e 3c 32 3e
3c |comment doo><2><|\n
*** v1 1.6 debug| [131008 more]\n
*** v1 1.6 debug| },\n
*** v1 1.6 debug| 765 {\n
*** v1 1.6 debug| 31 32 33 34 35 36 37 30 31 32 33 34 35 36 37
30 |1234567012345670|\n
*** v1 1.6 debug| 31 32 33 34 35 36 37 30 31 32 33 34 35 36 37
30 |1234567012345670|\n
*** v1 1.6 debug| 31 32 33 34 35 36 37 30 31 32 33 34 35 36 37
30 |1234567012345670|\n
*** v1 1.6 debug| 31 32 33 34 35 36 37 30 31 32 33 34 35 36 37
30 |1234567012345670|\n
*** v1 1.6 debug| [701 more]\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
** v1 1.6 Wait
*** v1 1.6 debug| Child cleanup complete\n
** v1 1.6 R 24943 Status: 0000 (u 0.088005 s 0.176011)
* top 1.6 TEST tests/e00019.vtc FAILED
}}}
--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1440>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator
More information about the varnish-bugs
mailing list