envoy icon indicating copy to clipboard operation
envoy copied to clipboard
verified publisher icon envoyproxy

ext_proc: FULL DUPLEX STREAMED response body truncated when multiple filters defined

Open guydc opened this issue 2 months ago • 6 comments

Title: *ext_ proc: FULL DUPLEX STREAMED response body truncated when multiple filters defined *

Description: envoy version: 1.35.4

Two ext-proc filters are defined:

  1. ext-proc-1: handles response headers
  2. ext-proc-2: handles response headers and body (FULL_DUPLEX_STREAMED)

When body responses are returned with some delay, there are sporadic failures, where:

  • The response body is truncated, see example in logs: UPSTREAM_WIRE_BYTES_RECEIVED:50730 DOWNSTREAM_WIRE_BYTES_SENT:4151
  • The ext-proc server encounters an error when sending a response: send error rpc error: code = Canceled desc = context canceled

Additional info:

  • When disabling ext-proc-1, issue does not reproduce. Is it possible that messages/processing mode of ext-proc-1 influences behavior of ext-proc-2?
  • From the logs, it seems that the issue is triggered when the payload is split into multiple chunks instead of being sent as a single chunk.

Config:

run ext_proc and echo backend:

  • simple ext proc: https://gist.github.com/guydc/2cb8fbb368c90d234b8a9a95d5b99336
  • simple echo server: https://gist.github.com/guydc/a6b069cf7951767a151b6ce53c7d80ed

run envoy:

admin:
  address:
    socket_address:
      address: 0.0.0.0
      port_value: 19000
static_resources:
  listeners:
    - name: listener_0
      address:
        socket_address:
          address: 0.0.0.0
          port_value: 10000
      filter_chains:
        - filters:
            - name: envoy.filters.network.http_connection_manager
              typed_config:
                "@type": type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager
                stat_prefix: ingress_http
                codec_type: AUTO
                access_log:
                  - name: envoy.access_loggers.stdout
                    typed_config:
                      "@type": type.googleapis.com/envoy.extensions.access_loggers.stream.v3.StdoutAccessLog
                      log_format:
                        text_format: |
                          [ %START_TIME% ] UPSTREAM_WIRE_BYTES_RECEIVED:%UPSTREAM_WIRE_BYTES_RECEIVED% DOWNSTREAM_WIRE_BYTES_SENT:%DOWNSTREAM_WIRE_BYTES_SENT%
                route_config:
                  name: local_route
                  virtual_hosts:
                    - name: local_service
                      domains: ["*"]
                      routes:
                        - name: myroute
                          match:
                            prefix: "/"
                          route:
                            cluster: echo
                http_filters:
                  - name: envoy.filters.http.ext_proc
                    typed_config:
                      "@type": type.googleapis.com/envoy.extensions.filters.http.ext_proc.v3.ExternalProcessor
                      failure_mode_allow: false
                      message_timeout: 300s
                      allow_mode_override: true
                      processing_mode:
                        request_header_mode: "SKIP"
                        response_header_mode: "SEND"
                        request_body_mode: "NONE"
                        response_body_mode: "NONE"
                        request_trailer_mode: "SKIP"
                        response_trailer_mode: "SKIP"
                      grpc_service:
                        envoy_grpc:
                          cluster_name: ext_proc_cluster
                  - name: envoy.filters.http.ext_proc
                    typed_config:
                      "@type": type.googleapis.com/envoy.extensions.filters.http.ext_proc.v3.ExternalProcessor
                      failure_mode_allow: false
                      message_timeout: 300s
                      allow_mode_override: true
                      processing_mode:
                        request_header_mode: "SKIP"
                        response_header_mode: "SEND"
                        request_body_mode: "NONE"
                        response_body_mode: "FULL_DUPLEX_STREAMED"
                        request_trailer_mode: "SKIP"
                        response_trailer_mode: "SEND"
                      grpc_service:
                        envoy_grpc:
                          cluster_name: ext_proc_cluster
                  - name: envoy.filters.http.router
                    typed_config:
                      "@type": type.googleapis.com/envoy.extensions.filters.http.router.v3.Router
  clusters:
    - name: echo
      type: STATIC
      dns_lookup_family: V4_ONLY
      lb_policy: ROUND_ROBIN
      load_assignment:
        cluster_name: echo
        endpoints:
          - lb_endpoints:
              - endpoint:
                  address:
                    socket_address:
                      address: 127.0.0.1
                      port_value: 8080
    - name: ext_proc_cluster
      type: STATIC
      connect_timeout: 0.25s
      dns_lookup_family: V4_ONLY
      http2_protocol_options: {}
      load_assignment:
        cluster_name: ext_proc_cluster
        endpoints:
          - lb_endpoints:
              - endpoint:
                  address:
                    socket_address:
                      address: 127.0.0.1
                      port_value: 9902

