search

owasp-modsecurity / ModSecurity-nginx

ModSecurity v3 Nginx Connector
Apache License 2.0
1.59k stars 282 forks source link

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

Closed theseion closed 4 years ago

theseion commented 5 years ago

Moved here from https://github.com/SpiderLabs/owasp-modsecurity-crs/issues/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

Confirmation

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

kjakub commented 5 years ago

:+1: 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 commented 5 years ago

@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 commented 5 years ago

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

theseion commented 5 years ago

Bummer. Thanks for checking.

zimmerle commented 5 years ago

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 commented 5 years ago

We built libmodsecurity with commit https://github.com/SpiderLabs/ModSecurity/commit/6d5198b1a60992416c9c8f1d77754e8e5edba996.

kjakub commented 5 years ago

@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 commented 5 years ago

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 commented 5 years ago

Let me know if I can help in any way.

danotrampus commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 4 years ago

Hi,

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

theseion commented 4 years ago

I'll have to build it and see what happens. I'll get back to you ASAP.

zimmerle commented 4 years ago

Thank you @theseion!

zimmerle commented 4 years ago

Hi @theseion, any news?

theseion commented 4 years ago

Not yet, sorry. Because the requests are so rare I'll have to make a deployment first and then watch the log for a bit. That will take me at least 3 to 4 days to be sure.

zimmerle commented 4 years ago

oh I see. thank you!

theseion commented 4 years ago

It has taken me a bit longer to set up the updated version. I'm now monitoring the logs. I'll get back to you ASAP.

theseion commented 4 years ago

I still see those bad matches. I found a whole batch from today and the metrics may be interesting: 12 requests within a 5 minute window from three unique IP's and two unique Host headers.

Web server: NGiNX 1.14.2 OS: Debian 9.11 (stretch) ModSecurity: https://github.com/SpiderLabs/ModSecurity/commit/6624a18a4e7fd9881a7a9b435db3e481e8e986a5 (master) Connector: c6fd13807299184acf3719e1deb499fcb14d2ef4 (master)

github-actions[bot] commented 4 years ago

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 5 days

theseion commented 4 years ago

Still relevant.

theseion commented 4 years ago

@victorhora Please reopen this issue.

martinhsv commented 4 years ago

There is one nginx expected behaviour that may be related to at least some of the reports in this thread.

If your config includes error page redirects something like this:

    error_page   500 502 503 504  /50x.html;
    location = /50x.html {
        root   /usr/share/nginx/html;
    }
    error_page   403  /403.html;
    location = /403.html {
        root   /usr/share/nginx/html;
    }

Then, when such a redirect occurs, it is expected behaviour that the original POST method will be converted to a GET ... but the non-zero Content-Length header is retained, along with the original request's body content. See https://trac.nginx.org/nginx/ticket/876 for more information. Near the bottom of that article are suggestions on how to drop the body for such redirects, as well as zero-ing the Content-Length value (I have not actually tried these).

Might this explain what's being reported here? Possibly.

In particular, the reports from Aug. 6 appear to fit this pattern, with ModSecurity detections always resulting in a second request reported (with non-GET/HEAD requests resulting in the 2nd request as a GET).

This could potentially also explain what the OP has reported. Suppose an occasional POST request results in a 50x within nginx itself or the connector. Then ModSecurity would never analyze the original POST request, but would instead see a GET request with a body and a nonzero Content-Length.

What happens in such cases may be less obvious than one might think from the logs. In my experiments, the second request (e.g. a GET request that has been redirected to 403.html) still shows up in the logs with the original url (e.g. /testpost.php rather than /403.html).

There are a few ways that you can confirm if this is what is happening for you. Perhaps the simplest is to experimentally turn off ModSecurity within the error-redirect location blocks.

shmurf commented 4 years ago

@martinhsv

You assessment sounds very accurate as in fact i am using custom error redirects. Someone mentioned the idea of disabling modsec in the error redirect blocks, see here for more on that https://github.com/SpiderLabs/ModSecurity-nginx/issues/76#issuecomment-518718375 You'll notice towards the end of my comment where I note the double logged requests.

theseion commented 4 years ago

@martinhsv Wow! Nice find! I think you're on to something. I went through the logs to check the request I had reported above and there was indeed a connection timeout in the proxy server. We also do use error_page for 50x redirects.

martinhsv commented 4 years ago

Based on the feedback last week and the lack of any new discussion since, I'm assuming that we think we have a satisfactory explanation for these reports.

Unless I hear objections in the meantime, I'll go ahead and close this at eod tomorrow.

theseion commented 4 years ago

Fine by me. I'll probably implement one of the suggestions from the bug ticket.

theseion commented 4 years ago

