No more processing in the WAF on Istio IngressGateway after Phase 1 rule triggered #594

dspeg · 2023-01-27T20:09:31Z

dspeg
Jan 27, 2023

I am testing the Coraza Waf WasmPlugin on an Istio Ingress Gateway. I added a dummy test rule in Phase 1 to block on certain parameter patterns. And I have SecDefaultAction "phase:1,log,deny,status:444" When the rule is triggered, it seems no more WAF processing happens after phase 1. Viewed from the client side, the server never returns any response.

When I changed the above rule to "Phase 2", the problem no longer reproduced. When I moved the above Coraza Waf WasmPlugin to an Istio side-car proxy, I didn't see the problem either.

From the Istio log, I found a line saying "error envoy wasm wasm log istio-system.modsecurity-wasm: interruption already handled, unexpected local response". Not sure whether this is related to the problem.

jptosso · 2023-01-27T20:18:12Z

jptosso
Jan 27, 2023
Maintainer

Hey! Unline ModSecurity, Coraza stops rule execution after interruption. Is this something we want to change? I don't see any good reason to continue evaluating rules, if there is a specific use case we could change it or create a configuration flag or directive

CC @fzipi @jcchavezs @anuraaga @M4tteoP

1 reply

jcchavezs Jan 27, 2023
Maintainer

I think @dspeg means that the server remains hanging without sending any response.

jcchavezs · 2023-01-27T20:46:47Z

jcchavezs
Jan 27, 2023
Maintainer

Interesting case. I wonder how does the request look like.

@M4tteoP could you please triage this?

0 replies

dspeg · 2023-01-27T21:28:03Z

dspeg
Jan 27, 2023
Author

@M4tteoP
Istio version used in my deployment:
control plane version: 1.14.4
data plane version: 1.14.4-tetratefips-v0 (5 proxies)

0 replies

M4tteoP · 2023-01-27T21:33:26Z

M4tteoP
Jan 27, 2023
Collaborator

Hey @dspeg! Glad to see you here :)
Thanks for the information, I will definitely try to reproduce it

0 replies

dspeg · 2023-01-27T22:08:07Z

dspeg
Jan 27, 2023
Author

Thank you Matteo!

0 replies

jcchavezs · 2023-01-30T09:49:45Z

jcchavezs
Jan 30, 2023
Maintainer

I had a WIP around e2e in istio but did not finish it, these e2e aim to triage this kind of issues. Maybe it is time to rework it? corazawaf/coraza-proxy-wasm#80

0 replies

M4tteoP · 2023-02-01T15:21:14Z

M4tteoP
Feb 1, 2023
Collaborator

Hi @dspeg, I'm on this issue. By any chance, could you please reproduce it with the following slightly modified coraza-proxy-wasm and report the Istio logs back? You may build it from this branch, or, for your convenience, directly retrieve the wasm filter from oci://docker.io/deltag/coraza-proxy-wasm:vheaders.
I'm expecting a log similar to the following:

error	envoy wasm	wasm log istio-system.waf-ingress: interruption already handled, unexpected local response
error	envoy wasm	wasm log istio-system.waf-ingress: Dumping Added Response header: :status|434
error	envoy wasm	wasm log istio-system.waf-ingress: Dumping Added Response header: test|true

In your deployment, it seems that the IngressGateway is adding some headers to the deny response generated following the interruption, It would be great to understand it a bit deeper.
Thanks!

0 replies

dspeg · 2023-02-02T18:31:18Z

dspeg
Feb 2, 2023
Author

Hi Matteo, I will test out the changes soon. I will share the log.
Thanks!

1 reply

M4tteoP Apr 12, 2023
Collaborator

Hi also here :D
Did you manage to give it a shot? Is this issue still happening? Pretty curious about it. Currently in coraza-proxy-wasm there is a strict check that expects to receive a response with only one header (the status code of the deny action) if an interruption has been raised. Maybe we have to loosen it a little bit.

dspeg · 2023-04-13T06:23:04Z

dspeg
Apr 13, 2023
Author

I'm very sorry about the delay. I tested the WasmPlugin on IngressGateway just now. I could still reproduce the problem.

Below are some log entries emitted from the WasmPlugin based on docker.io/deltag/coraza-proxy-wasm:vheaders

When I sent a request, which is to be blocked, to the app via the IngressGateway with "curl", no response will be sent back.

