Closed jcchavezs closed 11 months ago
First of all, thanks @dspeg for reporting this. What you are experiencing comes from a conceptually different behavior on how the request is handled by Envoy. Envoy:
OnHttpRequestBody
is never called. This is something that happens in your case. Even if you have SecRequestBodyAccess Off
, if OnHttpRequestBody
would have been called, phase 2 rules would have been executed (with the variables available, not including of course the body itself), and a debug message would have been printed. See this code. Not seeing this message, I think that indeed your request does not have a boy, so phase:2 is just executed when is "too late", during OnHttpResponseHeaders
. Please, take a look here. Your interruption log that reports phase "http_response_headers"
confirms that.In order to handle this problem we are mainly taking into account the following ideas:
OnHttpRequestHeaders
when no body is present. https://github.com/corazawaf/coraza-proxy-wasm/pull/128. This might not cover all the cases (especially because of Chunked encoding), but it can come in handy.944150
comes with the following variables REQUEST_LINE|ARGS|ARGS_NAMES|REQUEST_COOKIES|REQUEST_COOKIES_NAMES|REQUEST_HEADERS|XML:/*|XML://@*
. Based on this mapping we know that, for example, REQUEST_HEADERS
will be definitely read at phase:1 while XML
at phase:2. Therefore REQUEST_HEADERS
evaluation will be anticipated to phase:1, while for the XML
variables, we will wait for phase:2.
What we are aiming for is to inspect all data that has been received so far as soon as possible to be able to say that, up to this point, they are "inspected and good to go". This, in conjunction with the early blocking
CRS feature (https://github.com/corazawaf/coraza-proxy-wasm/pull/129), permits to effectively raise the anomaly score and eventually drop the request already at phase:1, before sending anything upstream.
It is experimental and it comes with complexity and not trivial corner cases, but in the last month, I think we made nice progress.
To learn more about it:
Any early feedback, comment, or idea is very welcome!
More background info regarding the original issue:
I did another round of testing. Note that I'm using a Wasm file built from a snapshot of the coraza-proxy-wasm project, with latest commit on Feb. 16, 2023.
Below are the logs:
2023-04-13T22:47:01.814995Z debug envoy wasm wasm log istio-system.coraza-wasm: skipping request body inspection, SecRequestBodyAccess is off.
2023-04-13T22:47:01.814998Z debug envoy wasm wasm log istio-system.coraza-wasm: [lSrpZLlKiPoRuIBvZbA] Evaluating phase 2
2023-04-13T22:47:01.815002Z debug envoy wasm wasm log istio-system.coraza-wasm: [lSrpZLlKiPoRuIBvZbA] [201] Evaluating rule 201
...
...
2023-04-13T22:47:01.815339Z debug envoy wasm wasm log istio-system.coraza-wasm: [lSrpZLlKiPoRuIBvZbA] [201] Disrupting transaction by rule 201
2023-04-13T22:47:01.815341Z debug envoy wasm wasm log istio-system.coraza-wasm: [lSrpZLlKiPoRuIBvZbA] [201] Evaluating action deny for rule 201
2023-04-13T22:47:01.815342Z debug envoy wasm wasm log istio-system.coraza-wasm: [lSrpZLlKiPoRuIBvZbA] rule 201 matched
2023-04-13T22:47:01.815362Z critical envoy wasm wasm log istio-system.coraza-wasm: [client "10.244.0.1"] Coraza: Warning. Dummy pattern blocking, rule 201 [file ""] [line "0"] [id "201"] [rev ""] [msg "Dummy pattern blocking, rule 201"] [data ""] [severity "emergency"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "10.244.67.237"] [uri "/sample-dotnet/v1.0/?param=attack_pattern_1"] [unique_id "lSrpZLlKiPoRuIBvZbA"]
[client "10.244.0.1"] Coraza: Warning. Dummy pattern blocking, rule 201 [file ""] [line "0"] [id "201"] [rev ""] [msg "Dummy pattern blocking, rule 201"] [data ""] [severity "emergency"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "10.244.67.237"] [uri "/sample-dotnet/v1.0/?param=attack_pattern_1"] [unique_id "lSrpZLlKiPoRuIBvZbA"]
[client "10.244.0.1"] Coraza: Warning. Dummy pattern blocking, rule 201 [file ""] [line "0"] [id "201"] [rev ""] [msg "Dummy pattern blocking, rule 201"] [data ""] [severity "emergency"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "10.244.67.237"] [uri "/sample-dotnet/v1.0/?param=attack_pattern_1"] [unique_id "lSrpZLlKiPoRuIBvZbA"]
2023-04-13T22:47:01.815380Z debug envoy wasm wasm log istio-system.coraza-wasm: [lSrpZLlKiPoRuIBvZbA] [201] Finish evaluating rule 201
2023-04-13T22:47:01.815383Z debug envoy wasm wasm log istio-system.coraza-wasm: [lSrpZLlKiPoRuIBvZbA] Finished phase 2
2023-04-13T22:47:01.815389Z info envoy wasm wasm log istio-system.coraza-wasm: 10 interrupted, action "deny", phase "http_request_body"
2023-04-13T22:47:01.815397Z debug envoy http [C1106807][S3828747809941241759] Sending local reply with details
2023-04-13T22:47:01.815417Z error envoy wasm wasm log istio-system.coraza-wasm: interruption already handled, unexpected local response
2023-04-13T22:47:01.815439Z debug envoy http [C1106807][S3828747809941241759] request end stream
2023-04-13T22:47:01.815955Z debug envoy client [C1106771] response complete
2023-04-13T22:47:01.815987Z debug envoy router [C1106807][S3828747809941241759] upstream headers complete: end_stream=true
2023-04-13T22:47:01.816011Z debug envoy router [C1106807][S3828747809941241759] resetting pool request
2023-04-13T22:47:01.816046Z error envoy wasm wasm log istio-system.coraza-wasm: interruption already handled, unexpected local response
After I sent "ctrl-c" to "curl", I saw additional logs:
2023-04-13T22:47:15.462786Z debug envoy connection [C1106815] closing data_to_write=143 type=0
2023-04-13T22:47:15.462805Z debug envoy connection [C1106815] setting delayed close timer with timeout 1000 ms
2023-04-13T22:47:15.462813Z debug envoy pool [C6] response complete
2023-04-13T22:47:15.462830Z debug envoy pool [C6] destroying stream: 0 remaining
2023-04-13T22:47:15.462884Z debug envoy connection [C1106815] write flush complete
2023-04-13T22:47:15.462904Z debug envoy connection [C1106815] closing socket: 1
2023-04-13T22:47:15.462924Z debug envoy conn_handler [C1106815] adding to cleanup list
2023-04-13T22:47:16.702398Z debug envoy connection [C1106807] remote close
2023-04-13T22:47:16.702426Z debug envoy connection [C1106807] closing socket: 0
2023-04-13T22:47:16.702465Z debug envoy connection [C1106807] SSL shutdown: rc=1
2023-04-13T22:47:16.702484Z debug envoy http [C1106807][S3828747809941241759] stream reset
2023-04-13T22:47:16.702658Z error envoy wasm wasm log istio-system.coraza-wasm: Calling ProcessResponseBody but there is a preexisting interruption
2023-04-13T22:47:16.702682Z debug envoy wasm wasm log istio-system.coraza-wasm: [lSrpZLlKiPoRuIBvZbA] Evaluating phase 5
2023-04-13T22:47:16.702691Z debug envoy wasm wasm log istio-system.coraza-wasm: [lSrpZLlKiPoRuIBvZbA] [0] Evaluating rule 0
2023-04-13T22:47:16.702695Z debug envoy wasm wasm log istio-system.coraza-wasm: [lSrpZLlKiPoRuIBvZbA] [0] Forcing rule 0 to match
2023-04-13T22:47:16.702699Z debug envoy wasm wasm log istio-system.coraza-wasm: [lSrpZLlKiPoRuIBvZbA] [0] Disrupting transaction by rule 0
2023-04-13T22:47:16.702700Z debug envoy wasm wasm log istio-system.coraza-wasm: [lSrpZLlKiPoRuIBvZbA] [0] Finish evaluating rule 0
2023-04-13T22:47:16.702702Z debug envoy wasm wasm log istio-system.coraza-wasm: [lSrpZLlKiPoRuIBvZbA] Finished phase 5
2023-04-13T22:47:16.702704Z debug envoy wasm wasm log istio-system.coraza-wasm: [lSrpZLlKiPoRuIBvZbA] Transaction marked for audit logging
2023-04-13T22:47:16.702731Z debug envoy wasm wasm log istio-system.coraza-wasm: [lSrpZLlKiPoRuIBvZbA] Transaction finished, disrupted: true
2023-04-13T22:47:16.702748Z info envoy wasm wasm log istio-system.coraza-wasm: 10 finished
After removing the config "SecRequestBodyAccess Off", I can still reproduce the problem.
Let's dig into it.
The to-be-denied request is "POST", with a request body, sent by "curl".
We can expect a curl request like: curl -XPOST 'http://localhost:8080/' -H "foo:maliciousheader" --data "test data"
The blocking rule is in Phase 2 There is still
SecRequestBodyAccess Off
or theSecRequestBodyAccess
directive is not added (So by default it is anywaysOff
)
We don't care about body access, therefore I'm guessing that the rule that we are running is checking something related to phase:1 (e.g. REQUEST_HEADERS or get ARGS) So, we can have a config like this:
"rules": [
"SecRuleEngine On",
"SecDebugLogLevel 9",
"SecRule REQUEST_HEADERS \"@rx maliciousheader\" \"id:102,phase:2,t:lowercase,deny,status:403\""
]
Request Lifecycle:
OnHttpRequestHeaders
callback is triggered. Phase 1
is executed, but no rules are in place. Following the Envoy streaming logic, the headers are already streamed upstream, so the application receives them.--data "test data"
), therefore OnHttpRequestBody
callback is triggered. The request body is not accessible. The callback logs Skipping request body inspection, SecRequestBodyAccess is off.
, but still proceeds to evaluate all the already populated variables (of course excluding the body itself). At this point, we have the match:
MATCH tx_id="..." rule_id=102 operator_function="@rx" operator_data="maliciousheader" arg="maliciousheader"
, the disruptive deny action is executed and the transaction is interrupted: Transaction interrupted tx_id="..." context_id=3 action="deny" phase="http_request_body"
. The client receives back a 403
, while the application detects a connection that has been closed with an unexpected EOF:
2023/04/14 10:23:05 POST /
> User-Agent: curl/7.87.0
> Foo: maliciousheader
> Content-Length: 5
> Content-Type: application/x-www-form-urlencoded
> X-Request-Id: 1ad85595-15e8-4f53-923a-af13c4973274
> X-Envoy-Expected-Rq-Timeout-Ms: 15000
> X-Forwarded-Proto: http
2023/04/14 11:23:05 failed to read request body: unexpected EOF
It happens because during phase 1 we already had elements that could have been evaluated, but it actually not happened, because the rule was expected to be executed only in phase 2. In the meanwhile, Envoy already started the connection to the application and started to stream data.
This is exactly the use-case that we are targeting with the MultiPhase evaluation, even if "SecRule REQUEST_HEADERS \"@rx maliciousheader\" \"id:102,phase:2,t:lowercase,deny,status:403\"
is set to be fired at phase:2, we are aware that the REQUEST_HEADERS
variable is already available at phase:1, therefore it is anticipated, the interruption is triggered at http_request_header phase (phase 1) and upstream does not receive any data.
And no response is sent back to "curl".
About this point, seeing the log line interruption already handled, unexpected local response
, I really think you are experiencing the same issue you reported https://github.com/corazawaf/coraza/discussions/594. Would be great if you could also run here the more verbose coraza-proxy-wasm to dump the response headers. The more we collect the more we are able to correct it in an optimal way.
Thank you so much for going into the details to explain the issue!
I will run the testing suggested.
This is exactly the use-case that we are targeting with the MultiPhase evaluation, even if "SecRule REQUEST_HEADERS \"@rx maliciousheader\" \"id:102,phase:2,t:lowercase,deny,status:403\" is set to be fired at phase:2, we are aware that the REQUEST_HEADERS variable is already available at phase:1, therefore it is anticipated, the interruption is triggered at http_request_header phase (phase 1) and upstream does not receive any data.
I see a Multi Phase evaluation PR mentioned had been merged in Jan. 2023. We need more changes to support this feature? Since my Wasm file was built in Feb. 2023, and multi phase evaluation is not working properly.
The suggested change to add "tx.early_blocking=1" to rule config should help some other cases. But it does not help my test case, and this is expected.
I have dumped more response headers using the provided wasm file. Still no response is received by "curl".
2023-04-14T17:24:25.505020Z debug envoy wasm wasm log istio-system.coraza-wasm: skipping request body inspection, SecRequestBodyAccess is off.
2023-04-14T17:24:25.505046Z debug envoy wasm wasm log istio-system.coraza-wasm: [ajTHFIvXwSeKniCNuRi] Evaluating phase 2
2023-04-14T17:24:25.505052Z debug envoy wasm wasm log istio-system.coraza-wasm: [ajTHFIvXwSeKniCNuRi] [201] Evaluating rule 201
...
...
2023-04-14T17:24:25.505598Z debug envoy wasm wasm log istio-system.coraza-wasm: [ajTHFIvXwSeKniCNuRi] [201] Disrupting transaction by rule 201
2023-04-14T17:24:25.505600Z debug envoy wasm wasm log istio-system.coraza-wasm: [ajTHFIvXwSeKniCNuRi] [201] Evaluating action deny for rule 201
2023-04-14T17:24:25.505601Z debug envoy wasm wasm log istio-system.coraza-wasm: [ajTHFIvXwSeKniCNuRi] rule 201 matched
2023-04-14T17:24:25.505619Z critical envoy wasm wasm log istio-system.coraza-wasm: [client "10.244.0.1"] Coraza: Warning. Dummy pattern blocking, rule 201 [file ""] [line "0"] [id "201"] [rev ""] [msg "Dummy pattern blocking, rule 201"] [data ""] [severity "emergency"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "10.244.67.237"] [uri "/sample-dotnet/v1.0/attack_pattern_1"] [unique_id "ajTHFIvXwSeKniCNuRi"]
[client "10.244.0.1"] Coraza: Warning. Dummy pattern blocking, rule 201 [file ""] [line "0"] [id "201"] [rev ""] [msg "Dummy pattern blocking, rule 201"] [data ""] [severity "emergency"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "10.244.67.237"] [uri "/sample-dotnet/v1.0/attack_pattern_1"] [unique_id "ajTHFIvXwSeKniCNuRi"]
2023-04-14T17:24:25.505638Z debug envoy wasm wasm log istio-system.coraza-wasm: [ajTHFIvXwSeKniCNuRi] [201] Finish evaluating rule 201
2023-04-14T17:24:25.505641Z debug envoy wasm wasm log istio-system.coraza-wasm: [ajTHFIvXwSeKniCNuRi] Finished phase 2
2023-04-14T17:24:25.505837Z info envoy wasm wasm log istio-system.coraza-wasm: 9 interrupted, action "deny", phase "http_request_body"
2023-04-14T17:24:25.505862Z debug envoy http [C1145970][S18915379674551781] Sending local reply with details
2023-04-14T17:24:25.505883Z error envoy wasm wasm log istio-system.coraza-wasm: interruption already handled, unexpected local response
2023-04-14T17:24:25.505888Z error envoy wasm wasm log istio-system.coraza-wasm: Dumping Added Response header: :status|444
2023-04-14T17:24:25.505892Z error envoy wasm wasm log istio-system.coraza-wasm: Dumping Added Response header: x-envoy-peer-metadata|CjgKDkFQUF9DT05UQUlORVJTEiYaJHNhbXBsZS1kb3RuZXQsbWljcm9zZXJ2aWNlLWNvbGxlY3RvcgoaCgpDTFVTVEVSX0lEEgwaCkt1YmVybmV0ZXMKHwoMSU5TVEFOQ0VfSVBTEg8aDTEwLjI0NC42Ny4yMzcKKAoNSVNUSU9fVkVSU0lPThIXGhUxLjE0LjQtdGV0cmF0ZWZpcHMtdjAK9gIKBkxBQkVMUxLrAiroAgoWCgNhcHASDxoNc2FtcGxlLWRvdG5ldAotChphcHAua3ViZXJuZXRlcy5pby9pbnN0YW5jZRIPGg1zYW1wbGUtZG90bmV0CikKFmFwcC5rdWJlcm5ldGVzLmlvL25hbWUSDxoNc2FtcGxlLWRvdG5ldAoqChpyb2xsb3V0cy1wb2QtdGVtcGxhdGUtaGFzaBIMGgo1ZDQ0Njg2OGQ3CiQKGXNlY3VyaXR5LmlzdGlvLmlvL3Rsc01vZGUSBxoFaXN0aW8KMgofc2VydmljZS5pc3Rpby5pby9jYW5vbmljYWwtbmFtZRIPGg1zYW1wbGUtZG90bmV0Ci8KI3NlcnZpY2UuaXN0aW8uaW8vY2Fub25pY2FsLXJldmlzaW9uEggaBmxhdGVzdAo9ChNza2FmZm9sZC5kZXYvcnVuLWlkEiYaJGJhZmU1NDdkLWIxYTctNDg1My04ZTIzLWUyMGM4N2M4YTg0NgoaCgdNRVNIX0lEEg8aDWNsdXN0ZXIubG9jYWwKKAoETkFNRRIgGh5zYW1wbGUtZG90bmV0LTVkNDQ2ODY4ZDctbThjcGYKFQoJTkFNRVNQQUNFEggaBnNhbXBsZQpbCgVPV05FUhJSGlBrdWJlcm5ldGVzOi8vYXBpcy9hcHBzL3YxL25hbWVzcGFjZXMvc2FtcGxlL3JlcGxpY2FzZXRzL3NhbXBsZS1kb3RuZXQtNWQ0NDY4NjhkNwoXChFQTEFURk9STV9NRVRBREFUQRICKgAKKwoNV09SS0xPQURfTkFNRRIaGhhzYW1wbGUtZG90bmV0LTVkNDQ2ODY4ZDc=
2023-04-14T17:24:25.505893Z error envoy wasm wasm log istio-system.coraza-wasm: Dumping Added Response header: x-envoy-peer-metadata-id|sidecar~10.244.67.237~sample-dotnet-5d446868d7-m8cpf.sample~sample.svc.cluster.local
2023-04-14T17:24:25.505898Z debug envoy http [C1145970][S18915379674551781] request end stream
2023-04-14T17:24:25.505925Z debug envoy connection [C1145971] connected
2023-04-14T17:24:25.505943Z debug envoy client [C1145971] connected
2023-04-14T17:24:25.505948Z debug envoy pool [C1145971] attaching to next stream
2023-04-14T17:24:25.505951Z debug envoy pool [C1145971] creating stream
2023-04-14T17:24:25.505955Z debug envoy router [C1145970][S18915379674551781] pool ready
2023-04-14T17:24:25.506360Z debug envoy client [C1145971] response complete
2023-04-14T17:24:25.506389Z debug envoy router [C1145970][S18915379674551781] upstream headers complete: end_stream=true
2023-04-14T17:24:25.506404Z debug envoy router [C1145970][S18915379674551781] resetting pool request
2023-04-14T17:24:25.506424Z error envoy wasm wasm log istio-system.coraza-wasm: interruption already handled, unexpected local response
2023-04-14T17:24:25.506452Z error envoy wasm wasm log istio-system.coraza-wasm: Dumping Added Response header: :status|404
2023-04-14T17:24:25.506456Z error envoy wasm wasm log istio-system.coraza-wasm: Dumping Added Response header: content-length|0
2023-04-14T17:24:25.506458Z error envoy wasm wasm log istio-system.coraza-wasm: Dumping Added Response header: date|Fri, 14 Apr 2023 17:24:24 GMT
2023-04-14T17:24:25.506459Z error envoy wasm wasm log istio-system.coraza-wasm: Dumping Added Response header: server|Kestrel
2023-04-14T17:24:25.506462Z error envoy wasm wasm log istio-system.coraza-wasm: Dumping Added Response header: x-envoy-peer-metadata|CjgKDkFQUF9DT05UQUlORVJTEiYaJHNhbXBsZS1kb3RuZXQsbWljcm9zZXJ2aWNlLWNvbGxlY3RvcgoaCgpDTFVTVEVSX0lEEgwaCkt1YmVybmV0ZXMKHwoMSU5TVEFOQ0VfSVBTEg8aDTEwLjI0NC42Ny4yMzcKKAoNSVNUSU9fVkVSU0lPThIXGhUxLjE0LjQtdGV0cmF0ZWZpcHMtdjAK9gIKBkxBQkVMUxLrAiroAgoWCgNhcHASDxoNc2FtcGxlLWRvdG5ldAotChphcHAua3ViZXJuZXRlcy5pby9pbnN0YW5jZRIPGg1zYW1wbGUtZG90bmV0CikKFmFwcC5rdWJlcm5ldGVzLmlvL25hbWUSDxoNc2FtcGxlLWRvdG5ldAoqChpyb2xsb3V0cy1wb2QtdGVtcGxhdGUtaGFzaBIMGgo1ZDQ0Njg2OGQ3CiQKGXNlY3VyaXR5LmlzdGlvLmlvL3Rsc01vZGUSBxoFaXN0aW8KMgofc2VydmljZS5pc3Rpby5pby9jYW5vbmljYWwtbmFtZRIPGg1zYW1wbGUtZG90bmV0Ci8KI3NlcnZpY2UuaXN0aW8uaW8vY2Fub25pY2FsLXJldmlzaW9uEggaBmxhdGVzdAo9ChNza2FmZm9sZC5kZXYvcnVuLWlkEiYaJGJhZmU1NDdkLWIxYTctNDg1My04ZTIzLWUyMGM4N2M4YTg0NgoaCgdNRVNIX0lEEg8aDWNsdXN0ZXIubG9jYWwKKAoETkFNRRIgGh5zYW1wbGUtZG90bmV0LTVkNDQ2ODY4ZDctbThjcGYKFQoJTkFNRVNQQUNFEggaBnNhbXBsZQpbCgVPV05FUhJSGlBrdWJlcm5ldGVzOi8vYXBpcy9hcHBzL3YxL25hbWVzcGFjZXMvc2FtcGxlL3JlcGxpY2FzZXRzL3NhbXBsZS1kb3RuZXQtNWQ0NDY4NjhkNwoXChFQTEFURk9STV9NRVRBREFUQRICKgAKKwoNV09SS0xPQURfTkFNRRIaGhhzYW1wbGUtZG90bmV0LTVkNDQ2ODY4ZDc=
2023-04-14T17:24:25.506464Z error envoy wasm wasm log istio-system.coraza-wasm: Dumping Added Response header: x-envoy-peer-metadata-id|sidecar~10.244.67.237~sample-dotnet-5d446868d7-m8cpf.sample~sample.svc.cluster.local
2023-04-14T17:24:25.506467Z debug envoy pool [C1145971] response complete
2023-04-14T17:24:25.506469Z debug envoy pool [C1145971] response before request complete
2023-04-14T17:24:25.506472Z debug envoy connection [C1145971] closing data_to_write=0 type=1
2023-04-14T17:24:25.506476Z debug envoy connection [C1145971] closing socket: 1
2023-04-14T17:24:25.506515Z debug envoy client [C1145971] disconnect. resetting 0 pending requests
2023-04-14T17:24:25.506539Z debug envoy pool [C1145971] client disconnected, failure reason:
2023-04-14T17:24:25.506545Z debug envoy pool invoking idle callbacks - is_draining_for_deletion_=false
2023-04-14T17:24:25.506556Z debug envoy pool [C1145971] destroying stream: 0 remaining
2023-04-14T17:24:26.824338Z debug envoy conn_handler [C1145972] new connection from 10.244.0.1:60138
I see a Multi Phase evaluation PR mentioned had been merged in Jan. 2023. We need more changes to support this feature? Since my Wasm file was built in Feb. 2023, and multi phase evaluation is not working properly.
Hi, I mainly pointed you all the PRs related to MultiPhase to give context about the ongoing work upstream (in the Coraza repo). A wasm file built in Feb. 2023 does not support multiphase, the feature has to be enabled at build time, and currently, it is not added in the main wasm build. You can find it under the multiphase branch: enabling it is a matter of providing an extra build tag with a recent Coraza version or, even better for experimental tests, pointing to the following PR: https://github.com/corazawaf/coraza/pull/719
Addressed by multiphase evaluation that is enabled by default (see #194)
Discussed in https://github.com/corazawaf/coraza/discussions/770