[Varnish] #1031: error 200 "long string" overflows obj.ws effectively unsetting obj.response which subsequently causes Bad Things
Varnish
varnish-bugs at varnish-cache.org
Wed Oct 12 19:17:48 CEST 2011
#1031: error 200 "long string" overflows obj.ws effectively unsetting obj.response
which subsequently causes Bad Things
----------------------+-----------------------------------------------------
Reporter: kristian | Owner:
Type: defect | Status: new
Priority: normal | Milestone:
Component: varnishd | Version: trunk
Severity: normal | Keywords:
----------------------+-----------------------------------------------------
VTC code:
{{{
kristian at freud:~$ cat foo.vtc
varnishtest "Test overflowing the response through sp->err_reason"
varnish v1 -vcl {
backend blatti {
.host = "127.0.0.1";
}
sub vcl_recv {
error 200
"aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa";
}
sub vcl_error {
return(deliver);
}
} -start
client c1 {
txreq -req GET
rxresp
expect resp.status == 200
} -run
}}}
Result:
{{{
**** top 0.0 macro def varnishd=varnishd
**** top 0.0 macro def pwd=/home/kristian
**** top 0.0 macro def topbuild=/home/kristian/../..
**** top 0.0 macro def bad_ip=10.255.255.255
**** top 0.0 macro def tmpdir=/tmp/vtc.931.5efb64dd
* top 0.0 TEST foo.vtc starting
*** top 0.0 varnishtest
* top 0.0 TEST Test overflowing the response through sp->err_reason
*** top 0.0 varnish
** v1 0.0 Launch
*** v1 0.0 CMD: cd ${pwd} && ${varnishd} -d -d -n
/tmp/vtc.931.5efb64dd/v1 -l 10m,1m,- -p auto_restart=off -p
syslog_cli_traffic=off -a '127.0.0.1:0' -S /tmp/vtc.931.5efb64dd/v1/_S -M
'127.0.0.1 46806' -P /tmp/vtc.931.5efb64dd/v1/varnishd.pid
-sfile,/tmp/vtc.931.5efb64dd/v1,10M
*** v1 0.0 CMD: cd /home/kristian && varnishd -d -d -n
/tmp/vtc.931.5efb64dd/v1 -l 10m,1m,- -p auto_restart=off -p
syslog_cli_traffic=off -a '127.0.0.1:0' -S /tmp/vtc.931.5efb64dd/v1/_S -M
'127.0.0.1 46806' -P /tmp/vtc.931.5efb64dd/v1/varnishd.pid
-sfile,/tmp/vtc.931.5efb64dd/v1,10M
*** v1 0.0 PID: 936
*** v1 0.0 debug| Platform: Linux,2.6.38-11-generic-
pae,i686,-sfile,-smalloc,-hcritbit\n
*** v1 0.0 debug| 200 245 \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,2.6.38-11-generic-
pae,i686,-sfile,-smalloc,-hcritbit\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 = 7
*** v1 0.1 CLI RX 107
**** v1 0.1 CLI RX| dfgufafbesqprwjuzishruoicbawioen\n
**** v1 0.1 CLI RX| \n
**** v1 0.1 CLI RX| Authentication required.\n
**** v1 0.1 CLI TX| auth
1c28913db635bc02fd8bcc0dc64bca844d65a1971c55ea2d86c6279ef09251cd\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,2.6.38-11-generic-
pae,i686,-sfile,-smalloc,-hcritbit\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| \n
**** v1 0.1 CLI TX| \tbackend blatti {\n
**** v1 0.1 CLI TX| \t\t.host = "127.0.0.1";\n
**** v1 0.1 CLI TX| \t}\n
**** v1 0.1 CLI TX| \n
**** v1 0.1 CLI TX| \tsub vcl_recv {\n
**** v1 0.1 CLI TX| \t\terror 200
"aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa...
*** v1 0.2 CLI RX 200
**** v1 0.2 CLI RX| VCL compiled.
**** v1 0.2 CLI TX| vcl.use vcl1
*** v1 0.2 CLI RX 200
** v1 0.2 Start
**** v1 0.2 CLI TX| start
*** v1 0.3 debug| child (949) Started\n
**** v1 0.3 vsl| 0 WorkThread - 0xb58fd00c start
**** v1 0.3 vsl| 0 CLI - Rd vcl.load "vcl1"
./vcl.ICtxlBZs.so
**** v1 0.3 vsl| 0 CLI - Wr 200 36 Loaded
"./vcl.ICtxlBZs.so" as "vcl1"
**** v1 0.3 vsl| 0 CLI - Rd vcl.use "vcl1"
**** v1 0.3 vsl| 0 CLI - Wr 200 0
**** v1 0.3 vsl| 0 CLI - Rd start
**** v1 0.3 vsl| 0 Debug - Acceptor is epoll
**** v1 0.3 vsl| 0 CLI - Wr 200 0
*** v1 0.3 CLI RX 200
**** v1 0.3 CLI TX| debug.xid 1000
*** v1 0.3 debug| Child (949) said Not running as root, no priv-sep\n
*** v1 0.3 debug| Child (949) said Child starts\n
*** v1 0.3 debug| Child (949) said SMF.s0 mmap'ed 10485760 bytes of
10485760\n
**** v1 0.3 vsl| 0 WorkThread - 0xb752700c start
**** v1 0.3 vsl| 0 WorkThread - 0xb751600c start
**** v1 0.3 vsl| 0 WorkThread - 0xb50eb00c start
**** v1 0.3 vsl| 0 WorkThread - 0xb50da00c start
**** v1 0.3 vsl| 0 WorkThread - 0xb50c900c start
**** v1 0.3 vsl| 0 WorkThread - 0xb50b800c start
**** v1 0.3 vsl| 0 WorkThread - 0xb50a700c start
**** v1 0.3 vsl| 0 WorkThread - 0xb509600c start
**** v1 0.3 vsl| 0 WorkThread - 0xb508500c start
*** v1 0.3 CLI RX 200
**** v1 0.3 CLI RX| XID is 1000
**** v1 0.3 CLI TX| debug.listen_address
**** v1 0.3 vsl| 0 CLI - Rd debug.xid 1000
**** v1 0.3 vsl| 0 CLI - Wr 200 11 XID is 1000
*** v1 0.3 CLI RX 200
**** v1 0.3 CLI RX| 127.0.0.1 38730\n
** v1 0.3 Listen on 127.0.0.1 38730
**** v1 0.3 macro def v1_addr=127.0.0.1
**** v1 0.3 macro def v1_port=38730
**** v1 0.3 macro def v1_sock=127.0.0.1 38730
*** top 0.3 client
** c1 0.3 Starting client
** c1 0.3 Waiting for client
*** c1 0.3 Connect to 127.0.0.1 38730
*** c1 0.3 connected fd 8 from 127.0.0.1 58396 to 127.0.0.1 38730
*** c1 0.3 txreq
**** c1 0.3 txreq| GET / HTTP/1.1\r\n
**** c1 0.3 txreq| \r\n
*** c1 0.3 rxresp
---- c1 0.3 HTTP rx EOF (fd:8 read: Success)
*** v1 0.3 debug| Child (949) died signal=6\n
* top 0.3 RESETTING after foo.vtc
*** v1 0.3 debug| Child (949) Panic message: Assert error in Tcheck(),
cache.h line 981:\n
*** v1 0.3 debug| Condition((t.b) != 0) not true.\n
*** v1 0.3 debug| thread = (cache-worker)\n
*** v1 0.3 debug| ident = Linux,2.6.38-11-generic-
pae,i686,-sfile,-smalloc,-hcritbit,epoll\n
*** v1 0.3 debug| Backtrace:\n
*** v1 0.3 debug| 0x80783a2: varnishd() [0x80783a2]\n
*** v1 0.3 debug| 0x80724d3: varnishd() [0x80724d3]\n
*** v1 0.3 debug| 0x807b807: varnishd(RES_BuildHttp+0x97)
[0x807b807]\n
*** v1 0.3 debug| 0x805cfd3: varnishd() [0x805cfd3]\n
*** v1 0.3 debug| 0x805dc12: varnishd(CNT_Session+0x842)
[0x805dc12]\n
*** v1 0.3 debug| 0x8079b3f: varnishd() [0x8079b3f]\n
*** v1 0.3 debug| 0x807a7d6: varnishd() [0x807a7d6]\n
*** v1 0.3 debug| 0x807ae2b: ...
*** v1 0.3 debug| Child cleanup complete\n
**** v1 0.4 vsl| 0 CLI - Rd debug.listen_address
**** v1 0.4 vsl| 0 CLI - Wr 200 16 127.0.0.1 38730
**** v1 0.4 vsl| 13 SessionOpen c 127.0.0.1 58396 127.0.0.1:0
** v1 1.3 Wait
** v1 1.3 R 936 Status: 0000
* top 1.4 TEST foo.vtc FAILED
# top TEST foo.vtc FAILED (1.370) exit=1
}}}
Discussion:
Note that setting a large obj.response manually in vcl_error will NOT
cause problems, even though the workspace is overflowed.
There are several different considerations:
1. We're using a rather mysterious workspace (aka: obj workspace) for
obj.response in vcl_error. There's no way to tune that.
2. The response message is set in two different ways depending on whether
it's set through sp->err_reason (which will cause it to be set in
cache_center.c:cnt_error() using http_PutResponse()) or later through
VRT_l_obj_response() which will use cache_vrt.c and vrt_do_string()).
3. I wish for an assert in the code that actually reads this value instead
of failing in Tcheck().
4. Perhaps even a test after VCL_error_method() setting the default if the
response is blank? I'd say "default VCL" but there isn't a valid
The biggest difference between the setter-methods is that going through
http_PutResponse() will actually /zero/ the existing value if the WS
allocation fails, thereby unsetting the response, while vrt_do_string()
will just log it as a lost header and return.
This was spotted by the APDM-people, pondered by Martin and finally broken
apart by Martin and myself. Unfortunately, we're now too hungry and sleepy
to fix it properly. The actual use-case that triggered it was HTTP
redirects, something along the lines of:
{{{
recv:
if (req.http.host ~ "^example\.com$") {
error 750 "http://www.example.com" + req.url;
}
error:
if (obj.status == 750) {
set obj.http.location = obj.response;
set obj.status = 301;
return (deliver);
}
}}}
Workaround:
{{{
recv:
... error 750 "CAKE";
error:
if (... == 750) {
set obj.http.location =
"http://www.example.com/Bunnies/fallback_for_overflow";
set obj.http.location = "http://www.example.com" + req.url;
}
}}}
The above will still fail due to overflowing the object workspace, but not
with an assert(). It will just be a losthdr and redirecting to a funny
bunny page instead of the real page. In theory.
Technically, this was only tested on 3.0.2-rc1, not trunk.
--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1031>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator
More information about the varnish-bugs
mailing list