"deny" action still passes the request down the filter chain?

[dspeg]

I am testing the Coraza Wasm Plugin on Envoy/Istio. I set up a SecRule to block certain requests in Phase 2 along with the setting SecDefaultAction "phase:2,log,deny,status:403". When a request is blocked by this rule, the client gets back the expected status code "403". However the application protected by the Coraza WAF still receives the request and processes it. This is not expected.

I'm not sure whether I have misconfigured Envoy/Istio or I have missed some Coraza rules or configs. Please help troubleshoot this issue. Thanks!

[dspeg]

@M4tteoP Could you comment on this issue? Thank you very much.

[M4tteoP]

Hey @dspeg, yep, I will come asap (tomorrow) with an exhaustive reply. In the meanwhile, do you have a chance to see the debug logs? When is the interruption actually triggered? What I'm guessing is that the phase:2 rule is enforced only at phase:3 (http_response_headers) and not before. You should see a log line similar to:
[info][wasm] [source/extensions/common/wasm/context.cc:1175] wasm log coraza-filter my_vm_id: Transaction interrupted tx_id="tMxDZnjPwfzfvyefgHo" context_id=2 action="deny" phase="http_response_headers"
Thanks!

[dspeg]

Thank you!
I can find a similar log line:
2023-04-12T00:59:46.852609Z info envoy wasm wasm log istio-system.coraza-wasm: 300 interrupted, action "deny", phase "http_response_headers"

Below are the related log entries:

2023-04-12T00:59:46.852476Z     debug   envoy wasm      wasm log istio-system.coraza-wasm: [lsSOpAPWOlyTsvySPXW] rule 944150 matched
2023-04-12T00:59:46.852562Z     critical        envoy wasm      wasm log istio-system.coraza-wasm: [client "10.244.0.1"] Coraza: Warning. Potential Remote Command Execution: Log4j / Log4shell [file "@owasp_crs/REQUEST-944-APPLICATION-ATTACK-JAVA.conf"] [line "0"] [id "944150"] [rev ""] [msg "Potential Remote Command Execution: Log4j / Log4shell"] [data ""] [severity "critical"] [ver "OWASP_CRS/4.0.0-rc1"] [maturity "0"] [accuracy "0"] [tag "application-multi"] [tag "language-java"] [tag "platform-multi"] [tag "attack-rce"] [tag "OWASP_CRS"] [tag "capec/1000/152/137/6"] [tag "PCI/6.5.2"] [tag "paranoia-level/1"] [hostname "10.244.67.237"] [uri "/sample-dotnet/v1.0/?param=${jndi}"] [unique_id "lsSOpAPWOlyTsvySPXW"]
[client "10.244.0.1"] Coraza: Warning. Potential Remote Command Execution: Log4j / Log4shell [file "@owasp_crs/REQUEST-944-APPLICATION-ATTACK-JAVA.conf"] [line "0"] [id "944150"] [rev ""] [msg "Potential Remote Command Execution: Log4j / Log4shell"] [data ""] [severity "critical"] [ver "OWASP_CRS/4.0.0-rc1"] [maturity "0"] [accuracy "0"] [tag "application-multi"] [tag "language-java"] [tag "platform-multi"] [tag "attack-rce"] [tag "OWASP_CRS"] [tag "capec/1000/152/137/6"] [tag "PCI/6.5.2"] [tag "paranoia-level/1"] [hostname "10.244.67.237"] [uri "/sample-dotnet/v1.0/?param=${jndi}"] [unique_id "lsSOpAPWOlyTsvySPXW"]
[client "10.244.0.1"] Coraza: Warning. Potential Remote Command Execution: Log4j / Log4shell [file "@owasp_crs/REQUEST-944-APPLICATION-ATTACK-JAVA.conf"] [line "0"] [id "944150"] [rev ""] [msg "Potential Remote Command Execution: Log4j / Log4shell"] [data ""] [severity "critical"] [ver "OWASP_CRS/4.0.0-rc1"] [maturity "0"] [accuracy "0"] [tag "application-multi"] [tag "language-java"] [tag "platform-multi"] [tag "attack-rce"] [tag "OWASP_CRS"] [tag "capec/1000/152/137/6"] [tag "PCI/6.5.2"] [tag "paranoia-level/1"] [hostname "10.244.67.237"] [uri "/sample-dotnet/v1.0/?param=${jndi}"] [unique_id "lsSOpAPWOlyTsvySPXW"]

