ModSecurity
ModSecurity copied to clipboard
Published
20 hours ago •
owasp-modsecurity
owasp-modsecurity
PATCH method dies with mod security with nginx configured as proxy/ingress
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 https://github.com/kubernetes/ingress-nginx/issues/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"
====================================
open to any triage suggestions --- I realize there are several moving parts here between Nginx, modsecurity, and the Nginx-connector
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
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.
@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.
@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:
- I do not (yet) know the control flow through the various Nginx modules.
- other than the level 4,9 modsecurity logging (initially passing) there is nothing in the Nginx info log, and the session is hanging ... UNTIL
- 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?
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.
@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.
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;
}
summary of what I have observed:
- Nginx ingress with no modsecurity/external_auth. -> works
- Nginx ingress with either modsecurity or external_auth. -> works
- 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]
Hi @PaulCharlton ,
Those are some good clues.
In some ways it sounds a bit like something akin to https://github.com/bitly/oauth2_proxy/issues/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
@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.
@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
adding information: the hung session only occurs with TLS client connections
Server: Nginx/modsecurity container: quay.io/kubernetes-ingress-controller/nginx-ingress-controller tag: "0.32.0"
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.
spoke too soon on the last one.
curl -X POST URI --header 'Content-Length: 0'works with modsecurity enabled.curl -X POST URI -d ''does not work with modsecurity enabled. (blank line,Content-Length: 0)curl -X POST URIworks 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))'."
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.
additional information:
it only hangs for http2. forcing curl to http1.1 works ... curl -X POST URI -d '' --http1.1 does not hang
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.
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.
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?
Over three years later, i'd like to chime in that HTTP/2 + ModSecurity + auth_request still hangs for POST/PUT request.
