Varnish Cache cuts a long HTTP Cookie header (seen in varnishlog)

Written by Claudio Kuenzler - 0 comments

Published on January 14th 2022 - Listed in Varnish

---

While deploying a new Varnish Cache setup, we came across an annoying problem - which turned out to be not a problem at all.

Too large headers usually returns a HTTP 400

The large request header problem is nothing new to us, so we immediately thought we've run into a request header limit, something we've dealt with in the past already. Varnish Cache sets this limit to 8k by default, but it can be increased using the http_req_hdr_len parameter.

When this request header limit is hit, the receiving web/proxy server usually responds with a HTTP 400 (Bad Request) status. But in this particular case a HTTP 200 was delivered back to the client - even though the varnishlog output clearly showed a cut (truncated) Cookie header:

$ curl -H "Host: www.example.com" "http://localhost:6081/" -H "Cookie: _ga=GA1.2.XXXXXXXXX.XXXXXXXXX; _ga_XXXXXXXXX=GS1.1.1111111111.5.1.2222222222.0; CLAUDIOTESTCOOKIE=adasfasfdasfasdfasdfasdf; ASP.NET_SessionId=5v3oxrpmereww5r5lfdfyalh; _STTT=1222,12.01.2022 00:00:00; cookieOptIn=1; ip-login=1; _gid=GA1.2.1234567891.1641981198; WP-XSRF-TOKEN=XXXXXXXXXXXXXXXXXXXXXXXXXXXX_XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX; WP-XSRF-V=-XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX; WP_UCONTEXT=WP_UCONTEXT=xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx_xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx_xxxxxxxxxxxxxxxxxxx;WP_UPDCHK=1;" -H "Upgrade-Insecure-Requests: 1"

$ sudo varnishlog
[...]
-   ReqHeader      Cookie: _ga=GA1.2.XXXXXXXXX.XXXXXXXXX; _ga_XXXXXXXXX=GS1.1.1111111111.5.1.2222222222.0; CLAUDIOTESTCOOKIE=adasfasfdasfasdfasdfasdf; ASP.NET_SessionId=5v3oxrpmereww5r5lfdfyalh; _STTT=1222,12.01.2022 00:00:00; cookieOptIn=1; ip-login=1; _gid=GA1.2.123456

All the other headers were also showing up fine, only the (large) Cookie header seems to be cut.

To find out the reason, all the relevant header and workspace parameters were adjusted, even though the typical symptom (HTTP 400), did not show up. But with no success, the result was still a cut Cookie header in varnishlog.

Display limit in varnishlog

After additional research, we finally came across an important hint in an old mailing list post. Varnish actually does not cut the Cookie header, it's merely a display limitation in the varnishlog command. This is controlled by the vsl_reclen (previously: shm_reclen) parameter and is by default set to 255 Bytes:

root@varnish:~# varnishadm param.show vsl_reclen
vsl_reclen
        Value is: 255b [bytes] (default)
        Minimum is: 16b
        Maximum is: 4084b

        Maximum number of bytes in SHM log record.

        The maximum tracks the vsl_buffer parameter - 12 bytes.

Note: In Varnish Plus (the commercial edition), the default is already set to the maximum of 4084b.

To change the default, the vsl_reclen parameter can be increased on the fly:

root@varnish:~# varnishadm param.set vsl_reclen 4084b

Right after this, the curl request was sent again and varnishlog finally displays the full Cookie header:

$ curl -H "Host: www.example.com" "http://localhost:6081/" -H "Cookie: _ga=GA1.2.XXXXXXXXX.XXXXXXXXX; _ga_XXXXXXXXX=GS1.1.1111111111.5.1.2222222222.0; CLAUDIOTESTCOOKIE=adasfasfdasfasdfasdfasdf; ASP.NET_SessionId=5v3oxrpmereww5r5lfdfyalh; _STTT=1222,12.01.2022 00:00:00; cookieOptIn=1; ip-login=1; _gid=GA1.2.1234567891.1641981198; WP-XSRF-TOKEN=XXXXXXXXXXXXXXXXXXXXXXXXXXXX_XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX; WP-XSRF-V=-XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX; WP_UCONTEXT=WP_UCONTEXT=xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx_xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx_xxxxxxxxxxxxxxxxxxx;; WP_UPDCHK=1;" -H "Upgrade-Insecure-Requests: 1"

$ sudo varnishlog
[...]-   ReqHeader      Cookie: _ga=GA1.2.XXXXXXXXX.XXXXXXXXX; _ga_XXXXXXXXX=GS1.1.1111111111.5.1.2222222222.0; CLAUDIOTESTCOOKIE=adasfasfdasfasdfasdfasdf; ASP.NET_SessionId=5v3oxrpmereww5r5lfdfyalh; _STTT=1222,12.01.2022 00:00:00; cookieOptIn=1; ip-login=1; _gid=GA1.2.1234567891.1641981198; WP-XSRF-TOKEN=XXXXXXXXXXXXXXXXXXXXXXXXXXXX_XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX; WP-XSRF-V=-XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX; WP_UCONTEXT=WP_UCONTEXT=xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx_xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx_xxxxxxxxxxxxxxxxxxx;; WP_UPDCHK=1;

Thanks to the adjusted line size in the output, all the Cookies could finally be analyzed. This is especially important, when Cookie trimming or replacement happens in the VCL.

Add a comment

Show form to leave a comment

Comments (newest first)

No comments yet.