Lighttpd

Heres the config:
https://pastebin.com/7vKE72zU

And we don't have traffic limits set in our setup so don't believe that is the issue.
As for issue 3058 which you linked, I looked at journalctl -u lighttpd.service and didn't spot any stack traces. Let me know if you need me to look elsewhere.

Thanks.

That's a fairly straightforward config. Thank you for sharing it.

Do you know if the stuck requests are HTTP/1.1 or HTTP/2 ?

Let me know if you need me to look elsewhere.

If you see lighttpd at 100% CPU usage, please pstack or use gdb to get obtain a stack trace to help narrow down where I need to look.

There was a bug fixed in lighttpd 1.4.58 commit 37ae9423 so if you can test with lighttpd 1.4.58, that would be appreciated. lighttpd 1.4.56 was a huge release of over a year of development, and unfortunately, there apparently remain some bugs to be squashed.

Unrelated: please check your ssl.cipher-list. I see that you include RC4 and disable AESGCM. You might have a look at lighttpd TLS docs for some recommendations.

I will look and confirm if they are HTTP/1.1 or 2 and try and use pstack/gdb to obtain a stack trace and update this when I can.

I forgot to mention that I did in fact update to 1.4.58 but the issue does persist unfortunately.

And thank you, I'll take a look at the documentation.

Appreciate it,
Mit

getsockopt(21, SOL_TCP, TCP_INFO, "\10\0\0\0\0\4x\0\200 \5\0@\234\0\0\264\5\0\0\264\5\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\374\231c\1\0\0\0\0\30\231c\1\234\257b\1\334\5\0\0\350\301\0\0007\275\1\0\233\336\0\0\377\377\377\177\n\0\0\0\264\5\0\0\3\0\0\0\0\0\0\0\20r\0\0\0\0\0\0", [104]) = 0

The call to getsockopt() for SOL_TCP TCP_INFO in fdevent_is_tcp_half_closed() tells me that lighttpd is detecting that the socket was closed (or at least half-closed). I'll dig in further to see if there is a reason why that does not result in the connection being closed soon afterwards. Once that is received, lighttpd ideally should not have to check that again for that connection (unless lighttpd has not yet drained what is in the kernel recv socket buffer for that connection).

Are you able to reproduce this error with any frequency?

The code which reaches fdevent_is_tcp_half_closed() is fairly small. In clear-text (non-TLS), lighttpd will read() and recv EOF. I am wondering if the underlying TLS library might be in a state which does not handle this.

You're using mod_openssl. Would you be willing to upgrade or downgrade your version of openssl? Would you be willing to try with mod_gnutls or mod_mbedtls or mod_wolfssl or mod_nss as a substitute for mod_openssl? To use the alternative TLS modules, you might have to modify ssl.cipher-list (or comment it out and use the default in lighttpd, which is ssl.cipher-list = "HIGH:!aNULL:!eNULL:!EXP", and in lighttpd 1.4.56 and later, "MinProtocol" => "TLSv1.2")

Some new info, the connections seem to be coming from one of our security scanners. So this happens each time the servers get scanned.
It uses HTTP/1.0 for the majority of the connections I saw.

Here is a pastebin of a longer strace since I had:
https://pastebin.com/3yMKzqud

I used gdb to connect to the process and ran bt which printed out the following:
(gdb) bt
#0 0x00007fb3b4914f1a in getsockopt () from /lib/x86_64-linux-gnu/libc.so.6
#1 0x000055c4b35156c8 in fdevent_is_tcp_half_closed ()
#2 0x000055c4b34f2762 in ?? ()
#3 0x000055c4b3502c9c in ?? ()
#4 0x000055c4b34f0f2e in main ()

I'll attempt to use a different TLS modules tomorrow.

The following patch is a worthwhile improvement, but I do not think it sufficient to address the issue here. This patch below should prevent repeated calls to getsockopt() after POLLRDHUP is received on the connection.

