Closed airween closed 3 years ago
Hi @airween ,
I have seen the 'UNMATCHED_BOUNDARY' in unexpected cases (i.e. where the final boundary is indeed present). Typically this is because the request body stopped being processed before the final boundary was reached (hence the parser does not signal that the final boundary was found). For example:
I tried your example in my test setup and did not get that error.
Suggestions to proceed:
Hi @martinhsv,
thanks for quick feedback.
- the request body stopped being processed due to a configured limit (for example using SecRequestBodyLimit with the associated action being ProcessPartial)
as you can see in my modsecurity.conf, I have an explicit value for that:
SecRequestBodyLimit 13107200
So I'm sure the problem is not this (the size of sent file is 10 bytes). Also you can see the whole config in @defanator's repository - the value is 256M.
- the request body stopped being processed due to a serious parsing issue. For example one of the multipart parts did not have a "name"
this is the relevant output of tcpdump it runs during the request:
POST /upload/ HTTP/1.1
Host: localhost
User-Agent: curl/7.64.0
Accept: */*
Content-Length: 196
Content-Type: multipart/form-data; boundary=------------------------426732a72a1236b1
--------------------------426732a72a1236b1
Content-Disposition: form-data; name="data"; filename="text.txt"
Content-Type: text/plain
test text
--------------------------426732a72a1236b1--
There are both name
argument and final boundary.
I tried your example in my test setup and did not get that error.
Can you share your setup? Or can you try with the mentioned Vagrant config?
- the debug log (at level 9) may give away what other error was encountered during parsing
you mean about this?
[1617312599] [] [4] Initializing transaction
[1617312599] [] [4] Transaction context created.
[1617312599] [] [4] Starting phase CONNECTION. (SecRules 0)
[1617312599] [] [9] This phase consists of 0 rule(s).
[1617312599] [] [4] Starting phase URI. (SecRules 0 + 1/2)
[1617312599] [/upload/] [4] Starting phase REQUEST_HEADERS. (SecRules 1)
[1617312599] [/upload/] [9] This phase consists of 2 rule(s).
[1617312599] [/upload/] [4] (Rule: 200000) Executing operator "Rx" with param "(?:application(?:/soap\+|/)|text/)xml" against REQUEST_HEADERS:Content-Type.
[1617312599] [/upload/] [9] T (0) t:lowercase: "multipart/form-data; boundary=------------------------426732a72a1236b1"
[1617312599] [/upload/] [9] Target value: "multipart/form-data; boundary=------------------------426732a72a1236b1" (Variable: REQUEST_HEADERS:Content-Type)
[1617312599] [/upload/] [4] Rule returned 0.
[1617312599] [/upload/] [9] Matched vars cleaned.
[1617312599] [/upload/] [4] (Rule: 200001) Executing operator "Rx" with param "application/json" against REQUEST_HEADERS:Content-Type.
[1617312599] [/upload/] [9] T (0) t:lowercase: "multipart/form-data; boundary=------------------------426732a72a1236b1"
[1617312599] [/upload/] [9] Target value: "multipart/form-data; boundary=------------------------426732a72a1236b1" (Variable: REQUEST_HEADERS:Content-Type)
[1617312599] [/upload/] [4] Rule returned 0.
[1617312599] [/upload/] [9] Matched vars cleaned.
[1617312599] [/upload/] [9] Appending request body: 196 bytes. Limit set to: 13107200.000000
[1617312599] [/upload/] [4] Starting phase REQUEST_BODY. (SecRules 2)
[1617312599] [/upload/] [9] Multipart: Boundary: ------------------------426732a72a1236b1
[1617312599] [/upload/] [9] Multipart: Added part header "Content-Disposition" "form-data; name="data"; filename="text.txt"".
[1617312599] [/upload/] [9] Multipart: Added part header "Content-Type" "text/plain".
[1617312599] [/upload/] [9] Multipart: Content-Disposition name: data.
[1617312599] [/upload/] [9] Multipart: Content-Disposition filename: text.txt.
[1617312599] [/upload/] [9] Multipart: Added file part to the list: name "data" file name "text.txt" (offset 138, length 10)
[1617312599] [/upload/] [4] Multipart: Cleanup started (keep files set to Not set)
[1617312599] [/upload/] [9] This phase consists of 4 rule(s).
[1617312599] [/upload/] [4] (Rule: 200002) Executing operator "Eq" with param "0" against REQBODY_ERROR.
[1617312599] [/upload/] [9] Target value: "0" (Variable: REQBODY_ERROR)
[1617312599] [/upload/] [4] Rule returned 0.
[1617312599] [/upload/] [9] Matched vars cleaned.
[1617312599] [/upload/] [4] (Rule: 200003) Executing operator "Eq" with param "0" against MULTIPART_STRICT_ERROR.
[1617312599] [/upload/] [9] Target value: "0" (Variable: MULTIPART_STRICT_ERROR)
[1617312599] [/upload/] [4] Rule returned 0.
[1617312599] [/upload/] [9] Matched vars cleaned.
[1617312599] [/upload/] [4] (Rule: 200004) Executing operator "Gt" with param "1" against MULTIPART_UNMATCHED_BOUNDARY.
[1617312599] [/upload/] [9] Target value: "2" (Variable: MULTIPART_UNMATCHED_BOUNDARY)
[1617312599] [/upload/] [9] Matched vars updated.
[1617312599] [/upload/] [4] Rule returned 1.
[1617312599] [/upload/] [9] Saving msg: Multipart parser detected a possible unmatched boundary.
[1617312599] [/upload/] [9] Running action: log
- is there a chance that the file content is triggering a parsing error? One thought is to try to try the same test but with extremely simple file content -- for example the 6-char string abcdef
$ cat abcdef.txt
abcdef
$ curl -vvv "http://localhost/upload/" -F "data=@abcdef.txt"
* Expire in 0 ms for 6 (transfer 0x55ffa8f4df50)
...
* Expire in 1 ms for 1 (transfer 0x55ffa8f4df50)
* Trying ::1...
* TCP_NODELAY set
* Expire in 149998 ms for 3 (transfer 0x55ffa8f4df50)
* Expire in 200 ms for 4 (transfer 0x55ffa8f4df50)
* connect to ::1 port 80 failed: Connection refused
* Trying 127.0.0.1...
* TCP_NODELAY set
* Expire in 149998 ms for 3 (transfer 0x55ffa8f4df50)
* Connected to localhost (127.0.0.1) port 80 (#0)
> POST /upload/ HTTP/1.1
> Host: localhost
> User-Agent: curl/7.64.0
> Accept: */*
> Content-Length: 195
> Content-Type: multipart/form-data; boundary=------------------------f67b76cec353b936
>
< HTTP/1.1 403 Forbidden
< Server: nginx/1.19.6
< Date: Thu, 01 Apr 2021 21:32:21 GMT
< Content-Type: text/html
< Content-Length: 153
< Connection: keep-alive
* HTTP error before end of send, stop sending
<
<html>
<head><title>403 Forbidden</title></head>
<body>
<center><h1>403 Forbidden</h1></center>
<hr><center>nginx/1.19.6</center>
</body>
</html>
* Closing connection 0
error.log:
2021/04/01 21:32:21 [error] 7378#7378: *3 [client 127.0.0.1] ModSecurity: Access denied with code 403 (phase 2). Matched "Operator `Gt' with parameter `1' against variable `MULTIPART_UNMATCHED_BOUNDARY' (Value: `2' ) [file "/etc/nginx/modsec/modsecurity.conf"] [line "15"] [id "200004"] [rev ""] [msg "Multipart parser detected a possible unmatched boundary."] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "127.0.0.1"] [uri "/upload/"] [unique_id "1617312741"] [ref "v180,1"], client: 127.0.0.1, server: , request: "POST /upload/ HTTP/1.1", host: "localhost"
debug.log
[1617312741] [] [4] Initializing transaction
[1617312741] [] [4] Transaction context created.
[1617312741] [] [4] Starting phase CONNECTION. (SecRules 0)
[1617312741] [] [9] This phase consists of 0 rule(s).
[1617312741] [] [4] Starting phase URI. (SecRules 0 + 1/2)
[1617312741] [/upload/] [4] Starting phase REQUEST_HEADERS. (SecRules 1)
[1617312741] [/upload/] [9] This phase consists of 2 rule(s).
[1617312741] [/upload/] [4] (Rule: 200000) Executing operator "Rx" with param "(?:application(?:/soap\+|/)|text/)xml" against REQUEST_HEADERS:Content-Type.
[1617312741] [/upload/] [9] T (0) t:lowercase: "multipart/form-data; boundary=------------------------f67b76cec353b936"
[1617312741] [/upload/] [9] Target value: "multipart/form-data; boundary=------------------------f67b76cec353b936" (Variable: REQUEST_HEADERS:Content-Type)
[1617312741] [/upload/] [4] Rule returned 0.
[1617312741] [/upload/] [9] Matched vars cleaned.
[1617312741] [/upload/] [4] (Rule: 200001) Executing operator "Rx" with param "application/json" against REQUEST_HEADERS:Content-Type.
[1617312741] [/upload/] [9] T (0) t:lowercase: "multipart/form-data; boundary=------------------------f67b76cec353b936"
[1617312741] [/upload/] [9] Target value: "multipart/form-data; boundary=------------------------f67b76cec353b936" (Variable: REQUEST_HEADERS:Content-Type)
[1617312741] [/upload/] [4] Rule returned 0.
[1617312741] [/upload/] [9] Matched vars cleaned.
[1617312741] [/upload/] [9] Appending request body: 195 bytes. Limit set to: 13107200.000000
[1617312741] [/upload/] [4] Starting phase REQUEST_BODY. (SecRules 2)
[1617312741] [/upload/] [9] Multipart: Boundary: ------------------------f67b76cec353b936
[1617312741] [/upload/] [9] Multipart: Added part header "Content-Disposition" "form-data; name="data"; filename="abcdef.txt"".
[1617312741] [/upload/] [9] Multipart: Added part header "Content-Type" "text/plain".
[1617312741] [/upload/] [9] Multipart: Content-Disposition name: data.
[1617312741] [/upload/] [9] Multipart: Content-Disposition filename: abcdef.txt.
[1617312741] [/upload/] [9] Multipart: Added file part to the list: name "data" file name "abcdef.txt" (offset 140, length 7)
[1617312741] [/upload/] [4] Multipart: Cleanup started (keep files set to Not set)
[1617312741] [/upload/] [9] This phase consists of 4 rule(s).
[1617312741] [/upload/] [4] (Rule: 200002) Executing operator "Eq" with param "0" against REQBODY_ERROR.
[1617312741] [/upload/] [9] Target value: "0" (Variable: REQBODY_ERROR)
[1617312741] [/upload/] [4] Rule returned 0.
[1617312741] [/upload/] [9] Matched vars cleaned.
[1617312741] [/upload/] [4] (Rule: 200003) Executing operator "Eq" with param "0" against MULTIPART_STRICT_ERROR.
[1617312741] [/upload/] [9] Target value: "0" (Variable: MULTIPART_STRICT_ERROR)
[1617312741] [/upload/] [4] Rule returned 0.
[1617312741] [/upload/] [9] Matched vars cleaned.
[1617312741] [/upload/] [4] (Rule: 200004) Executing operator "Gt" with param "1" against MULTIPART_UNMATCHED_BOUNDARY.
[1617312741] [/upload/] [9] Target value: "2" (Variable: MULTIPART_UNMATCHED_BOUNDARY)
[1617312741] [/upload/] [9] Matched vars updated.
[1617312741] [/upload/] [4] Rule returned 1.
[1617312741] [/upload/] [9] Saving msg: Multipart parser detected a possible unmatched boundary.
[1617312741] [/upload/] [9] Running action: log
Same result.
Thanks for the extra information. I'll try to have a closer look on Monday.
I think I found the root cause of the problem - check this rule:
+SecRule MULTIPART_UNMATCHED_BOUNDARY "@gt 1" \
+ "id:'200004',phase:2,t:none,log,deny,msg:'Multipart parser detected a possible unmatched boundary.'"
I have no idea where did I got this rule, but this is definitely wrong. According to recommended modsecurity.conf, the correct operator and its argument are @eq 1
not @gt 1
.
So that was my faul - thanks for your time and sorry for the noise.
Hi @airween ,
Given your update, I didn't wind up debugging this.
However, I strongly suspect that this is an unintended effect of the way the PEM solution was implemented (#1747 and #1924) .
In my 'B' comments at https://github.com/SpiderLabs/ModSecurity/pull/2417#issuecomment-712296544 , note the use case when the PEM-like content is in the final part of the multipart body.
Just from code inspection, I suspect what you've recently seen is a similarly impacted case. I.e. that in your case, the flag=2 result is being triggered because there is only one part within the whole multipart body.
I think this lends weight that we this PEM-inspired modification should really be properly revisited.
Hi @martinhsv,
thanks for your time.
Just from code inspection, I suspect what you've recently seen is a similarly impacted case. I.e. that in your case, the flag=2 result is being triggered because there is only one part within the whole multipart body.
yes, I think this is true - but the problem was in my config, namely the operator and its argument was wrong in that rule. I have no idea where did I get, but luckily I found the root case.
I think this lends weight that we this PEM-inspired modification should really be properly revisited.
yes, absolutely - as I see the sent PR is nearly half year old. Do you plan to approve it only to 3.1?
Thanks again.
I always run into a MULTIPART_UNMATCHED_BOUNDARY error when I upload any kind of file.
The test environment is @defanator's Vagrant image.
Components:
This is what I modified:
Short summary of modifications:
modsecurity.conf
- few things were modifedHere is the PHP file what I used:
The file what I try to upload:
curl commands:
in the error.log:
Note: this request has sent to
/upload/
which was already configured.Another curl command:
in the error log I got:
When I run tcpdump, I see that there IS the final boundary in the request. I also tried it from browser, final boundary also at there.
Am I spoiling something? Or is this a really unexpected behavior?