Hi !
I've upgraded from Debian 9 to 11 (via 10) just recently, i.e. from nginx "1.10.3-1+deb9u7" to "1.18.0-6.1". I'm also running ispconfig on this machine, which modifies configuration. But therefore, I try to post complete configurations at this point in time.
Shortly after the upgrade nginx became unresponsive. After restarting the service, it works again, then it takes some days until it's unresponsive again.
In the error.log I only see these lines, but many of them:
2022/06/08 23:45:01 [alert] 592#592: 768 worker_connections are not enough
Now, then running: lsof | egrep '^nginx .* sock'
I get a long list (well, 760+x or so) of these:
nginx 592 www-data 3u sock 0,8 0t0 69062 protocol: TCP
Thus, it seems that nginx still has a lot of open connections which prevent new requests. Note that this is NOT a high traffic site. It's the very opposite in fact.
I enabled debug log and tried to figure out when a connection was left, and it seems to be this:
2022/06/10 00:05:26 [debug] 1548997#1548997: accept on 0.0.0.0:8080, ready: 0
2022/06/10 00:05:26 [debug] 1548997#1548997: posix_memalign: 000055C757E54E10:512 @16
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 accept: <ip_removed>:57006 fd:18
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 event timer add: 18: 60000:740999452
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 reusable connection: 1
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 epoll add event: fd:18 op:1 ev:80002001
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http check ssl handshake
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http recv(): 1
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 plain http
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http wait request handler
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 malloc: 000055C757F3A150:1024
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 recv: eof:1, avail:-1
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 recv: fd:18 311 of 1024
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 reusable connection: 0
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 posix_memalign: 000055C757F4BF60:4096 @16
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http process request line
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http request line: "POST /cgi-bin/ViewLog.asp HTTP/1.1"
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http uri: "/cgi-bin/ViewLog.asp"
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http args: ""
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http exten: "asp"
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 posix_memalign: 000055C758001210:4096 @16
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http process request header line
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http header: "Host: 192.168.0.14:80"
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http header: "Connection: keep-alive"
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http header: "Accept-Encoding: gzip, deflate"
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http header: "Accept: */*"
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http header: "User-Agent: python-requests/2.20.0"
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http header: "Content-Length: 227"
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http header: "Content-Type: application/x-www-form-urlencoded"
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http header done
2022/06/10 00:05:26 [info] 1548997#1548997: *2544 client sent plain HTTP request to HTTPS port while reading client request headers, client: <ip_removed>, server: _, request: "POST /cgi-bin/ViewLog.asp HTTP/1.1", host: "192.168.0.14:80"
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http finalize request: 497, "/cgi-bin/ViewLog.asp?" a:1, c:1
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 event timer del: 18: 740999452
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http special response: 497, "/cgi-bin/ViewLog.asp?"
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http script copy: "https://"
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http script var: "192.168.0.14"
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http script copy: ":8080"
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http script var: "/cgi-bin/ViewLog.asp"
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http set discard body
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http read discarded body
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 recv: eof:1, avail:0
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 recv: fd:18 0 of 152
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http set discard body
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http read discarded body
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 xslt filter header
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 HTTP/1.1 302 Moved Temporarily
Server: nginx/1.18.0
Date: Thu, 09 Jun 2022 22:05:26 GMT
Content-Type: text/html
Content-Length: 145
Connection: close
Location: https://192.168.0.14:8080/cgi-bin/ViewLog.asp
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 write new buf t:1 f:0 000055C7580015F0, pos 000055C7580015F0, size: 215 file: 0, size: 0
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http write filter: l:0 f:0 s:215
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http output filter "/cgi-bin/ViewLog.asp?"
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http copy filter: "/cgi-bin/ViewLog.asp?"
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 image filter
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 xslt filter body
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http postpone filter "/cgi-bin/ViewLog.asp?" 000055C757F4CF28
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 write old buf t:1 f:0 000055C7580015F0, pos 000055C7580015F0, size: 215 file: 0, size: 0
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 write new buf t:0 f:0 0000000000000000, pos 000055C756470AC0, size: 92 file: 0, size: 0
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 write new buf t:0 f:0 0000000000000000, pos 000055C756470E20, size: 53 file: 0, size: 0
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http write filter: l:1 f:0 s:360
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http write filter limit 0
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 writev: 360 of 360
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http write filter 0000000000000000
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http copy filter: 0 "/cgi-bin/ViewLog.asp?"
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http finalize request: 0, "/cgi-bin/ViewLog.asp?" a:1, c:2
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http request count:2 blk:0
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http run request: "/cgi-bin/ViewLog.asp?"
2022/06/10 00:05:26 [debug] 1548997#1548997: *2544 http reading blocked
2022/06/10 00:05:26 [debug] 1548997#1548997: accept on 0.0.0.0:8080, ready: 0
2022/06/10 00:05:26 [debug] 1548997#1548997: posix_memalign: 000055C757F4B510:512 @16
2022/06/10 00:05:26 [debug] 1548997#1548997: *2545 accept: <ip_removed>:57013 fd:20
2022/06/10 00:05:26 [debug] 1548997#1548997: *2545 event timer add: 20: 60000:740999700
2022/06/10 00:05:26 [debug] 1548997#1548997: *2545 reusable connection: 1
2022/06/10 00:05:26 [debug] 1548997#1548997: *2545 epoll add event: fd:20 op:1 ev:80002001
2022/06/10 00:05:26 [debug] 1548997#1548997: *2545 http check ssl handshake
2022/06/10 00:05:26 [debug] 1548997#1548997: *2545 http recv(): 0
2022/06/10 00:05:26 [info] 1548997#1548997: *2545 client closed connection while SSL handshaking, client: <ip_removed>, server: 0.0.0.0:8080
2022/06/10 00:05:26 [debug] 1548997#1548997: *2545 close http connection: 20
2022/06/10 00:05:26 [debug] 1548997#1548997: *2545 event timer del: 20: 740999700
2022/06/10 00:05:26 [debug] 1548997#1548997: *2545 reusable connection: 0
2022/06/10 00:05:26 [debug] 1548997#1548997: *2545 free: 000055C757F4B510, unused: 232
It seems to be a web scanner sending a POST for /cgi-bin/ViewLog.asp - which does not exist. It finally ends with "http reading blocked" - why? There is a 2nd connection attempt from the same IP in the same second, but I guess the problem comes from the first request.
Is it necessary the nginx sends back a 302 if it receives a request for another server (see the "Host: 192.168.0.14:80" line in the request). Is this a default configuration? I did not spot it...
Does this sound familiar to anyone? I did not find anything in the forum...
Thanks!
Daniel