execute request:

dd if=/dev/random of=50k.dat bs=1k count=50
curl -v -X POST -d "@50k.dat" http://localhost:10000

Logs:

Logs from working flow (note chunks begin before second headers response):

[2025-10-22 15:28:42.473][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:601] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] Opening gRPC stream to external processor
[2025-10-22 15:28:42.473][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:966] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] Trying to encode filter protocol configurations
[2025-10-22 15:28:42.473][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:975] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] Filter protocol configurations encoded response_body_mode: FULL_DUPLEX_STREAMED

[2025-10-22 15:28:42.473][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:23] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] Start external processing call
[2025-10-22 15:28:42.473][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:721] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] Sending headers message
[2025-10-22 15:28:42.473][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1225] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] Sending a body chunk of 50593 bytes, end_stream false
[2025-10-22 15:28:42.473][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:966] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] Trying to encode filter protocol configurations
[2025-10-22 15:28:42.473][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:23] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] Start external processing call
[2025-10-22 15:28:42.473][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1225] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] Sending a body chunk of 0 bytes, end_stream true
[2025-10-22 15:28:42.473][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:966] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] Trying to encode filter protocol configurations
[2025-10-22 15:28:42.473][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:23] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] Start external processing call
[2025-10-22 15:28:42.474][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1556] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] Received response headers response
[2025-10-22 15:28:42.474][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:151] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] applying headers response. body mode = FULL_DUPLEX_STREAMED
[2025-10-22 15:28:42.474][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:42] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] Finish external processing call
[2025-10-22 15:28:43.477][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1556] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] Received response body response
[2025-10-22 15:28:43.477][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:327] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] Processing body response
[2025-10-22 15:28:43.477][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:396] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] FULL_DUPLEX_STREAMED body response is received and body_mode_: FULL_DUPLEX_STREAMED
[2025-10-22 15:28:43.478][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:601] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] Opening gRPC stream to external processor
[2025-10-22 15:28:43.479][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:966] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] Trying to encode filter protocol configurations
[2025-10-22 15:28:43.479][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:975] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] Filter protocol configurations encoded
[2025-10-22 15:28:43.479][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:23] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] Start external processing call
[2025-10-22 15:28:43.479][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:33] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] Traffic direction OUTBOUND: 300000 ms timer enabled
[2025-10-22 15:28:43.479][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:721] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] Sending headers message
[2025-10-22 15:28:43.479][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:42] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] Finish external processing call
[2025-10-22 15:28:43.481][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1556] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] Received response headers response
[2025-10-22 15:28:43.481][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:151] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] applying headers response. body mode = NONE
[2025-10-22 15:28:43.481][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:42] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] Finish external processing call
[2025-10-22 15:28:43.481][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:63] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] Traffic direction OUTBOUND: timer disabled
[2025-10-22 15:28:43.481][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:555] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] Continuing processing
[2025-10-22 15:28:43.481][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:668] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] onDestroy
[2025-10-22 15:28:43.481][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:63] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] Traffic direction OUTBOUND: timer disabled
[2025-10-22 15:28:43.481][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:634] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] Calling close on stream
[2025-10-22 15:28:43.481][123910306][debug][ext_proc] [./source/extensions/filters/common/ext_proc/grpc_client_impl.h:135] Closing gRPC stream
[2025-10-22 15:28:43.482][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:668] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] onDestroy
[2025-10-22 15:28:43.482][123910306][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:634] [Tags: "ConnectionId":"15","StreamId":"10353900998556077585"] Calling close on stream
[2025-10-22 15:28:43.482][123910306][debug][ext_proc] [./source/extensions/filters/common/ext_proc/grpc_client_impl.h:135] Closing gRPC stream
[ 2025-10-22T20:28:42.472Z ] UPSTREAM_WIRE_BYTES_RECEIVED:50730 DOWNSTREAM_WIRE_BYTES_SENT:50779

