Ext-proc STREAMED mode with router Retry_policy will send duplicated request body

Open xr opened this issue 5 months ago • 6 comments

Description: The upstream service will get duplicated payload when:

enable ext-proc requestBody:STREAMED mode
enable router retry_policy. (with any policy)

Repro steps:

envoy version: 7b8baff1758f0a584dcc3cb657b5032000bcb3d7/1.31.0/Distribution/RELEASE/BoringSSL

1. envoycfg.yaml

admin:
  address:
    socket_address:
      address: 127.0.0.1
      port_value: 9902
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
          access_log:
          - name: envoy.access_loggers.stdout
            typed_config:
              "@type": type.googleapis.com/envoy.extensions.access_loggers.stream.v3.StdoutAccessLog
          http_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
          access_log:
          - name: envoy.access_loggers.stdout
            typed_config:
              "@type": type.googleapis.com/envoy.extensions.access_loggers.stream.v3.StdoutAccessLog
          http_filters:
          - name: envoy.filters.http.ext_proc
            typed_config:
              "@type": type.googleapis.com/envoy.extensions.filters.http.ext_proc.v3.ExternalProcessor
              allow_mode_override: false
              failure_mode_allow: false
              processing_mode:
                request_header_mode: SEND
                response_header_mode: SEND
                request_body_mode: STREAMED
                response_body_mode: STREAMED
              message_timeout: 30s
              grpc_service:
                timeout: 60s
                google_grpc:
                  stat_prefix: test-ext-proc
                  target_uri: 127.0.0.1:20001
          - name: envoy.filters.http.router
            typed_config:
              "@type": type.googleapis.com/envoy.extensions.filters.http.router.v3.Router
          route_config:
            name: echo_route
            virtual_hosts:
            - name: local_service
              domains: ["*"]
              retry_policy:
                retry_on: "connect-failure"
                num_retries: 2
              routes:
              - match:
                  prefix: "/"
                route:
                  cluster: echo_server

  clusters:
  - name: echo_server
    type: static
    load_assignment:
      cluster_name: echo_server
      endpoints:
      - lb_endpoints:
        - endpoint:
            address:
              socket_address:
                address: 127.0.0.1
                port_value: 4000

2. echo_server code example:

var express = require('express')
var app = express()

app.post('/', function (req, res) {
    let payloadSize = 0;
    req.on('data', (chunk) => {
      payloadSize += chunk.length;
      console.log(`received chunk length: ${chunk.length}, total: ${payloadSize}`);
    });

    req.on('end', () => {
      console.log(`received total payload size: ${payloadSize}`);
      res.send({
        headers: req.headers,
        query: req.query,
        params: req.params,
        url: req.url,
        body: req.body,
        hostname: req.hostname,
        ip: req.ip,
        ips: req.ips,
        method: req.method,
        baseUrl: req.baseUrl,
        originalUrl: req.originalUrl,
        protocol: req.protocol,
        cookies: req.cookies,
        payloadSize: payloadSize,
      });
    });

})
app.listen(4000);

3. side stream server

here is one example of ext-proc side stream server implementation to use: https://gist.github.com/xr/94a6cb60e11028c837f46fac01ae37bd

4. send request

curl --location 'http://localhost:10000/' \
--header 'Content-Type: application/octet-stream' \
--data '@/Path/to/1MB_file.bin'

The size of file i used is 1048576 bytes.

Problem

I got payload size from the upstream server is 2097152 which is doubled the amount.

Logs from ext-proc side server (looks good):

