Nginx with modsecurity enabled stop to process request

[nithril]

Is this a request for help? (If yes, you should use our troubleshooting guide and community support channels, see https://kubernetes.io/docs/tasks/debug-application-cluster/troubleshooting/.): BUG

Is this a BUG REPORT or FEATURE REQUEST? (choose one): BUG

NGINX Ingress controller version: 0.26.1

Kubernetes version (use kubectl version): 1.14.4

Environment:

• Cloud provider or hardware configuration: Azure
• OS (e.g. from /etc/os-release): Centos 7.6

What happened:

Nginx is installed with helm. When enable-modsecurity is enabled, after some time, especially under load, nginx stops to process requests but it still accepts connection. The issue happens that the request comes from the outside or even when performing a curl from inside the controller container (eg. curl localhost:80) but not from the status port.

Killing workers manually resolves the issue.

How to reproduce it (as minimally and precisely as possible):

I do not have yet a minimal scenario

Anything else we need to know:

Can it relate to that issue?
owasp-modsecurity/ModSecurity#1927

[joshbranham]

We saw similar issues and I think it was related to modsecurity default config of serially writing to the same file its audit of each connection.

[nithril]

I will recheck, AFAIR, I got the issue even with Concurrent or Parallel

[DaveAurionix]

@nithril We're seeing something that might be similar. We're trying to narrow it down. This didn't seem to happen in 0.24.1, but in 0.26.1 when we place NGINX under moderate load in a performance test (not a ridiculous load) a few minutes into the test then 0.26.1 will seem to lock up and stop processing new requests.

We haven't changed the ModSecurity configuration but we will look at that (we are serially writing to stderr which is not ideal but seemed to be OK in 0.24.1 at way past this load).

As far as I can tell, but I might be wrong, we are seeing NGINX refusing to accept new SSL connections. Logs are not showing anything useful (at least, the logs I can find).

[DaveAurionix]

@joshbranham Interesting - we disabled ModSecurity audit-logging and ran another performance test and it sailed through. It's only one data-point so might be a bit early to tell but if tonight's tests go through OK I think you've found the issue for us - thank you for posting your experience.

[joshbranham]

@joshbranham Interesting - we disabled ModSecurity audit-logging and ran another performance test and it sailed through. It's only one data-point so might be a bit early to tell but if tonight's tests go through OK I think you've found the issue for us - thank you for posting your experience.

🤞

[DaveAurionix]

@nithril FYI this definitely fixed our issue. More serious performance tests overnight all went through fine. Not sure why this is worse for us in 0.26.1 causing a visible problem at our required load that wasn't visible in 0.24.1, but it was definitely configuration that we needed to fix anyway.

[nithril]

Good to know!

I was planning to first enable modsecurity in detection mode to analyze the logs. By disabling audit log, AFAIK I will not be able to analyze the detection event.

[DaveAurionix]

At the moment we are using the container logs for that, which are not the audit logs in my limited understanding so please do contradict me if you know more. The container logs show us a warning with brief details whenever a rule is tripped (client ip, rule id, rule detail, excerpts from the part of the request that caused a failure). We've found so far that this is enough detail for us.

As far as I understand it, the audit logs allow much larger parts of the request and/or response to be logged (such as the whole request body if that caused a rule to trip) which is why they can be a performance bottleneck if lots of requests trigger audit log entries (e.g. 4XX upstream responses) and if those entries cannot be written concurrently. We don't really want all of that detail anyway so have disabled it entirely with SecAuditEngine Off. Since doing that, the performance tests are passing yet the container logs are still showing enough detail for our needs today.

Admittedly, I have struggled to find what the log-lines that ModSecurity writes to stdout or stderr are called and how to configure them (the stdout or stderr output appears in the Kubernetes or Docker container logs). It's possible that they are cut-down audit logs and although I think I've turned off auditlogs, actually I haven't.

[DaveAurionix]

P.S. when analysing tripped rules we also look at our standard NGINX web-request log entries so maybe we have enough data (for us today) because we use both those sources (ModSecurity warnings and NGINX web request access log entries).

[kwaazaar]

I think I'm experiencing exactly this issue. We've got ModSecurity enabled for a few ingresses as well (although it doesn't block any requests, but that's another issue :-() and after a while, usually less than a day the ingress controllers take forever to accept new connections.

The logs show no detail (even with --v=5) and the metrics, as reported to Prometheus, don't seem to contain any useful information either. Killing all controller pods resolves the issue.

I've been trying to troubleshoot this issue for a few days, but cannot find anything that explains this behavior. We had a similar issue on 1.10 once, so switched to to 1.24.3 (0.26.1), but since this issue appeared similar to the first issue, I didn't realize the version upgrade caused the increase of the problem.

I reproduce the issue pretty quickly by using this script:

#!/bin/bash
echo "Bash version ${BASH_VERSION}"
for i in {1..5000}
do
    echo "Attempt $i..."
    curl --no-keepalive --connect-timeout 5 -k -v --silent -o /dev/nul https://mysite
done

Because I use Bash, it creates new connections all the time. When using Postman Collection Runner, I didn't see these issues, since it reuses the connection for every request. So it seems like either the TCP or SSL handshake is related to the issue.

I've now tried to reproduce the issue on a separate ingress controller with an ingress that does not have ModSecurity enabled and I can't seem to reproduce the issue, so this is most likely related to ModSecurity.

[joshbranham]

@kwaazaar have you tried changing mod security’s logging settings to not be serial (the default)? That seemed to fix it for me

[kwaazaar]

I just tried. But things still broke, maybe because I also have loglevel set to 9, causing a lot of content to be written to the logs. This is my modsecurity snippet:

  nginx.ingress.kubernetes.io/modsecurity-snippet: |
    SecRule REQUEST_HEADERS_NAMES "^x-waf-test" "log,deny,id:48,status:403,t:lowercase,msg:WAFWAFWAF"
    SecRequestBodyAccess On
    SecDebugLog /tmp/modsec_debug.log
    SecDebugLogLevel 9
    SecAuditLogType Concurrent
    SecRuleEngine On

I'm going to disable modsecurity all together, since it's not working on our cluster anyway.

[kwaazaar]

I did a quick run with SecDebugLogLevel 1 and I can no longer reproduce the issue. Seems like the extensive logging is an issue.

[sc250024]

Seeing the same issue, this time with around 50 - 60 machines that are collecting Kubernetes metrics on machines, and sending those metrics to our tooling cluster.

This is deployed using the Helm chart, with the following config:

controller:
  config:
    enable-modsecurity: "true"
    enable-owasp-modsecurity-crs: "true"

Is there a way to turn down the logging like @kwaazaar mentioned?

[gravis]

We're seeing the same issue when logging with Serial. Could it be linked to owasp-modsecurity/ModSecurity#1927 (and owasp-modsecurity/ModSecurity#1949)?