Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

PATCH method dies with mod security with nginx configured as proxy/ingress #2341

Open
PaulCharlton opened this issue Jun 16, 2020 · 22 comments
Labels
3.x Related to ModSecurity version 3.x Platform - Nginx workaround available The issue has either a temporary or permanent workaround available

Comments

@PaulCharlton
Copy link

Version info:

version: libmodsecurity.so.3.0.3

name: nginx-ingress
repository: https://kubernetes-charts.storage.googleapis.com
version: 1.33.5
kubectl version
Server Version: version.Info{Major:"1", Minor:"16", GitVersion:"v1.16.9", GitCommit:"a17149e1a189050796ced469dbd78d380f2ed5ef", GitTreeState:"clean", BuildDate:"2020-04-16T23:15:50Z", GoVersion:"go1.13.9", Compiler:"gc", Platform:"linux/amd64"}

===> cross-post from kubernetes/ingress-nginx#5723

Summary Observations:
PATCH method with JSON request body sent to ingress receives no response bytes on connection and connection is left open.

Connection is closed only when NGINX ingress is bounced due to server reload (on change of ConfigMap, pod deletion ... etc)

when Debug logging is enabled with
SecDebugLog /dev/stdout
SecDebugLogLevel 4

the debug log shows that phase 1 of the Modsecurity (a) recognized the "application/json", and that (b) phase 2 assigned the JSON attributes into ARGS for subsequent scanning.

** Changing from "DetectOnly" to rule enforcement does not change the behavior. Adding the CRS ruleset does not change the behavior.

** POST and PUT methods work without hanging the connection
** PATCH method works correctly when enable-modsecurity: "false"

====================================

@PaulCharlton PaulCharlton changed the title PATCH method dies with enable-modsecurity: "true" default configuration PATCH method dies within mod security with nginx configured as proxy/ingress Jun 16, 2020
@PaulCharlton
Copy link
Author

open to any triage suggestions --- I realize there are several moving parts here between Nginx, modsecurity, and the Nginx-connector

@PaulCharlton
Copy link
Author

PaulCharlton commented Jun 16, 2020

Additional info:
The PATCH request body is a single JSON object, not terminated with a newline. The size in bytes of that JSON object matches exactly the Content-Length header. and Content-Type: application/json;charset=utf-8

Additional info:
adding EOL to the payload (and increasing the content length accordingly) is misbehaving in the same way

@martinhsv
Copy link
Contributor

Hi @PaulCharlton ,

Probably the single most useful thing would be to increase your log levels. SecDebugLogLevel set to 9 will show a lot more detail about what is happening within ModSecurity. Similarly, if the error is occurring in nginx code, setting the error_log level to info, or even debug, might help.

@victorhora victorhora added 3.x Related to ModSecurity version 3.x Platform - Nginx labels Jun 18, 2020
@PaulCharlton
Copy link
Author

PaulCharlton commented Jun 20, 2020

@martinhsv thanks for the insights on how to proceed. Increasing the ModSecurity debug log level to 9 did not show anything useful -- all rules appear to be passing. I will continue some data gathering with the Nginx error_log level settings.

@PaulCharlton
Copy link
Author

@martinhsv this may be the best clue thus far:
2020/06/20 15:11:03 [info] 34461#34461: *4116259 ModSecurity: Warning. Matched "Operator 'Rx' with parameter '^0?$' against variable 'REQUEST_HEADERS:content-length' (Value: '945' ) [file "/etc/nginx/owasp-modsecurity-crs/rules/REQUEST-920-PROTOCOL-ENFORCEMENT.conf"] [line "161"] [id "920170"] [rev ""] [msg "GET or HEAD Request with Body Content."] [data "GET"] [severity "2"] [ver "OWASP_CRS/3.2.0"] [maturity "0"] [accuracy "0"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-protocol"] [tag "OWASP_CRS"] [tag "OWASP_CRS/PROTOCOL_VIOLATION/INVALID_HREQ"] [tag "CAPEC-272"] [hostname "10.240.0.26"] [uri "{redacted"] [unique_id "159266586361.523559"] [ref "o0,3v0,3v2318,3"], client: 10.240.0.35, server: _, request: "POST {redacted} HTTP/2.0", subrequest: "/_external-auth-L2NmLWVsbSgvfCQpKC4qKQ", host: "{redacted}"

For context:

  1. I do not (yet) know the control flow through the various Nginx modules.
  2. other than the level 4,9 modsecurity logging (initially passing) there is nothing in the Nginx info log, and the session is hanging ... UNTIL
  3. UNTIL I break the session from the client side. When I break the session from the client side, it produces the log entry above, which appears to be a clue as to where NGINX was hanging in the session flow.
    3a) yes, we do have an external auth provider -- which works fine with POST/PATCH until modsecurity is injected into the control flow.

so I am still investigating the following: (a) why does the session hang, and where in the code is it hanging? (b) what happens if I disable external auth, (c) can I increase logging on the external auth to see how the session state differs if modsecurity is on/off (d) why does breaking the session from the client side produce any additional modsecurity logging AFTER session is closed?

@PaulCharlton
Copy link
Author

continuing that investigation -- the entire control flow works when I disable our external auth by removing the auth related annotations from the k8s ingress resource.

combining that with the info from the log above -- Nginx appears to be sending the entire request body to the auth provider -- even on a POST/PATCH/PUT request ... and all our auth provider really cares about is a couple of the request headers.

@PaulCharlton
Copy link
Author

@martinhsv so -- modsecurity flagging on a sub-request -- what is the control flow supposed to be? it definitely should not be hanging the session until client-side terminates.

@PaulCharlton
Copy link
Author

more information:
disabling modsecurity at the "location" level does NOT change the behavior -- its presence, even when disabled at location, and even when all rules are disable, still produces the hang.

Looking at the issue I identified in the log above, I went looking for the configuration for the external auth, and contrary to the modsecurity log above, the external auth location does not pass the request body ...

                location = /_external-auth-L2NmLWFwcCgvfCQpKC4qKQ {                               
                        internal;                                                                 
                                                                                                  
                        # ngx_auth_request module overrides variables in the parent request,      
                        # therefore we have to explicitly set this variable again so that when the parent request
                        # resumes it has the correct value set for this variable so that Lua can pick backend correctly
                        set $proxy_upstream_name "cfk8s-cf-react-app-docker-80";                                       
                                                                                                                       
                        proxy_pass_request_body     off;                                                               
                        proxy_set_header            Content-Length "";                                                 
                        proxy_set_header            X-Forwarded-Proto "";                                              
                                                                                                                       
                        proxy_set_header            Host                    $host;                                     
                        proxy_set_header            X-Original-URL          $scheme://$http_host$request_uri;          
                        proxy_set_header            X-Original-Method       $request_method;                           
                        proxy_set_header            X-Sent-From             "nginx-ingress-controller";                
                        proxy_set_header            X-Real-IP               $remote_addr;                              
                                                                                                                       
                        proxy_set_header            X-Forwarded-For        $remote_addr;                               
                                                                                                                       
                        proxy_set_header            X-Auth-Request-Redirect $request_uri;                              
                                                                                                                       
                        proxy_buffering                         off;                                                   
                                                                                                                       
                        proxy_buffer_size                       8k;                                                    
                        proxy_buffers                           4 8k;                                                  
                        proxy_request_buffering                 on;                                          
                        proxy_http_version                      1.1;                                         
                                                                                                             
                        proxy_ssl_server_name       on;                                                      
                        proxy_pass_request_headers  on;                                                      
                                                                                                             
                        client_max_body_size        1m;                                                      
                                                                                                             
                        # Pass the extracted client certificate to the auth provider                   
                                                                                                       
                        set $target https://$host/oauth2/auth;                                        
                        proxy_pass $target;                                              
                } 

@PaulCharlton
Copy link
Author

PaulCharlton commented Jun 20, 2020

summary of what I have observed:

  1. Nginx ingress with no modsecurity/external_auth. -> works
  2. Nginx ingress with either modsecurity or external_auth. -> works
  3. Nginx ingress with both modsecurity and external_auth. -> hangs session until broken by client
    3a) modsecurity logs "invalid request body" (Rule #920170) with external auth path upon session break by client

I am imagining that something in the control flow nginx->modsecurity->nginx->external_auth->nginx->proxied_server is corrupting session state at the boundary where modsecurity returns to nginx. [or doing a req_read, not realizing that req is already at EOF/(content-length) boundary]

@martinhsv
Copy link
Contributor

martinhsv commented Jun 22, 2020

Hi @PaulCharlton ,

Those are some good clues.

In some ways it sounds a bit like something akin to bitly/oauth2_proxy#442 . I.e. if no body is sent but a Content-Length header is present with a nonzero value, then a hang could be occurring due to a waiting-for-body state.

A few things you could try to further clarify what is happening:
A) Are you able to actually sniff what is being sent to the auth provider in that subrequest (auth endpoint logging, wireshark, etc. )? Can you confirm that it is actually receiving a Content-Length header with value 945? And a body is present also?
B) If A) is yes/yes, does the same thing happen when auth is on but ModSecurity is off entirely (i.e. a scenario that 'works' per number 2 in your previous posting). If this is yes also, then that suggests that at least part of the answer is not directly related to ModSecurity, but a problem that your settings within location = /_external-auth-L2NmLWFwcCgvfCQpKC4qKQ are not being respected.
C) With ModSecurity back on in general, can you modify the the behaviour within the auth location besides using 'modsecurity off'. E.g. can you use a modsecurity_rules directive to either i) use SecRuleEngine Off, or a SecRule or SecAction that performs a ctl:ruleRemoveById=920170. I.e. does that action appear in the debug log, and does the log entry for 920170 stop appearing?