I'd like to share my solution for working around the request method conversion. It's a bit more complicated than I would have liked but I had to work around some limitations (e.g. that status codes can't be variables).

Quick note on the setup: we use NGiNX as reverse proxy with multiple backend web servers. We don't interfere with errors returned from the downstream servers except for 5xx errors (note that there appears to be a bug in NGiNX so that my idea fails to convert 502 to 503):

proxy_intercept_errors on;
error_page 502 503 504 @error503; # always reply with 503

This is the error configuration we use:

# We use named locations for handling errors so that we can prevent
# NGiNX from converting the request method to GET for requests with
# other methods (usually POST). See https://github.com/SpiderLabs/ModSecurity-nginx/issues/152

# the error handlers may use the `error_page` directive internally
# so we have to enable recursive error pages
recursive_error_pages on;
error_page 404 = @error404;
error_page 410 = @error410;
error_page 500 = @error500;
error_page 503 504 = @error503;

## error handlers
location @error404 {
    # internal 404 only occur for files and in that case we
    # don't need to return HTML to the client.

    # disable recursive error pages for the remainder of the request
    # or we'll end up in an infinite loop because we end up using
    # the same `error_page` directive over and over
    recursive_error_pages off;
    return 404;
}
location @error410 {
    if ($request_method = GET) {
        # override the directive from the outer scope
        error_page 410 /errors/gone.html;
        # now return the error status code, which will
        # trigger the `error_page` we just set
        return 410;
    }
    # disable recursive error pages for the remainder of the request
    # or we'll end up in an infinite loop because we end up using
    # the same `error_page` directive over and over
    recursive_error_pages off;
    # we already hit `error_page` once and now that we've disabled
    # recursive error pages this will return the response to the client
    return 410;
}
location @error500 {
    # see comments in @error410
    if ($request_method = GET) {
        error_page 500 /errors/internalservererror.html;
        return 500;
    }
    recursive_error_pages off;
    return 500;
}
location @error503 {
    # see comments in @error410
    if ($request_method = GET) {
        error_page 503 /errors/maintenance.html;
        return 503;
    }
    recursive_error_pages off;
    return 503;
}

# handles all error page requests
location /errors {
    root ${error_root};
    internal;
}
cello86 commented 2 years ago

@martinhsv I noticed another issue with some POST transformed in GET and the internal redirect has been applied after the 403 matched from mod_security. The problem is present after a buffering of a client request:

 2022/04/13 11:40:13 [debug] 181#181: *34 reusable connection: 0
 2022/04/13 11:40:13 [debug] 181#181: *34 posix_memalign: 00000000038D8150:4096 @16
 2022/04/13 11:40:13 [debug] 181#181: *34 event timer del: 3: 1924828244
 2022/04/13 11:40:13 [debug] 181#181: *34 http process request line
 2022/04/13 11:40:13 [debug] 181#181: *34 http request line: "POST /v1/intranet/public/uploads/2653 HTTP/1.1"
 2022/04/13 11:40:13 [debug] 181#181: *34 http uri: "/v1/intranet/public/uploads/2653"
 2022/04/13 11:40:13 [debug] 181#181: *34 http args: ""
 2022/04/13 11:40:13 [debug] 181#181: *34 http exten: ""
 2022/04/13 11:40:13 [debug] 181#181: *34 posix_memalign: 00000000038C9580:4096 @16
 2022/04/13 11:40:13 [debug] 181#181: *34 http process request header line
 2022/04/13 11:40:13 [debug] 181#181: *34 http header: "Host: test.local"
 2022/04/13 11:40:13 [debug] 181#181: *34 http header: "Connection: keep-alive"
 2022/04/13 11:40:13 [debug] 181#181: *34 http header: "Content-Length: 142336"
 2022/04/13 11:40:13 [debug] 181#181: *34 http header: "sec-ch-ua: " Not A;Brand";v="99", "Chromium";v="99", "Google Chrome";v="99""
 2022/04/13 11:40:13 [debug] 181#181: *34 http header: "Upload-Offset: 0"
 2022/04/13 11:40:13 [debug] 181#181: *34 http header: "sec-ch-ua-mobile: ?0"
 2022/04/13 11:40:13 [debug] 181#181: *34 http header: "User-Agent: Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/99.0.4844.74 Safari/537.36"
 2022/04/13 11:40:13 [debug] 181#181: *34 http header: "Content-Type: application/offset+octet-stream"
 2022/04/13 11:40:13 [debug] 181#181: *34 http header: "Tus-Resumable: 1.0.0"
 2022/04/13 11:40:13 [debug] 181#181: *34 http header: "X-HTTP-Method-Override: PATCH"
 2022/04/13 11:40:13 [debug] 181#181: *34 http header: "sec-ch-ua-platform: "Windows""
 2022/04/13 11:40:13 [debug] 181#181: *34 http header: "Accept: */*"
 2022/04/13 11:40:13 [debug] 181#181: *34 http alloc large header buffer
 2022/04/13 11:40:13 [debug] 181#181: *34 malloc: 00000000038D9300:8192
 2022/04/13 11:40:13 [debug] 181#181: *34 http large header alloc: 00000000038D9300 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 http large header copy: 2
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: 456
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: -1
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_get_error: 2
 2022/04/13 11:40:13 [debug] 181#181: *34 http header: "Origin: https://test.local"
 2022/04/13 11:40:13 [debug] 181#181: *34 http header: "Sec-Fetch-Site: same-site"
 2022/04/13 11:40:13 [debug] 181#181: *34 http header: "Sec-Fetch-Mode: cors"
 2022/04/13 11:40:13 [debug] 181#181: *34 http header: "Sec-Fetch-Dest: empty"
 2022/04/13 11:40:13 [debug] 181#181: *34 http header: "Accept-Encoding: gzip, deflate, br"
 2022/04/13 11:40:13 [debug] 181#181: *34 http header: "Accept-Language: en-US,en;q=0.9"
 2022/04/13 11:40:13 [debug] 181#181: *34 http header: "Cookie:"
 2022/04/13 11:40:13 [debug] 181#181: *34 http header done
 2022/04/13 11:40:13 [debug] 181#181: *34 rewrite phase: 0
 2022/04/13 11:40:13 [debug] 181#181: *34 test location: "/error"
 2022/04/13 11:40:13 [debug] 181#181: *34 test location: "/probe.html"
 2022/04/13 11:40:13 [debug] 181#181: *34 test location: ~ "/(actuator/|actuator)"
 2022/04/13 11:40:13 [debug] 181#181: *34 test location: ~ "/(api-docs/|api-docs)"
 2022/04/13 11:40:13 [debug] 181#181: *34 test location: ~ "^(/v1/intranet/private/|/v1/intranet/public|/admin/)"
 2022/04/13 11:40:13 [debug] 181#181: *34 using configuration "^(/v1/intranet/private/|/v1/intranet/public|/admin/)"
 2022/04/13 11:40:13 [debug] 181#181: *34 http cl:142336 max:1048576
 2022/04/13 11:40:13 [debug] 181#181: *34 rewrite phase: 2
 2022/04/13 11:40:13 [debug] 181#181: *34 http script var: "POST"
 2022/04/13 11:40:13 [debug] 181#181: *34 http script copy: " "
 2022/04/13 11:40:13 [debug] 181#181: *34 http script var: "/v1/intranet/public/uploads/2653"
 2022/04/13 11:40:13 [debug] 181#181: *34 http script var: "POST"
 2022/04/13 11:40:13 [debug] 181#181: *34 http script copy: " "
 2022/04/13 11:40:13 [debug] 181#181: *34 http script var: "/v1/intranet/public/uploads/2653"
 2022/04/13 11:40:13 [debug] 181#181: *34 add cleanup: 00000000038D9130
 2022/04/13 11:40:13 [debug] 181#181: *34 rewrite phase: 3
 2022/04/13 11:40:13 [debug] 181#181: *34 add cleanup: 00000000038C99A8
 2022/04/13 11:40:13 [debug] 181#181: *34 rewrite phase: 4
 2022/04/13 11:40:13 [debug] 181#181: *34 rewrite phase: 5
 2022/04/13 11:40:13 [debug] 181#181: *34 headers more rewrite handler, uri "/v1/intranet/public/uploads/2653"
 2022/04/13 11:40:13 [debug] 181#181: *34 post rewrite phase: 6
 2022/04/13 11:40:13 [debug] 181#181: *34 generic phase: 7
 2022/04/13 11:40:13 [debug] 181#181: *34 http request body content length filter
 2022/04/13 11:40:13 [debug] 181#181: *34 malloc: 00000000038CE840:8192
 2022/04/13 11:40:13 [debug] 181#181: *34 http read client request body
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: -1
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_get_error: 2
 2022/04/13 11:40:13 [debug] 181#181: *34 http client request body recv -2
 2022/04/13 11:40:13 [debug] 181#181: *34 http client request body rest 142336
 2022/04/13 11:40:13 [debug] 181#181: *34 event timer add: 3: 60000:1924868305
 2022/04/13 11:40:13 [debug] 181#181: *34 http run request: "/v1/intranet/public/uploads/2653?"
 2022/04/13 11:40:13 [debug] 181#181: *34 http request empty handler
 2022/04/13 11:40:13 [debug] 181#181: *34 http run request: "/v1/intranet/public/uploads/2653?"
 2022/04/13 11:40:13 [debug] 181#181: *34 http read client request body
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: avail:0
 2022/04/13 11:40:13 [debug] 181#181: *34 http client request body recv 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 http body new buf t:1 f:0 00000000038CE840, pos 00000000038CE840, size: 8192 file: 0, size: 0
 2022/04/13 11:40:13 [debug] 181#181: *34 http write client request body, bufs 00000000038C9B30
 2022/04/13 11:40:13 [debug] 181#181: *34 add cleanup: 00000000038C9C88
 2022/04/13 11:40:13 [debug] 181#181: *34 hashed path: /usr/local/nginx/client_body_temp/0000000006
 2022/04/13 11:40:13 [debug] 181#181: *34 temp fd:17
 2022/04/13 11:40:13 [warn] 181#181: *34 a client request body is buffered to a temporary file /usr/local/nginx/client_body_temp/0000000006, client: xxx.xxx.xxx.xxx, server: test.local, request: "POST /v1/intranet/public/uploads/2653 HTTP/1.1", host: "test.local"
 2022/04/13 11:40:13 [debug] 181#181: *34 write: 17, 00000000038CE840, 8192, 0
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 post event 00000000037E3960
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: avail:0
 2022/04/13 11:40:13 [debug] 181#181: *34 http client request body recv 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 http body new buf t:1 f:0 00000000038CE840, pos 00000000038CE840, size: 8192 file: 0, size: 0
 2022/04/13 11:40:13 [debug] 181#181: *34 http write client request body, bufs 00000000038C9B30
 2022/04/13 11:40:13 [debug] 181#181: *34 write: 17, 00000000038CE840, 8192, 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 delete posted event 00000000037E3960
 2022/04/13 11:40:13 [debug] 181#181: *34 post event 00000000037E3960
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: avail:0
 2022/04/13 11:40:13 [debug] 181#181: *34 http client request body recv 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 http body new buf t:1 f:0 00000000038CE840, pos 00000000038CE840, size: 8192 file: 0, size: 0
 2022/04/13 11:40:13 [debug] 181#181: *34 http write client request body, bufs 00000000038C9B30
 2022/04/13 11:40:13 [debug] 181#181: *34 write: 17, 00000000038CE840, 8192, 16384
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 delete posted event 00000000037E3960
 2022/04/13 11:40:13 [debug] 181#181: *34 post event 00000000037E3960
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: avail:0
 2022/04/13 11:40:13 [debug] 181#181: *34 http client request body recv 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 http body new buf t:1 f:0 00000000038CE840, pos 00000000038CE840, size: 8192 file: 0, size: 0
 2022/04/13 11:40:13 [debug] 181#181: *34 http write client request body, bufs 00000000038C9B30
 2022/04/13 11:40:13 [debug] 181#181: *34 write: 17, 00000000038CE840, 8192, 24576
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 delete posted event 00000000037E3960
 2022/04/13 11:40:13 [debug] 181#181: *34 post event 00000000037E3960
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: avail:0
 2022/04/13 11:40:13 [debug] 181#181: *34 http client request body recv 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 http body new buf t:1 f:0 00000000038CE840, pos 00000000038CE840, size: 8192 file: 0, size: 0
 2022/04/13 11:40:13 [debug] 181#181: *34 http write client request body, bufs 00000000038C9B30
 2022/04/13 11:40:13 [debug] 181#181: *34 write: 17, 00000000038CE840, 8192, 32768
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 delete posted event 00000000037E3960
 2022/04/13 11:40:13 [debug] 181#181: *34 post event 00000000037E3960
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: avail:0
 2022/04/13 11:40:13 [debug] 181#181: *34 http client request body recv 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 http body new buf t:1 f:0 00000000038CE840, pos 00000000038CE840, size: 8192 file: 0, size: 0
 2022/04/13 11:40:13 [debug] 181#181: *34 http write client request body, bufs 00000000038C9B30
 2022/04/13 11:40:13 [debug] 181#181: *34 write: 17, 00000000038CE840, 8192, 40960
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 delete posted event 00000000037E3960
 2022/04/13 11:40:13 [debug] 181#181: *34 post event 00000000037E3960
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: avail:0
 2022/04/13 11:40:13 [debug] 181#181: *34 http client request body recv 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 http body new buf t:1 f:0 00000000038CE840, pos 00000000038CE840, size: 8192 file: 0, size: 0
 2022/04/13 11:40:13 [debug] 181#181: *34 http write client request body, bufs 00000000038C9B30
 2022/04/13 11:40:13 [debug] 181#181: *34 write: 17, 00000000038CE840, 8192, 49152
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 delete posted event 00000000037E3960
 2022/04/13 11:40:13 [debug] 181#181: *34 post event 00000000037E3960
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: avail:0
 2022/04/13 11:40:13 [debug] 181#181: *34 http client request body recv 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 http body new buf t:1 f:0 00000000038CE840, pos 00000000038CE840, size: 8192 file: 0, size: 0
 2022/04/13 11:40:13 [debug] 181#181: *34 http write client request body, bufs 00000000038C9B30
 2022/04/13 11:40:13 [debug] 181#181: *34 write: 17, 00000000038CE840, 8192, 57344
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 delete posted event 00000000037E3960
 2022/04/13 11:40:13 [debug] 181#181: *34 post event 00000000037E3960
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: avail:0
 2022/04/13 11:40:13 [debug] 181#181: *34 http client request body recv 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 http body new buf t:1 f:0 00000000038CE840, pos 00000000038CE840, size: 8192 file: 0, size: 0
 2022/04/13 11:40:13 [debug] 181#181: *34 http write client request body, bufs 00000000038C9B30
 2022/04/13 11:40:13 [debug] 181#181: *34 write: 17, 00000000038CE840, 8192, 65536
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 delete posted event 00000000037E3960
 2022/04/13 11:40:13 [debug] 181#181: *34 post event 00000000037E3960
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: avail:0
 2022/04/13 11:40:13 [debug] 181#181: *34 http client request body recv 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 http body new buf t:1 f:0 00000000038CE840, pos 00000000038CE840, size: 8192 file: 0, size: 0
 2022/04/13 11:40:13 [debug] 181#181: *34 http write client request body, bufs 00000000038C9B30
 2022/04/13 11:40:13 [debug] 181#181: *34 write: 17, 00000000038CE840, 8192, 73728
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: -1
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_get_error: 2
 2022/04/13 11:40:13 [debug] 181#181: *34 http client request body recv -2
 2022/04/13 11:40:13 [debug] 181#181: *34 http client request body rest 60416
 2022/04/13 11:40:13 [debug] 181#181: *34 event timer: 3, old: 1924868305, new: 1924868308
 2022/04/13 11:40:13 [debug] 181#181: *34 http run request: "/v1/intranet/public/uploads/2653?"
 2022/04/13 11:40:13 [debug] 181#181: *34 http request empty handler
 2022/04/13 11:40:13 [debug] 181#181: *34 http run request: "/v1/intranet/public/uploads/2653?"
 2022/04/13 11:40:13 [debug] 181#181: *34 http request empty handler
 2022/04/13 11:40:13 [debug] 181#181: *34 delete posted event 00000000037E3960
 2022/04/13 11:40:13 [debug] 181#181: *34 http run request: "/v1/intranet/public/uploads/2653?"
 2022/04/13 11:40:13 [debug] 181#181: *34 http read client request body
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: -1
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_get_error: 2
 2022/04/13 11:40:13 [debug] 181#181: *34 http client request body recv -2
 2022/04/13 11:40:13 [debug] 181#181: *34 http client request body rest 60416
 2022/04/13 11:40:13 [debug] 181#181: *34 event timer: 3, old: 1924868305, new: 1924868311
 2022/04/13 11:40:13 [debug] 181#181: *34 http run request: "/v1/intranet/public/uploads/2653?"
 2022/04/13 11:40:13 [debug] 181#181: *34 http read client request body
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: avail:32509
 2022/04/13 11:40:13 [debug] 181#181: *34 http client request body recv 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 http body new buf t:1 f:0 00000000038CE840, pos 00000000038CE840, size: 8192 file: 0, size: 0
 2022/04/13 11:40:13 [debug] 181#181: *34 http write client request body, bufs 00000000038C9B30
 2022/04/13 11:40:13 [debug] 181#181: *34 write: 17, 00000000038CE840, 8192, 81920
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: avail:24317
 2022/04/13 11:40:13 [debug] 181#181: *34 http client request body recv 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 http body new buf t:1 f:0 00000000038CE840, pos 00000000038CE840, size: 8192 file: 0, size: 0
 2022/04/13 11:40:13 [debug] 181#181: *34 http write client request body, bufs 00000000038C9B30
 2022/04/13 11:40:13 [debug] 181#181: *34 write: 17, 00000000038CE840, 8192, 90112
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: avail:16125
 2022/04/13 11:40:13 [debug] 181#181: *34 http client request body recv 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 http body new buf t:1 f:0 00000000038CE840, pos 00000000038CE840, size: 8192 file: 0, size: 0
 2022/04/13 11:40:13 [debug] 181#181: *34 http write client request body, bufs 00000000038C9B30
 2022/04/13 11:40:13 [debug] 181#181: *34 write: 17, 00000000038CE840, 8192, 98304
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: avail:7933
 2022/04/13 11:40:13 [debug] 181#181: *34 http client request body recv 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 http body new buf t:1 f:0 00000000038CE840, pos 00000000038CE840, size: 8192 file: 0, size: 0
 2022/04/13 11:40:13 [debug] 181#181: *34 http write client request body, bufs 00000000038C9B30
 2022/04/13 11:40:13 [debug] 181#181: *34 write: 17, 00000000038CE840, 8192, 106496
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 post event 00000000037E3960
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: avail:0
 2022/04/13 11:40:13 [debug] 181#181: *34 http client request body recv 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 http body new buf t:1 f:0 00000000038CE840, pos 00000000038CE840, size: 8192 file: 0, size: 0
 2022/04/13 11:40:13 [debug] 181#181: *34 http write client request body, bufs 00000000038C9B30
 2022/04/13 11:40:13 [debug] 181#181: *34 write: 17, 00000000038CE840, 8192, 114688
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 delete posted event 00000000037E3960
 2022/04/13 11:40:13 [debug] 181#181: *34 post event 00000000037E3960
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: avail:0
 2022/04/13 11:40:13 [debug] 181#181: *34 http client request body recv 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 http body new buf t:1 f:0 00000000038CE840, pos 00000000038CE840, size: 8192 file: 0, size: 0
 2022/04/13 11:40:13 [debug] 181#181: *34 http write client request body, bufs 00000000038C9B30
 2022/04/13 11:40:13 [debug] 181#181: *34 write: 17, 00000000038CE840, 8192, 122880
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: -1
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_get_error: 2
 2022/04/13 11:40:13 [debug] 181#181: *34 http client request body recv -2
 2022/04/13 11:40:13 [debug] 181#181: *34 http client request body rest 11264
 2022/04/13 11:40:13 [debug] 181#181: *34 event timer: 3, old: 1924868305, new: 1924868312
 2022/04/13 11:40:13 [debug] 181#181: *34 http run request: "/v1/intranet/public/uploads/2653?"
 2022/04/13 11:40:13 [debug] 181#181: *34 http request empty handler
 2022/04/13 11:40:13 [debug] 181#181: *34 http run request: "/v1/intranet/public/uploads/2653?"
 2022/04/13 11:40:13 [debug] 181#181: *34 http request empty handler
 2022/04/13 11:40:13 [debug] 181#181: *34 delete posted event 00000000037E3960
 2022/04/13 11:40:13 [debug] 181#181: *34 http run request: "/v1/intranet/public/uploads/2653?"
 2022/04/13 11:40:13 [debug] 181#181: *34 http read client request body
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: -1
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_get_error: 2
 2022/04/13 11:40:13 [debug] 181#181: *34 http client request body recv -2
 2022/04/13 11:40:13 [debug] 181#181: *34 http client request body rest 11264
 2022/04/13 11:40:13 [debug] 181#181: *34 event timer: 3, old: 1924868305, new: 1924868313
 2022/04/13 11:40:13 [debug] 181#181: *34 http run request: "/v1/intranet/public/uploads/2653?"
 2022/04/13 11:40:13 [debug] 181#181: *34 http read client request body
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: avail:0
 2022/04/13 11:40:13 [debug] 181#181: *34 http client request body recv 8192
 2022/04/13 11:40:13 [debug] 181#181: *34 http body new buf t:1 f:0 00000000038CE840, pos 00000000038CE840, size: 8192 file: 0, size: 0
 2022/04/13 11:40:13 [debug] 181#181: *34 http write client request body, bufs 00000000038C9B30
 2022/04/13 11:40:13 [debug] 181#181: *34 write: 17, 00000000038CE840, 8192, 131072
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: 3072
 2022/04/13 11:40:13 [debug] 181#181: *34 post event 00000000037E3960
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_read: avail:0
 2022/04/13 11:40:13 [debug] 181#181: *34 http client request body recv 3072
 2022/04/13 11:40:13 [debug] 181#181: *34 http body new buf t:1 f:0 00000000038CE840, pos 00000000038CE840, size: 3072 file: 0, size: 0
 2022/04/13 11:40:13 [debug] 181#181: *34 http write client request body, bufs 00000000038C9B30
 2022/04/13 11:40:13 [debug] 181#181: *34 write: 17, 00000000038CE840, 3072, 139264
 2022/04/13 11:40:13 [debug] 181#181: *34 http client request body rest 0
 2022/04/13 11:40:13 [debug] 181#181: *34 event timer del: 3: 1924868305
 2022/04/13 11:40:13 [debug] 181#181: *34 generic phase: 7
 2022/04/13 11:40:13 [debug] 181#181: *34 malloc: 00000000038D0940:4096
 2022/04/13 11:40:13 [debug] 181#181: *34 malloc: 00000000038D1950:4096
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 00000000038D0940
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 00000000038D1950
 2022/04/13 11:40:13 [debug] 181#181: *34 malloc: 00000000038D16E0:4096
 2022/04/13 11:40:13 [debug] 181#181: *34 malloc: 00000000038D26F0:4096
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 00000000038D16E0
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 00000000038D26F0
 2022/04/13 11:40:13 [debug] 181#181: *34 posix_memalign: 000000000393A710:4096 @16
 2022/04/13 11:40:13 [debug] 181#181: *34 malloc: 000000000393B720:4096
 2022/04/13 11:40:13 [debug] 181#181: *34 malloc: 000000000393C730:4096
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 000000000393B720
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 000000000393C730
 2022/04/13 11:40:13 [debug] 181#181: *34 http finalize request: 403, "/v1/intranet/public/uploads/2653?" a:1, c:1
 2022/04/13 11:40:13 [debug] 181#181: *34 http special response: 403, "/v1/intranet/public/uploads/2653?"
 2022/04/13 11:40:13 [debug] 181#181: *34 internal redirect: "/error/403.json?"
 2022/04/13 11:40:13 [debug] 181#181: *34 rewrite phase: 0
 2022/04/13 11:40:13 [debug] 181#181: *34 test location: "/error"
 2022/04/13 11:40:13 [debug] 181#181: *34 using configuration "/error"
 2022/04/13 11:40:13 [debug] 181#181: *34 http cl:142336 max:1048576
 2022/04/13 11:40:13 [debug] 181#181: *34 rewrite phase: 2
 2022/04/13 11:40:13 [debug] 181#181: *34 rewrite phase: 3
 2022/04/13 11:40:13 [debug] 181#181: *34 add cleanup: 000000000393A9B0
 2022/04/13 11:40:13 [debug] 181#181: *34 rewrite phase: 4
 2022/04/13 11:40:13 [debug] 181#181: *34 rewrite phase: 5
 2022/04/13 11:40:13 [debug] 181#181: *34 headers more rewrite handler, uri "/error/403.json"
 2022/04/13 11:40:13 [debug] 181#181: *34 post rewrite phase: 6
 2022/04/13 11:40:13 [debug] 181#181: *34 generic phase: 7
 2022/04/13 11:40:13 [debug] 181#181: *34 malloc: 0000000003997960:4096
 2022/04/13 11:40:13 [debug] 181#181: *34 malloc: 0000000003998970:4096
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 0000000003997960
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 0000000003998970
 2022/04/13 11:40:13 [debug] 181#181: *34 posix_memalign: 0000000003999010:4096 @16
 2022/04/13 11:40:13 [debug] 181#181: *34 malloc: 000000000399A020:4096
 2022/04/13 11:40:13 [debug] 181#181: *34 malloc: 000000000399B030:4096
 2022/04/13 11:40:13 [debug] 181#181: *34 malloc: 000000000399C040:4096
 2022/04/13 11:40:13 [debug] 181#181: *34 malloc: 000000000399D050:4096
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 000000000399A020
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 000000000399D050
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 000000000399C040
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 000000000399B030
 2022/04/13 11:40:13 [debug] 181#181: *34 malloc: 000000000399E1E0:4096
 2022/04/13 11:40:13 [debug] 181#181: *34 malloc: 000000000399F1F0:4096
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 000000000399E1E0
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 000000000399F1F0
 2022/04/13 11:40:13 [debug] 181#181: *34 generic phase: 8
 2022/04/13 11:40:13 [debug] 181#181: *34 generic phase: 9
 2022/04/13 11:40:13 [debug] 181#181: *34 generic phase: 10
 2022/04/13 11:40:13 [debug] 181#181: *34 access phase: 11
 2022/04/13 11:40:13 [debug] 181#181: *34 access phase: 12
 2022/04/13 11:40:13 [debug] 181#181: *34 post access phase: 13
 2022/04/13 11:40:13 [debug] 181#181: *34 generic phase: 14
 2022/04/13 11:40:13 [debug] 181#181: *34 generic phase: 15
 2022/04/13 11:40:13 [debug] 181#181: *34 content phase: 16
 2022/04/13 11:40:13 [debug] 181#181: *34 content phase: 17
 2022/04/13 11:40:13 [debug] 181#181: *34 content phase: 18
 2022/04/13 11:40:13 [debug] 181#181: *34 http filename: "/usr/local/nginx/error/403.json"
 2022/04/13 11:40:13 [debug] 181#181: *34 add cleanup: 000000000393B5D8
 2022/04/13 11:40:13 [debug] 181#181: *34 http static fd: 20
 2022/04/13 11:40:13 [debug] 181#181: *34 headers more header filter, uri "/error/403.json"
 2022/04/13 11:40:13 [debug] 181#181: *34 HTTP/1.1 403 Forbidden#015#012Date: Wed, 13 Apr 2022 09:40:13 GMT#015#012Content-Type: application/json#015#012Transfer-Encoding: chunked#015#012Connection: keep-alive#015#012X-Powered-By: ASP.NET#015#012Server: Microsoft-IIS/10.0#015
 2022/04/13 11:40:13 [debug] 181#181: *34 write new buf t:1 f:0 00000000039998F8, pos 00000000039998F8, size: 198 file: 0, size: 0
 2022/04/13 11:40:13 [debug] 181#181: *34 http write filter: l:0 f:0 s:198
 2022/04/13 11:40:13 [debug] 181#181: *34 http output filter "/error/403.json?"
 2022/04/13 11:40:13 [debug] 181#181: *34 http copy filter: "/error/403.json?"
 2022/04/13 11:40:13 [debug] 181#181: *34 read: 20, 0000000003999AB0, 144, 0
 2022/04/13 11:40:13 [debug] 181#181: *34 http sub filter "/error/403.json"
 2022/04/13 11:40:13 [debug] 181#181: *34 parse: 0, looked: "" 0000000003999AB0-0000000003999ACA
 2022/04/13 11:40:13 [debug] 181#181: *34 http script var: "1df7ed447fc62ce7d0b49f24ca3366f2"
 2022/04/13 11:40:13 [debug] 181#181: *34 parse: -2, looked: " ] }#012" 0000000003999AD4-0000000003999B3B
 2022/04/13 11:40:13 [debug] 181#181: *34 sub out: 0000000003999B70 0000000003999AB0
 2022/04/13 11:40:13 [debug] 181#181: *34 sub out: 0000000003999BD0 0000000003999C50
 2022/04/13 11:40:13 [debug] 181#181: *34 sub out: 0000000003999C80 0000000003999AD4
 2022/04/13 11:40:13 [debug] 181#181: *34 sub out: 0000000003999CE0 000000000393B69D
 2022/04/13 11:40:13 [debug] 181#181: *34 http postpone filter "/error/403.json?" 0000000003999B60
 2022/04/13 11:40:13 [debug] 181#181: *34 http chunk: 26
 2022/04/13 11:40:13 [debug] 181#181: *34 http chunk: 32
 2022/04/13 11:40:13 [debug] 181#181: *34 http chunk: 103
 2022/04/13 11:40:13 [debug] 181#181: *34 http chunk: 5
 2022/04/13 11:40:13 [debug] 181#181: *34 write old buf t:1 f:0 00000000039998F8, pos 00000000039998F8, size: 198 file: 0, size: 0
 2022/04/13 11:40:13 [debug] 181#181: *34 write new buf t:1 f:0 0000000003999DD0, pos 0000000003999DD0, size: 4 file: 0, size: 0
 2022/04/13 11:40:13 [debug] 181#181: *34 write new buf t:1 f:1 0000000003999AB0, pos 0000000003999AB0, size: 26 file: 0, size: 26
 2022/04/13 11:40:13 [debug] 181#181: *34 write new buf t:0 f:0 0000000000000000, pos 0000000003999C50, size: 32 file: 0, size: 0
 2022/04/13 11:40:13 [debug] 181#181: *34 write new buf t:1 f:1 0000000003999AB0, pos 0000000003999AD4, size: 103 file: 36, size: 103
 2022/04/13 11:40:13 [debug] 181#181: *34 write new buf t:0 f:0 0000000000000000, pos 000000000393B69D, size: 5 file: 0, size: 0
 2022/04/13 11:40:13 [debug] 181#181: *34 write new buf t:0 f:0 0000000000000000, pos 00000000007232C4, size: 7 file: 0, size: 0
 2022/04/13 11:40:13 [debug] 181#181: *34 http write filter: l:1 f:0 s:375
 2022/04/13 11:40:13 [debug] 181#181: *34 http write filter limit 2097152
 2022/04/13 11:40:13 [debug] 181#181: *34 malloc: 000000000399EA70:16384
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL buf copy: 198
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL buf copy: 4
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL buf copy: 26
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL buf copy: 32
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL buf copy: 103
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL buf copy: 5
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL buf copy: 7
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL to write: 375
 2022/04/13 11:40:13 [debug] 181#181: *34 SSL_write: 375
 2022/04/13 11:40:13 [debug] 181#181: *34 http write filter 0000000000000000
 2022/04/13 11:40:13 [debug] 181#181: *34 http copy filter: 0 "/error/403.json?"
 2022/04/13 11:40:13 [debug] 181#181: *34 http finalize request: 0, "/error/403.json?" a:1, c:2
 2022/04/13 11:40:13 [debug] 181#181: *34 http request count:2 blk:0
 2022/04/13 11:40:13 [debug] 181#181: *34 http finalize request: -4, "/error/403.json?" a:1, c:1
 2022/04/13 11:40:13 [debug] 181#181: *34 set http keepalive handler
 2022/04/13 11:40:13 [debug] 181#181: *34 http close request
 2022/04/13 11:40:13 [debug] 181#181: *34 http log handler
 2022/04/13 11:40:13 [debug] 181#181: *34 posix_memalign: 00000000039A2A80:4096 @16
 2022/04/13 11:40:13 [debug] 181#181: *34 malloc: 00000000039A3A90:4096
 2022/04/13 11:40:13 [debug] 181#181: *34 malloc: 0000000003A71420:4096
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 00000000039A3A90
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 0000000003A71420
 2022/04/13 11:40:13 [debug] 181#181: *34 malloc: 00000000039A3A90:4096
 2022/04/13 11:40:13 [debug] 181#181: *34 malloc: 0000000003A71420:4096
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 00000000039A3A90
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 0000000003A71420
 2022/04/13 11:40:13 [debug] 181#181: *34 malloc: 00000000039A3A90:4096
 2022/04/13 11:40:13 [debug] 181#181: *34 malloc: 0000000003A71420:4096
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 00000000039A3A90
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 0000000003A71420
 2022/04/13 11:40:13 [debug] 181#181: *34 http script var: "181"
 2022/04/13 11:40:13 [debug] 181#181: *34 http script var: "xxx.xxx.xxx.xxx"
 2022/04/13 11:40:13 [debug] 181#181: *34 http script copy: ":"
 2022/04/13 11:40:13 [debug] 181#181: *34 http script var: "62919"
 2022/04/13 11:40:13 [debug] 181#181: *34 http script var: "GET"
 2022/04/13 11:40:13 [debug] 181#181: *34 http script var: "https"
 2022/04/13 11:40:13 [debug] 181#181: *34 http script copy: "://"
 2022/04/13 11:40:13 [debug] 181#181: *34 http script var: "test.local"
 2022/04/13 11:40:13 [debug] 181#181: *34 http script var: "/v1/intranet/public/uploads/2653"
 2022/04/13 11:40:13 [debug] 181#181: *34 http script var: "test.local"
 2022/04/13 11:40:13 [debug] 181#181: *34 http script var: "GET"
 2022/04/13 11:40:13 [debug] 181#181: *34 http script copy: " "
 2022/04/13 11:40:13 [debug] 181#181: *34 http script var: "/error/403.json"
 2022/04/13 11:40:13 [debug] 181#181: *34 http script var: "181"
 2022/04/13 11:40:13 [debug] 181#181: *34 http script var: "xxx.xxx.xxx.xxxx"
 2022/04/13 11:40:13 [debug] 181#181: *34 http script copy: ":"
 2022/04/13 11:40:13 [debug] 181#181: *34 http script var: "62919"
 2022/04/13 11:40:13 [debug] 181#181: *34 http script var: "GET"
 2022/04/13 11:40:13 [debug] 181#181: *34 http script var: "https"
 2022/04/13 11:40:13 [debug] 181#181: *34 http script copy: "://"
 2022/04/13 11:40:13 [debug] 181#181: *34 http script var: "test.local"
 2022/04/13 11:40:13 [debug] 181#181: *34 http script var: "/v1/intranet/public/uploads/2653"
 2022/04/13 11:40:13 [debug] 181#181: *34 http script var: "test.local"
 2022/04/13 11:40:13 [debug] 181#181: *34 http script var: "GET"
 2022/04/13 11:40:13 [debug] 181#181: *34 http script copy: " "
 2022/04/13 11:40:13 [debug] 181#181: *34 http script var: "/error/403.json"
 2022/04/13 11:40:13 [debug] 181#181: *34 run cleanup: 000000000393B5D8
 2022/04/13 11:40:13 [debug] 181#181: *34 file cleanup: fd:20
 2022/04/13 11:40:13 [debug] 181#181: *34 run cleanup: 000000000393A9B0
 2022/04/13 11:40:13 [debug] 181#181: *34 run cleanup: 00000000038C9C88
 2022/04/13 11:40:13 [debug] 181#181: *34 file cleanup: fd:17 /usr/local/nginx/client_body_temp/0000000006
 2022/04/13 11:40:13 [debug] 181#181: *34 run cleanup: 00000000038C99A8
 2022/04/13 11:40:13 [debug] 181#181: *34 run cleanup: 00000000038D9130
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 0000000000000000
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 0000000000000000
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 0000000000000000
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 0000000000000000
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 00000000038CE840
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 00000000038D8150, unused: 0
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 00000000038C9580, unused: 2
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 000000000393A710, unused: 0
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 0000000003999010, unused: 2
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 00000000039A2A80, unused: 1032
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 00000000038BADC0
 2022/04/13 11:40:13 [debug] 181#181: *34 hc free: 0000000000000000
 2022/04/13 11:40:13 [debug] 181#181: *34 hc busy: 00000000038D6D10 1
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 00000000038D9300
 2022/04/13 11:40:13 [debug] 181#181: *34 free: 000000000399EA70
 2022/04/13 11:40:13 [debug] 181#181: *34 reusable connection: 1
 2022/04/13 11:40:13 [debug] 181#181: *34 event timer add: 3: 20000:1924828320
 2022/04/13 11:40:13 [debug] 181#181: *34 http empty handler
 2022/04/13 11:40:14 [debug] 181#181: *34 delete posted event 00000000037E3960
 2022/04/13 11:40:14 [debug] 181#181: *34 http keepalive handler
 2022/04/13 11:40:14 [debug] 181#181: *34 malloc: 00000000038BADC0:1024
 2022/04/13 11:40:14 [debug] 181#181: *34 SSL_read: -1
 2022/04/13 11:40:14 [debug] 181#181: *34 SSL_get_error: 2
 2022/04/13 11:40:14 [debug] 181#181: *34 free: 00000000038BADC0
 2022/04/13 11:40:16 [info] 181#181: *35 client closed connection while waiting for request, client: xxx.xxx.xxx.xxx, server: 0.0.0.0:443
 2022/04/13 11:40:33 [debug] 181#181: *34 event timer del: 3: 1924828320
 2022/04/13 11:40:33 [debug] 181#181: *34 http keepalive handler
 2022/04/13 11:40:33 [debug] 181#181: *34 close http connection: 3
 2022/04/13 11:40:33 [debug] 181#181: *34 SSL_shutdown: 1
 2022/04/13 11:40:33 [debug] 181#181: *34 reusable connection: 0
 2022/04/13 11:40:33 [debug] 181#181: *34 free: 0000000000000000
 2022/04/13 11:40:33 [debug] 181#181: *34 free: 0000000000000000
 2022/04/13 11:40:33 [debug] 181#181: *34 free: 0000000000000000
 2022/04/13 11:40:33 [debug] 181#181: *34 free: 00000000038D79A0, unused: 8

Marcello

martinhsv commented 2 years ago

Hello @cello86 ,

I'm not sure I understand what you are asserting here and for what purpose.

The reason this issue was closed was because a POST being transformed into a GET due to an error redirect is expected behaviour in nginx.

cello86 commented 2 years ago

Hi @martinhsv on our config we don't have an internal redirect that permits to match the 403 condition reported in these rows:

 2022/04/13 11:40:13 [debug] 181#181: *34 http finalize request: 403, "/v1/intranet/public/uploads/2653?" a:1, c:1
 2022/04/13 11:40:13 [debug] 181#181: *34 http special response: 403, "/v1/intranet/public/uploads/2653?"
 2022/04/13 11:40:13 [debug] 181#181: *34 internal redirect: "/error/403.json?"

Could it be mod_security matching rule?

On modsec_audit.log we noticed that all warning were created by the GET method:

---gZt2p6sB---H--
ModSecurity: Warning. Matched "Operator `BeginsWith' with parameter `/' against variable `REQUEST_URI' (Value: `/v1/intranet/public/uploads/2663' ) [file "<<reference missing or not informed>>"] [line "1"] [id "1"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "172.17.0.2"] [uri "/v1/intranet/public/uploads/2663"] [unique_id "1649856272"] [ref
"o0,1v4,32"]
ModSecurity: Warning. Matched "Operator `Rx' with parameter `^0?$' against variable `REQUEST_HEADERS:Content-Length' (Value: `142336' ) [file "/usr/local/nginx/conf/crs-rules/REQUEST-920-PROTOCOL-ENFORCEMENT.conf"] [line "161"] [id "920170"] [rev ""] [msg "GET or HEAD Request with Body Content."] [data "142336"] [severity "2"] [ver "OWASP_CRS/3.2.0"] [maturity "0"] [accuracy "0"] [tag "app
lication-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-protocol"] [tag "OWASP_CRS"] [tag "OWASP_CRS/PROTOCOL_VIOLATION/INVALID_HREQ"] [tag "CAPEC-272"] [hostname "172.17.0.2"] [uri "/v1/intranet/public/uploads/2663"] [unique_id "1649856272"] [ref "o0,3v0,3v117,6"]
ModSecurity: Warning. Matched "Operator `Rx' with parameter `^application/x-www-form-urlencoded|multipart/form-data|text/xml|application/xml|application/soap+xml|application/x-amf|application/json|application/octet-stream|application/csp-report|application/xss- (26 characters omitted)' against variable `TX:0' (Value: `application/offset+octet-stream' ) [file "/usr/local/nginx/conf/crs-rule
s/REQUEST-920-PROTOCOL-ENFORCEMENT.conf"] [line "894"] [id "920420"] [rev ""] [msg "Request content type is not allowed by policy"] [data "application/offset+octet-stream"] [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/POLICY/CONTENT_TYPE_
NOT_ALLOWED"] [tag "WASCTC/WASC-20"] [tag "OWASP_TOP_10/A1"] [tag "OWASP_AppSensor/EE2"] [tag "PCI/12.1"] [hostname "172.17.0.2"] [uri "/v1/intranet/public/uploads/2663"] [unique_id "1649856272"] [ref "o0,31v374,31"]
ModSecurity: Warning. Matched "Operator `Rx' with parameter `(?i)(?:\x5c|(?:%(?:c(?:0%(?:[2aq]f|5c|9v)|1%(?:[19p]c|8s|af))|2(?:5(?:c(?:0%25af|1%259c)|2f|5c)|%46|f)|(?:(?:f(?:8%8)?0%8|e)0%80%a|bg%q)f|%3(?:2(?:%(?:%6|4)6|F)|5%%63)|u(?:221[56]|002f|EFC8|F025)|1u|5 (400 characters omitted)' against variable `REQUEST_BODY' (Value: `\xd0\xcf\x11\xe0\xa1\xb1\x1a\xe1\x00\x00\x00\x00\x00\x00\x00\x0
0\x00\x00\x00\x00\x00\x00\x00\x00>\x0 (412452 characters omitted)' ) [file "/usr/local/nginx/conf/crs-rules/REQUEST-930-APPLICATION-ATTACK-LFI.conf"] [line "29"] [id "930100"] [rev ""] [msg "Path Traversal Attack (/../)"] [data "Matched Data: /.?/ found within REQUEST_BODY: \xd0\xcf\x11\xe0\xa1\xb1\x1a\xe1\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00>\x00\x03\x00\xfe\xff
\x09\x00\x06\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x10\x00\x00\x02\x00\x00\x00\x04\x00\x00\x00\xfe\xff\xff\xff\x00\x00\x00\x00\x00\x00\x00\x00`\x00\x00\x00\x00\x01\x00\x00\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xf
f\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff (142182 characters omitted)"] [severity "2"] [ver "OWASP_CRS/3.2.0"] [maturity "0"] [accuracy "0"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-lfi"] [tag "OWASP_CRS"] [tag "OWASP_CRS/WEB_ATTACK/DIR_TRAVERSAL"] [hostname "172.17.0.2"] [uri "/v1/intra
net/public/uploads/2663"] [unique_id "1649856272"] [ref "o81205,4v1456,142336"]
ModSecurity: Warning. Matched "Operator `Ge' with parameter `5' against variable `TX:ANOMALY_SCORE' (Value: `15' ) [file "/usr/local/nginx/conf/crs-rules/REQUEST-949-BLOCKING-EVALUATION.conf"] [line "79"] [id "949110"] [rev ""] [msg "Inbound Anomaly Score Exceeded (Total Score: 15)"] [data ""] [severity "2"] [ver ""] [maturity "0"] [accuracy "0"] [tag "application-multi"] [tag "language-mu
lti"] [tag "platform-multi"] [tag "attack-generic"] [hostname "172.17.0.2"] [uri "/v1/intranet/public/uploads/2663"] [unique_id "1649856272"] [ref ""]