Received request type: *ext_procv3.ProcessingRequest_RequestHeaders
Received headers: headers:{headers:{key:":authority"  raw_value:"localhost:10000"}  headers:{key:":path"  raw_value:"/"}  headers:{key:":method"  raw_value:"POST"}  headers:{key:":scheme"  raw_value:"http"}  headers:{key:"user-agent"  raw_value:"PostmanRuntime/7.37.3"}  headers:{key:"accept"  raw_value:"*/*"}  headers:{key:"cache-control"  raw_value:"no-cache"}  headers:{key:"postman-token"  raw_value:"9e3d4f39-a71a-4a7d-b004-4b63e5f5bec0"}  headers:{key:"accept-encoding"  raw_value:"gzip, deflate, br"}  headers:{key:"content-length"  raw_value:"1048576"}  headers:{key:"content-type"  raw_value:"application/octet-stream"}  headers:{key:"x-forwarded-proto"  raw_value:"http"}  headers:{key:"x-request-id"  raw_value:"46021c15-769d-4a87-b225-9c2238c25125"}}
Received request type: *ext_procv3.ProcessingRequest_RequestBody
Received request body size 65536, endOfStream: false
Received request type: *ext_procv3.ProcessingRequest_RequestBody
Received request body size 917504, endOfStream: false
Received request type: *ext_procv3.ProcessingRequest_RequestBody
Received request body size 65536, endOfStream: false
Received request type: *ext_procv3.ProcessingRequest_RequestBody
Received request body size 0, endOfStream: true
Received end of stream
Received request type: *ext_procv3.ProcessingRequest_ResponseHeaders
Received request type: *ext_procv3.ProcessingRequest_ResponseBody
Stream closed by proxy

Logs from the upstrea server, which is not good, duplicated payload:

received chunk length: 64903, total: 64903
received chunk length: 633, total: 65536
received chunk length: 65529, total: 131065
received chunk length: 65536, total: 196601
received chunk length: 65536, total: 262137
received chunk length: 65536, total: 327673
received chunk length: 65536, total: 393209
received chunk length: 65536, total: 458745
received chunk length: 65536, total: 524281
received chunk length: 65536, total: 589817
received chunk length: 65536, total: 655353
received chunk length: 65536, total: 720889
received chunk length: 65536, total: 786425
received chunk length: 65536, total: 851961
received chunk length: 65536, total: 917497
received chunk length: 65536, total: 983033
received chunk length: 7, total: 983040
received chunk length: 65520, total: 1048560
received chunk length: 16, total: 1048576
received chunk length: 65510, total: 1114086
received chunk length: 65536, total: 1179622
received chunk length: 65536, total: 1245158
received chunk length: 65536, total: 1310694
received chunk length: 65536, total: 1376230
received chunk length: 65536, total: 1441766
received chunk length: 65536, total: 1507302
received chunk length: 65536, total: 1572838
received chunk length: 65536, total: 1638374
received chunk length: 65536, total: 1703910
received chunk length: 65536, total: 1769446
received chunk length: 65536, total: 1834982
received chunk length: 65536, total: 1900518
received chunk length: 65536, total: 1966054
received chunk length: 65536, total: 2031590
received chunk length: 65536, total: 2097126
received chunk length: 26, total: 2097152
received total payload size: 2097152

envoy logs

[2024-09-13 15:47:55.440][64800441][debug][main] [source/server/server.cc:237] flushing stats
[2024-09-13 15:47:55.988][64800452][debug][http] [source/common/http/conn_manager_impl.cc:385] [Tags: "ConnectionId":"0"] new stream
[2024-09-13 15:47:55.988][64800452][debug][http] [source/common/http/conn_manager_impl.cc:1135] [Tags: "ConnectionId":"0","StreamId":"8704630574034820302"] request headers complete (end_stream=false):
':authority', 'localhost:10000'
':path', '/'
':method', 'POST'
'user-agent', 'PostmanRuntime/7.37.3'
'accept', '*/*'
'cache-control', 'no-cache'
'postman-token', '5fb57b61-d5b4-43f5-8488-7893728fcbd7'
'accept-encoding', 'gzip, deflate, br'
'connection', 'keep-alive'
'content-length', '1048576'
'content-type', 'application/octet-stream'

