Project

General

Profile

[Solved] Oversized request-header

Added by avij over 2 years ago

I had been running lighttpd from git (dadfb5fcf502ae338df0a69d4713fabf774a9672) since September 6th without any apparent problems. On October 16th I updated my lighttpd to git commit d3f4a62c10b2634811e8202b9c653532ff86783b and I started getting thousands of "oversized request-header -> sending Status 431" messages in my error.log. I did get those before as well, but up to 50 per day. At that point I did not have server.max-request-field-size set, so presumably lighttpd used the default of 8192 bytes.

I tried bisecting to find out which of the ~30 commits in between caused the sudden increase in those error messages, but those results were inconclusive. Even the d3f4a62c10b2634811e8202b9c653532ff86783b build which had previously shown problems seemed to work fine in testing.

At that point I briefly gave up, and updated to the newest version in git (fa1eef0071bd52a968cb53d17a371641122556e1) and set server.max-request-field-size to 32768. This seemed to quiet down the error messages.

Fast forward to this day, and I tried accessing http://leopardi.miuku.net/stats/net.html . The first image did not load. I wondered about that for a few seconds, and then hit reload to reload the page. I ended up getting a page with only a "431 -" as the content. Here are the relevant log entries:

2001:2003:f6bb:a700::1 leopardi.miuku.net - [18/Oct/2017:14:34:47 +0300] "GET /stats/net.html HTTP/1.1" 200 1827 "http://miuku.net/stats/all.html" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/61.0.3163.100 Safari/537.36"
2001:2003:f6bb:a700::1 leopardi.miuku.net - [18/Oct/2017:14:34:47 +0300] "" 431 327 "-" "-"
2001:2003:f6bb:a700::1 leopardi.miuku.net - [18/Oct/2017:14:34:47 +0300] "GET /stats/net-week.png HTTP/1.1" 200 3506 "http://leopardi.miuku.net/stats/net.html" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/61.0.3163.100 Safari/537.36"
2001:2003:f6bb:a700::1 leopardi.miuku.net - [18/Oct/2017:14:34:47 +0300] "GET /stats/net-month.png HTTP/1.1" 304 0 "http://leopardi.miuku.net/stats/net.html" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/61.0.3163.100 Safari/537.36"
2001:2003:f6bb:a700::1 leopardi.miuku.net - [18/Oct/2017:14:34:47 +0300] "GET /stats/net-year.png HTTP/1.1" 304 0 "http://leopardi.miuku.net/stats/net.html" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/61.0.3163.100 Safari/537.36"
2001:2003:f6bb:a700::1 leopardi.miuku.net - [18/Oct/2017:14:34:56 +0300] "" 431 327 "-" "-"
2001:2003:f6bb:a700::1 leopardi.miuku.net - [18/Oct/2017:14:34:56 +0300] "GET /favicon.ico HTTP/1.1" 200 1078 "http://leopardi.miuku.net/stats/net.html" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/61.0.3163.100 Safari/537.36"

The first 431 is probably for net-day.png, and the second 431 for the reloaded net.html. I can't imagine what might cause an oversized request-header when requesting a static file. I don't even have any cookies set for this hostname.

Controlled reproduction of this problem might be difficult. I can make lighttpd emit a 431 if I use a very long user agent string, but I did not notice a difference in behaviour with old and new versions when testing with such a long user agent string.

I'm now running 17373221b8b52e3d087f2655517f5340050e4c71, but I'm still getting a few too many oversized request-header messages to be comfortable with the situation. I'll try downgrading to e951152e2b54831d2cb1d325c237f8462713b953 when I get that built.

I did my own testing using Chrome 61.0.3163.100 on a Mac via squid. A somewhat scrubbed lighttpd.conf is attached.


Replies (10)

RE: Oversized request-header - Added by stbuehler over 2 years ago

Hm.

A packet capture (tcpdump/wireshark) would probably be helpful to see what state lighttpd might have been in when detecting "oversized request-header" (this would also allow us to see whether the complain was valid or buggy).

I think the last change in the code logging the error was 1018ff992215e1e9271b2eb77cd878fa721fee65, which was before 1.4.42 - not sure what else might be involved.

Anyway, before 1.4.42 the limit was 64kB, and it wouldn't show the error if the connection got closed before lighttpd realized the limit was reached, or when the header already was found it wouldn't care about the length anymore. I.e. before 1.4.42 lighttpd would only complain about the limit if it had to wait for the header - if you got a busy server and/or the header came in fast enough lighttpd didn't notice.

As far as I can tell from looking at the code "pipelining" requests (sending many requests before the response came in) shouldn't be a problem; if there is a valid header in the data it should only measure the length of that header, not of the remaining data.

RE: Oversized request-header - Added by avij over 2 years ago

Nearly all traffic to that server is over HTTPS, so tcpdumps might not be that useful. The example I gave above was an exception to this. I could set up tcpdump to capture traffic to port 80. I set that up now.

I just switched to e951152e2b54831d2cb1d325c237f8462713b953 with some custom modifications to logging to show the values of last_chunk, and buffer_string_length(con->request.request) or (size_t)chunkqueue_length(cq) (based on last_chunk). Let's see if I get anything useful out of it.

RE: Oversized request-header - Added by avij over 2 years ago

Sigh.. While writing this reply my Chrome crashed so I'll need to start again.

