ActionPause will not pause the processing in the filter chain

[xr]

Hey guys, noticed some case that actionPause will not pause the processing in the filter chain.

I have a wasm filter and ext-proc filter configure in my envoy sth like:

...
- name: envoy.filters.http.wasm
    typed_config:
      "@type": type.googleapis.com/envoy.extensions.filters.http.wasm.v3.Wasm
      config:
        name: custom-filter
        root_id: wasm_filter
        vm_config:
          runtime: envoy.wasm.runtime.v8
          code:
            local:
              filename: /build.wasm
        configuration:
          "@type": "type.googleapis.com/google.protobuf.StringValue"
  - name: envoy.filters.http.ext_proc
    typed_config:
      "@type": type.googleapis.com/envoy.extensions.filters.http.ext_proc.v3.ExternalProcessor
      allow_mode_override: true
      failure_mode_allow: false
      message_timeout:
        seconds: 2
      grpc_service:
        timeout:
          seconds: 600
        google_grpc:
          stat_prefix: ext_proc
          target_uri: invalid_url:20001

I'm return ActionPause and SendHttpResponse with status (400) in the OnHttpRequestHeaders in my wasm filter, similar with:

proxy-wasm-go-sdk/examples/http_body/main.go

Line 84 in b089ccb

if err := proxywasm.SendHttpResponse(400, nil, []byte("content must be provided"), -1); err != nil {

i'm expecting the response (400) will be sent to the downstream immediately and terminate the processing further in the filter chain, however, the logs shows the response is not sent back immediately but "preparing" and "execute" for later and processing further to the external processing filter, eventually I got the response from external processing filter instead of wasm filter, which is 500 (as i have configure failure_mode_allow:false)

highlights from the logs, as you can see after the wasm filter issuing sendHttpResponse and return ActionPause, the processing is NOT paused but continuing to the ext-proc filter.

...
[2024-01-09 18:34:08.160][49462][debug][http] [source/common/http/filter_manager.cc:946] [Tags: "ConnectionId":"5","StreamId":"7565293074993893387"] Preparing local reply with details
[2024-01-09 18:34:08.160][49462][debug][http] [source/common/http/filter_manager.cc:988] [Tags: "ConnectionId":"5","StreamId":"7565293074993893387"] Executing sending local reply.
...
[2024-01-09 18:34:08.164][49462][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:839] Sending local reply with status code 500

[2024-01-09 18:34:08.164][49462][debug][http] [source/common/http/filter_manager.cc:923] [Tags: "ConnectionId":"5","StreamId":"7565293074993893387"] Sending local reply with details ext_proc_error_gRPC_error_13 directly to the encoder

checked from the envoy code, it ends up at: https://github.com/envoyproxy/envoy/blob/50324229d7cf6024c43c7fd4bae1e042beea4728/source/common/http/filter_manager.cc#L984

but ext-proc might hit directly. https://github.com/envoyproxy/envoy/blob/50324229d7cf6024c43c7fd4bae1e042beea4728/source/common/http/filter_manager.cc#L1099

Feel like the actionPause and sendHttpResponse could be easily misleading and the abi is a bit ambiguous https://github.com/proxy-wasm/spec/pull/42/files#diff-39c0fcbaec7f6ffb311e442b6f0774bf3c050cd9b3318f51f55c2d6c38d4976dR943.

My question is:

• If we expect ActionPause to pause any operations further in the filter chain, will situation like this a potential bugs in envoy?
• is there anyway from the sdk point of view to alter the behaviour of sendHttpResponse to call sendDirectLocalReply directly instead of preparing and exec later? linked the question in the abi PR: https://github.com/proxy-wasm/spec/pull/42/files#r1447012913

Thanks!

complete logs:

[2024-01-09 18:34:08.160][49462][debug][http] [source/common/http/conn_manager_impl.cc:1149] [Tags: "ConnectionId":"5","StreamId":"7565293074993893387"] request end stream
[2024-01-09 18:34:08.160][49462][debug][connection] [./source/common/network/connection_impl.h:98] [C5] current connecting state: false
[2024-01-09 18:34:08.160][49462][debug][router] [source/common/router/config_impl.cc:1850] route was resolved but final route list did not match incoming request
[2024-01-09 18:34:08.160][49462][info][wasm] [source/extensions/common/wasm/context.cc:1148] wasm log custom-filter wasm_filter: request host: echo.example.com, /x, GET
[2024-01-09 18:34:08.160][49462][info][wasm] [source/extensions/common/wasm/context.cc:1148] wasm log custom-filter wasm_filter: error getting headers from configuration: <nil>


[2024-01-09 18:34:08.160][49462][debug][http] [source/common/http/filter_manager.cc:946] [Tags: "ConnectionId":"5","StreamId":"7565293074993893387"] Preparing local reply with details
[2024-01-09 18:34:08.160][49462][debug][http] [source/common/http/filter_manager.cc:988] [Tags: "ConnectionId":"5","StreamId":"7565293074993893387"] Executing sending local reply.


[2024-01-09 18:34:08.160][49462][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:162] Opening gRPC stream to external processor
[2024-01-09 18:34:08.162][49462][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:30] Traffic direction OUTBOUND: 2000 ms timer enabled
[2024-01-09 18:34:08.162][49462][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:229] Sending headers message
[2024-01-09 18:34:08.162][49462][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:452] Watermark raised on encoding
[2024-01-09 18:34:08.162][49462][debug][http] [source/common/http/filter_manager.cc:1651] [Tags: "ConnectionId":"5","StreamId":"7565293074993893387"] Disabling upstream stream due to filter callbacks.
[2024-01-09 18:34:08.164][49462][debug][grpc] [source/common/grpc/google_async_client_impl.cc:224] notifyRemoteClose 13
[2024-01-09 18:34:08.164][49462][debug][ext_proc] [source/extensions/filters/http/ext_proc/client_impl.cc:77] gRPC stream closed remotely with status 13:
[2024-01-09 18:34:08.164][49462][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:729] Received gRPC error on stream: 13
[2024-01-09 18:34:08.164][49462][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:188] Calling close on stream
[2024-01-09 18:34:08.164][49462][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:52] Traffic direction OUTBOUND: timer disabled

[2024-01-09 18:34:08.164][49462][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:839] Sending local reply with status code 500

[2024-01-09 18:34:08.164][49462][debug][http] [source/common/http/filter_manager.cc:923] [Tags: "ConnectionId":"5","StreamId":"7565293074993893387"] Sending local reply with details ext_proc_error_gRPC_error_13 directly to the encoder

[MengjiaLiang]

which Envoy version are you using?
I have a similar issue in Istio 1.15, but no issues in Istio1.18+

[mathetake]

#451