strange behaviour

Question

strange behaviour

Closed this issue 11 years ago · 12 comments

Hi,
I'm trying your vmod (last version, with varnish 303) to improve readability of our vcl.
At the moment I'm dryrunning it, but after a few hours of usage it stops running.
I have something like this in my vcl_recv:

std.log ("------------------------------------------------------------------------");
cookie.clean();
cookie.parse(req.http.cookie);
cookie.filter_except("cookie1,cookie2,cookie3");
set req.http.cookie = cookie.get_string();
std.log ("cookie: #######" + req.http.cookie + "#######");
set req.http.var_cookie1 = cookie.get("cookie1");
set req.http.var_cookie2 = cookie.get("cookie2");
set req.http.var_cookie3 = cookie.get("cookie3");
std.log ("cookie1: " + req.http.var_cookie1);
std.log ("cookie2: " + req.http.var_cookie2);
std.log ("cookie3: " + req.http.var_cookie3);

and this is the resulting log

4108 VCL_Log c ------------------------------------------------------------------------
4108 VCL_Log c cookie: #######cookie2="27a24821fee02b5,4"; cookie1=_vf=1380625446&_vt=1383260400&cnt_dry_run%5Bc%5D=2;#######
4108 VCL_Log c cookie1: _vf=1380625446&_vt=1383260400&cnt_dry_run%5Bc%5D=2
4108 VCL_Log c cookie2: "27a24821fee02b5,4"
4108 VCL_Log c cookie3: null
0 VCL_Log - libvmod-cookie: parsed 1110779246 cookies.

according to the log it parsed 1110779246 cookies !!!

And moreover,
after some hours it stops filling the cookie header, and in order to let it work again I have to restart varnish.

I've jus raised twice the sess_workspace, now at 524288 bytes.

Any ideas?

Answer 1 · 2013-10-03T18:36:32.000Z

Hi.

Thanks for reporting this.

You shouldn't have to tune sess_workspace that high. 128k should be plenty, unless you have kilobytes of cookie contents with ESI and whatnot.

The very high counter was a bug, I've pushed a fix for it now.

I haven't heard of anyone else seeing lockups of Varnish when using the vmod.
Are you running other vmods as well?

Answer 2 · 2013-10-03T19:41:49.000Z

Hi, with the default sess_workspace I had some panics with assert errors, so I thought I should better raise it in order to be sure it wasn't responsible for the behaviour. Ok, asap I'll install the patched vmod.
Actually I haven't a lockup, simply the vmod stops doing what is expected. The cookie.parse(req.http.cookie) stops working correctly and doesn't return cookies anymore until a varnish restart. All the rest of the vcl is ok. Yes, I have other vmods running:
import std;
import var;
import shield;
import geoip;
import curl;
import header;
import cookie;
import digest;

Thanks.

Answer 3 · 2013-10-03T20:34:03.000Z

patch installed, now the numbers are correct:
0 VCL_Log - libvmod-cookie: parsed 15 cookies.

let's see in a few hours what happens

Answer 4 · 2013-10-04T13:17:56.000Z

