Lighttpd

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.

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.

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?

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;
                            }
                        }

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).

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.

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

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...

--- 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;

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