`
2023-04-13T06:06:33.192715Z debug envoy wasm wasm log istio-system.coraza-wasm: New transaction created with id "NSmYQBqAXnvNGiPijfA"
2023-04-13T06:06:33.192912Z debug envoy wasm wasm log istio-system.coraza-wasm: [NSmYQBqAXnvNGiPijfA] Evaluating phase 1
2023-04-13T06:06:33.192948Z debug envoy wasm wasm log istio-system.coraza-wasm: [NSmYQBqAXnvNGiPijfA] [900100] Evaluating rule 900100
...
...
2023-04-13T06:06:33.193013Z debug envoy wasm wasm log istio-system.coraza-wasm: [NSmYQBqAXnvNGiPijfA] [201] Evaluating rule 201
2023-04-13T06:06:33.193016Z debug envoy wasm wasm log istio-system.coraza-wasm: [NSmYQBqAXnvNGiPijfA] [201] Expanding 1 arguments for rule 201
2023-04-13T06:06:33.193020Z debug envoy wasm wasm log istio-system.coraza-wasm: [NSmYQBqAXnvNGiPijfA] [201] Transforming argument "GET /sample-dotnet/v1.0/?param=attack_pattern_1 HTTP/2" for rule 201
2023-04-13T06:06:33.193028Z debug envoy wasm wasm log istio-system.coraza-wasm: [NSmYQBqAXnvNGiPijfA] [201] Arguments transformed for rule 201: [GET /sample-dotnet/v1.0/?param=attack_pattern_1 HTTP/2]
2023-04-13T06:06:33.193069Z debug envoy wasm wasm log istio-system.coraza-wasm: [NSmYQBqAXnvNGiPijfA] [201] Matching rule 201 REQUEST_LINE:
2023-04-13T06:06:33.193089Z debug envoy wasm wasm log istio-system.coraza-wasm: [NSmYQBqAXnvNGiPijfA] [201] Evaluating action log for rule 201
2023-04-13T06:06:33.193095Z debug envoy wasm wasm log istio-system.coraza-wasm: [NSmYQBqAXnvNGiPijfA] [201] Evaluating operator "@rx attack_pattern_." against "GET /sample-dotnet/v1.0/?param=attack_pattern_1 HTTP/2": MATCH
2023-04-13T06:06:33.193098Z debug envoy wasm wasm log istio-system.coraza-wasm: [NSmYQBqAXnvNGiPijfA] [201] Expanding 1 arguments for rule 201
2023-04-13T06:06:33.193101Z debug envoy wasm wasm log istio-system.coraza-wasm: [NSmYQBqAXnvNGiPijfA] [201] Transforming argument "attack_pattern_1" for rule 201
2023-04-13T06:06:33.193103Z debug envoy wasm wasm log istio-system.coraza-wasm: [NSmYQBqAXnvNGiPijfA] [201] Arguments transformed for rule 201: [attack_pattern_1]
2023-04-13T06:06:33.193106Z debug envoy wasm wasm log istio-system.coraza-wasm: [NSmYQBqAXnvNGiPijfA] [201] Matching rule 201 ARGS:param
2023-04-13T06:06:33.193109Z debug envoy wasm wasm log istio-system.coraza-wasm: [NSmYQBqAXnvNGiPijfA] [201] Evaluating action log for rule 201
2023-04-13T06:06:33.193111Z debug envoy wasm wasm log istio-system.coraza-wasm: [NSmYQBqAXnvNGiPijfA] [201] Evaluating operator "@rx attack_pattern_." against "attack_pattern_1": MATCH
...
...
2023-04-13T06:06:33.193205Z debug envoy wasm wasm log istio-system.coraza-wasm: [NSmYQBqAXnvNGiPijfA] [201] Disrupting transaction by rule 201
2023-04-13T06:06:33.193207Z debug envoy wasm wasm log istio-system.coraza-wasm: [NSmYQBqAXnvNGiPijfA] [201] Evaluating action deny for rule 201
2023-04-13T06:06:33.193209Z debug envoy wasm wasm log istio-system.coraza-wasm: [NSmYQBqAXnvNGiPijfA] rule 201 matched
2023-04-13T06:06:33.193232Z 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.224"] [uri "/sample-dotnet/v1.0/?param=attack_pattern_1"] [unique_id "NSmYQBqAXnvNGiPijfA"]
[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.224"] [uri "/sample-dotnet/v1.0/?param=attack_pattern_1"] [unique_id "NSmYQBqAXnvNGiPijfA"]
[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.224"] [uri "/sample-dotnet/v1.0/?param=attack_pattern_1"] [unique_id "NSmYQBqAXnvNGiPijfA"]

2023-04-13T06:06:33.193235Z debug envoy wasm wasm log istio-system.coraza-wasm: [NSmYQBqAXnvNGiPijfA] [201] Finish evaluating rule 201
2023-04-13T06:06:33.193236Z debug envoy wasm wasm log istio-system.coraza-wasm: [NSmYQBqAXnvNGiPijfA] Finished phase 1
2023-04-13T06:06:33.193246Z info envoy wasm wasm log istio-system.coraza-wasm: 2 interrupted, action "deny", phase "http_request_headers"
2023-04-13T06:06:33.193256Z debug envoy http [C1041201][S14530288490468214773] Sending local reply with details
2023-04-13T06:06:33.193354Z error envoy wasm wasm log istio-system.coraza-wasm: interruption already handled, unexpected local response
2023-04-13T06:06:33.193361Z error envoy wasm wasm log istio-system.coraza-wasm: Dumping Added Response header: :status|434
2023-04-13T06:06:33.193363Z error envoy wasm wasm log istio-system.coraza-wasm: Dumping Added Response header: vary|Accept-Encoding
`