[2024-09-13 15:47:55.988][64800452][debug][connection] [./source/common/network/connection_impl.h:98] [Tags: "ConnectionId":"0"] current connecting state: false
[2024-09-13 15:47:55.988][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:338] Opening gRPC stream to external processor
[2024-09-13 15:47:55.989][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction INBOUND: 30000 ms timer enabled
[2024-09-13 15:47:55.989][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:433] Sending headers message
[2024-09-13 15:47:55.989][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:408] Watermark raised on decoding
[2024-09-13 15:47:55.989][64800452][debug][http] [source/common/http/conn_manager_impl.cc:1878] [Tags: "ConnectionId":"0","StreamId":"8704630574034820302"] Read-disabling downstream stream due to filter callbacks.
[2024-09-13 15:47:55.989][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1074] Received request headers response
[2024-09-13 15:47:55.989][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:87] applying headers response. body mode = STREAMED
[2024-09-13 15:47:55.989][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction INBOUND: timer disabled
[2024-09-13 15:47:55.989][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:159] Sending first chunk using buffered data (65536)
[2024-09-13 15:47:55.989][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:862] Sending a body chunk of 65536 bytes, end_stream false
[2024-09-13 15:47:55.989][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction INBOUND: 30000 ms timer enabled
[2024-09-13 15:47:55.990][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:416] Watermark lowered on decoding
[2024-09-13 15:47:55.990][64800452][debug][http] [source/common/http/conn_manager_impl.cc:1868] [Tags: "ConnectionId":"0","StreamId":"8704630574034820302"] Read-enabling downstream stream due to filter callbacks.
[2024-09-13 15:47:55.990][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:392] Continuing processing
[2024-09-13 15:47:55.990][64800452][debug][router] [source/common/router/router.cc:525] [Tags: "ConnectionId":"0","StreamId":"8704630574034820302"] cluster 'echo_server' match for URL '/'
[2024-09-13 15:47:55.990][64800452][debug][router] [source/common/router/router.cc:750] [Tags: "ConnectionId":"0","StreamId":"8704630574034820302"] router decoding headers:
':authority', 'localhost:10000'
':path', '/'
':method', 'POST'
':scheme', 'http'
'user-agent', 'PostmanRuntime/7.37.3'
'accept', '*/*'
'cache-control', 'no-cache'
'postman-token', '5fb57b61-d5b4-43f5-8488-7893728fcbd7'
'accept-encoding', 'gzip, deflate, br'
'content-type', 'application/octet-stream'
'x-forwarded-proto', 'http'
'x-request-id', '8708f5a3-3446-4a9f-8ed8-2775599dde58'
'x-envoy-expected-rq-timeout-ms', '15000'

[2024-09-13 15:47:55.990][64800452][debug][pool] [source/common/http/conn_pool_base.cc:78] queueing stream due to no available connections (ready=0 busy=0 connecting=0)
[2024-09-13 15:47:55.990][64800452][debug][pool] [source/common/conn_pool/conn_pool_base.cc:291] trying to create new connection
[2024-09-13 15:47:55.990][64800452][debug][pool] [source/common/conn_pool/conn_pool_base.cc:145] creating a new connection (connecting=0)
[2024-09-13 15:47:55.990][64800452][debug][connection] [./source/common/network/connection_impl.h:98] [Tags: "ConnectionId":"4"] current connecting state: true
[2024-09-13 15:47:55.990][64800452][debug][client] [source/common/http/codec_client.cc:57] [Tags: "ConnectionId":"4"] connecting
[2024-09-13 15:47:55.990][64800452][debug][connection] [source/common/network/connection_impl.cc:1017] [Tags: "ConnectionId":"4"] connecting to 127.0.0.1:4000
[2024-09-13 15:47:55.990][64800452][debug][connection] [source/common/network/connection_impl.cc:1036] [Tags: "ConnectionId":"4"] connection in progress
[2024-09-13 15:47:55.990][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:862] Sending a body chunk of 917504 bytes, end_stream false
[2024-09-13 15:47:55.991][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction INBOUND: 30000 ms timer enabled
[2024-09-13 15:47:55.991][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1074] Received request body response
[2024-09-13 15:47:55.991][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:225] Processing body response
[2024-09-13 15:47:55.991][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction INBOUND: timer disabled
[2024-09-13 15:47:55.991][64800452][debug][connection] [source/common/network/connection_impl.cc:746] [Tags: "ConnectionId":"4"] connected
[2024-09-13 15:47:55.991][64800452][debug][client] [source/common/http/codec_client.cc:88] [Tags: "ConnectionId":"4"] connected
[2024-09-13 15:47:55.991][64800452][debug][pool] [source/common/conn_pool/conn_pool_base.cc:328] [Tags: "ConnectionId":"4"] attaching to next stream
[2024-09-13 15:47:55.991][64800452][debug][pool] [source/common/conn_pool/conn_pool_base.cc:182] [Tags: "ConnectionId":"4"] creating stream
[2024-09-13 15:47:55.991][64800452][debug][router] [source/common/router/upstream_request.cc:595] [Tags: "ConnectionId":"0","StreamId":"8704630574034820302"] pool ready
[2024-09-13 15:47:55.991][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:862] Sending a body chunk of 65536 bytes, end_stream false
[2024-09-13 15:47:55.992][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction INBOUND: 30000 ms timer enabled
[2024-09-13 15:47:55.992][64800452][debug][http] [source/common/http/conn_manager_impl.cc:1118] [Tags: "ConnectionId":"0","StreamId":"8704630574034820302"] request end stream
[2024-09-13 15:47:55.992][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:862] Sending a body chunk of 0 bytes, end_stream true
[2024-09-13 15:47:55.992][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction INBOUND: 30000 ms timer enabled
[2024-09-13 15:47:55.992][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1074] Received request body response
[2024-09-13 15:47:55.992][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:225] Processing body response
[2024-09-13 15:47:55.993][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction INBOUND: timer disabled
[2024-09-13 15:47:55.993][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1074] Received request body response
[2024-09-13 15:47:55.993][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:225] Processing body response
[2024-09-13 15:47:55.993][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction INBOUND: timer disabled
[2024-09-13 15:47:55.993][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1074] Received request body response
[2024-09-13 15:47:55.993][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:225] Processing body response
[2024-09-13 15:47:55.993][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction INBOUND: timer disabled
[2024-09-13 15:47:55.993][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:392] Continuing processing
[2024-09-13 15:47:55.993][64800452][debug][router] [source/common/router/router.cc:877] The request payload has at least 2097152 bytes data which exceeds buffer limit 1048576. Give up on the retry/shadow.
[2024-09-13 15:47:55.993][64800452][debug][http] [source/common/http/conn_manager_impl.cc:1878] [Tags: "ConnectionId":"0","StreamId":"8704630574034820302"] Read-disabling downstream stream due to filter callbacks.
[2024-09-13 15:47:55.993][64800452][debug][http] [source/common/http/conn_manager_impl.cc:1868] [Tags: "ConnectionId":"0","StreamId":"8704630574034820302"] Read-enabling downstream stream due to filter callbacks.
[2024-09-13 15:47:55.993][64800452][debug][connection] [source/common/network/connection_impl.cc:594] [Tags: "ConnectionId":"4"] onAboveWriteBufferHighWatermark
[2024-09-13 15:47:55.993][64800452][debug][http] [source/common/http/conn_manager_impl.cc:1878] [Tags: "ConnectionId":"0","StreamId":"8704630574034820302"] Read-disabling downstream stream due to filter callbacks.
[2024-09-13 15:47:55.993][64800452][debug][client] [source/common/http/codec_client.cc:142] [Tags: "ConnectionId":"4"] encode complete
[2024-09-13 15:47:55.994][64800452][debug][connection] [source/common/network/connection_impl.cc:583] [Tags: "ConnectionId":"4"] onBelowWriteBufferLowWatermark
[2024-09-13 15:47:55.994][64800452][debug][http] [source/common/http/conn_manager_impl.cc:1868] [Tags: "ConnectionId":"0","StreamId":"8704630574034820302"] Read-enabling downstream stream due to filter callbacks.
[2024-09-13 15:47:55.996][64800452][debug][router] [source/common/router/router.cc:1551] [Tags: "ConnectionId":"0","StreamId":"8704630574034820302"] upstream headers complete: end_stream=false
[2024-09-13 15:47:55.996][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction OUTBOUND: 30000 ms timer enabled
[2024-09-13 15:47:55.996][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:433] Sending headers message
[2024-09-13 15:47:55.996][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:474] Watermark raised on encoding
[2024-09-13 15:47:55.996][64800452][debug][http] [source/common/http/filter_manager.cc:1736] [Tags: "ConnectionId":"0","StreamId":"8704630574034820302"] Disabling upstream stream due to filter callbacks.
[2024-09-13 15:47:55.997][64800452][debug][client] [source/common/http/codec_client.cc:129] [Tags: "ConnectionId":"4"] response complete
[2024-09-13 15:47:55.997][64800452][debug][pool] [source/common/http/http1/conn_pool.cc:53] [Tags: "ConnectionId":"4"] response complete
[2024-09-13 15:47:55.997][64800452][debug][pool] [source/common/conn_pool/conn_pool_base.cc:215] [Tags: "ConnectionId":"4"] destroying stream: 0 remaining
[2024-09-13 15:47:55.997][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1074] Received response headers response
[2024-09-13 15:47:55.997][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:87] applying headers response. body mode = STREAMED
[2024-09-13 15:47:55.997][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction OUTBOUND: timer disabled
[2024-09-13 15:47:55.997][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:862] Sending a body chunk of 647 bytes, end_stream true
[2024-09-13 15:47:55.997][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction OUTBOUND: 30000 ms timer enabled
[2024-09-13 15:47:55.997][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:482] Watermark lowered on decoding
[2024-09-13 15:47:55.997][64800452][debug][http] [source/common/http/filter_manager.cc:1741] [Tags: "ConnectionId":"0","StreamId":"8704630574034820302"] Enabling upstream stream due to filter callbacks.
[2024-09-13 15:47:55.997][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1074] Received response body response
[2024-09-13 15:47:55.997][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:225] Processing body response
[2024-09-13 15:47:55.997][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction OUTBOUND: timer disabled
[2024-09-13 15:47:55.997][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:392] Continuing processing
[2024-09-13 15:47:55.997][64800452][debug][http] [source/common/http/conn_manager_impl.cc:1825] [Tags: "ConnectionId":"0","StreamId":"8704630574034820302"] encoding headers via codec (end_stream=false):
':status', '200'
'x-powered-by', 'Express'
'access-control-allow-origin', '*'
'content-type', 'application/json; charset=utf-8'
'etag', 'W/"287-ZAOJ/ey45dda2/J3tn21U+HNqLg"'
'date', 'Fri, 13 Sep 2024 12:47:55 GMT'
'x-envoy-upstream-service-time', '3'
'server', 'envoy'

[2024-09-13 15:47:55.997][64800452][debug][http] [source/common/http/conn_manager_impl.cc:1937] [Tags: "ConnectionId":"0","StreamId":"8704630574034820302"] Codec completed encoding stream.
[2024-09-13 15:47:55.997][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:392] onDestroy
[2024-09-13 15:47:55.997][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction INBOUND: timer disabled
[2024-09-13 15:47:55.997][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction OUTBOUND: timer disabled
[2024-09-13 15:47:55.997][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:374] Calling close on stream
[2024-09-13 15:47:55.997][64800452][debug][ext_proc] [source/extensions/filters/http/ext_proc/client_impl.cc:64] Closing gRPC stream
[2024-09-13 15:47:55.997][64800452][debug][grpc] [source/common/grpc/google_async_client_impl.cc:283] resetStream
[2024-09-13 15:47:55.997][64800452][debug][grpc] [source/common/grpc/google_async_client_impl.cc:456] Stream cleanup with 2 in-flight tags
[2024-09-13 15:47:55.997][64800452][debug][grpc] [source/common/grpc/google_async_client_impl.cc:445] Deferred delete
[2024-09-13 15:47:55.997][64800452][debug][grpc] [source/common/grpc/google_async_client_impl.cc:194] GoogleAsyncStreamImpl destruct
[2024-09-13 15:48:00.440][64800441][debug][main] [source/server/server.cc:237] flushing stats
[2024-09-13 15:48:00.997][64800452][debug][connection] [source/common/network/connection_impl.cc:714] [Tags: "ConnectionId":"4"] remote close
[2024-09-13 15:48:00.997][64800452][debug][connection] [source/common/network/connection_impl.cc:276] [Tags: "ConnectionId":"4"] closing socket: 0
[2024-09-13 15:48:00.997][64800452][debug][client] [source/common/http/codec_client.cc:107] [Tags: "ConnectionId":"4"] disconnect. resetting 0 pending requests
[2024-09-13 15:48:00.997][64800452][debug][pool] [source/common/conn_pool/conn_pool_base.cc:495] [Tags: "ConnectionId":"4"] client disconnected, failure reason:
[2024-09-13 15:48:00.998][64800452][debug][pool] [source/common/conn_pool/conn_pool_base.cc:463] invoking 1 idle callback(s) - is_draining_for_deletion_=false
[2024-09-13 15:48:01.514][64800441][debug][http] [source/common/http/conn_manager_impl.cc:385] [Tags: "ConnectionId":"2"] new stream
[2024-09-13 15:48:01.514][64800441][debug][http] [source/common/http/conn_manager_impl.cc:1135] [Tags: "ConnectionId":"2","StreamId":"2355020986288252190"] request headers complete (end_stream=false):
':authority', 'localhost:9902'
':path', '/logging'
':method', 'POST'
'connection', 'keep-alive'
'content-length', '17'
'cache-control', 'max-age=0'
'sec-ch-ua', '"Not)A;Brand";v="99", "Google Chrome";v="127", "Chromium";v="127"'
'sec-ch-ua-mobile', '?0'
'sec-ch-ua-platform', '"macOS"'
'upgrade-insecure-requests', '1'
'origin', 'http://localhost:9902'
'content-type', 'application/x-www-form-urlencoded'
'user-agent', 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/127.0.0.0 Safari/537.36'
'accept', 'text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.7'
'sec-fetch-site', 'same-origin'
'sec-fetch-mode', 'navigate'
'sec-fetch-user', '?1'
'sec-fetch-dest', 'document'
'referer', 'http://localhost:9902/'
'accept-encoding', 'gzip, deflate, br, zstd'
'accept-language', 'en-GB,en-US;q=0.9,en;q=0.8,zh-CN;q=0.7,zh;q=0.6'

[2024-09-13 15:48:01.514][64800441][debug][connection] [./source/common/network/connection_impl.h:98] [Tags: "ConnectionId":"2"] current connecting state: false
[2024-09-13 15:48:01.514][64800441][debug][http] [source/common/http/conn_manager_impl.cc:1118] [Tags: "ConnectionId":"2","StreamId":"2355020986288252190"] request end stream
[2024-09-13 15:48:01.514][64800441][debug][admin] [source/server/admin/admin_filter.cc:85] [Tags: "ConnectionId":"2","StreamId":"2355020986288252190"] request complete: path: /logging
[2024-09-13 15:48:01.514][64800441][info][misc] [source/common/common/logger.cc:220] change all log levels: level='info'

Other Findings:

change to request_body_mode: BUFFERED or BUFFERED_PARTIAL both works, no duplicated payload
remove retry_policy or set retry_on to empty string "" works.

Sep 13 '24 12:09 xr

envoy envoy copied to clipboard

Ext-proc STREAMED mode with router Retry_policy will send duplicated request body

Repro steps:

1. envoycfg.yaml

2. echo_server code example:

3. side stream server

4. send request

Problem

Logs from ext-proc side server (looks good):

Logs from the upstrea server, which is not good, duplicated payload:

envoy logs

Other Findings:

envoy
envoy copied to clipboard