Two additional possibilities to proceed:

  • you mentioned that you are using ModSecurity v3.0.3. There is a newer version (v3.0.4) that has a fair number of fixes that you could try upgrading to. I haven't spotted any fixes that appear obviously applicable to this situation, but it could be worth a try.
  • the ModSecurity-nginx recently has a newer version as (v1.0.1), so if you're still using v1.0.0, you could consider upgrading to see if that helps. Same caveat as in the previous bullet point

@PaulCharlton
Copy link
Author

PaulCharlton commented Jun 22, 2020

@martinhsv I will follow up on your ideas and let you know:
A) -- sniffing -- can do one better and inject a lightweight proxy server in between Nginx and the auth server and trace everything
B) the location policy for the auth server already has proxy_pass_request_body off; proxy_set_header Content-Length ""; so I would be surprised if there was any actual body or content-length sent out ... however, the truth may be stranger than fiction, so back to the sniffing.
C) re: versions, I am going to set up a standalone helm chart and k8s cluster to reproduce the issue with the minimal number of components and play with levers such as component version numbers. I will also do some visual code review/inspection before resorting to a debug build of Nginx / modsecurity-nginx / etc.

@PaulCharlton
Copy link
Author

PaulCharlton commented Jun 26, 2020

@martinhsv was able to confirm that the session is hung between the modsecurity pass and the invocation of the auth sub request. Also discovered that the auth sub request completes successfully immediately after the client breaks the session.

In a nutshell, when modsecurity is enabled (even with "SecRulesEngine Off"), Nginx ingests an extra byte from the client SSL connection. I am still drilling into the root cause, and I have attached a CSV of logs demonstrating the different in SSL protocol behavior.

Noting also that the difference in SSL behavior occurs before the auth subRequest even begins processing, and that there is enough difference in session state with/without modsecurity that the auth subRequest performs a blocking read if and only if modsecurity is enabled.

I can imagine from the attached log that modsecurity is introducing enough extra latency that Nginx "SSL Read" at line 10 of the attached trace no longer returns "-1" (ie: EAGAIN or EWOULDBLOCK).

datadog-debug-nginx-nohang-filtered-002.csv:1705,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_do_handshake: -1
datadog-debug-nginx-nohang-filtered-002.csv:1706,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_get_error: 2
datadog-debug-nginx-nohang-filtered-002.csv:1709,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_do_handshake: 1
datadog-debug-nginx-nohang-filtered-002.csv:1719,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_read: -1
datadog-debug-nginx-nohang-filtered-002.csv:1720,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_get_error: 2
datadog-debug-nginx-nohang-filtered-002.csv:1727,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_write: 40
datadog-debug-nginx-nohang-filtered-002.csv:1739,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_read: 24
datadog-debug-nginx-nohang-filtered-002.csv:1740,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_read: 27
datadog-debug-nginx-nohang-filtered-002.csv:1741,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_read: 13
datadog-debug-nginx-nohang-filtered-002.csv:1742,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,,Different,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_read: -1
datadog-debug-nginx-nohang-filtered-002.csv:1743,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,,Different,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_get_error: 2
datadog-debug-nginx-nohang-filtered-002.csv:1758,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,,Different,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_write: 9
datadog-debug-nginx-nohang-filtered-002.csv:1768,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,,Different,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_read: 1738
datadog-debug-nginx-nohang-filtered-002.csv:1769,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_read: 9
datadog-debug-nginx-nohang-filtered-002.csv:1770,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_read: 954
datadog-debug-nginx-nohang-filtered-002.csv:1771,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_read: -1
datadog-debug-nginx-nohang-filtered-002.csv:1772,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_get_error: 2
datadog-debug-nginx-nohang-filtered-002.csv:2005,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,authSubRequest,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_do_handshake: -1
datadog-debug-nginx-nohang-filtered-002.csv:2006,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,authSubRequest,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_get_error: 2
datadog-debug-nginx-nohang-filtered-002.csv:2038,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,authSubRequest,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_do_handshake: -1
datadog-debug-nginx-nohang-filtered-002.csv:2039,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,authSubRequest,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_get_error: 2
datadog-debug-nginx-nohang-filtered-002.csv:2041,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,authSubRequest,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_do_handshake: -1
datadog-debug-nginx-nohang-filtered-002.csv:2042,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,authSubRequest,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_get_error: 2
datadog-debug-nginx-nohang-filtered-002.csv:2054,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,authSubRequest,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_do_handshake: 1
datadog-debug-nginx-nohang-filtered-002.csv:2065,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,authSubRequest,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_write: 2471
datadog-debug-nginx-nohang-filtered-002.csv:2071,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,authSubRequest,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_read: -1
datadog-debug-nginx-nohang-filtered-002.csv:2072,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,authSubRequest,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_get_error: 2
datadog-debug-nginx-nohang-filtered-002.csv:2349,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,authSubRequest,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_read: 4096
datadog-debug-nginx-nohang-filtered-002.csv:2350,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,authSubRequest,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_read: 1267
datadog-debug-nginx-nohang-filtered-002.csv:2351,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,authSubRequest,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_read: 0
datadog-debug-nginx-nohang-filtered-002.csv:2352,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,authSubRequest,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_get_error: 6
datadog-debug-nginx-nohang-filtered-002.csv:2379,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,authSubRequest,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_shutdown: 1
datadog-debug-nginx-nohang-filtered-002.csv:2528,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,authSubRequest,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_write: 4096
datadog-debug-nginx-nohang-filtered-002.csv:2531,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,authSubRequest,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_write: 2833
datadog-debug-nginx-nohang-filtered-002.csv:2556,2020-06-26T17:12:31.000Z,dev,debug,modsecurity=disabled,authSubRequest,,,,2020/06/26 17:12:31 [debug] 836#836: *152457 SSL_write: 9
datadog-debug-nginx-nohang-filtered-002.csv:2657,2020-06-26T17:12:32.000Z,dev,debug,modsecurity=disabled,authSubRequest,,,,2020/06/26 17:12:32 [debug] 836#836: *152457 SSL_read: 0
datadog-debug-nginx-nohang-filtered-002.csv:2658,2020-06-26T17:12:32.000Z,dev,debug,modsecurity=disabled,authSubRequest,,,,2020/06/26 17:12:32 [debug] 836#836: *152457 SSL_get_error: 6
datadog-debug-nginx-nohang-filtered-002.csv:2661,2020-06-26T17:12:32.000Z,dev,debug,modsecurity=disabled,authSubRequest,,,,2020/06/26 17:12:32 [debug] 836#836: *152457 SSL_shutdown: 1
,,,,,,,,,
datadog-debug-nginx-post-hang-filtered.csv:1217,2020-06-26T12:09:15.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",,,,,2020/06/26 12:09:15 [debug] 525#525: *12999 SSL_do_handshake: -1
datadog-debug-nginx-post-hang-filtered.csv:1218,2020-06-26T12:09:15.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",,,,,2020/06/26 12:09:15 [debug] 525#525: *12999 SSL_get_error: 2
datadog-debug-nginx-post-hang-filtered.csv:1221,2020-06-26T12:09:16.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",,,,,2020/06/26 12:09:16 [debug] 525#525: *12999 SSL_do_handshake: 1
datadog-debug-nginx-post-hang-filtered.csv:1231,2020-06-26T12:09:16.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",,,,,2020/06/26 12:09:16 [debug] 525#525: *12999 SSL_read: -1
datadog-debug-nginx-post-hang-filtered.csv:1232,2020-06-26T12:09:16.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",,,,,2020/06/26 12:09:16 [debug] 525#525: *12999 SSL_get_error: 2
datadog-debug-nginx-post-hang-filtered.csv:1239,2020-06-26T12:09:16.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",,,,,2020/06/26 12:09:16 [debug] 525#525: *12999 SSL_write: 40
datadog-debug-nginx-post-hang-filtered.csv:1291,2020-06-26T12:09:16.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",,,,,2020/06/26 12:09:16 [debug] 525#525: *12999 SSL_read: 24
datadog-debug-nginx-post-hang-filtered.csv:1292,2020-06-26T12:09:16.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",,,,,2020/06/26 12:09:16 [debug] 525#525: *12999 SSL_read: 27
datadog-debug-nginx-post-hang-filtered.csv:1293,2020-06-26T12:09:16.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",,,,,2020/06/26 12:09:16 [debug] 525#525: *12999 SSL_read: 13
datadog-debug-nginx-post-hang-filtered.csv:1294,2020-06-26T12:09:16.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",,Different - reading extra byte from client stream,,,2020/06/26 12:09:16 [debug] 525#525: *12999 SSL_read: 1739
datadog-debug-nginx-post-hang-filtered.csv:1295,2020-06-26T12:09:16.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",,,,,2020/06/26 12:09:16 [debug] 525#525: *12999 SSL_read: 9
datadog-debug-nginx-post-hang-filtered.csv:1296,2020-06-26T12:09:16.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",,,,,2020/06/26 12:09:16 [debug] 525#525: *12999 SSL_read: 954
datadog-debug-nginx-post-hang-filtered.csv:1297,2020-06-26T12:09:16.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",,,,,2020/06/26 12:09:16 [debug] 525#525: *12999 SSL_read: -1
datadog-debug-nginx-post-hang-filtered.csv:1298,2020-06-26T12:09:16.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",,,,,2020/06/26 12:09:16 [debug] 525#525: *12999 SSL_get_error: 2
datadog-debug-nginx-post-hang-filtered.csv:1480,2020-06-26T12:09:16.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",authSubRequest,Different,,,2020/06/26 12:09:16 [debug] 525#525: *12999 SSL_write: 22
datadog-debug-nginx-post-hang-filtered.csv:6279,2020-06-26T12:10:02.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",authSubRequest,Different - Gap while waiting on client - terminated by client,,,2020/06/26 12:10:02 [debug] 525#525: *12999 SSL_read: 0
datadog-debug-nginx-post-hang-filtered.csv:6280,2020-06-26T12:10:02.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",authSubRequest,Different,,,2020/06/26 12:10:02 [debug] 525#525: *12999 SSL_get_error: 5
datadog-debug-nginx-post-hang-filtered.csv:6370,2020-06-26T12:10:02.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",authSubRequest,,,,2020/06/26 12:10:02 [debug] 525#525: *12999 SSL_do_handshake: -1
datadog-debug-nginx-post-hang-filtered.csv:6371,2020-06-26T12:10:02.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",authSubRequest,,,,2020/06/26 12:10:02 [debug] 525#525: *12999 SSL_get_error: 2
datadog-debug-nginx-post-hang-filtered.csv:6403,2020-06-26T12:10:02.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",authSubRequest,,,,2020/06/26 12:10:02 [debug] 525#525: *12999 SSL_do_handshake: -1
datadog-debug-nginx-post-hang-filtered.csv:6404,2020-06-26T12:10:02.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",authSubRequest,,,,2020/06/26 12:10:02 [debug] 525#525: *12999 SSL_get_error: 2
datadog-debug-nginx-post-hang-filtered.csv:6406,2020-06-26T12:10:02.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",authSubRequest,,,,2020/06/26 12:10:02 [debug] 525#525: *12999 SSL_do_handshake: -1
datadog-debug-nginx-post-hang-filtered.csv:6407,2020-06-26T12:10:02.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",authSubRequest,,,,2020/06/26 12:10:02 [debug] 525#525: *12999 SSL_get_error: 2
datadog-debug-nginx-post-hang-filtered.csv:6419,2020-06-26T12:10:02.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",authSubRequest,,,,2020/06/26 12:10:02 [debug] 525#525: *12999 SSL_do_handshake: 1
datadog-debug-nginx-post-hang-filtered.csv:6430,2020-06-26T12:10:02.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",authSubRequest,,,,2020/06/26 12:10:02 [debug] 525#525: *12999 SSL_write: 2471
datadog-debug-nginx-post-hang-filtered.csv:6436,2020-06-26T12:10:02.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",authSubRequest,,,,2020/06/26 12:10:02 [debug] 525#525: *12999 SSL_read: -1
datadog-debug-nginx-post-hang-filtered.csv:6437,2020-06-26T12:10:02.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",authSubRequest,,,,2020/06/26 12:10:02 [debug] 525#525: *12999 SSL_get_error: 2
datadog-debug-nginx-post-hang-filtered.csv:6741,2020-06-26T12:10:02.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",authSubRequest,,,,2020/06/26 12:10:02 [debug] 525#525: *12999 SSL_read: 4096
datadog-debug-nginx-post-hang-filtered.csv:6742,2020-06-26T12:10:02.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",authSubRequest,,,,2020/06/26 12:10:02 [debug] 525#525: *12999 SSL_read: 1267
datadog-debug-nginx-post-hang-filtered.csv:6743,2020-06-26T12:10:02.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",authSubRequest,,,,2020/06/26 12:10:02 [debug] 525#525: *12999 SSL_read: 0
datadog-debug-nginx-post-hang-filtered.csv:6744,2020-06-26T12:10:02.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",authSubRequest,,,,2020/06/26 12:10:02 [debug] 525#525: *12999 SSL_get_error: 6
datadog-debug-nginx-post-hang-filtered.csv:6771,2020-06-26T12:10:02.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",authSubRequest,,,,2020/06/26 12:10:02 [debug] 525#525: *12999 SSL_shutdown: 1
datadog-debug-nginx-post-hang-filtered.csv:6820,2020-06-26T12:10:02.000Z,dev,debug,"enabled=modsecurity, SecRulesEngine ""off"" or ""on""",,,,,2020/06/26 12:10:02 [debug] 525#525: *12999 SSL_shutdown: 1

