nginx unresponsive after a while

Sun Jun 12 22:15:05 UTC 2022

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

Posted at Nginx Forum: https://forum.nginx.org/read.php?2,294468,294468#msg-294468