Unfortunately after a few hours it stops working again (I'm having approx 30 reqs/sec if it helps).
this piece of code:

std.log ("cookie originale: #######" + req.http.cookie + "#######");
cookie.clean();
cookie.parse(req.http.cookie);
cookie.filter_except("cookie1,cookie2,cookie3");
set req.http.cookie = cookie.get_string();
std.log ("cookie modificato: #######" + req.http.cookie + "#######");

after a few hours of usage starts emptying the cookie header (and yes, I have at least one of the three cookies).
please advise how to debug, I'd really love to use it....

Answer 5 · 2013-10-04T13:24:52.000Z

Hi.

This shouldn't happen. I'll look into this in detail after the weekend.

2013/10/4 pippoppo notifications@github.com

Unfortunately after a few hours it stops working again:
this piece of code:

std.log ("cookie originale: #######" + req.http.cookie + "#######");

cookie.clean();
cookie.parse(req.http.cookie);
cookie.filter_except("cookie1,cookie2,cookie3");
set req.http.cookie = cookie.get_string();
std.log ("cookie modificato: #######" + req.http.cookie + "#######");

after a few hours of usage starts emptying the cookie header (and yes, I
have at least one of the three cookies).
please advise how to debug, I'd really love to use it....

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/10#issuecomment-25697680
.

With regards,
Lasse Karstensen

Answer 6 · 2013-10-07T10:48:24.000Z

Hi.

I ran this through the stress testing tool we use for testing Varnish itself.

I can't reproduce your problem.

varnishd from the 3.0.3 tag in git.

This was the VCL:
import cookie; sub vcl_recv { cookie.clean(); cookie.parse(req.http.cookie); cookie.parse(req.http.cookie); set req.http.foo = cookie.get("foo"); cookie.delete("foo"); cookie.filter_except("b,e,j"); set req.http.a = cookie.get("a"); cookie.set("bar", "baz"); set req.http.cookie = cookie.get_string(); unset req.http.cookie; }
12:15:49 [ INFO] run[fryer1]: cd github-lkarsten__libvmod-cookie.git && git show --oneline -s
12:15:49 [DEBUG] 38fd658 Better safe than sorry

12:16:00 [ INFO] run[fryer1]: /opt/varnish/sbin/varnishd -T localhost:6082 -a :6081 -f /opt/varnish/etc/testsuite.vcl -smalloc,20M -p thread_pool_min=100
12:16:03 [ INFO] run[fryer2]: ulimit -n 65548; siege -t 2h -c 15 --header='cookie:a=ohtoojie7ay4kiethohk3cuaraTahl;b=Gieneichaiboh9aiciw8fi3aph6ohw; c=aleenootae4chohd6eeTeexeingoh5; d=3dYg; e=92cL; f=FK3P; g=5tZS; h=SR0M; i=P9mw; j=eb6Ne3hi; k=Odah5tha; l=Iequair8;' http://fryer1:6081/

I've hit this with 40kreq/s for about an hour now, no ill effects seen.

Can you reproduce this on your setup with a minimal VCL (like the one above) that only uses the cookie vmod?

Answer 7 · 2013-10-07T11:10:47.000Z

Hi,
I'll try to setup a test env as you suggest, let me also see if I can extract a cookie dataset to play with. I'll be back asap with the results.

Thanks

Answer 8 · 2013-10-07T16:30:47.000Z

Hi,
I'm using a slightly modified version, in order to log something:
import cookie;
import std;
backend testbackend {
.host = "192.168.x.y";
.port = "80";
.probe = {
.url = "/";
}
}
sub vcl_recv {
cookie.clean();
cookie.parse(req.http.cookie);
cookie.filter_except("b,e,j");
set req.http.cookie = cookie.get_string();
std.log ("cookie after: #######" + req.http.cookie + "#######");
if (req.url ~ "^/loadbalancer$") {
error 998 "varnish ok";
}
}
sub vcl_error {
if (obj.status == 998) {
set obj.status = 200;
synthetic {""} + obj.response + {""};
return(deliver);
}
}

my command:

ulimit -n 65548; siege -t 2m -c 15 --header='cookie:a=ohtoojie7ay4kiethohk3cuaraTahl;b=Gieneichaiboh9aiciw8fi3aph6ohw; c=aleenootae4chohd6eeTeexeingoh5; d=3dYg; e=92cL; f=FK3P; g=5tZS; h=SR0M; i=P9mw; j=eb6Ne3hi; k=Odah5tha; l=Iequair8;' http://127.0.0.1/loadbalancer

and this is what happens

varnishlog | grep cookie

......
13 RxHeader c cookie:a=ohtoojie7ay4kiethohk3cuaraTahl;b=Gieneichaiboh9aiciw8fi3aph6ohw; c=aleenootae4chohd6eeTeexeingoh5; d=3dYg; e=92cL; f=FK3P; g=5tZS; h=SR0M; i=P9mw; j=eb6Ne3hi; k=Odah5tha; l=Iequair8;
13 VCL_Log c cookie after: #######b=Gieneichaiboh9aiciw8fi3aph6ohw; e=92cL; j=eb6Ne3hi;#######
9 RxHeader c cookie:a=ohtoojie7ay4kiethohk3cuaraTahl;b=Gieneichaiboh9aiciw8fi3aph6ohw; c=aleenootae4chohd6eeTeexeingoh5; d=3dYg; e=92cL; f=FK3P; g=5tZS; h=SR0M; i=P9mw; j=eb6Ne3hi; k=Odah5tha; l=Iequair8;
9 VCL_Log c cookie after: #######b=Gieneichaiboh9aiciw8fi3aph6ohw; e=92cL; j=eb6Ne3hi; a=ohtoojie7ay4kiethohk3cuaraTahl; c=aleenootae4chohd6eeTeexeingoh5; d=3dYg; f=FK3P; g=5tZS; h=SR0M; i=P9mw; k=Odah5tha; l=Iequair8;#######
0 VCL_Log - libvmod-cookie: parsed 12 cookies.
13 RxHeader c cookie:a=ohtoojie7ay4kiethohk3cuaraTahl;b=Gieneichaiboh9aiciw8fi3aph6ohw; c=aleenootae4chohd6eeTeexeingoh5; d=3dYg; e=92cL; f=FK3P; g=5tZS; h=SR0M; i=P9mw; j=eb6Ne3hi; k=Odah5tha; l=Iequair8;
13 VCL_Log c cookie after: #######b=Gieneichaiboh9aiciw8fi3aph6ohw; e=92cL; j=eb6Ne3hi;#######
0 VCL_Log - libvmod-cookie: parsed 12 cookies.
0 VCL_Log - libvmod-cookie: parsed 12 cookies.
9 RxHeader c cookie:a=ohtoojie7ay4kiethohk3cuaraTahl;b=Gieneichaiboh9aiciw8fi3aph6ohw; c=aleenootae4chohd6eeTeexeingoh5; d=3dYg; e=92cL; f=FK3P; g=5tZS; h=SR0M; i=P9mw; j=eb6Ne3hi; k=Odah5tha; l=Iequair8;
9 VCL_Log c cookie after: ##############
0 VCL_Log - libvmod-cookie: parsed 12 cookies.
0 VCL_Log - libvmod-cookie: parsed 12 cookies.
15 RxHeader c cookie:a=ohtoojie7ay4kiethohk3cuaraTahl;b=Gieneichaiboh9aiciw8fi3aph6ohw; c=aleenootae4chohd6eeTeexeingoh5; d=3dYg; e=92cL; f=FK3P; g=5tZS; h=SR0M; i=P9mw; j=eb6Ne3hi; k=Odah5tha; l=Iequair8;
15 VCL_Log c cookie after: ##############
0 VCL_Log - libvmod-cookie: parsed 12 cookies.

after a few seconds, the req.http.cookie header is empty after the cookie.get_string

hope it helps

thanks

(and hope github doesn't eat also this comment :-)

Answer 9 · 2013-10-10T12:28:54.000Z

I've just removed the "import std" and inserted a logline:
VSL(SLT_VCL_Log, 0, "libvmod-cookie: printing my cookies %s", p);
in
const char * vmod_get_string(struct sess *sp) {

just before the
return (p);

and I can confirm that after a few seconds the string is empty inside the vmod_get_string function

Answer 10 · 2013-10-10T13:42:25.000Z

And it seems that it happens when in vmod_filter_except(struct sess *sp, const char *whitelist) {

we're not entering anymore in
VTAILQ_FOREACH_SAFE(cookie, &cookielist, list, tmp) {

hope you'll read my findings and understand what's happening to my cookies :-)

I'll try to investigate further more but fear I'm lacking some varnish internal knowledge

Answer 11 · 2013-11-01T16:52:32.000Z

Hello again.
I just merged some code that I believe will fix this issue. Can you please try the latest git master?

Thanks.

Answer 12 · 2013-11-04T11:35:25.000Z

Hi,
I can confirm it works now, I'm going to close the issue.

Thanks!