@PaulCharlton
Copy link
Author

adding information: the hung session only occurs with TLS client connections

@PaulCharlton
Copy link
Author

Server: Nginx/modsecurity container: quay.io/kubernetes-ingress-controller/nginx-ingress-controller
tag: "0.32.0"

@PaulCharlton PaulCharlton changed the title PATCH method dies within mod security with nginx configured as proxy/ingress PATCH method dies with mod security with nginx configured as proxy/ingress Jun 27, 2020
@PaulCharlton
Copy link
Author

adding information: the session does not hang if the POST/PUT/PATCH has an empty request body and no Content-Length header. Even a "Content-Length: 0" hangs.

SecRequestBodyAccess Off (or On) does not change the outcome.

@PaulCharlton
Copy link
Author

spoke too soon on the last one.

  1. curl -X POST URI --header 'Content-Length: 0' works with modsecurity enabled.
  2. curl -X POST URI -d '' does not work with modsecurity enabled. (blank line, Content-Length: 0)
  3. curl -X POST URI works with modsecurity enabled (no body, no content length header)
    for each of the above: SecRulesEngine Off

for evidence below, first request worked; second request hung until CTL-C on client side.
trail of evidence ->

seq,date,cf-env,Status,http.method,URL Path,Status Code,network.bytes_read,msg,message
1,2020-06-27T04:47:41.000Z,dev,ok,GET,/oauth2/auth,202,0,,"10.240.0.35 - - [27/Jun/2020:04:47:41 +0000] ""GET /oauth2/auth HTTP/1.1"" 202 0 ""-"" ""curl/7.64.1"" 2471 0.010 [cfk8s-cf-oauth-proxy-docker-80] [] 10.240.0.75:4180 0 0.012 202 e41261dda38ac07282ff11a27ab2814e"
2,2020-06-27T04:47:41.000Z,dev,ok,POST,/cf-echo,202,0,,"10.240.0.35 - - [27/Jun/2020:04:47:41 +0000] ""POST /cf-echo HTTP/2.0"" 202 0 ""-"" ""curl/7.64.1"" 0 0.031 [cfk8s-cf-http-https-echo-80] [] 52.149.172.235:443 0 0.016 202 e41261dda38ac07282ff11a27ab2814e"
3,2020-06-27T04:47:41.000Z,dev,ok,POST,/cf-echo,200,4943,,"10.240.0.35 - - [27/Jun/2020:04:47:41 +0000] ""POST /cf-echo HTTP/2.0"" 200 4943 ""-"" ""curl/7.64.1"" 1728 0.044 [cfk8s-cf-http-https-echo-80] [] 10.240.0.17:80 4943 0.012 200 e41261dda38ac07282ff11a27ab2814e"
4,2020-06-27T04:47:41.000Z,dev,info,,,,,,"2020/06/27 04:47:41 [info] 600#600: *161514 client closed connection while SSL handshaking, client: 10.240.0.35, server: 0.0.0.0:443"
5,2020-06-27T04:47:41.000Z,dev,info,,,,,,"2020/06/27 04:47:41 [info] 599#599: *161513 client closed connection while waiting for request, client: 10.240.0.35, server: 0.0.0.0:80"
6,2020-06-27T04:47:41.154Z,dev,error,,,,,,[159323326157.663567] [] [4] Initializing transaction
7,2020-06-27T04:47:41.155Z,dev,error,,,,,,[159323326157.663567] [] [4] Transaction context created.
8,2020-06-27T04:47:41.155Z,dev,error,,,,,,[159323326157.663567] [] [4] Starting phase CONNECTION. (SecRules 0)
9,2020-06-27T04:47:41.164Z,dev,error,,,,,,[159323326157.663567] [] [9] This phase consists of 0 rule(s).
10,2020-06-27T04:47:41.164Z,dev,error,,,,,,[159323326157.663567] [] [4] Starting phase URI. (SecRules 0 + 1/2)
11,2020-06-27T04:47:41.164Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [4] Starting phase REQUEST_HEADERS.  (SecRules 1)
12,2020-06-27T04:47:41.164Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [9] This phase consists of 2 rule(s).
13,2020-06-27T04:47:41.164Z,dev,error,,,,,,"[159323326157.663567] [/cf-echo] [4] (Rule: 200000) Executing operator ""Rx"" with param ""(?:application(?:/soap\+|/)|text/)xml"" against REQUEST_HEADERS:Content-Type."
14,2020-06-27T04:47:41.164Z,dev,error,,,,,,"[159323326157.663567] [/cf-echo] [9]  T (0) t:lowercase: ""application/json;charset=utf-8"""
15,2020-06-27T04:47:41.164Z,dev,error,,,,,,"[159323326157.663567] [/cf-echo] [9] Target value: ""application/json;charset=utf-8"" (Variable: REQUEST_HEADERS:content-type)"
16,2020-06-27T04:47:41.164Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [4] Rule returned 0.
17,2020-06-27T04:47:41.164Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [9] Matched vars cleaned.
18,2020-06-27T04:47:41.164Z,dev,error,,,,,,"[159323326157.663567] [/cf-echo] [4] (Rule: 200001) Executing operator ""Rx"" with param ""application/json"" against REQUEST_HEADERS:Content-Type."
19,2020-06-27T04:47:41.164Z,dev,error,,,,,,"[159323326157.663567] [/cf-echo] [9]  T (0) t:lowercase: ""application/json;charset=utf-8"""
20,2020-06-27T04:47:41.164Z,dev,error,,,,,,"[159323326157.663567] [/cf-echo] [9] Target value: ""application/json;charset=utf-8"" (Variable: REQUEST_HEADERS:content-type)"
21,2020-06-27T04:47:41.164Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [9] Matched vars updated.
22,2020-06-27T04:47:41.164Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [4] Rule returned 1.
23,2020-06-27T04:47:41.164Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [9] Running action: nolog
24,2020-06-27T04:47:41.164Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [9] Running action: ctl
25,2020-06-27T04:47:41.164Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [4] Not running any disruptive action (or block): pass. SecRuleEngine is not On.
26,2020-06-27T04:47:41.164Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [9] Appending request body: 0 bytes. Limit set to: 13107200.000000
27,2020-06-27T04:47:41.164Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [4] Starting phase REQUEST_BODY. (SecRules 2)
28,2020-06-27T04:47:41.164Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [9] This phase consists of 4 rule(s).
29,2020-06-27T04:47:41.164Z,dev,error,,,,,,"[159323326157.663567] [/cf-echo] [4] (Rule: 200002) Executing operator ""Eq"" with param ""0"" against REQBODY_ERROR."
30,2020-06-27T04:47:41.165Z,dev,error,,,,,,"[159323326157.663567] [/cf-echo] [9] Target value: ""0"" (Variable: REQBODY_ERROR)"
31,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [4] Rule returned 0.
32,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [9] Matched vars cleaned.
33,2020-06-27T04:47:41.165Z,dev,error,,,,,,"[159323326157.663567] [/cf-echo] [4] (Rule: 200003) Executing operator ""Eq"" with param ""0"" against MULTIPART_STRICT_ERROR."
34,2020-06-27T04:47:41.165Z,dev,error,,,,,,"[159323326157.663567] [/cf-echo] [9] Target value: """" (Variable: MULTIPART_STRICT_ERROR)"
35,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [4] Rule returned 0.
36,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [9] Matched vars cleaned.
37,2020-06-27T04:47:41.165Z,dev,error,,,,,,"[159323326157.663567] [/cf-echo] [4] (Rule: 200004) Executing operator ""Eq"" with param ""1"" against MULTIPART_UNMATCHED_BOUNDARY."
38,2020-06-27T04:47:41.165Z,dev,error,,,,,,"[159323326157.663567] [/cf-echo] [9] Target value: """" (Variable: MULTIPART_UNMATCHED_BOUNDARY)"
39,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [4] Rule returned 0.
40,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [9] Matched vars cleaned.
41,2020-06-27T04:47:41.165Z,dev,error,,,,,,"[159323326157.663567] [/cf-echo] [4] (Rule: 200005) Executing operator ""StrEq"" with param ""0"" against TX:regex(^MSC_)."
42,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [4] Rule returned 0.
43,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [9] Matched vars cleaned.
44,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326198.737226] [] [4] Initializing transaction
45,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326198.737226] [] [4] Transaction context created.
46,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326198.737226] [] [4] Starting phase CONNECTION. (SecRules 0)
47,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326198.737226] [] [9] This phase consists of 0 rule(s).
48,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326198.737226] [] [4] Starting phase URI. (SecRules 0 + 1/2)
49,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326198.737226] [/cf-echo] [4] Starting phase REQUEST_HEADERS.  (SecRules 1)
50,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326198.737226] [/cf-echo] [9] This phase consists of 2 rule(s).
51,2020-06-27T04:47:41.165Z,dev,error,,,,,,"[159323326198.737226] [/cf-echo] [4] (Rule: 200000) Executing operator ""Rx"" with param ""(?:application(?:/soap\+|/)|text/)xml"" against REQUEST_HEADERS:Content-Type."
52,2020-06-27T04:47:41.165Z,dev,error,,,,,,"[159323326198.737226] [/cf-echo] [9]  T (0) t:lowercase: ""application/json;charset=utf-8"""
53,2020-06-27T04:47:41.165Z,dev,error,,,,,,"[159323326198.737226] [/cf-echo] [9] Target value: ""application/json;charset=utf-8"" (Variable: REQUEST_HEADERS:content-type)"
54,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326198.737226] [/cf-echo] [4] Rule returned 0.
55,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326198.737226] [/cf-echo] [9] Matched vars cleaned.
56,2020-06-27T04:47:41.165Z,dev,error,,,,,,"[159323326198.737226] [/cf-echo] [4] (Rule: 200001) Executing operator ""Rx"" with param ""application/json"" against REQUEST_HEADERS:Content-Type."
57,2020-06-27T04:47:41.165Z,dev,error,,,,,,"[159323326198.737226] [/cf-echo] [9]  T (0) t:lowercase: ""application/json;charset=utf-8"""
58,2020-06-27T04:47:41.165Z,dev,error,,,,,,"[159323326198.737226] [/cf-echo] [9] Target value: ""application/json;charset=utf-8"" (Variable: REQUEST_HEADERS:content-type)"
59,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326198.737226] [/cf-echo] [9] Matched vars updated.
60,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326198.737226] [/cf-echo] [4] Rule returned 1.
61,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326198.737226] [/cf-echo] [9] Running action: nolog
62,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326198.737226] [/cf-echo] [9] Running action: ctl
63,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326198.737226] [/cf-echo] [4] Not running any disruptive action (or block): pass. SecRuleEngine is not On.
64,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326198.737226] [/cf-echo] [4] Starting phase REQUEST_BODY. (SecRules 2)
65,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326198.737226] [/cf-echo] [9] This phase consists of 4 rule(s).
66,2020-06-27T04:47:41.165Z,dev,error,,,,,,"[159323326198.737226] [/cf-echo] [4] (Rule: 200002) Executing operator ""Eq"" with param ""0"" against REQBODY_ERROR."
67,2020-06-27T04:47:41.165Z,dev,error,,,,,,"[159323326198.737226] [/cf-echo] [9] Target value: ""0"" (Variable: REQBODY_ERROR)"
68,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326198.737226] [/cf-echo] [4] Rule returned 0.
69,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326198.737226] [/cf-echo] [9] Matched vars cleaned.
70,2020-06-27T04:47:41.165Z,dev,error,,,,,,"[159323326198.737226] [/cf-echo] [4] (Rule: 200003) Executing operator ""Eq"" with param ""0"" against MULTIPART_STRICT_ERROR."
71,2020-06-27T04:47:41.165Z,dev,error,,,,,,"[159323326198.737226] [/cf-echo] [9] Target value: """" (Variable: MULTIPART_STRICT_ERROR)"
72,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326198.737226] [/cf-echo] [4] Rule returned 0.
73,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326198.737226] [/cf-echo] [9] Matched vars cleaned.
74,2020-06-27T04:47:41.165Z,dev,error,,,,,,"[159323326198.737226] [/cf-echo] [4] (Rule: 200004) Executing operator ""Eq"" with param ""1"" against MULTIPART_UNMATCHED_BOUNDARY."
75,2020-06-27T04:47:41.165Z,dev,error,,,,,,"[159323326198.737226] [/cf-echo] [9] Target value: """" (Variable: MULTIPART_UNMATCHED_BOUNDARY)"
76,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326198.737226] [/cf-echo] [4] Rule returned 0.
77,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326198.737226] [/cf-echo] [9] Matched vars cleaned.
78,2020-06-27T04:47:41.165Z,dev,error,,,,,,"[159323326198.737226] [/cf-echo] [4] (Rule: 200005) Executing operator ""StrEq"" with param ""0"" against TX:regex(^MSC_)."
79,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326198.737226] [/cf-echo] [4] Rule returned 0.
80,2020-06-27T04:47:41.165Z,dev,error,,,,,,[159323326198.737226] [/cf-echo] [9] Matched vars cleaned.
81,2020-06-27T04:47:41.175Z,dev,error,,,,,,[159323326177.486063] [] [4] Initializing transaction
82,2020-06-27T04:47:41.175Z,dev,error,,,,,,[159323326177.486063] [] [4] Transaction context created.
83,2020-06-27T04:47:41.175Z,dev,error,,,,,,[159323326177.486063] [] [4] Starting phase CONNECTION. (SecRules 0)
84,2020-06-27T04:47:41.175Z,dev,error,,,,,,[159323326177.486063] [] [9] This phase consists of 0 rule(s).
85,2020-06-27T04:47:41.176Z,dev,error,,,,,,[159323326177.486063] [] [4] Starting phase URI. (SecRules 0 + 1/2)
86,2020-06-27T04:47:41.176Z,dev,error,,,,,,[159323326177.486063] [/oauth2/auth] [4] Starting phase REQUEST_HEADERS.  (SecRules 1)
87,2020-06-27T04:47:41.176Z,dev,error,,,,,,[159323326177.486063] [/oauth2/auth] [9] This phase consists of 2 rule(s).
88,2020-06-27T04:47:41.176Z,dev,error,,,,,,"[159323326177.486063] [/oauth2/auth] [4] (Rule: 200000) Executing operator ""Rx"" with param ""(?:application(?:/soap\+|/)|text/)xml"" against REQUEST_HEADERS:Content-Type."
89,2020-06-27T04:47:41.176Z,dev,error,,,,,,"[159323326177.486063] [/oauth2/auth] [9]  T (0) t:lowercase: ""application/json;charset=utf-8"""
90,2020-06-27T04:47:41.177Z,dev,error,,,,,,"[159323326177.486063] [/oauth2/auth] [9] Target value: ""application/json;charset=utf-8"" (Variable: REQUEST_HEADERS:content-type)"
91,2020-06-27T04:47:41.177Z,dev,error,,,,,,[159323326177.486063] [/oauth2/auth] [4] Rule returned 0.
92,2020-06-27T04:47:41.177Z,dev,error,,,,,,[159323326177.486063] [/oauth2/auth] [9] Matched vars cleaned.
93,2020-06-27T04:47:41.177Z,dev,error,,,,,,"[159323326177.486063] [/oauth2/auth] [4] (Rule: 200001) Executing operator ""Rx"" with param ""application/json"" against REQUEST_HEADERS:Content-Type."
94,2020-06-27T04:47:41.178Z,dev,error,,,,,,"[159323326177.486063] [/oauth2/auth] [9]  T (0) t:lowercase: ""application/json;charset=utf-8"""
95,2020-06-27T04:47:41.178Z,dev,error,,,,,,"[159323326177.486063] [/oauth2/auth] [9] Target value: ""application/json;charset=utf-8"" (Variable: REQUEST_HEADERS:content-type)"
96,2020-06-27T04:47:41.178Z,dev,error,,,,,,[159323326177.486063] [/oauth2/auth] [9] Matched vars updated.
97,2020-06-27T04:47:41.179Z,dev,error,,,,,,[159323326177.486063] [/oauth2/auth] [4] Rule returned 1.
98,2020-06-27T04:47:41.179Z,dev,error,,,,,,[159323326177.486063] [/oauth2/auth] [9] Running action: nolog
99,2020-06-27T04:47:41.179Z,dev,error,,,,,,[159323326177.486063] [/oauth2/auth] [9] Running action: ctl
100,2020-06-27T04:47:41.179Z,dev,error,,,,,,[159323326177.486063] [/oauth2/auth] [4] Not running any disruptive action (or block): pass. SecRuleEngine is not On.
101,2020-06-27T04:47:41.179Z,dev,error,,,,,,[159323326177.486063] [/oauth2/auth] [4] Starting phase REQUEST_BODY. (SecRules 2)
102,2020-06-27T04:47:41.180Z,dev,error,,,,,,[159323326177.486063] [/oauth2/auth] [9] This phase consists of 4 rule(s).
103,2020-06-27T04:47:41.180Z,dev,error,,,,,,"[159323326177.486063] [/oauth2/auth] [4] (Rule: 200002) Executing operator ""Eq"" with param ""0"" against REQBODY_ERROR."
104,2020-06-27T04:47:41.180Z,dev,error,,,,,,"[159323326177.486063] [/oauth2/auth] [9] Target value: ""0"" (Variable: REQBODY_ERROR)"
105,2020-06-27T04:47:41.180Z,dev,error,,,,,,[159323326177.486063] [/oauth2/auth] [4] Rule returned 0.
106,2020-06-27T04:47:41.181Z,dev,error,,,,,,[159323326177.486063] [/oauth2/auth] [9] Matched vars cleaned.
107,2020-06-27T04:47:41.181Z,dev,error,,,,,,"[159323326177.486063] [/oauth2/auth] [4] (Rule: 200003) Executing operator ""Eq"" with param ""0"" against MULTIPART_STRICT_ERROR."
108,2020-06-27T04:47:41.181Z,dev,error,,,,,,"[159323326177.486063] [/oauth2/auth] [9] Target value: """" (Variable: MULTIPART_STRICT_ERROR)"
109,2020-06-27T04:47:41.182Z,dev,error,,,,,,[159323326177.486063] [/oauth2/auth] [4] Rule returned 0.
110,2020-06-27T04:47:41.182Z,dev,error,,,,,,[159323326177.486063] [/oauth2/auth] [9] Matched vars cleaned.
111,2020-06-27T04:47:41.182Z,dev,error,,,,,,"[159323326177.486063] [/oauth2/auth] [4] (Rule: 200004) Executing operator ""Eq"" with param ""1"" against MULTIPART_UNMATCHED_BOUNDARY."
112,2020-06-27T04:47:41.182Z,dev,error,,,,,,"[159323326177.486063] [/oauth2/auth] [9] Target value: """" (Variable: MULTIPART_UNMATCHED_BOUNDARY)"
113,2020-06-27T04:47:41.182Z,dev,error,,,,,,[159323326177.486063] [/oauth2/auth] [4] Rule returned 0.
114,2020-06-27T04:47:41.182Z,dev,error,,,,,,[159323326177.486063] [/oauth2/auth] [9] Matched vars cleaned.
115,2020-06-27T04:47:41.182Z,dev,error,,,,,,"[159323326177.486063] [/oauth2/auth] [4] (Rule: 200005) Executing operator ""StrEq"" with param ""0"" against TX:regex(^MSC_)."
116,2020-06-27T04:47:41.182Z,dev,error,,,,,,[159323326177.486063] [/oauth2/auth] [4] Rule returned 0.
117,2020-06-27T04:47:41.182Z,dev,error,,,,,,[159323326177.486063] [/oauth2/auth] [9] Matched vars cleaned.
118,2020-06-27T04:47:41.186Z,dev,error,,,,,,[159323326177.486063] [/oauth2/auth] [4] Starting phase RESPONSE_HEADERS. (SecRules 3)
119,2020-06-27T04:47:41.186Z,dev,error,,,,,,[159323326177.486063] [/oauth2/auth] [9] This phase consists of 0 rule(s).
120,2020-06-27T04:47:41.186Z,dev,error,,,,,,[159323326177.486063] [/oauth2/auth] [4] Not appending response body. Response Content-Type is . It is not marked to be inspected.
121,2020-06-27T04:47:41.186Z,dev,error,,,,,,[159323326177.486063] [/oauth2/auth] [4] Not appending response body. Response Content-Type is . It is not marked to be inspected.
122,2020-06-27T04:47:41.186Z,dev,error,,,,,,[159323326177.486063] [/oauth2/auth] [4] Starting phase RESPONSE_BODY. (SecRules 4)
123,2020-06-27T04:47:41.186Z,dev,error,,,,,,[159323326177.486063] [/oauth2/auth] [5] Response Content-Type is . It is not marked to be inspected.
124,2020-06-27T04:47:41.186Z,dev,error,,,,,,[159323326177.486063] [/oauth2/auth] [8] Content-Type(s) marked to be inspected: text/html text/plain text/xml
125,2020-06-27T04:47:41.186Z,dev,error,,,,,,[159323326177.486063] [/oauth2/auth] [4] Starting phase LOGGING. (SecRules 5)
126,2020-06-27T04:47:41.186Z,dev,error,,,,,,[159323326177.486063] [/oauth2/auth] [9] This phase consists of 0 rule(s).
127,2020-06-27T04:47:41.186Z,dev,error,,,,,,[159323326177.486063] [/oauth2/auth] [8] Checking if this request is suitable to be saved as an audit log.
128,2020-06-27T04:47:41.186Z,dev,error,,,,,,[159323326177.486063] [/oauth2/auth] [8] Checking if this request is relevant to be part of the audit logs.
129,2020-06-27T04:47:41.186Z,dev,error,,,,,,"[159323326177.486063] [/oauth2/auth] [9] Return code `202' is not interesting to audit logs, relevant code(s): `^(?:5|4(?!04))'."
130,2020-06-27T04:47:41.186Z,dev,error,,,,,,[159323326198.737226] [/cf-echo] [4] Starting phase RESPONSE_HEADERS. (SecRules 3)
131,2020-06-27T04:47:41.186Z,dev,error,,,,,,[159323326198.737226] [/cf-echo] [9] This phase consists of 0 rule(s).
132,2020-06-27T04:47:41.186Z,dev,error,,,,,,[159323326198.737226] [/cf-echo] [4] Starting phase LOGGING. (SecRules 5)
133,2020-06-27T04:47:41.186Z,dev,error,,,,,,[159323326198.737226] [/cf-echo] [9] This phase consists of 0 rule(s).
134,2020-06-27T04:47:41.186Z,dev,error,,,,,,[159323326198.737226] [/cf-echo] [8] Checking if this request is suitable to be saved as an audit log.
135,2020-06-27T04:47:41.186Z,dev,error,,,,,,[159323326198.737226] [/cf-echo] [8] Checking if this request is relevant to be part of the audit logs.
136,2020-06-27T04:47:41.186Z,dev,error,,,,,,"[159323326198.737226] [/cf-echo] [9] Return code `202' is not interesting to audit logs, relevant code(s): `^(?:5|4(?!04))'."
137,2020-06-27T04:47:41.198Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [4] Starting phase RESPONSE_HEADERS. (SecRules 3)
138,2020-06-27T04:47:41.198Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [9] This phase consists of 0 rule(s).
139,2020-06-27T04:47:41.198Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [4] Not appending response body. Response Content-Type is application/json. It is not marked to be inspected.
140,2020-06-27T04:47:41.198Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [4] Not appending response body. Response Content-Type is application/json. It is not marked to be inspected.
141,2020-06-27T04:47:41.198Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [4] Starting phase RESPONSE_BODY. (SecRules 4)
142,2020-06-27T04:47:41.198Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [5] Response Content-Type is application/json. It is not marked to be inspected.
143,2020-06-27T04:47:41.198Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [8] Content-Type(s) marked to be inspected: text/html text/plain text/xml
144,2020-06-27T04:47:41.198Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [4] Starting phase LOGGING. (SecRules 5)
145,2020-06-27T04:47:41.198Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [9] This phase consists of 0 rule(s).
146,2020-06-27T04:47:41.198Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [8] Checking if this request is suitable to be saved as an audit log.
147,2020-06-27T04:47:41.198Z,dev,error,,,,,,[159323326157.663567] [/cf-echo] [8] Checking if this request is relevant to be part of the audit logs.
148,2020-06-27T04:47:41.198Z,dev,error,,,,,,"[159323326157.663567] [/cf-echo] [9] Return code `200' is not interesting to audit logs, relevant code(s): `^(?:5|4(?!04))'."
149,,,,,,,,,
150,2020-06-27T04:48:10.627Z,dev,error,,,,,,[159323329016.713340] [] [4] Initializing transaction
151,2020-06-27T04:48:10.627Z,dev,error,,,,,,[159323329016.713340] [] [4] Transaction context created.
152,2020-06-27T04:48:10.627Z,dev,error,,,,,,[159323329016.713340] [] [4] Starting phase CONNECTION. (SecRules 0)
153,2020-06-27T04:48:10.627Z,dev,error,,,,,,[159323329016.713340] [] [9] This phase consists of 0 rule(s).
154,2020-06-27T04:48:10.627Z,dev,error,,,,,,[159323329016.713340] [] [4] Starting phase URI. (SecRules 0 + 1/2)
155,2020-06-27T04:48:10.627Z,dev,error,,,,,,[159323329016.713340] [/cf-echo] [4] Starting phase REQUEST_HEADERS.  (SecRules 1)
156,2020-06-27T04:48:10.627Z,dev,error,,,,,,[159323329016.713340] [/cf-echo] [9] This phase consists of 2 rule(s).
157,2020-06-27T04:48:10.627Z,dev,error,,,,,,"[159323329016.713340] [/cf-echo] [4] (Rule: 200000) Executing operator ""Rx"" with param ""(?:application(?:/soap\+|/)|text/)xml"" against REQUEST_HEADERS:Content-Type."
158,2020-06-27T04:48:10.627Z,dev,error,,,,,,"[159323329016.713340] [/cf-echo] [9]  T (0) t:lowercase: ""application/json;charset=utf-8"""
159,2020-06-27T04:48:10.627Z,dev,error,,,,,,"[159323329016.713340] [/cf-echo] [9] Target value: ""application/json;charset=utf-8"" (Variable: REQUEST_HEADERS:content-type)"
160,2020-06-27T04:48:10.627Z,dev,error,,,,,,[159323329016.713340] [/cf-echo] [4] Rule returned 0.
161,2020-06-27T04:48:10.627Z,dev,error,,,,,,[159323329016.713340] [/cf-echo] [9] Matched vars cleaned.
162,2020-06-27T04:48:10.627Z,dev,error,,,,,,"[159323329016.713340] [/cf-echo] [4] (Rule: 200001) Executing operator ""Rx"" with param ""application/json"" against REQUEST_HEADERS:Content-Type."
163,2020-06-27T04:48:10.627Z,dev,error,,,,,,"[159323329016.713340] [/cf-echo] [9]  T (0) t:lowercase: ""application/json;charset=utf-8"""
164,2020-06-27T04:48:10.627Z,dev,error,,,,,,"[159323329016.713340] [/cf-echo] [9] Target value: ""application/json;charset=utf-8"" (Variable: REQUEST_HEADERS:content-type)"
165,2020-06-27T04:48:10.627Z,dev,error,,,,,,[159323329016.713340] [/cf-echo] [9] Matched vars updated.
166,2020-06-27T04:48:10.627Z,dev,error,,,,,,[159323329016.713340] [/cf-echo] [4] Rule returned 1.
167,2020-06-27T04:48:10.627Z,dev,error,,,,,,[159323329016.713340] [/cf-echo] [9] Running action: nolog
168,2020-06-27T04:48:10.627Z,dev,error,,,,,,[159323329016.713340] [/cf-echo] [9] Running action: ctl
169,2020-06-27T04:48:10.627Z,dev,error,,,,,,[159323329016.713340] [/cf-echo] [4] Not running any disruptive action (or block): pass. SecRuleEngine is not On.
170,2020-06-27T04:48:10.627Z,dev,error,,,,,,[159323329016.713340] [/cf-echo] [9] Appending request body: 0 bytes. Limit set to: 13107200.000000
171,2020-06-27T04:48:10.627Z,dev,error,,,,,,[159323329016.713340] [/cf-echo] [4] Starting phase REQUEST_BODY. (SecRules 2)
172,2020-06-27T04:48:10.627Z,dev,error,,,,,,[159323329016.713340] [/cf-echo] [9] This phase consists of 4 rule(s).
173,2020-06-27T04:48:10.627Z,dev,error,,,,,,"[159323329016.713340] [/cf-echo] [4] (Rule: 200002) Executing operator ""Eq"" with param ""0"" against REQBODY_ERROR."
174,2020-06-27T04:48:10.627Z,dev,error,,,,,,"[159323329016.713340] [/cf-echo] [9] Target value: ""0"" (Variable: REQBODY_ERROR)"
175,2020-06-27T04:48:10.627Z,dev,error,,,,,,[159323329016.713340] [/cf-echo] [4] Rule returned 0.
176,2020-06-27T04:48:10.627Z,dev,error,,,,,,[159323329016.713340] [/cf-echo] [9] Matched vars cleaned.
177,2020-06-27T04:48:10.627Z,dev,error,,,,,,"[159323329016.713340] [/cf-echo] [4] (Rule: 200003) Executing operator ""Eq"" with param ""0"" against MULTIPART_STRICT_ERROR."
178,2020-06-27T04:48:10.627Z,dev,error,,,,,,"[159323329016.713340] [/cf-echo] [9] Target value: """" (Variable: MULTIPART_STRICT_ERROR)"
179,2020-06-27T04:48:10.627Z,dev,error,,,,,,[159323329016.713340] [/cf-echo] [4] Rule returned 0.
180,2020-06-27T04:48:10.628Z,dev,error,,,,,,[159323329016.713340] [/cf-echo] [9] Matched vars cleaned.
181,2020-06-27T04:48:10.628Z,dev,error,,,,,,"[159323329016.713340] [/cf-echo] [4] (Rule: 200004) Executing operator ""Eq"" with param ""1"" against MULTIPART_UNMATCHED_BOUNDARY."
182,2020-06-27T04:48:10.628Z,dev,error,,,,,,"[159323329016.713340] [/cf-echo] [9] Target value: """" (Variable: MULTIPART_UNMATCHED_BOUNDARY)"
183,2020-06-27T04:48:10.628Z,dev,error,,,,,,[159323329016.713340] [/cf-echo] [4] Rule returned 0.
184,2020-06-27T04:48:10.628Z,dev,error,,,,,,[159323329016.713340] [/cf-echo] [9] Matched vars cleaned.
185,2020-06-27T04:48:10.628Z,dev,error,,,,,,"[159323329016.713340] [/cf-echo] [4] (Rule: 200005) Executing operator ""StrEq"" with param ""0"" against TX:regex(^MSC_)."
186,2020-06-27T04:48:10.628Z,dev,error,,,,,,[159323329016.713340] [/cf-echo] [4] Rule returned 0.
187,2020-06-27T04:48:10.628Z,dev,error,,,,,,[159323329016.713340] [/cf-echo] [9] Matched vars cleaned.
188,2020-06-27T04:48:11.000Z,dev,info,,,,,,"2020/06/27 04:48:11 [info] 599#599: *161756 client closed connection while SSL handshaking, client: 10.240.0.35, server: 0.0.0.0:443"
189,2020-06-27T04:48:11.000Z,dev,info,,,,,,"2020/06/27 04:48:11 [info] 599#599: *161755 client closed connection while waiting for request, client: 10.240.0.35, server: 0.0.0.0:80"
190,2020-06-27T04:48:12.000Z,dev,info,,,,,,"2020/06/27 04:48:12 [info] 599#599: *161758 client closed connection while waiting for request, client: 10.240.0.4, server: 0.0.0.0:80"
191,2020-06-27T04:48:12.000Z,dev,info,,,,,,"2020/06/27 04:48:12 [info] 599#599: *161757 client closed connection while SSL handshaking, client: 10.240.0.4, server: 0.0.0.0:443"
192,2020-06-27T04:48:12.000Z,dev,info,,,,,,"2020/06/27 04:48:12 [info] 599#599: *161789 client prematurely closed connection while processing HTTP/2 connection, client: 10.240.0.4, server: 0.0.0.0:443"
193,2020-06-27T04:48:12.000Z,dev,ok,GET,/oauth2/auth,202,0,,"10.240.0.35 - - [27/Jun/2020:04:48:12 +0000] ""GET /oauth2/auth HTTP/1.1"" 202 0 ""-"" ""curl/7.64.1"" 2469 0.003 [cfk8s-cf-oauth-proxy-docker-80] [] 10.240.0.75:4180 0 0.004 202 c410861f61f25fb6b2e0fe9b3fd593f6"
194,2020-06-27T04:48:12.000Z,dev,info,POST,/cf-echo,0,,,"10.240.0.4 - - [27/Jun/2020:04:48:12 +0000] ""POST /cf-echo HTTP/2.0"" 000 0 ""-"" ""curl/7.64.1"" 1728 2.008 [cfk8s-cf-http-https-echo-80] [] - - - - c410861f61f25fb6b2e0fe9b3fd593f6"
195,2020-06-27T04:48:12.581Z,dev,error,,,,,,[159323329272.103746] [] [4] Initializing transaction
196,2020-06-27T04:48:12.582Z,dev,error,,,,,,[159323329272.103746] [] [4] Transaction context created.
197,2020-06-27T04:48:12.582Z,dev,error,,,,,,[159323329272.103746] [] [4] Starting phase CONNECTION. (SecRules 0)
198,2020-06-27T04:48:12.582Z,dev,error,,,,,,[159323329272.103746] [] [9] This phase consists of 0 rule(s).
199,2020-06-27T04:48:12.582Z,dev,error,,,,,,[159323329272.103746] [] [4] Starting phase URI. (SecRules 0 + 1/2)
200,2020-06-27T04:48:12.582Z,dev,error,,,,,,[159323329272.103746] [/cf-echo] [4] Starting phase REQUEST_HEADERS.  (SecRules 1)
201,2020-06-27T04:48:12.582Z,dev,error,,,,,,[159323329272.103746] [/cf-echo] [9] This phase consists of 2 rule(s).
202,2020-06-27T04:48:12.582Z,dev,error,,,,,,"[159323329272.103746] [/cf-echo] [4] (Rule: 200000) Executing operator ""Rx"" with param ""(?:application(?:/soap\+|/)|text/)xml"" against REQUEST_HEADERS:Content-Type."
203,2020-06-27T04:48:12.582Z,dev,error,,,,,,"[159323329272.103746] [/cf-echo] [9]  T (0) t:lowercase: ""application/json;charset=utf-8"""
204,2020-06-27T04:48:12.582Z,dev,error,,,,,,"[159323329272.103746] [/cf-echo] [9] Target value: ""application/json;charset=utf-8"" (Variable: REQUEST_HEADERS:content-type)"
205,2020-06-27T04:48:12.582Z,dev,error,,,,,,[159323329272.103746] [/cf-echo] [4] Rule returned 0.
206,2020-06-27T04:48:12.582Z,dev,error,,,,,,[159323329272.103746] [/cf-echo] [9] Matched vars cleaned.
207,2020-06-27T04:48:12.582Z,dev,error,,,,,,"[159323329272.103746] [/cf-echo] [4] (Rule: 200001) Executing operator ""Rx"" with param ""application/json"" against REQUEST_HEADERS:Content-Type."
208,2020-06-27T04:48:12.582Z,dev,error,,,,,,"[159323329272.103746] [/cf-echo] [9]  T (0) t:lowercase: ""application/json;charset=utf-8"""
209,2020-06-27T04:48:12.582Z,dev,error,,,,,,"[159323329272.103746] [/cf-echo] [9] Target value: ""application/json;charset=utf-8"" (Variable: REQUEST_HEADERS:content-type)"
210,2020-06-27T04:48:12.582Z,dev,error,,,,,,[159323329272.103746] [/cf-echo] [9] Matched vars updated.
211,2020-06-27T04:48:12.582Z,dev,error,,,,,,[159323329272.103746] [/cf-echo] [4] Rule returned 1.
212,2020-06-27T04:48:12.582Z,dev,error,,,,,,[159323329272.103746] [/cf-echo] [9] Running action: nolog
213,2020-06-27T04:48:12.583Z,dev,error,,,,,,[159323329272.103746] [/cf-echo] [9] Running action: ctl
214,2020-06-27T04:48:12.583Z,dev,error,,,,,,[159323329272.103746] [/cf-echo] [4] Not running any disruptive action (or block): pass. SecRuleEngine is not On.
215,2020-06-27T04:48:12.583Z,dev,error,,,,,,[159323329272.103746] [/cf-echo] [4] Starting phase REQUEST_BODY. (SecRules 2)
216,2020-06-27T04:48:12.583Z,dev,error,,,,,,[159323329272.103746] [/cf-echo] [9] This phase consists of 4 rule(s).
217,2020-06-27T04:48:12.583Z,dev,error,,,,,,"[159323329272.103746] [/cf-echo] [4] (Rule: 200002) Executing operator ""Eq"" with param ""0"" against REQBODY_ERROR."
218,2020-06-27T04:48:12.583Z,dev,error,,,,,,"[159323329272.103746] [/cf-echo] [9] Target value: ""0"" (Variable: REQBODY_ERROR)"
219,2020-06-27T04:48:12.583Z,dev,error,,,,,,[159323329272.103746] [/cf-echo] [4] Rule returned 0.
220,2020-06-27T04:48:12.583Z,dev,error,,,,,,[159323329272.103746] [/cf-echo] [9] Matched vars cleaned.
221,2020-06-27T04:48:12.583Z,dev,error,,,,,,"[159323329272.103746] [/cf-echo] [4] (Rule: 200003) Executing operator ""Eq"" with param ""0"" against MULTIPART_STRICT_ERROR."
222,2020-06-27T04:48:12.583Z,dev,error,,,,,,"[159323329272.103746] [/cf-echo] [9] Target value: """" (Variable: MULTIPART_STRICT_ERROR)"
223,2020-06-27T04:48:12.583Z,dev,error,,,,,,[159323329272.103746] [/cf-echo] [4] Rule returned 0.
224,2020-06-27T04:48:12.583Z,dev,error,,,,,,[159323329272.103746] [/cf-echo] [9] Matched vars cleaned.
225,2020-06-27T04:48:12.583Z,dev,error,,,,,,"[159323329272.103746] [/cf-echo] [4] (Rule: 200004) Executing operator ""Eq"" with param ""1"" against MULTIPART_UNMATCHED_BOUNDARY."
226,2020-06-27T04:48:12.583Z,dev,error,,,,,,"[159323329272.103746] [/cf-echo] [9] Target value: """" (Variable: MULTIPART_UNMATCHED_BOUNDARY)"
227,2020-06-27T04:48:12.583Z,dev,error,,,,,,[159323329272.103746] [/cf-echo] [4] Rule returned 0.
228,2020-06-27T04:48:12.583Z,dev,error,,,,,,[159323329272.103746] [/cf-echo] [9] Matched vars cleaned.
229,2020-06-27T04:48:12.583Z,dev,error,,,,,,"[159323329272.103746] [/cf-echo] [4] (Rule: 200005) Executing operator ""StrEq"" with param ""0"" against TX:regex(^MSC_)."
230,2020-06-27T04:48:12.583Z,dev,error,,,,,,[159323329272.103746] [/cf-echo] [4] Rule returned 0.
231,2020-06-27T04:48:12.583Z,dev,error,,,,,,[159323329272.103746] [/cf-echo] [9] Matched vars cleaned.
232,2020-06-27T04:48:12.629Z,dev,error,,,,,,[15932332928.240075] [] [4] Initializing transaction
233,2020-06-27T04:48:12.629Z,dev,error,,,,,,[15932332928.240075] [] [4] Transaction context created.
234,2020-06-27T04:48:12.629Z,dev,error,,,,,,[15932332928.240075] [] [4] Starting phase CONNECTION. (SecRules 0)
235,2020-06-27T04:48:12.630Z,dev,error,,,,,,[15932332928.240075] [] [9] This phase consists of 0 rule(s).
236,2020-06-27T04:48:12.630Z,dev,error,,,,,,[15932332928.240075] [] [4] Starting phase URI. (SecRules 0 + 1/2)
237,2020-06-27T04:48:12.630Z,dev,error,,,,,,[15932332928.240075] [/oauth2/auth] [4] Starting phase REQUEST_HEADERS.  (SecRules 1)
238,2020-06-27T04:48:12.630Z,dev,error,,,,,,[15932332928.240075] [/oauth2/auth] [9] This phase consists of 2 rule(s).
239,2020-06-27T04:48:12.630Z,dev,error,,,,,,"[15932332928.240075] [/oauth2/auth] [4] (Rule: 200000) Executing operator ""Rx"" with param ""(?:application(?:/soap\+|/)|text/)xml"" against REQUEST_HEADERS:Content-Type."
240,2020-06-27T04:48:12.630Z,dev,error,,,,,,"[15932332928.240075] [/oauth2/auth] [9]  T (0) t:lowercase: ""application/json;charset=utf-8"""
241,2020-06-27T04:48:12.631Z,dev,error,,,,,,"[15932332928.240075] [/oauth2/auth] [9] Target value: ""application/json;charset=utf-8"" (Variable: REQUEST_HEADERS:content-type)"
242,2020-06-27T04:48:12.632Z,dev,error,,,,,,[15932332928.240075] [/oauth2/auth] [4] Rule returned 0.
243,2020-06-27T04:48:12.632Z,dev,error,,,,,,[15932332928.240075] [/oauth2/auth] [9] Matched vars cleaned.
244,2020-06-27T04:48:12.632Z,dev,error,,,,,,"[15932332928.240075] [/oauth2/auth] [4] (Rule: 200001) Executing operator ""Rx"" with param ""application/json"" against REQUEST_HEADERS:Content-Type."
245,2020-06-27T04:48:12.632Z,dev,error,,,,,,"[15932332928.240075] [/oauth2/auth] [9]  T (0) t:lowercase: ""application/json;charset=utf-8"""
246,2020-06-27T04:48:12.632Z,dev,error,,,,,,"[15932332928.240075] [/oauth2/auth] [9] Target value: ""application/json;charset=utf-8"" (Variable: REQUEST_HEADERS:content-type)"
247,2020-06-27T04:48:12.632Z,dev,error,,,,,,[15932332928.240075] [/oauth2/auth] [9] Matched vars updated.
248,2020-06-27T04:48:12.632Z,dev,error,,,,,,[15932332928.240075] [/oauth2/auth] [4] Rule returned 1.
249,2020-06-27T04:48:12.632Z,dev,error,,,,,,[15932332928.240075] [/oauth2/auth] [9] Running action: nolog
250,2020-06-27T04:48:12.632Z,dev,error,,,,,,[15932332928.240075] [/oauth2/auth] [9] Running action: ctl
251,2020-06-27T04:48:12.632Z,dev,error,,,,,,[15932332928.240075] [/oauth2/auth] [4] Not running any disruptive action (or block): pass. SecRuleEngine is not On.
252,2020-06-27T04:48:12.632Z,dev,error,,,,,,[15932332928.240075] [/oauth2/auth] [4] Starting phase REQUEST_BODY. (SecRules 2)
253,2020-06-27T04:48:12.632Z,dev,error,,,,,,[15932332928.240075] [/oauth2/auth] [9] This phase consists of 4 rule(s).
254,2020-06-27T04:48:12.632Z,dev,error,,,,,,"[15932332928.240075] [/oauth2/auth] [4] (Rule: 200002) Executing operator ""Eq"" with param ""0"" against REQBODY_ERROR."
255,2020-06-27T04:48:12.632Z,dev,error,,,,,,"[15932332928.240075] [/oauth2/auth] [9] Target value: ""0"" (Variable: REQBODY_ERROR)"
256,2020-06-27T04:48:12.632Z,dev,error,,,,,,[15932332928.240075] [/oauth2/auth] [4] Rule returned 0.
257,2020-06-27T04:48:12.632Z,dev,error,,,,,,[15932332928.240075] [/oauth2/auth] [9] Matched vars cleaned.
258,2020-06-27T04:48:12.632Z,dev,error,,,,,,"[15932332928.240075] [/oauth2/auth] [4] (Rule: 200003) Executing operator ""Eq"" with param ""0"" against MULTIPART_STRICT_ERROR."
259,2020-06-27T04:48:12.632Z,dev,error,,,,,,"[15932332928.240075] [/oauth2/auth] [9] Target value: """" (Variable: MULTIPART_STRICT_ERROR)"
260,2020-06-27T04:48:12.632Z,dev,error,,,,,,[15932332928.240075] [/oauth2/auth] [4] Rule returned 0.
261,2020-06-27T04:48:12.632Z,dev,error,,,,,,[15932332928.240075] [/oauth2/auth] [9] Matched vars cleaned.
262,2020-06-27T04:48:12.632Z,dev,error,,,,,,"[15932332928.240075] [/oauth2/auth] [4] (Rule: 200004) Executing operator ""Eq"" with param ""1"" against MULTIPART_UNMATCHED_BOUNDARY."
263,2020-06-27T04:48:12.632Z,dev,error,,,,,,"[15932332928.240075] [/oauth2/auth] [9] Target value: """" (Variable: MULTIPART_UNMATCHED_BOUNDARY)"
264,2020-06-27T04:48:12.632Z,dev,error,,,,,,[15932332928.240075] [/oauth2/auth] [4] Rule returned 0.
265,2020-06-27T04:48:12.632Z,dev,error,,,,,,[15932332928.240075] [/oauth2/auth] [9] Matched vars cleaned.
266,2020-06-27T04:48:12.632Z,dev,error,,,,,,"[15932332928.240075] [/oauth2/auth] [4] (Rule: 200005) Executing operator ""StrEq"" with param ""0"" against TX:regex(^MSC_)."
267,2020-06-27T04:48:12.632Z,dev,error,,,,,,[15932332928.240075] [/oauth2/auth] [4] Rule returned 0.
268,2020-06-27T04:48:12.632Z,dev,error,,,,,,[15932332928.240075] [/oauth2/auth] [9] Matched vars cleaned.
269,2020-06-27T04:48:12.632Z,dev,error,,,,,,[15932332928.240075] [/oauth2/auth] [4] Starting phase RESPONSE_HEADERS. (SecRules 3)
270,2020-06-27T04:48:12.632Z,dev,error,,,,,,[15932332928.240075] [/oauth2/auth] [9] This phase consists of 0 rule(s).
271,2020-06-27T04:48:12.632Z,dev,error,,,,,,[15932332928.240075] [/oauth2/auth] [4] Not appending response body. Response Content-Type is . It is not marked to be inspected.
272,2020-06-27T04:48:12.632Z,dev,error,,,,,,[15932332928.240075] [/oauth2/auth] [4] Not appending response body. Response Content-Type is . It is not marked to be inspected.
273,2020-06-27T04:48:12.632Z,dev,error,,,,,,[15932332928.240075] [/oauth2/auth] [4] Starting phase RESPONSE_BODY. (SecRules 4)
274,2020-06-27T04:48:12.632Z,dev,error,,,,,,[15932332928.240075] [/oauth2/auth] [5] Response Content-Type is . It is not marked to be inspected.
275,2020-06-27T04:48:12.634Z,dev,error,,,,,,[15932332928.240075] [/oauth2/auth] [8] Content-Type(s) marked to be inspected: text/html text/plain text/xml
276,2020-06-27T04:48:12.634Z,dev,error,,,,,,[15932332928.240075] [/oauth2/auth] [4] Starting phase LOGGING. (SecRules 5)
277,2020-06-27T04:48:12.634Z,dev,error,,,,,,[15932332928.240075] [/oauth2/auth] [9] This phase consists of 0 rule(s).
278,2020-06-27T04:48:12.634Z,dev,error,,,,,,[15932332928.240075] [/oauth2/auth] [8] Checking if this request is suitable to be saved as an audit log.
279,2020-06-27T04:48:12.634Z,dev,error,,,,,,[15932332928.240075] [/oauth2/auth] [8] Checking if this request is relevant to be part of the audit logs.
280,2020-06-27T04:48:12.634Z,dev,error,,,,,,"[15932332928.240075] [/oauth2/auth] [9] Return code `202' is not interesting to audit logs, relevant code(s): `^(?:5|4(?!04))'."
281,2020-06-27T04:48:12.634Z,dev,error,,,,,,[159323329272.103746] [/cf-echo] [4] Starting phase RESPONSE_HEADERS. (SecRules 3)
282,2020-06-27T04:48:12.634Z,dev,error,,,,,,[159323329272.103746] [/cf-echo] [9] This phase consists of 0 rule(s).
283,2020-06-27T04:48:12.636Z,dev,error,,,,,,[159323329016.713340] [/cf-echo] [4] Starting phase LOGGING. (SecRules 5)
284,2020-06-27T04:48:12.636Z,dev,error,,,,,,[159323329016.713340] [/cf-echo] [9] This phase consists of 0 rule(s).
285,2020-06-27T04:48:12.636Z,dev,error,,,,,,[159323329016.713340] [/cf-echo] [8] Checking if this request is suitable to be saved as an audit log.
286,2020-06-27T04:48:12.636Z,dev,error,,,,,,[159323329016.713340] [/cf-echo] [8] Checking if this request is relevant to be part of the audit logs.
287,2020-06-27T04:48:12.636Z,dev,error,,,,,,"[159323329016.713340] [/cf-echo] [9] Return code `200' is not interesting to audit logs, relevant code(s): `^(?:5|4(?!04))'."