Anyway, I do still see some 431 errors with e951152e2b54831d2cb1d325c237f8462713b953, but I'm unsure if they are legit or not. In these tests last_chunk has usually been nonzero, in which case chunkqueue_length(cq) gets examined.

2017-10-18 17:59:22: (connections.c.827) oversized request-header -> sending Status 431 586792192 34118
2017-10-18 17:59:22: (connections.c.827) oversized request-header -> sending Status 431 580807280 34117
2017-10-18 17:59:22: (connections.c.827) oversized request-header -> sending Status 431 589066640 34116
2017-10-18 17:59:22: (connections.c.827) oversized request-header -> sending Status 431 587503632 34146
2017-10-18 18:00:23: (connections.c.827) oversized request-header -> sending Status 431 583211520 32817

I was happy to see a 431 error in my port 80 tcpdump, but apparently that one was issued for a legitimate reason. This particular iPad sent a near-infinite stream of If-Modified-Since timestamps with some requests. https://www.cloudshark.org/captures/889f029a1d6d if you're curious, but it will not be useful for this case.

What would be the best way to dump the chunk queue (cq) somewhere so that it could be examined?

RE: Oversized request-header - Added by avij over 2 years ago

I guess this will do for this purpose:

                        if (cq != NULL) {
                            chunk *aj_c = cq->first;
                            while (NULL != aj_c) {
                                log_error_write(srv, __FILE__, __LINE__, "s", aj_c->mem->ptr);
                                aj_c = aj_c->next;
                            }
                        }

RE: Oversized request-header - Added by stbuehler over 2 years ago

Wow, those iPad headers are really screwed up.

Increasing the size limit (e.g. 64k) might temporarily fix your problems :)

To log the request you might want to use the "b" format string and pass aj_c->mem (so it handles null characters).

RE: Oversized request-header - Added by avij over 2 years ago

OK, changed. I'm now logging either con->request.request or "mem"s from cq, depending on the state of last_chunk.

For the record, I saw the same thing happen with Chrome (not mine but someone else's): https://www.cloudshark.org/captures/5e4f4825c8a2

I'm hoping to get some other results tomorrow. I get a feeling that this is somehow related to how busy the server is, and it's already quieter at this time of the day. At least I have proper logging in place now.

RE: Oversized request-header - Added by gstrauss over 2 years ago

This particular iPad sent a near-infinite stream of If-Modified-Since timestamps with some requests.

Is there an intermediate proxy in the way which is corrupting If-Modified-Since? If it is not a transparent proxy, info should show up in the full request headers, but you might want to increase the size limit of the allowed headers to 64k, and then modify your debug code to log request headers if they exceed a certain (smaller) size. At least then we'll be able to see all the other headers in the request (as long as the request is < 64k)

RFC7232 lists the contents as a single HTTP-date
https://tools.ietf.org/html/rfc7232#section-3.3

If-Modified-Since = HTTP-date

RE: Oversized request-header - Added by avij over 2 years ago

I think I found the reason for this. lighttpd itself seems to send a long list of Last-Modified dates, and some clients seem to echo those dates back. The attached tcpdump file has all the gory details. At this time I'm using git commit fa1eef0071bd52a968cb53d17a371641122556e1 + some changes for extra logging.

HTTP/1.1 200 OK
Content-Type: image/gif
Accept-Ranges: bytes
ETag: "1646250428"
Last-Modified: Sat, 23 Jul 2016 11:07:45 GMTThu, 13 Dec 2012 17:01:42 GMTSun, 15 Aug 2010 21:03:00 GMTThu, 01 Dec 2016 04:24:43 GMTSat, 23 Jul 2016 11:07:53 GMTSat, 02 Sep 2017 09:38:21 GMTThu, 13 Dec 2012 17:01:43 GMTThu, 24 Sep 2015 02:48:00 GMTThu, 13 Dec 2012 17:01:42 GMTWed, 25 Sep 2013 19:44:35 GMTThu, 13 Dec 2012 17:01:52 GMTThu, 01 Dec 2016 04:24:43 GMTSat, 21 Oct 2017 21:08:57 GMTSun, 16 Jul 2017 10:34:59 GMTWed, 10 Apr 2013 12:00:59 GMTSat, 02 Sep 2017 09:38:21 GMTThu, 13 Dec 2012 17:01:42 GMTThu, 01 Dec 2016 04:24:43 GMTThu, 13 Dec 2012 17:00:44 GMTFri...

RE: Oversized request-header - Added by gstrauss over 2 years ago

--- a/src/http-header-glue.c
+++ b/src/http-header-glue.c
@@ -142,6 +142,7 @@ buffer * strftime_cache_get(server *srv, time_t last_mod) {

        srv->mtime_cache[i].mtime = last_mod;
        tm = gmtime(&(srv->mtime_cache[i].mtime));
+       buffer_string_set_length(srv->mtime_cache[i].str, 0);
        buffer_append_strftime(srv->mtime_cache[i].str, "%a, %d %b %Y %H:%M:%S GMT", tm);

        return srv->mtime_cache[i].str;

RE: [Solved] Oversized request-header - Added by gstrauss over 2 years ago

Fixed in lighttpd 1.4.47. This was a regression in lighttpd 1.4.46. Thank you for tracking it down.

    (1-10/10)