Detected request method (GET) sometimes does not match actual method (POST)

[theseion]

Moved here from SpiderLabs/owasp-modsecurity-crs#1304.

Type of Issue

Incorrect blocking (false positive)

Description

I find sporadic instances of requests blocked by the protocol enforcement rule that checks whether GET or HEAD requests have a Content-Length header > 0. When I try to match the requests to the NGiNX access log I see POST requests (as expected). I can reproduce the requests but haven't found a way to reproduce the blocking. Note that this occurs with different URL's and different body data as well.

The frequency of these events is around 1 to 2 a day in around 20000 POST requests.

audit log sample:

---HHaiBrX0---A--
[08/Feb/2019:13:55:07 +0100] 154963050792.701804 redacted 11912 redacted 443
---HHaiBrX0---B--
GET /redacted HTTP/2.0
accept-encoding: gzip, deflate, br
cookie: redacted
content-type: application/x-www-form-urlencoded; charset=UTF-8
x-requested-with: XMLHttpRequest
referer: https://redacted
origin: https://redacted
user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_2) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/71.0.3578.98 Safari/537.36
x-prototype-version: 1.7.3
accept: text/javascript, text/html, application/xml, text/xml, */*
content-length: 66
host: redacted
accept-language: de-DE,de;q=0.9,en-US;q=0.8,en;q=0.7

---HHaiBrX0---C--
_k=RZAuWjdS&1&2=W3siZXZlbnQiOiJhY3Rpb24iLCJlbGVtZW50IjoiMjgifV0%3D

---HHaiBrX0---F--
HTTP/2.0 403
Server: nginx/1.14.1
Date: Fri, 08 Feb 2019 12:55:07 GMT
Content-Length: 571
Content-Type: text/html
Connection: close
Strict-Transport-Security: max-age=15768000

---HHaiBrX0---H--
ModSecurity: Warning. Matched "Operator `Rx' with parameter `^0?$' against variable `REQUEST_HEADERS:content-length' (Value: `66' ) [file "/redacted/owasp-modsecurity-crs/rules/REQUEST-920-PROTOCOL-ENFORCEMENT.conf"] [line "227"] [id "920170"] [rev ""] [msg "GET or HEAD Request with Body Content."] [data "GET"] [severity "2"] [ver "OWASP_CRS/3.1.0"] [maturity "0"] [accuracy "0"] [hostname "redacted"] [uri "/redacted"] [unique_id "154963050792.701804"] [ref "o0,3v0,3v65,2"]
ModSecurity: Warning. Matched "Operator `Rx' with parameter `^0?$' against variable `REQUEST_HEADERS:content-length' (Value: `66' ) [file "/redacted/owasp-modsecurity-crs/rules/REQUEST-920-PROTOCOL-ENFORCEMENT.conf"] [line "227"] [id "920170"] [rev ""] [msg "GET or HEAD Request with Body Content."] [data "GET"] [severity "2"] [ver "OWASP_CRS/3.1.0"] [maturity "0"] [accuracy "0"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-protocol"] [tag "OWASP_CRS/PROTOCOL_VIOLATION/INVALID_HREQ"] [tag "CAPEC-272"] [hostname "217.11.221.129"] [uri "/redacted"] [unique_id "154963050792.701804"] [ref "o0,3v0,3v65,2"]
ModSecurity: Access denied with code 403 (phase 2). Matched "Operator `Ge' with parameter `5' against variable `TX:ANOMALY_SCORE' (Value: `5' ) [file "/redacted/owasp-modsecurity-crs/rules/REQUEST-949-BLOCKING-EVALUATION.conf"] [line "80"] [id "949110"] [rev ""] [msg "Inbound Anomaly Score Exceeded (Total Score: 5)"] [data ""] [severity "2"] [ver ""] [maturity "0"] [accuracy "0"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-generic"] [hostname "redacted"] [uri "/redacted"] [unique_id "154963050792.701804"] [ref ""]
ModSecurity: Warning. Matched "Operator `Ge' with parameter `5' against variable `TX:INBOUND_ANOMALY_SCORE' (Value: `5' ) [file "/redacted/owasp-modsecurity-crs/rules/RESPONSE-980-CORRELATION.conf"] [line "76"] [id "980130"] [rev ""] [msg "Inbound Anomaly Score Exceeded (Total Inbound Score: 5 - SQLI=0,XSS=0,RFI=0,LFI=0,RCE=0,PHPI=0,HTTP=0,SESS=0): GET or HEAD Request with Body Content.; individual paranoia level scores: 5, 0, 0, 0"] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [tag "event-correlation"] [hostname "redacted"] [uri "/redacted"] [unique_id "154963050792.701804"] [ref ""]

---HHaiBrX0---Z--

Matching request from NGiNX access log:

<redacted host> <redacted ip> - - [08/Feb/2019:13:55:07 +0100] "POST /redacted HTTP/2.0" 403 185 "<redacted referrer>" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_2) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/71.0.3578.98 Safari/537.36"

Your Environment

• CRS version: v3.1.0
• ModSecurity version: v3.0.2 (owasp-modsecurity/ModSecurity@6d5198b)
• Web Server and version: nginx 1.14.1
• Operating System and version: Debian 9.7

Confirmation

[x] I have removed any personal data (email addresses, IP addresses,
passwords, domain names) from any logs posted.

[kjakub]

👍 same issue here, we can reproduce the bug everytime when we attach particular body (file to the POST request) I will come back here once i will get the file.

[theseion]

@kjakub Very interesting. Can you share more details? Maybe we can come up with a test case. That will make it more likely for the problem to be solved fast.

[kjakub]

@theseion sorry, false alarm that we are NOT able reproduce everytime. Seems random too :-(

[theseion]

Bummer. Thanks for checking.

[zimmerle]

Hi @theseion,

Can you tell us the exact version of your libModSecurity? So that we can try to replicate the issue here as well

[theseion]

We built libmodsecurity with commit owasp-modsecurity/ModSecurity@6d5198b.

[kjakub]

@zimmerle @theseion just yesterday, we registered one more occurrence of this case

2019/04/02 22:42:18 [error] 10#10: *25779 [client x.x.x.x] ModSecurity: Access denied with code 403 (phase 2). Matched "Operator Rx' with parameter ^0?$' against variable REQUEST_HEADERS:Content-Length' (Value: 332' ) [file "/etc/nginx/conf/rules/REQUEST-920-PROTOCOL-ENFORCEMENT.conf"] [line "229"] [id "920170"] [rev ""] [msg "GET or HEAD Request with Body Content."] [data "GET"] [severity "2"] [ver "OWASP_CRS/3.1.0"] [maturity "0"] [accuracy "0"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-protocol"] [tag "OWASP_CRS/PROTOCOL_VIOLATION/INVALID_HREQ"] [tag "CAPEC-272"] [hostname "x.x.x.x"] [uri "/x_x"] [unique_id "155424493824.824245"] [ref "o0,3v0,3v119,3"], client: x.x.x.x, server: *.x.x.x, request: "POST /x_x HTTP/1.1", upstream: "http://x.x.x.x:x/x", host: "x.x.x.x", referrer: "https://x.x.x.x/x_x"

Our nginx is running on latest modsecurity everytime we build - which was 2019/03/11 (March 11, 2019) - latest build which was deployed regarding to cicd pipeline. We are using slightly modified docker image which i publish here https://github.com/kjakub/docker-nginx-modsecurity-v3-waf and the core of build is here https://github.com/kjakub/docker-nginx-modsecurity-v3-waf/blob/master/waf/build.sh

[zimmerle]

Thank you for all the details guys, sorry for the trouble and the time to answer. I will have a look at it ASAP. That kind of issue is annoying.

[theseion]

Let me know if I can help in any way.

[danotrampus]

For us the behaviour is consistent within one api endpoint.
LibModSecurity detects the request as GET when the actual HTTP_METHOD is POST.

CRS version: v3.1.0
ModSecurity version: v3.0.3
Web Server and version: nginx 1.14.1
Operating System and version: Alpine 3.10.0

[shmurf]

I was experiencing similar issues, so i tailed the debug log as follows
tail -f ....../modsec_debug.log | grep "Variable: REQUEST_METHOD"
and this is what i saw

[ID1.865933] [/ENDPOINT] [9] Target value: "POST" (Variable: REQUEST_METHOD)
[ID1.865933] [/ENDPOINT] [9] Target value: "POST" (Variable: REQUEST_METHOD)
[ID1.865933] [/ENDPOINT] [9] Target value: "POST" (Variable: REQUEST_METHOD)
[ID1.865933] [/ENDPOINT] [9] Target value: "POST" (Variable: REQUEST_METHOD)
[ID1.865933] [/ENDPOINT] [9] Target value: "POST" (Variable: REQUEST_METHOD)
[ID1.865933] [/ENDPOINT] [9] Target value: "POST" (Variable: REQUEST_METHOD)
[ID2.594002] [/ENDPOINT] [9] Target value: "GET" (Variable: REQUEST_METHOD)
[ID2.594002] [/ENDPOINT] [9] Target value: "GET" (Variable: REQUEST_METHOD)
[ID2.594002] [/ENDPOINT] [9] Target value: "GET" (Variable: REQUEST_METHOD)
[ID2.594002] [/ENDPOINT] [9] Target value: "GET" (Variable: REQUEST_METHOD)
[ID2.594002] [/ENDPOINT] [9] Target value: "GET" (Variable: REQUEST_METHOD)
[ID2.594002] [/ENDPOINT] [9] Target value: "GET" (Variable: REQUEST_METHOD)
[ID2.594002] [/ENDPOINT] [9] Target value: "GET" (Variable: REQUEST_METHOD)

turns out, that the POST requests that were appearing in the audit log as a GET were actually being processed twice with the first post request not being sent to the audit log

[ID1.865933] [/ENDPOINT] [9] Saving transaction to logs
[ID1.865933] [/ENDPOINT] [4] Running (disruptive)     action: deny.
[ID1.865933] [/ENDPOINT] [8] Running action deny
[ID1.865933] [/ENDPOINT] [8] Skipping this phase as this request was already intercepted.
[ID2.594002] [] [4] Initializing transaction
[ID2.594002] [] [4] Transaction context created.
[ID2.594002] [] [4] Starting phase CONNECTION. (SecRules 0)
[ID2.594002] [] [9] This phase consists of 37 rule(s).
[ID2.594002] [] [4] Starting phase URI. (SecRules 0 + 1/2)

Not exactly sure what this means, but hopefully this info is helpful

[shmurf]

Update:

Seems like every request that gets blocked gets processed as the original method type and then again as a GET, including GET itself which gets processed twice
The HEAD method is similar to GET in that it gets reprocessed twice both times as HEAD.

The nginx logs show only one request.

Not sure if my experience is related to this issue or just a bad config. If anyone has any suggestions or other tests they think I should run, please let me know.

Thanks

[zimmerle]

Hi,

Can you confirm that it is still an issue within the most recent version of the library+connector?