@PaulCharlton
Copy link
Author

in a nutshell, the hung session boils down to whether there is an empty line after the headers to separate the headers from a content body, and the hang only occurs when modsecurity is enabled, even if all rules are disabled, and only hangs for TLS session.

@PaulCharlton
Copy link
Author

additional information:
it only hangs for http2. forcing curl to http1.1 works ... curl -X POST URI -d '' --http1.1 does not hang

@PaulCharlton
Copy link
Author

definitive workaround:
add use-http2: false to the Nginx listen block.

At this point, we can write a unit test that sets conditions: (1) "POST + non-empty body", (2) side-car sub request Auth, (3) modsecurity enabled, (4) force HTTP2 + TLS session. iterate until the unit test works.

@PaulCharlton
Copy link
Author

there seems to be some ambiguity in the various interpretations of the HTTP2 protocol as it is translated back to NGINX request buffers ... does the blank line between the request_header and the request_body belong to the header, to the body, or as a standalone entity? I imagine we will find that modsecurity-nginx, Nginx auth subrequest, and Nginx proxy request have different views of that question.

@martinhsv martinhsv added the workaround available The issue has either a temporary or permanent workaround available label Jul 27, 2020
@finbourne-bot-public
Copy link

We are seeing the same issue (POST with non-empty body hangs if using http2, but is fine if using http1.1). Disabling use of http2 is not an option for us. Are there plans/an eta for a fix?

@jangrewe
Copy link

jangrewe commented Dec 9, 2023

Over three years later, i'd like to chime in that HTTP/2 + ModSecurity + auth_request still hangs for POST/PUT request.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
3.x Related to ModSecurity version 3.x Platform - Nginx workaround available The issue has either a temporary or permanent workaround available
Projects
None yet
Development

No branches or pull requests

5 participants