2023-04-12T00:59:46.852591Z     debug   envoy wasm      wasm log istio-system.coraza-wasm: [lsSOpAPWOlyTsvySPXW] [944150] Finish evaluating rule 944150
2023-04-12T00:59:46.852596Z     debug   envoy wasm      wasm log istio-system.coraza-wasm: [lsSOpAPWOlyTsvySPXW] Finished phase 2
2023-04-12T00:59:46.852609Z     info    envoy wasm      wasm log istio-system.coraza-wasm: 300 interrupted, action "deny", phase "http_response_headers"
2023-04-12T00:59:46.852627Z     debug   envoy http      [C1009340][S2484932781187557378] Sending local reply with details  directly to the encoder
2023-04-12T00:59:46.852662Z     debug   envoy http      [C1009340][S2484932781187557378] encoding headers via codec (end_stream=true):
':status', '403'
'date', 'Wed, 12 Apr 2023 00:59:46 GMT'
'server', 'istio-envoy'

2023-04-12T00:59:46.852943Z     error   envoy wasm      wasm log istio-system.coraza-wasm: Calling ProcessResponseBody but there is a preexisting interruption
2023-04-12T00:59:46.852980Z     debug   envoy wasm      wasm log istio-system.coraza-wasm: [lsSOpAPWOlyTsvySPXW] Evaluating phase 5
2023-04-12T00:59:46.852991Z     debug   envoy wasm      wasm log istio-system.coraza-wasm: [lsSOpAPWOlyTsvySPXW] [0] Evaluating rule 0
2023-04-12T00:59:46.852996Z     debug   envoy wasm      wasm log istio-system.coraza-wasm: [lsSOpAPWOlyTsvySPXW] [0] Forcing rule 0 to match
2023-04-12T00:59:46.852999Z     debug   envoy wasm      wasm log istio-system.coraza-wasm: [lsSOpAPWOlyTsvySPXW] [0] Disrupting transaction by rule 0
2023-04-12T00:59:46.853002Z     debug   envoy wasm      wasm log istio-system.coraza-wasm: [lsSOpAPWOlyTsvySPXW] [0] Finish evaluating rule 0
2023-04-12T00:59:46.853005Z     debug   envoy wasm      wasm log istio-system.coraza-wasm: [lsSOpAPWOlyTsvySPXW] Finished phase 5
2023-04-12T00:59:46.853008Z     debug   envoy wasm      wasm log istio-system.coraza-wasm: [lsSOpAPWOlyTsvySPXW] Transaction marked for audit logging
2023-04-12T00:59:46.853056Z     debug   envoy wasm      wasm log istio-system.coraza-wasm: [lsSOpAPWOlyTsvySPXW] Transaction finished, disrupted: true
2023-04-12T00:59:46.853081Z     info    envoy wasm      wasm log istio-system.coraza-wasm: 300 finished
2023-04-12T00:59:46.853174Z     debug   envoy wasm      wasm log stats_inbound stats_inbound: [extensions/stats/plugin.cc:645]::report() metricKey cache hit , stat=16
2023-04-12T00:59:46.853226Z     debug   envoy wasm      wasm log stats_inbound stats_inbound: [extensions/stats/plugin.cc:645]::report() metricKey cache hit , stat=18
2023-04-12T00:59:46.853231Z     debug   envoy wasm      wasm log stats_inbound stats_inbound: [extensions/stats/plugin.cc:645]::report() metricKey cache hit , stat=22
2023-04-12T00:59:46.853233Z     debug   envoy wasm      wasm log stats_inbound stats_inbound: [extensions/stats/plugin.cc:645]::report() metricKey cache hit , stat=26
2023-04-12T00:59:46.853249Z     debug   envoy router    [C1009340][S2484932781187557378] resetting pool request
2023-04-12T00:59:46.853256Z     debug   envoy client    [C1010491] request reset
2023-04-12T00:59:46.853263Z     debug   envoy connection        [C1010491] closing data_to_write=0 type=1
2023-04-12T00:59:46.853266Z     debug   envoy connection        [C1010491] closing socket: 1

Note that "SecRequestBodyAccess Off" is added to the Wasm config, as we are still testing the WAF.

[M4tteoP]

Great, thanks! I tried to write the reply sticking with these logs to make everything more immediate :)
To give it more visibility, I replied inside the issue that JC created starting from this discussion (in the coraza-proxy-wasm repo):
corazawaf/coraza-proxy-wasm#171 (comment)