--- a/src/connections.c
+++ b/src/connections.c
@@ -1218,7 +1224,9 @@ connection_set_fdevent_interest (request_st * const r, connection * const con)
     int n = 0;
     switch(r->state) {
       case CON_STATE_READ:
-        n = FDEVENT_IN | FDEVENT_RDHUP;
+        n = FDEVENT_IN;
+        if (!(r->conf.stream_request_body & FDEVENT_STREAM_REQUEST_POLLRDHUP))
+            n |= FDEVENT_RDHUP;
         break;
       case CON_STATE_WRITE:
         if (!chunkqueue_is_empty(con->write_queue)

That's an interesting strace. Thanks.
I don't see anything trying to read() after the event is received and need to try to track down why that is.

If this is reproducible after a scan, I'd be curious what the request is.

debug.log-request-header = "enable" 
debug.log-response-header = "enable" 

If you can attach gdb to the lighttpd process using 100% CPU and step (repeat from epoll_wait() to the next epoll_wait()), then if you can share that result, it should help pinpoint what is going on.

debug.log-state-handling = "enable" will generate a lot of noise in the error logs on a busy site, but would also be very useful to help identify where things are spinning.

I attempted to step through using gdb today and generated the following:
https://pastebin.com/niNTr7Ja
I'm unsure if I did it correctly (I'm unfamiliar unfortunately).

I've added:
debug.log-request-header = "enable"
debug.log-response-header = "enable"
And I'll add:
debug.log-state-handling = "enable"
afterwards.
I'm in the process of gaining the rights necessary to run the scans on demand so I can reproduce the error state easily. Switching TLS modules will also hopefully be done soon. Once I get the rights I'll see if I can get a print of the error log around that time frame.

It does not look like lighttpd was built with full debugging symbols, or maybe lighttpd has not been deployed with debugging symbols available on the system on which you are running gdb on lighttpd

The calls to BIO_write () tell me that you're getting into mod_openssl and into the underlying openssl libraries. I don't know why in your strace we do not see a read() or write() system call from mod_openssl, or why openssl is not detecting that the connection has closed.

The most recent trace that you shared shows BIO_write() and write() along with SIGPIPE, which is blocked, but the write() should fail with EPIPE

It is curious that you did not see write() in your original strace

In any case, it is still a mystery why this error is not being propagated through lighttpd. I'm still looking through the code...

Only because I haven't yet asked: is there any trace in the lighttpd error log?

What version of the openssl libraries are installed on your system?
openssl version

@mitd: I am interested in helping to track this down. Do you have an estimate when you might have time to come back to this?

It would be useful to know what commands are being sent by the scanner. From your traces, two of the connections seem to end up in this problem state.

Also, please share openssl version. Thanks.

Sorry about the delay, had things come up. Still looking into it.
What I've tried so far.
I've installed wolfssl and am testing now with the config changes you mentioned above.
openssl version
OpenSSL 1.1.1i 8 Dec 2020

I don't see a trace in the error logs. I've gotten some access to run the scans (all I can do is initiate them, not much else). But with that hopefully I can produce the calls in the access.log from the scanner. I'll reply once I get that info, I've initiated a scan now but am waiting for it to actually start.

Great. Thanks. If you reproduce the CLOSE_WAIT, you may have to attach with gdb and issue call (int)close(xxxx) before the request will end up in the access.log, since logging occurs after the request ends. debug.log-request-header = "enable" shows up in the error log once the request headers are received. If they do not show up, then it is possible that things are caught up somewhere in the TLS negotiation between the scanner and lighttpd, before the HTTP request is received by lighttpd.

14561 lines of requests is, ... um ..., a lot.
Would you share your server.feature-flags settings, if you have set any? (I am specifically interested in "server.h2proto" and "server.h2c")

Unfortunately yes, it sends tons of requests.
Here are the flags:

server.feature-flags += ("server.h2proto" => "enable")
server.feature-flags += ("server.h2c" => "enable")

Attempted to close the connections and here is what I got in the error log:
https://pastebin.com/zuQAkKe8
That was pulled a few seconds after closing the connection.

In an effort to bound where the problem is, does the problem occur if you (temporarily) disable those feature flags and then trigger a scan? If it does, does the problem occur if you set only server.feature-flags += ("server.h2c" => "disable") and leave server.feature-flags += ("server.h2proto" => "enable") ?

Looks like it still occurs with both flags disabled. Will try it with h2c disabled and h2proto enabled once this scan is finished.

Issue persists with:
server.feature-flags += ("server.h2c" => "disable") and server.feature-flags += ("server.h2proto" => "enable")

That is expected, as most of the requests in your scan access log are HTTP/1.0 with a few HTTP/1.1. There was one HTTP/2.0 "prior knowledge" request, and if the problem still happened when you disabled "server.h2c" and disabled "server.h2proto" (which also disables "server.h2c"), then the issue is much less likely to be in the HTTP/2 code in lighttpd.

Your the scan access log you shared has the HTTP request-line, but does not have the headers the went along with the request. Having those headers may help me to reproduce the issue.

So far, running all of the request lines against lighttpd does not trigger the issue on my test box, and I tried with and without HTTPS.

I don't have any good hunches right now. If you can temporarily run a scan without port 80 enabled, we can establish whether or not the issue occurs with HTTPS (probably does). To do so, temporary change server.bind = 80 to server.bind = 443 and comment out the $SERVER["socket"] == "[::]:80" section in your config.

If you have enabled request header logging with debug.log-request-header = "enable" then the error log will contain a log line with the file descriptor, followed by the request headers. When you trigger the error and the server has that fd in CLOSE_WAIT, the last instance in the error logs which uses the fd (and the subsequent request headers) is likely the request that triggered the issue. (This is before you attach with gdb to try to close() the fd). That might help give us a starting point. There is a chance that a sequence of requests cause the problem, but it would still be useful to see the request that gets stuck.

I attempted to bind to port 443 but had to comment out
include_shell "/usr/share/lighttpd/use-ipv6.pl " + server.port
Once that was removed I was able to start the service. However looking at the access log, it started throwing 400s. I think this is due to our anycast setup (not 100% familiar with it) and the requests themselves.

In order to continue down that route, I'll have to remove one server from the published anycast config.
That may also help clear up the access and error log to help debug. There are some steps involved to change that so I'll try and get started asap.

In order to continue down that route, I'll have to remove one server from the published anycast config.

I am not sure if that is worth the effort. You might instead modify the access log to include the server IP with %A

We do not yet know if the trigger for the error condition is due to a specific HTTP request or due to a TCP behavior.

I do know that it is also effort to scrub your error log before possibly sharing it.

Do you think I might be able to reproduce this using the Qualsys Community Edition?

The community edition may work but I'm not 100%. A quick search seems to indicate that the scanning capabilities are the same between community and express lite at least (not sure which variant we use internally) so that's somewhat promising. Since the scan is initiated through an RPC call on my end, it's somewhat obfuscated, all I can tell is that it's a "default scan" which scans all plugins at a normal testing rate but no credential bruteforcing.
And I'll still look into the possibility of removing it from our anycast config just in case.

Awesome, happy to hear that.

Thanks for your help and patience through this. My team and a few others will be quite happy about this as I know a few folks had just gone ahead and disabled lighttpd in the meantime.