After I sent "ctrl-c" to "curl", a few more log entries were appended:
2023-04-13T06:07:21.214615Z debug envoy connection [C1041233] closing data_to_write=143 type=0 2023-04-13T06:07:21.214636Z debug envoy connection [C1041233] setting delayed close timer with timeout 1000 ms 2023-04-13T06:07:21.214648Z debug envoy pool [C43] response complete 2023-04-13T06:07:21.214652Z debug envoy pool [C43] destroying stream: 0 remaining 2023-04-13T06:07:21.214700Z debug envoy connection [C1041233] write flush complete 2023-04-13T06:07:21.214721Z debug envoy connection [C1041233] closing socket: 1 2023-04-13T06:07:21.214744Z debug envoy conn_handler [C1041233] adding to cleanup list 2023-04-13T06:07:21.434632Z debug envoy connection [C1041201] remote close 2023-04-13T06:07:21.434686Z debug envoy connection [C1041201] closing socket: 0 2023-04-13T06:07:21.434749Z debug envoy connection [C1041201] SSL shutdown: rc=0 2023-04-13T06:07:21.434829Z debug envoy http [C1041201][S14530288490468214773] stream reset 2023-04-13T06:07:21.435233Z error envoy wasm wasm log istio-system.coraza-wasm: Calling ProcessResponseBody but there is a preexisting interruption 2023-04-13T06:07:21.435261Z debug envoy wasm wasm log istio-system.coraza-wasm: [NSmYQBqAXnvNGiPijfA] Evaluating phase 5 2023-04-13T06:07:21.435274Z debug envoy wasm wasm log istio-system.coraza-wasm: [NSmYQBqAXnvNGiPijfA] [0] Evaluating rule 0 2023-04-13T06:07:21.435280Z debug envoy wasm wasm log istio-system.coraza-wasm: [NSmYQBqAXnvNGiPijfA] [0] Forcing rule 0 to match 2023-04-13T06:07:21.435286Z debug envoy wasm wasm log istio-system.coraza-wasm: [NSmYQBqAXnvNGiPijfA] [0] Disrupting transaction by rule 0 2023-04-13T06:07:21.435288Z debug envoy wasm wasm log istio-system.coraza-wasm: [NSmYQBqAXnvNGiPijfA] [0] Finish evaluating rule 0 2023-04-13T06:07:21.435290Z debug envoy wasm wasm log istio-system.coraza-wasm: [NSmYQBqAXnvNGiPijfA] Finished phase 5 2023-04-13T06:07:21.435294Z debug envoy wasm wasm log istio-system.coraza-wasm: [NSmYQBqAXnvNGiPijfA] Transaction not marked for audit logging, AuditEngine is disabled 2023-04-13T06:07:21.435309Z debug envoy wasm wasm log istio-system.coraza-wasm: [NSmYQBqAXnvNGiPijfA] Transaction finished, disrupted: true 2023-04-13T06:07:21.435312Z info envoy wasm wasm log istio-system.coraza-wasm: 2 finished 2023-04-13T06:07:21.435469Z debug envoy wasm wasm log stats_outbound stats_outbound: [extensions/stats/plugin.cc:664]::report() metricKey cache miss istio_requests_total , stat=24, recurrent=0 2023-04-13T06:07:21.435511Z debug envoy wasm wasm log stats_outbound stats_outbound: [extensions/stats/plugin.cc:664]::report() metricKey cache miss istio_response_bytes , stat=42, recurrent=0 2023-04-13T06:07:21.437358Z debug envoy wasm wasm log stats_outbound stats_outbound: [extensions/stats/plugin.cc:664]::report() metricKey cache miss istio_request_duration_milliseconds , stat=46, recurrent=0 2023-04-13T06:07:21.439452Z debug envoy wasm wasm log stats_outbound stats_outbound: [extensions/stats/plugin.cc:664]::report() metricKey cache miss istio_request_bytes , stat=50, recurrent=0 2023-04-13T06:07:21.441441Z debug envoy conn_handler [C1041201] adding to cleanup list {"downstream_tls_cipher":"TLS_AES_256_GCM_SHA384","duration":48241,"upstream_service_time":null,"auth_jwt":null,"authority":"services.local","response_flags":"DC","upstream_local_address":null,"path":"/sample-dotnet/v1.0/?param=attack_pattern_1","bytes_received":0,"istio_policy_status":null,"bytes_sent":0,"downstream_tls_version":"TLSv1.3","x_forwarded_for":"10.244.0.1","upstream_host":null,"start_time":"2023-04-13T06:06:33.192Z","downstream_local_address":"10.244.67.224:8443","route_name":null,"method":"GET","response_code":434,"downstream_remote_address":"10.244.0.1:49892","upstream_transport_failure_reason":null,"request_id":"172b3f2a-81fd-9cff-8890-cd8c850f3d4f","log_type":"access_log","requested_server_name":"services.local","upstream_cluster":"outbound|80||sample-dotnet.sample.svc.cluster.local","user_agent":"curl/7.68.0","traceparent":null,"protocol":"HTTP/2"} 2023-04-13T06:07:22.655655Z debug envoy main flushing stats