If we disable the SecRequestBodyAccess parameter the POST action passes without issues.

Marcello

theseion commented 2 years ago

It looks like the same issue. But I can only reiterate what @martinhsv has already written: it's NGINX, not ModSecurity. What you need is an NGiNX configuration that catches error responses before they are handled internally, like I have done in my workaround above.

The only other option you have is to disable ModSecurity / CRS stuff, which you definitely shouldn't.

/error/403.json doesn't look like NGiNX native error handling to me. Are you sure you don't have a rule that handles errors or ends the request with 403?

cello86 commented 2 years ago

@theseion we have already implemented the suggestion:

error_page 403 /error/403.json;

location ^~ /error {
    modsecurity_rules 'SecRule REQUEST_URI "@beginsWith /" "id:1,pass,phase:2,log,ctl:ruleEngine=DetectionOnly"';
    alias "/usr/local/nginx/error";
     sub_filter_types application/json;
     sub_filter_once off;
     sub_filter 'request_id' '$request_id';
}
theseion commented 2 years ago

It has been a long time since I wrote the workaround, so I have to do some guessing here. What I notice is that your location above does not use return. I think that could be (part of) the issue. The underlying bug is caused by redirect code and return prevents the redirect (and returns immediately), from what I recall.

zffocussss commented 2 years ago

still confused