ingress-nginx: Dynamic reconfiguration failed, blocked by ModSecurity CRS

NGINX Ingress controller version 4.0.1 Kubernetes version 1.21

Environment: Baremetal, helm, with the following relevant values:

enable-modsecurity: "true"
enable-owasp-modsecurity-crs: "true"
modsecurity-snippet: |
  SecRuleEngine On

Also using cert-manager for automatic TLS certificate creation.

What happened:

Ingress-nginx can perform “dynamic reloads” by sending a POST /configuration/backends request to 127.0.0.1:10246, which is handled by Lua code.

For as far back as I have logs (30 days), ingress-nginx has apparently never performed “dynamic reconfiguration”. It has exclusively performed the full backend reload from this line of code.

But today, ingress-nginx happened to perform a dynamic reconfiguration, which was blocked by ModSecurity CRS (since the request puts an IP address in the Host header). This caused ingress-nginx to be stuck in a loop, constantly reloading and failing, which used up all the RAM and caused cascading failures. The failures were only stopped after I added a ModSecurity rule exception that disabled ModSecurity for those internal requests to 127.0.0.1:10246.

What you expected to happen:

Ingress-nginx should not block requests to itself, either by having modsecurity disabled for the internal requests or shipping with some default rule exceptions.

How to reproduce it:

Good question. How can you trigger a dynamic reload as opposed to a full reload reliably? The comments in the code indicate that if you change a certificate or an L4 IP, it will skip the full reload and just do a dynamic one. But deleting a certificate secret, changing Endpoints, deleting endpoints, all triggers the full reload. And after a full reload, the dynamic reload is skipped.

The only way I can think to trigger a dynamic reload is to hope the configuration changes after the full reload but before the dynamic reload. Maybe this is due to a race condition?

Here are the logs around the event:

I0112 20:42:17.957691       7 store.go:371] "Found valid IngressClass" ingress="balhoff/cm-acme-http-solver-vv5ls" ingressclass="nginx"
I0112 20:42:17.957805       7 event.go:282] Event(v1.ObjectReference{Kind:"Ingress", Namespace:"balhoff", Name:"cm-acme-http-solver-vv5ls", UID:"9c9b7c23-4524-4c10-9044-f6076e3d8dbe", APIVersion:"networking.k8s.io/v1", ResourceVersion:"53881641", FieldPath:""}): type: 'Normal' reason: 'Sync' Scheduled for sync
W0112 20:42:21.150264       7 controller.go:1047] Service "balhoff/cm-acme-http-solver-g6qrv" does not have any active Endpoint.
W0112 20:42:21.150416       7 controller.go:1270] Error getting SSL certificate "balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls": local SSL certificate balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls was not found. Using default certificate
I0112 20:42:21.150637       7 controller.go:152] "Configuration changes detected, backend reload required"
I0112 20:42:21.523706       7 controller.go:169] "Backend successfully reloaded"
I0112 20:42:21.523851       7 event.go:282] Event(v1.ObjectReference{Kind:"Pod", Namespace:"ingress-nginx", Name:"ingress-nginx-controller-jsprp", UID:"d32bee4d-7f81-41d4-98ca-b88caec6c7db", APIVersion:"v1", ResourceVersion:"53755667", FieldPath:""}): type: 'Normal' reason: 'RELOAD' NGINX reload triggered due to a change in configuration
I0112 20:42:21.792188       7 store.go:371] "Found valid IngressClass" ingress="wstephens/helx-nginx" ingressclass="nginx"
I0112 20:42:21.792311       7 event.go:282] Event(v1.ObjectReference{Kind:"Ingress", Namespace:"wstephens", Name:"helx-nginx", UID:"31a7eb2f-9b21-49d8-b5d2-157d1abf9f00", APIVersion:"networking.k8s.io/v1", ResourceVersion:"53881900", FieldPath:""}): type: 'Normal' reason: 'Sync' Scheduled for sync
W0112 20:42:24.484049       7 controller.go:1047] Service "wstephens/helx-nginx" does not have any active Endpoint.
W0112 20:42:24.484202       7 controller.go:1270] Error getting SSL certificate "balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls": local SSL certificate balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls was not found. Using default certificate
I0112 20:42:24.484401       7 controller.go:152] "Configuration changes detected, backend reload required"
I0112 20:42:24.850243       7 controller.go:169] "Backend successfully reloaded"
I0112 20:42:24.850386       7 event.go:282] Event(v1.ObjectReference{Kind:"Pod", Namespace:"ingress-nginx", Name:"ingress-nginx-controller-jsprp", UID:"d32bee4d-7f81-41d4-98ca-b88caec6c7db", APIVersion:"v1", ResourceVersion:"53755667", FieldPath:""}): type: 'Normal' reason: 'RELOAD' NGINX reload triggered due to a change in configuration
I0112 20:42:26.584376       7 status.go:300] "updating Ingress status" namespace="balhoff" ingress="phenoscape-services-1-0-kb-services-service-ingress" currentValue=[] newValue=[{IP:152.54.15.132 Hostname: Ports:[]}]
I0112 20:42:26.584376       7 status.go:300] "updating Ingress status" namespace="balhoff" ingress="cm-acme-http-solver-vv5ls" currentValue=[] newValue=[{IP:152.54.15.132 Hostname: Ports:[]}]
I0112 20:42:26.584376       7 status.go:300] "updating Ingress status" namespace="wstephens" ingress="helx-nginx" currentValue=[] newValue=[{IP:152.54.15.132 Hostname: Ports:[]}]
I0112 20:42:26.590511       7 event.go:282] Event(v1.ObjectReference{Kind:"Ingress", Namespace:"wstephens", Name:"helx-nginx", UID:"31a7eb2f-9b21-49d8-b5d2-157d1abf9f00", APIVersion:"networking.k8s.io/v1", ResourceVersion:"53882009", FieldPath:""}): type: 'Normal' reason: 'Sync' Scheduled for sync
I0112 20:42:26.590855       7 event.go:282] Event(v1.ObjectReference{Kind:"Ingress", Namespace:"balhoff", Name:"phenoscape-services-1-0-kb-services-service-ingress", UID:"f5c40b1b-f8cb-4f8a-9992-0a9539469711", APIVersion:"networking.k8s.io/v1", ResourceVersion:"53882010", FieldPath:""}): type: 'Normal' reason: 'Sync' Scheduled for sync
W0112 20:42:26.590884       7 backend_ssl.go:46] Error obtaining X.509 certificate: no object matching key "balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls" in local store
I0112 20:42:26.590968       7 event.go:282] Event(v1.ObjectReference{Kind:"Ingress", Namespace:"balhoff", Name:"cm-acme-http-solver-vv5ls", UID:"9c9b7c23-4524-4c10-9044-f6076e3d8dbe", APIVersion:"networking.k8s.io/v1", ResourceVersion:"53882011", FieldPath:""}): type: 'Normal' reason: 'Sync' Scheduled for sync
W0112 20:42:27.816720       7 controller.go:1047] Service "wstephens/helx-nginx" does not have any active Endpoint.
W0112 20:42:27.816858       7 controller.go:1270] Error getting SSL certificate "balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls": local SSL certificate balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls was not found. Using default certificate
W0112 20:42:31.149938       7 controller.go:1047] Service "wstephens/helx-nginx" does not have any active Endpoint.
W0112 20:42:31.150084       7 controller.go:1270] Error getting SSL certificate "balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls": local SSL certificate balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls was not found. Using default certificate
W0112 20:42:34.483420       7 controller.go:1047] Service "wstephens/helx-nginx" does not have any active Endpoint.
W0112 20:42:34.483606       7 controller.go:1270] Error getting SSL certificate "balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls": local SSL certificate balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls was not found. Using default certificate
W0112 20:42:37.817216       7 controller.go:1047] Service "wstephens/helx-nginx" does not have any active Endpoint.
W0112 20:42:37.817393       7 controller.go:1270] Error getting SSL certificate "balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls": local SSL certificate balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls was not found. Using default certificate
W0112 20:42:41.673417       7 controller.go:1047] Service "wstephens/helx-nginx" does not have any active Endpoint.
W0112 20:42:41.673603       7 controller.go:1270] Error getting SSL certificate "balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls": local SSL certificate balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls was not found. Using default certificate
W0112 20:42:45.007543       7 controller.go:1047] Service "wstephens/helx-nginx" does not have any active Endpoint.
W0112 20:42:45.007683       7 controller.go:1270] Error getting SSL certificate "balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls": local SSL certificate balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls was not found. Using default certificate
W0112 20:42:57.584197       7 controller.go:1047] Service "wstephens/helx-nginx" does not have any active Endpoint.
W0112 20:42:57.584365       7 controller.go:1270] Error getting SSL certificate "balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls": local SSL certificate balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls was not found. Using default certificate
W0112 20:43:04.317801       7 controller.go:1270] Error getting SSL certificate "balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls": local SSL certificate balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls was not found. Using default certificate
W0112 20:43:07.649716       7 controller.go:1270] Error getting SSL certificate "balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls": local SSL certificate balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls was not found. Using default certificate
W0112 20:43:10.983235       7 controller.go:1270] Error getting SSL certificate "balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls": local SSL certificate balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls was not found. Using default certificate
W0112 20:43:33.456137       7 controller.go:1270] Error getting SSL certificate "balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls": local SSL certificate balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls was not found. Using default certificate
W0112 20:43:36.790048       7 controller.go:1270] Error getting SSL certificate "balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls": local SSL certificate balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls was not found. Using default certificate
W0112 20:43:49.508637       7 controller.go:952] Error obtaining Endpoints for Service "balhoff/cm-acme-http-solver-g6qrv": no object matching key "balhoff/cm-acme-http-solver-g6qrv" in local store
W0112 20:43:49.508778       7 controller.go:1270] Error getting SSL certificate "balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls": local SSL certificate balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls was not found. Using default certificate
I0112 20:43:49.509008       7 controller.go:152] "Configuration changes detected, backend reload required"
I0112 20:43:49.876006       7 controller.go:169] "Backend successfully reloaded"
I0112 20:43:49.876133       7 event.go:282] Event(v1.ObjectReference{Kind:"Pod", Namespace:"ingress-nginx", Name:"ingress-nginx-controller-jsprp", UID:"d32bee4d-7f81-41d4-98ca-b88caec6c7db", APIVersion:"v1", ResourceVersion:"53755667", FieldPath:""}): type: 'Normal' reason: 'RELOAD' NGINX reload triggered due to a change in configuration
I0112 20:43:50.778858       7 store.go:509] "Secret was added and it is used in ingress annotations. Parsing" secret="balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls"
I0112 20:43:50.779265       7 backend_ssl.go:66] "Adding secret to local store" name="balhoff/phenoscape-kb-services-1-0.apps.renci.org-tls"
I0112 20:43:52.842949       7 controller.go:152] "Configuration changes detected, backend reload required"
I0112 20:43:53.208385       7 controller.go:169] "Backend successfully reloaded"
I0112 20:43:53.208809       7 event.go:282] Event(v1.ObjectReference{Kind:"Pod", Namespace:"ingress-nginx", Name:"ingress-nginx-controller-jsprp", UID:"d32bee4d-7f81-41d4-98ca-b88caec6c7db", APIVersion:"v1", ResourceVersion:"53755667", FieldPath:""}): type: 'Normal' reason: 'RELOAD' NGINX reload triggered due to a change in configuration
2022/01/12 20:43:53 [error] 13549#13549: *277346 [client 127.0.0.1] ModSecurity: Access denied with code 403 (phase 2). Matched "Operator `Ge' with parameter `5' against variable `TX:ANOMALY_SCORE' (Value: `8' ) [file "/etc/nginx/owasp-modsecurity-crs/rules/REQUEST-949-BLOCKING-EVALUATION.conf"] [line "80"] [id "949110"] [rev ""] [msg "Inbound Anomaly Score Exceeded (Total Score: 8)"] [data ""] [severity "2"] [ver "OWASP_CRS/3.3.2"] [maturity "0"] [accuracy "0"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-generic"] [hostname "127.0.0.1"] [uri "/configuration/servers"] [unique_id "1642020233"] [ref ""], client: 127.0.0.1, server: , request: "POST /configuration/servers HTTP/1.1", host: "127.0.0.1:10246"
W0112 20:43:54.000587       7 controller.go:198] Dynamic reconfiguration failed: unexpected error code: 403
E0112 20:43:54.000606       7 controller.go:202] Unexpected failure reconfiguring NGINX:
unexpected error code: 403
E0112 20:43:54.000618       7 queue.go:130] "requeuing" err="unexpected error code: 403" key="balhoff/cm-acme-http-solver-vv5ls"
I0112 20:43:56.176351       7 controller.go:152] "Configuration changes detected, backend reload required"
I0112 20:43:56.537687       7 controller.go:169] "Backend successfully reloaded"
I0112 20:43:56.537940       7 event.go:282] Event(v1.ObjectReference{Kind:"Pod", Namespace:"ingress-nginx", Name:"ingress-nginx-controller-jsprp", UID:"d32bee4d-7f81-41d4-98ca-b88caec6c7db", APIVersion:"v1", ResourceVersion:"53755667", FieldPath:""}): type: 'Normal' reason: 'RELOAD' NGINX reload triggered due to a change in configuration
2022/01/12 20:43:57 [error] 13837#13837: *277405 [client 127.0.0.1] ModSecurity: Access denied with code 403 (phase 2). Matched "Operator `Ge' with parameter `5' against variable `TX:ANOMALY_SCORE' (Value: `8' ) [file "/etc/nginx/owasp-modsecurity-crs/rules/REQUEST-949-BLOCKING-EVALUATION.conf"] [line "80"] [id "949110"] [rev ""] [msg "Inbound Anomaly Score Exceeded (Total Score: 8)"] [data ""] [severity "2"] [ver "OWASP_CRS/3.3.2"] [maturity "0"] [accuracy "0"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-generic"] [hostname "127.0.0.1"] [uri "/configuration/servers"] [unique_id "1642020237"] [ref ""], client: 127.0.0.1, server: , request: "POST /configuration/servers HTTP/1.1", host: "127.0.0.1:10246"
W0112 20:43:57.362644       7 controller.go:198] Dynamic reconfiguration failed: unexpected error code: 403
E0112 20:43:57.362662       7 controller.go:202] Unexpected failure reconfiguring NGINX:
unexpected error code: 403