1 reply

M4tteoP Apr 14, 2023
Collaborator

Great, thank you!
What we were looking for are these lines:

Dumping Added Response header: :status|434
Dumping Added Response header: vary|Accept-Encoding

Currently, proxy-wasm expects to have only a single response header, namely :status. Because of the extra header vary, the filter detects the response as an unexpected one that leads to the hanging status.

We definitely have to loosen this check. If you manage to collect also this header corazawaf/coraza-proxy-wasm#171 (comment) would be awesome.

Thanks for your tests and your help!

M4tteoP · 2023-04-18T15:26:57Z

M4tteoP
Apr 18, 2023
Collaborator

Hey @dspeg, thanks also for this dump (corazawaf/coraza-proxy-wasm#171 (comment)). Just updating you that there is an open PR that should fix this issue: corazawaf/coraza-proxy-wasm#172. Feel free to join the conversation if needed!

0 replies

M4tteoP · 2023-05-09T10:14:18Z

M4tteoP
May 9, 2023
Collaborator

Fixed by corazawaf/coraza-proxy-wasm#172

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

No more processing in the WAF on Istio IngressGateway after Phase 1 rule triggered #594

{{title}}

Replies: 11 comments 3 replies

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

Select a reply

No more processing in the WAF on Istio IngressGateway after Phase 1 rule triggered #594

dspeg Jan 27, 2023

Replies: 11 comments · 3 replies

jptosso Jan 27, 2023 Maintainer

jcchavezs Jan 27, 2023 Maintainer

jcchavezs Jan 27, 2023 Maintainer

dspeg Jan 27, 2023 Author

M4tteoP Jan 27, 2023 Collaborator

dspeg Jan 27, 2023 Author

jcchavezs Jan 30, 2023 Maintainer

M4tteoP Feb 1, 2023 Collaborator

dspeg Feb 2, 2023 Author

M4tteoP Apr 12, 2023 Collaborator

dspeg Apr 13, 2023 Author

M4tteoP Apr 14, 2023 Collaborator

M4tteoP Apr 18, 2023 Collaborator

M4tteoP May 9, 2023 Collaborator

dspeg
Jan 27, 2023

Replies: 11 comments 3 replies

jptosso
Jan 27, 2023
Maintainer

jcchavezs Jan 27, 2023
Maintainer

jcchavezs
Jan 27, 2023
Maintainer

dspeg
Jan 27, 2023
Author

M4tteoP
Jan 27, 2023
Collaborator

dspeg
Jan 27, 2023
Author

jcchavezs
Jan 30, 2023
Maintainer

M4tteoP
Feb 1, 2023
Collaborator

dspeg
Feb 2, 2023
Author

M4tteoP Apr 12, 2023
Collaborator

dspeg
Apr 13, 2023
Author

M4tteoP Apr 14, 2023
Collaborator

M4tteoP
Apr 18, 2023
Collaborator

M4tteoP
May 9, 2023
Collaborator