Logs from failing flow (note body mode = NONE seems to terminate the):

[2025-10-22 15:28:28.339][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:601] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Opening gRPC stream to external processor
[2025-10-22 15:28:28.339][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:966] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Trying to encode filter protocol configurations
[2025-10-22 15:28:28.339][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:975] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Filter protocol configurations encoded response_body_mode: FULL_DUPLEX_STREAMED

[2025-10-22 15:28:28.339][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:23] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Start external processing call
[2025-10-22 15:28:28.339][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:721] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Sending headers message
[2025-10-22 15:28:28.340][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1225] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Sending a body chunk of 3966 bytes, end_stream false
[2025-10-22 15:28:28.340][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:966] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Trying to encode filter protocol configurations
[2025-10-22 15:28:28.340][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:23] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Start external processing call
[2025-10-22 15:28:28.340][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1225] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Sending a body chunk of 16332 bytes, end_stream false
[2025-10-22 15:28:28.340][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:966] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Trying to encode filter protocol configurations
[2025-10-22 15:28:28.340][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:23] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Start external processing call
[2025-10-22 15:28:28.340][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1225] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Sending a body chunk of 16332 bytes, end_stream false
[2025-10-22 15:28:28.340][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:966] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Trying to encode filter protocol configurations
[2025-10-22 15:28:28.340][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:23] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Start external processing call
[2025-10-22 15:28:28.340][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1225] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Sending a body chunk of 13963 bytes, end_stream false
[2025-10-22 15:28:28.340][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:966] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Trying to encode filter protocol configurations
[2025-10-22 15:28:28.340][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:23] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Start external processing call
[2025-10-22 15:28:28.340][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1225] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Sending a body chunk of 0 bytes, end_stream true
[2025-10-22 15:28:28.340][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:966] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Trying to encode filter protocol configurations
[2025-10-22 15:28:28.340][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:23] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Start external processing call
[2025-10-22 15:28:28.344][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1556] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Received response headers response
[2025-10-22 15:28:28.344][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:151] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] applying headers response. body mode = FULL_DUPLEX_STREAMED
[2025-10-22 15:28:28.344][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:42] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Finish external processing call
[2025-10-22 15:28:29.346][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1556] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Received response body response
[2025-10-22 15:28:29.346][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:327] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Processing body response
[2025-10-22 15:28:29.346][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:396] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] FULL_DUPLEX_STREAMED body response is received and body_mode_: FULL_DUPLEX_STREAMED
[2025-10-22 15:28:29.346][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:601] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Opening gRPC stream to external processor
[2025-10-22 15:28:29.348][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:966] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Trying to encode filter protocol configurations
[2025-10-22 15:28:29.348][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:975] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Filter protocol configurations encoded
[2025-10-22 15:28:29.348][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:23] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Start external processing call
[2025-10-22 15:28:29.348][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:33] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Traffic direction OUTBOUND: 300000 ms timer enabled
[2025-10-22 15:28:29.348][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:721] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Sending headers message
[2025-10-22 15:28:29.351][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:42] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Finish external processing call
[2025-10-22 15:28:29.353][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1556] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Received response headers response
[2025-10-22 15:28:29.353][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:151] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] applying headers response. body mode = NONE
[2025-10-22 15:28:29.353][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:42] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Finish external processing call
[2025-10-22 15:28:29.353][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:63] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Traffic direction OUTBOUND: timer disabled
[2025-10-22 15:28:29.353][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:555] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Continuing processing
[2025-10-22 15:28:29.353][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:668] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] onDestroy
[2025-10-22 15:28:29.353][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:63] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Traffic direction OUTBOUND: timer disabled
[2025-10-22 15:28:29.353][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:634] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Calling close on stream
[2025-10-22 15:28:29.353][123910309][debug][ext_proc] [./source/extensions/filters/common/ext_proc/grpc_client_impl.h:135] Closing gRPC stream
[2025-10-22 15:28:29.353][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:668] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] onDestroy
[2025-10-22 15:28:29.353][123910309][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:634] [Tags: "ConnectionId":"12","StreamId":"7965781118008110716"] Calling close on stream
[2025-10-22 15:28:29.353][123910309][debug][ext_proc] [./source/extensions/filters/common/ext_proc/grpc_client_impl.h:135] Closing gRPC stream
[ 2025-10-22T20:28:28.335Z ] UPSTREAM_WIRE_BYTES_RECEIVED:50730 DOWNSTREAM_WIRE_BYTES_SENT:4151

ext-proc logs from a failure instance:

2025/10/22 15:51:45 Got stream:  -->  
2025/10/22 15:51:45 return headers                        # ext-proc-2 headers, body = FDS
2025/10/22 15:51:45 sending response
2025/10/22 15:51:46 return body                             # ext-proc-2 body
2025/10/22 15:51:46 sending response
2025/10/22 15:51:46 Got stream:  -->  
2025/10/22 15:51:46 return headers                        # ext-proc-1 headers, body = none
2025/10/22 15:51:46 sending response
2025/10/22 15:51:47 return body                              # ext-proc 2 body after second headers response
2025/10/22 15:51:47 sending response
2025/10/22 15:51:47 send error rpc error: code = Canceled desc = context canceled

guydc avatar Oct 22 '25 20:10 guydc

cc @yanjunxiang-google

guydc avatar Oct 22 '25 21:10 guydc

When the ext proc Y (the second ext proc filter in your configuration) received the body processing response (this may happens multiples if there are multiple body chunks) from the ext proc server, it will inject the responded body data to the HTTP filter chain directly and proceed the filter chain to continue. But note, because the ext proc X (the first ext proc filter in your configuration) also is ext proc filter and will trigger an async gRPC calling. Then the filter chain will be hung up here again and the responded body data will be buffered in the stream buffer. When the async gRPC calling of ext proc X is completed, it will recover the execution of the filter chain. Then problem happens, when HTTP filter chain is recovered from an async calling, if Envoy has received all data from upstream, Envoy will assume the data in the stream buffer is all the data of the request/response and will set the end stream flag is true and complete the processing of the whole request/response. The assumption is correct in most cases for most filters. But in some edge cases like here, it’s wrong.

Before the fix, if you want to use the ext proc + FULL_DUPLEX_STREAMED correctly, you may try to ensure no filters after the ext proc will hang the execution of filter chain up (won’t return a stop flag in their decodeHeaders/encodeHeaders/decodeData/….). Then ideally, it should works.

wbpcode avatar Oct 23 '25 14:10 wbpcode

"Then problem happens, when HTTP filter chain is recovered from an async calling, if Envoy has received all data from upstream, Envoy will assume the data in the stream buffer is all the data of the request/response and will set the end stream flag is true" ----- emm, I thought if the ext_proc Y filter inject the data into buffer, it contain end_of_stream info: https://github.com/envoyproxy/envoy/blob/4364cb50418cbd26a64a8caf3db49e3b7e9bf423/source/extensions/filters/http/ext_proc/processor_state.cc#L592. i.e, if there are more data to arrive, EoS here should be false.

yanjunxiang-google avatar Oct 24 '25 20:10 yanjunxiang-google

"Then problem happens, when HTTP filter chain is recovered from an async calling, if Envoy has received all data from upstream, Envoy will assume the data in the stream buffer is all the data of the request/response and will set the end stream flag is true" ----- emm, I thought if the ext_proc Y filter inject the data into buffer, it contain end_of_stream info:

envoy/source/extensions/filters/http/ext_proc/processor_state.cc

Line 592 in 4364cb5

injectDataToFilterChain(buffer, end_of_stream); . i.e, if there are more data to arrive, EoS here should be false.

Ideally, yeah. And the injectDataToFilterChain do set the end_of_stream as false. But there is a bug, or we should say the injectDataToFilterChain cannot be used in this way. So, when the filter chain is hung up and be proceed again, problem happens.

wbpcode avatar Oct 25 '25 03:10 wbpcode

This issue has been automatically marked as stale because it has not had activity in the last 30 days. It will be closed in the next 7 days unless it is tagged "help wanted" or "no stalebot" or other activity occurs. Thank you for your contributions.

github-actions[bot] avatar Nov 24 '25 04:11 github-actions[bot]

This issue has been automatically closed because it has not had activity in the last 37 days. If this issue is still valid, please ping a maintainer and ask them to label it as "help wanted" or "no stalebot". Thank you for your contributions.

github-actions[bot] avatar Dec 01 '25 04:12 github-actions[bot]