Pausing filter chain on http request body doesn't work for dynamic forward proxy. It works when envoy is reverse-proxy.

[dandlake]

I have a HTTP WASM filter where I make a http callout in the request body callback. After the callout, I return FilterDataStatus::StopIterationAndBuffer(which is 1) for this callback and want envoy to pause and wait for the callout reply to decide to stop or continue.

This works when envoy is reverse-proxy. However, when envoy is dynamic-forward-proxy, the pause didn't happen for the request body and the filter chain continued for the request body.

Looking at the log, for dynamic forward proxy, it's possible that after DNS is resolved asynchronously(which was triggered by http request headers), when it tried to continue the filter chain, it didn't check for the filter chain's current status and continued even when a previous filter returned FilterDataStatus::StopIterationAndBuffer.

[2021-07-23 01:24:03.141][558823][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host<-vm] proxy_on_request_body return: 1
[2021-07-23 01:24:03.141][558823][trace][http] [source/common/http/filter_manager.cc:676] [C0][S12846879879184174189] decode data called: filter=0x47c1bd46cf50 status=1
[2021-07-23 01:24:03.141][558823][trace][http] [source/common/http/http1/codec_impl.cc:613] [C0] parsed 223 bytes
[2021-07-23 01:24:03.141][558823][debug][upstream] [source/common/upstream/cluster_manager_impl.cc:1250] membership update for TLS cluster dynamic_forward_proxy_cluster added 1 removed 0
[2021-07-23 01:24:03.141][558823][debug][upstream] [source/common/upstream/cluster_manager_impl.cc:1257] re-creating local LB for TLS cluster dynamic_forward_proxy_cluster
[2021-07-23 01:24:03.142][558823][debug][forward_proxy] [source/extensions/filters/http/dynamic_forward_proxy/proxy_filter.cc:142] [C0][S12846879879184174189] load DNS cache complete, continuing
[2021-07-23 01:24:03.142][558823][trace][http] [source/common/http/filter_manager.cc:70] [C0][S12846879879184174189] continuing filter chain: filter=0x47c1bd46d030
[2021-07-23 01:24:03.142][558823][debug][router] [source/common/router/router.cc:448] [C0][S12846879879184174189] cluster 'dynamic_forward_proxy_cluster' match for URL '/'
[2021-07-23 01:24:03.142][558823][debug][router] [source/common/router/router.cc:634] [C0][S12846879879184174189] router decoding headers:

In the above log, when "load DNS cache complete, continuing", looks like it didn't check the fact that a filter previously returned 1(FilterDataStatus::StopIterationAndBuffer) for the request body. Can someone confirm if this is a bug? I can provide the repro code if needed.

[alyssawilk]

Just to get a bit more detail on this, it looks like you tried to stop iteration on the request body but your logs show that after DNS succeeded the router continued processing request headers.

If you tell Envoy to stop iteration on the body it doesn't stop processing headers, but it should hold back the body until you're done processing that. Are you seeing the body processed as well or was there a misunderstanding on what you're trying to pause?

[dandlake]

Thank you for looking into this, @alyssawilk. Yes, your description matches my intention. In other words, I want to sanitize request body before it's sent to upstream. It's ok if the request headers are continued and sent to upstream.

For "Are you seeing the body processed as well", I think so. The whole request body were sent to upstream without waiting for the callout reply. This problem only happens when envoy is running as dynamic forward proxy. With the same filter code, if I run envoy as reverse-proxy, the request body was held until I do resume_http_request() in the callout reply. That's why I suspect it's a bug in dynamic forward proxy when DNS is completed and filters are continued.

[alyssawilk]

hm, the logs pasted only show forwarding the headers. any chance you have a more complete trace of this happening?

[dandlake]

Yes. Here is the complete trace and my filter code:

[2021-08-03 07:41:41.584][594068][debug][conn_handler] [source/server/active_tcp_listener.cc:332] [C0] new connection from 127.0.0.1:49960
[2021-08-03 07:41:41.584][594068][trace][connection] [source/common/network/connection_impl.cc:552] [C0] socket event: 3
[2021-08-03 07:41:41.584][594068][trace][connection] [source/common/network/connection_impl.cc:661] [C0] write ready
[2021-08-03 07:41:41.584][594068][trace][connection] [source/common/network/connection_impl.cc:590] [C0] read ready. dispatch_buffered_data=false
[2021-08-03 07:41:41.584][594068][trace][connection] [source/common/network/raw_buffer_socket.cc:24] [C0] read returns: 227
[2021-08-03 07:41:41.584][594068][trace][connection] [source/common/network/raw_buffer_socket.cc:38] [C0] read error: Resource temporarily unavailable
[2021-08-03 07:41:41.585][594068][trace][http] [source/common/http/http1/codec_impl.cc:564] [C0] parsing 227 bytes
[2021-08-03 07:41:41.585][594068][trace][http] [source/common/http/http1/codec_impl.cc:843] [C0] message begin
[2021-08-03 07:41:41.585][594068][debug][http] [source/common/http/conn_manager_impl.cc:274] [C0] new stream
[2021-08-03 07:41:41.585][594068][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x444afcea0850 for 300000ms, min is 300000ms
[2021-08-03 07:41:41.586][594068][trace][http] [source/common/http/http1/codec_impl.cc:484] [C0] completed header: key=Host value=myserver.com:9100
[2021-08-03 07:41:41.586][594068][trace][http] [source/common/http/http1/codec_impl.cc:484] [C0] completed header: key=User-Agent value=curl/7.68.0
[2021-08-03 07:41:41.586][594068][trace][http] [source/common/http/http1/codec_impl.cc:484] [C0] completed header: key=Accept value=*/*
[2021-08-03 07:41:41.586][594068][trace][http] [source/common/http/http1/codec_impl.cc:484] [C0] completed header: key=Proxy-Connection value=Keep-Alive
[2021-08-03 07:41:41.586][594068][trace][http] [source/common/http/http1/codec_impl.cc:484] [C0] completed header: key=Content-Type value=application/json
[2021-08-03 07:41:41.586][594068][trace][http] [source/common/http/http1/codec_impl.cc:694] [C0] onHeadersCompleteBase
[2021-08-03 07:41:41.586][594068][trace][http] [source/common/http/http1/codec_impl.cc:484] [C0] completed header: key=Content-Length value=32
[2021-08-03 07:41:41.586][594068][trace][http] [source/common/http/http1/codec_impl.cc:1041] [C0] Server: onHeadersComplete size=6
[2021-08-03 07:41:41.586][594068][debug][http] [source/common/http/conn_manager_impl.cc:872] [C0][S12839156143591365990] request headers complete (end_stream=false):
':authority', 'myserver.com:9100'
':scheme', 'http'
':path', '/predict'
':method', 'POST'
'user-agent', 'curl/7.68.0'
'accept', '*/*'
'proxy-connection', 'Keep-Alive'
'content-type', 'application/json'
'content-length', '32'

[2021-08-03 07:41:41.586][594068][trace][http] [source/common/http/filter_manager.cc:527] [C0][S12839156143591365990] decodeHeaders loop filter=0x444afcea08c0
[2021-08-03 07:41:41.586][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host->vm] proxy_on_context_create(2, 1)
[2021-08-03 07:41:41.587][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host<-vm] proxy_on_context_create return: void
[2021-08-03 07:41:41.587][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host->vm] proxy_on_request_headers(2, 10)
[2021-08-03 07:41:41.589][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [vm->host] env.proxy_get_header_map_pairs(0, 1048448, 1048452)
[2021-08-03 07:41:41.589][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host->vm] malloc(309)
[2021-08-03 07:41:41.591][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host<-vm] malloc return: 1114248
[2021-08-03 07:41:41.591][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [vm<-host] env.proxy_get_header_map_pairs return: 0
[2021-08-03 07:41:41.591][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [vm->host] env.proxy_log(1, 1115488, 330)
[2021-08-03 07:41:41.591][594068][debug][wasm] [source/extensions/common/wasm/context.cc:1215] wasm log test test: on_http_request_headers: [(":authority", "myserver.com:9100"), (":scheme", "http"), (":path", "/predict"), (":method", "POST"), ("user-agent", "curl/7.68.0"), ("accept", "*/*"), ("content-type", "application/json"), ("content-length", "32"), ("x-forwarded-proto", "http"), ("x-request-id", "55097614-592a-49b9-bc04-0adf64ddfb4d")]
[2021-08-03 07:41:41.591][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [vm<-host] env.proxy_log return: 0
[2021-08-03 07:41:41.592][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host<-vm] proxy_on_request_headers return: 0
[2021-08-03 07:41:41.592][594068][trace][http] [source/common/http/filter_manager.cc:546] [C0][S12839156143591365990] decode headers called: filter=0x444afcea08c0 status=0
[2021-08-03 07:41:41.592][594068][trace][http] [source/common/http/filter_manager.cc:527] [C0][S12839156143591365990] decodeHeaders loop filter=0x444afcea09a0
[2021-08-03 07:41:41.592][594068][debug][forward_proxy] [source/extensions/common/dynamic_forward_proxy/dns_cache_impl.cc:101] thread local lookup for host 'myserver.com:9100'
[2021-08-03 07:41:41.592][594068][debug][forward_proxy] [source/extensions/common/dynamic_forward_proxy/dns_cache_impl.cc:122] cache miss for host 'myserver.com:9100', posting to main thread
[2021-08-03 07:41:41.592][594068][debug][forward_proxy] [source/extensions/filters/http/dynamic_forward_proxy/proxy_filter.cc:128] [C0][S12839156143591365990] waiting to load DNS cache entry
[2021-08-03 07:41:41.592][594068][trace][http] [source/common/http/filter_manager.cc:546] [C0][S12839156143591365990] decode headers called: filter=0x444afcea09a0 status=4
[2021-08-03 07:41:41.592][594068][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x444afcea0850 for 300000ms, min is 300000ms
[2021-08-03 07:41:41.592][594068][trace][http] [source/common/http/http1/codec_impl.cc:821] [C0] message complete
[2021-08-03 07:41:41.592][594068][trace][http] [source/common/http/http1/codec_impl.cc:1132] [C0] body size=32
[2021-08-03 07:41:41.592][594044][debug][forward_proxy] [source/extensions/common/dynamic_forward_proxy/dns_cache_impl.cc:269] starting main thread resolve for host='myserver.com:9100' dns='myserver.com' port='9100'
[2021-08-03 07:41:41.592][594068][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x444afcea0850 for 300000ms, min is 300000ms
[2021-08-03 07:41:41.592][594068][trace][http] [source/common/http/filter_manager.cc:620] [C0][S12839156143591365990] decodeData loop filter=0x444afcea08c0
[2021-08-03 07:41:41.592][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host->vm] proxy_on_request_body(2, 32, 0)
[2021-08-03 07:41:41.592][594044][trace][upstream] [source/common/network/dns_impl.cc:219] Setting DNS resolution timer for 5000 milliseconds
[2021-08-03 07:41:41.593][594044][debug][forward_proxy] [source/extensions/common/dynamic_forward_proxy/dns_cache_impl.cc:287] main thread resolve complete for host 'myserver.com:9100'. 1 results
[2021-08-03 07:41:41.593][594044][debug][forward_proxy] [source/extensions/common/dynamic_forward_proxy/dns_cache_impl.cc:326] host 'myserver.com:9100' address has changed
[2021-08-03 07:41:41.593][594044][debug][upstream] [source/extensions/clusters/dynamic_forward_proxy/cluster.cc:104] Adding host info for myserver.com:9100
[2021-08-03 07:41:41.593][594044][debug][upstream] [source/extensions/clusters/dynamic_forward_proxy/cluster.cc:83] adding new dfproxy cluster host 'myserver.com:9100'
[2021-08-03 07:41:41.593][594044][debug][upstream] [source/common/upstream/upstream_impl.cc:257] transport socket match, socket default selected for host with address 10.5.17.41:9100
[2021-08-03 07:41:41.593][594044][trace][upstream] [source/common/upstream/upstream_impl.cc:1358] Local locality: 
[2021-08-03 07:41:41.593][594044][debug][upstream] [source/common/upstream/cluster_manager_impl.cc:1250] membership update for TLS cluster dynamic_forward_proxy_cluster added 1 removed 0
[2021-08-03 07:41:41.593][594044][debug][upstream] [source/common/upstream/cluster_manager_impl.cc:1257] re-creating local LB for TLS cluster dynamic_forward_proxy_cluster
[2021-08-03 07:41:41.593][594067][debug][upstream] [source/common/upstream/cluster_manager_impl.cc:1250] membership update for TLS cluster dynamic_forward_proxy_cluster added 1 removed 0
[2021-08-03 07:41:41.593][594044][debug][forward_proxy] [source/extensions/common/dynamic_forward_proxy/dns_cache_impl.cc:345] DNS refresh rate reset for host 'myserver.com:9100', refresh rate 60000 ms
[2021-08-03 07:41:41.593][594067][debug][upstream] [source/common/upstream/cluster_manager_impl.cc:1257] re-creating local LB for TLS cluster dynamic_forward_proxy_cluster
[2021-08-03 07:41:41.594][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [vm->host] env.proxy_log(1, 1114248, 54)
[2021-08-03 07:41:41.594][594068][debug][wasm] [source/extensions/common/wasm/context.cc:1215] wasm log test test: on_http_request_body: body_size 32 end_of_stream false
[2021-08-03 07:41:41.594][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [vm<-host] env.proxy_log return: 0
[2021-08-03 07:41:41.595][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host<-vm] proxy_on_request_body return: 1
[2021-08-03 07:41:41.595][594068][trace][http] [source/common/http/filter_manager.cc:683] [C0][S12839156143591365990] decode data called: filter=0x444afcea08c0 status=1
[2021-08-03 07:41:41.595][594068][trace][http] [source/common/http/filter_manager.cc:208] return false 2
[2021-08-03 07:41:41.595][594068][trace][http] [source/common/http/filter_manager.cc:698] [C0][S12839156143591365990] filter=0x444afcea08c0 status=1, return here.
[2021-08-03 07:41:41.595][594068][trace][connection] [source/common/network/connection_impl.cc:354] [C0] readDisable: disable=true disable_count=0 state=0 buffer_length=227
[2021-08-03 07:41:41.595][594068][debug][http] [source/common/http/filter_manager.cc:817] [C0][S12839156143591365990] request end stream
[2021-08-03 07:41:41.595][594068][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x444afcea0850 for 300000ms, min is 300000ms
[2021-08-03 07:41:41.595][594068][trace][http] [source/common/http/filter_manager.cc:620] [C0][S12839156143591365990] decodeData loop filter=0x444afcea08c0
[2021-08-03 07:41:41.595][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host->vm] proxy_on_request_body(2, 32, 1)
[2021-08-03 07:41:41.595][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [vm->host] env.proxy_log(1, 1114248, 53)
[2021-08-03 07:41:41.595][594068][debug][wasm] [source/extensions/common/wasm/context.cc:1215] wasm log test test: on_http_request_body: body_size 32 end_of_stream true
[2021-08-03 07:41:41.595][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [vm<-host] env.proxy_log return: 0
[2021-08-03 07:41:41.595][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [vm->host] env.proxy_http_call(1050536, 7, 1114304, 78, 0, 0, 1114248, 4, 5000, 1048452)
[2021-08-03 07:41:41.595][594068][debug][router] [source/common/router/router.cc:448] [C0][S1704033592469637009] cluster 'httpbin' match for URL '/bytes/1'
[2021-08-03 07:41:41.595][594068][debug][router] [source/common/router/router.cc:634] [C0][S1704033592469637009] router decoding headers:
':method', 'GET'
':path', '/bytes/1'
':authority', 'httpbin.org'
':scheme', 'http'
'x-envoy-internal', 'true'
'x-forwarded-for', '10.5.76.100'
'x-envoy-expected-rq-timeout-ms', '5000'

[2021-08-03 07:41:41.595][594068][debug][pool] [source/common/http/conn_pool_base.cc:74] queueing stream due to no available connections
[2021-08-03 07:41:41.595][594068][debug][pool] [source/common/conn_pool/conn_pool_base.cc:241] trying to create new connection
[2021-08-03 07:41:41.595][594068][trace][pool] [source/common/conn_pool/conn_pool_base.cc:242] ConnPoolImplBase 0x444afd938160, ready_clients_.size(): 0, busy_clients_.size(): 0, connecting_clients_.size(): 0, connecting_stream_capacity_: 0, num_active_streams_: 0, pending_streams_.size(): 1 per upstream preconnect ratio: 1
[2021-08-03 07:41:41.595][594068][debug][pool] [source/common/conn_pool/conn_pool_base.cc:139] creating a new connection
[2021-08-03 07:41:41.596][594068][debug][client] [source/common/http/codec_client.cc:60] [C1] connecting
[2021-08-03 07:41:41.596][594068][debug][connection] [source/common/network/connection_impl.cc:866] [C1] connecting to 52.201.75.114:80
[2021-08-03 07:41:41.596][594068][debug][connection] [source/common/network/connection_impl.cc:884] [C1] connection in progress
[2021-08-03 07:41:41.596][594068][trace][pool] [source/common/conn_pool/conn_pool_base.cc:125] not creating a new connection, shouldCreateNewConnection returned false.
[2021-08-03 07:41:41.596][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [vm<-host] env.proxy_http_call return: 0
[2021-08-03 07:41:41.596][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [vm->host] env.proxy_log(0, 1114248, 18)
[2021-08-03 07:41:41.596][594068][trace][wasm] [source/extensions/common/wasm/context.cc:1212] wasm log test test: pause request body
[2021-08-03 07:41:41.596][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [vm<-host] env.proxy_log return: 0
[2021-08-03 07:41:41.596][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host<-vm] proxy_on_request_body return: 1
[2021-08-03 07:41:41.596][594068][trace][http] [source/common/http/filter_manager.cc:683] [C0][S12839156143591365990] decode data called: filter=0x444afcea08c0 status=1
[2021-08-03 07:41:41.596][594068][trace][http] [source/common/http/filter_manager.cc:208] return false 2
[2021-08-03 07:41:41.596][594068][trace][http] [source/common/http/filter_manager.cc:698] [C0][S12839156143591365990] filter=0x444afcea08c0 status=1, return here.
[2021-08-03 07:41:41.596][594068][trace][http] [source/common/http/http1/codec_impl.cc:613] [C0] parsed 227 bytes
[2021-08-03 07:41:41.596][594068][debug][upstream] [source/common/upstream/cluster_manager_impl.cc:1250] membership update for TLS cluster dynamic_forward_proxy_cluster added 1 removed 0
[2021-08-03 07:41:41.596][594068][debug][upstream] [source/common/upstream/cluster_manager_impl.cc:1257] re-creating local LB for TLS cluster dynamic_forward_proxy_cluster
[2021-08-03 07:41:41.596][594068][debug][forward_proxy] [source/extensions/filters/http/dynamic_forward_proxy/proxy_filter.cc:142] [C0][S12839156143591365990] load DNS cache complete, continuing
[2021-08-03 07:41:41.596][594068][trace][http] [source/common/http/filter_manager.cc:70] [C0][S12839156143591365990] continuing filter chain: filter=0x444afcea09a0
[2021-08-03 07:41:41.596][594068][trace][http] [source/common/http/filter_manager.cc:527] [C0][S12839156143591365990] decodeHeaders loop filter=0x444afcea0a10
[2021-08-03 07:41:41.596][594068][debug][router] [source/common/router/router.cc:448] [C0][S12839156143591365990] cluster 'dynamic_forward_proxy_cluster' match for URL '/predict'
[2021-08-03 07:41:41.597][594068][debug][router] [source/common/router/router.cc:634] [C0][S12839156143591365990] router decoding headers:
':authority', 'myserver.com:9100'
':scheme', 'http'
':path', '/predict'
':method', 'POST'
'user-agent', 'curl/7.68.0'
'accept', '*/*'
'content-type', 'application/json'
'content-length', '32'
'x-forwarded-proto', 'http'
'x-request-id', '55097614-592a-49b9-bc04-0adf64ddfb4d'
'x-envoy-expected-rq-timeout-ms', '15000'

[2021-08-03 07:41:41.597][594068][debug][pool] [source/common/http/conn_pool_base.cc:74] queueing stream due to no available connections
[2021-08-03 07:41:41.597][594068][debug][pool] [source/common/conn_pool/conn_pool_base.cc:241] trying to create new connection
[2021-08-03 07:41:41.597][594068][trace][pool] [source/common/conn_pool/conn_pool_base.cc:242] ConnPoolImplBase 0x444afd938000, ready_clients_.size(): 0, busy_clients_.size(): 0, connecting_clients_.size(): 0, connecting_stream_capacity_: 0, num_active_streams_: 0, pending_streams_.size(): 1 per upstream preconnect ratio: 1
[2021-08-03 07:41:41.597][594068][debug][pool] [source/common/conn_pool/conn_pool_base.cc:139] creating a new connection
[2021-08-03 07:41:41.597][594068][debug][client] [source/common/http/codec_client.cc:60] [C2] connecting
[2021-08-03 07:41:41.597][594068][debug][connection] [source/common/network/connection_impl.cc:866] [C2] connecting to 10.5.17.41:9100
[2021-08-03 07:41:41.598][594068][debug][connection] [source/common/network/connection_impl.cc:884] [C2] connection in progress
[2021-08-03 07:41:41.598][594068][trace][pool] [source/common/conn_pool/conn_pool_base.cc:125] not creating a new connection, shouldCreateNewConnection returned false.
[2021-08-03 07:41:41.598][594068][trace][http] [source/common/http/filter_manager.cc:546] [C0][S12839156143591365990] decode headers called: filter=0x444afcea0a10 status=1
[2021-08-03 07:41:41.598][594068][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x444afcea0850 for 300000ms, min is 300000ms
[2021-08-03 07:41:41.598][594068][trace][http] [source/common/http/filter_manager.cc:620] [C0][S12839156143591365990] decodeData loop filter=0x444afcea09a0
[2021-08-03 07:41:41.598][594068][trace][http] [source/common/http/filter_manager.cc:683] [C0][S12839156143591365990] decode data called: filter=0x444afcea09a0 status=0
[2021-08-03 07:41:41.598][594068][trace][http] [source/common/http/filter_manager.cc:212] return true
[2021-08-03 07:41:41.598][594068][trace][http] [source/common/http/filter_manager.cc:620] [C0][S12839156143591365990] decodeData loop filter=0x444afcea0a10
[2021-08-03 07:41:41.598][594068][trace][router] [source/common/router/upstream_request.cc:235] [C0][S12839156143591365990] buffering 32 bytes
[2021-08-03 07:41:41.598][594068][trace][http] [source/common/http/filter_manager.cc:683] [C0][S12839156143591365990] decode data called: filter=0x444afcea0a10 status=3
[2021-08-03 07:41:41.598][594068][trace][http] [source/common/http/filter_manager.cc:208] return false 2
[2021-08-03 07:41:41.598][594068][trace][connection] [source/common/network/connection_impl.cc:552] [C0] socket event: 2
[2021-08-03 07:41:41.598][594068][trace][connection] [source/common/network/connection_impl.cc:661] [C0] write ready
[2021-08-03 07:41:41.599][594068][trace][connection] [source/common/network/connection_impl.cc:552] [C2] socket event: 2
[2021-08-03 07:41:41.599][594068][trace][connection] [source/common/network/connection_impl.cc:661] [C2] write ready
[2021-08-03 07:41:41.599][594068][debug][connection] [source/common/network/connection_impl.cc:670] [C2] connected
[2021-08-03 07:41:41.599][594068][trace][connection] [source/common/network/connection_impl.cc:415] [C2] raising connection event 2
[2021-08-03 07:41:41.599][594068][debug][client] [source/common/http/codec_client.cc:88] [C2] connected
[2021-08-03 07:41:41.599][594068][debug][pool] [source/common/conn_pool/conn_pool_base.cc:285] [C2] attaching to next stream
[2021-08-03 07:41:41.599][594068][debug][pool] [source/common/conn_pool/conn_pool_base.cc:171] [C2] creating stream
[2021-08-03 07:41:41.599][594068][debug][router] [source/common/router/upstream_request.cc:386] [C0][S12839156143591365990] pool ready
[2021-08-03 07:41:41.599][594068][trace][connection] [source/common/network/connection_impl.cc:475] [C2] writing 257 bytes, end_stream false
[2021-08-03 07:41:41.599][594068][trace][connection] [source/common/network/connection_impl.cc:475] [C2] writing 32 bytes, end_stream false
[2021-08-03 07:41:41.599][594068][trace][connection] [source/common/network/connection_impl.cc:661] [C2] write ready
[2021-08-03 07:41:41.599][594068][trace][connection] [source/common/network/raw_buffer_socket.cc:67] [C2] write returns: 289
[2021-08-03 07:41:41.599][594068][trace][connection] [source/common/network/connection_impl.cc:552] [C2] socket event: 2
[2021-08-03 07:41:41.599][594068][trace][connection] [source/common/network/connection_impl.cc:661] [C2] write ready
[2021-08-03 07:41:41.618][594068][trace][connection] [source/common/network/connection_impl.cc:552] [C2] socket event: 3
[2021-08-03 07:41:41.618][594068][trace][connection] [source/common/network/connection_impl.cc:661] [C2] write ready
[2021-08-03 07:41:41.618][594068][trace][connection] [source/common/network/connection_impl.cc:590] [C2] read ready. dispatch_buffered_data=false
[2021-08-03 07:41:41.618][594068][trace][connection] [source/common/network/raw_buffer_socket.cc:24] [C2] read returns: 137
[2021-08-03 07:41:41.618][594068][trace][connection] [source/common/network/raw_buffer_socket.cc:38] [C2] read error: Resource temporarily unavailable
[2021-08-03 07:41:41.618][594068][trace][http] [source/common/http/http1/codec_impl.cc:564] [C2] parsing 137 bytes
[2021-08-03 07:41:41.618][594068][trace][http] [source/common/http/http1/codec_impl.cc:843] [C2] message begin
[2021-08-03 07:41:41.619][594068][trace][http] [source/common/http/http1/codec_impl.cc:484] [C2] completed header: key=Date value=Tue, 03 Aug 2021 07:41:41 GMT
[2021-08-03 07:41:41.619][594068][trace][http] [source/common/http/http1/codec_impl.cc:484] [C2] completed header: key=Content-Length value=20
[2021-08-03 07:41:41.619][594068][trace][http] [source/common/http/http1/codec_impl.cc:694] [C2] onHeadersCompleteBase
[2021-08-03 07:41:41.619][594068][trace][http] [source/common/http/http1/codec_impl.cc:484] [C2] completed header: key=Content-Type value=text/plain; charset=utf-8
[2021-08-03 07:41:41.619][594068][trace][http] [source/common/http/http1/codec_impl.cc:1268] [C2] status_code 200
[2021-08-03 07:41:41.619][594068][trace][http] [source/common/http/http1/codec_impl.cc:1278] [C2] Client: onHeadersComplete size=3
[2021-08-03 07:41:41.619][594068][debug][router] [source/common/router/router.cc:1234] [C0][S12839156143591365990] upstream headers complete: end_stream=false
[2021-08-03 07:41:41.621][594068][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x444afcea0850 for 300000ms, min is 300000ms
[2021-08-03 07:41:41.621][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host->vm] proxy_on_response_headers(2, 5)
[2021-08-03 07:41:41.623][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host<-vm] proxy_on_response_headers return: 0
[2021-08-03 07:41:41.623][594068][trace][http] [source/common/http/filter_manager.cc:1077] [C0][S12839156143591365990] encode headers called: filter=0x444afcea0930 status=0
[2021-08-03 07:41:41.623][594068][debug][http] [source/common/http/conn_manager_impl.cc:1471] [C0][S12839156143591365990] encoding headers via codec (end_stream=false):
':status', '200'
'date', 'Tue, 03 Aug 2021 07:41:41 GMT'
'content-length', '20'
'content-type', 'text/plain; charset=utf-8'
'x-envoy-upstream-service-time', '21'
'server', 'envoy'

[2021-08-03 07:41:41.623][594068][trace][connection] [source/common/network/connection_impl.cc:475] [C0] writing 167 bytes, end_stream false
[2021-08-03 07:41:41.623][594068][trace][http] [source/common/http/http1/codec_impl.cc:821] [C2] message complete
[2021-08-03 07:41:41.623][594068][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x444afcea0850 for 300000ms, min is 300000ms
[2021-08-03 07:41:41.623][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host->vm] proxy_on_response_body(2, 20, 0)
[2021-08-03 07:41:41.626][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host<-vm] proxy_on_response_body return: 0
[2021-08-03 07:41:41.626][594068][trace][http] [source/common/http/filter_manager.cc:1240] [C0][S12839156143591365990] encode data called: filter=0x444afcea0930 status=0
[2021-08-03 07:41:41.626][594068][trace][http] [source/common/http/filter_manager.cc:212] return true
[2021-08-03 07:41:41.626][594068][trace][http] [source/common/http/conn_manager_impl.cc:1480] [C0][S12839156143591365990] encoding data via codec (size=20 end_stream=false)
[2021-08-03 07:41:41.626][594068][trace][connection] [source/common/network/connection_impl.cc:475] [C0] writing 20 bytes, end_stream false
[2021-08-03 07:41:41.626][594068][trace][http] [source/common/http/http1/codec_impl.cc:1350] [C2] message complete
[2021-08-03 07:41:41.626][594068][debug][client] [source/common/http/codec_client.cc:130] [C2] response complete
[2021-08-03 07:41:41.626][594068][trace][main] [source/common/event/dispatcher_impl.cc:251] item added to deferred deletion list (size=1)
[2021-08-03 07:41:41.627][594068][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x444afcea0850 for 300000ms, min is 300000ms
[2021-08-03 07:41:41.627][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host->vm] proxy_on_response_body(2, 0, 1)
[2021-08-03 07:41:41.627][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host<-vm] proxy_on_response_body return: 0
[2021-08-03 07:41:41.627][594068][trace][http] [source/common/http/filter_manager.cc:1240] [C0][S12839156143591365990] encode data called: filter=0x444afcea0930 status=0
[2021-08-03 07:41:41.627][594068][trace][http] [source/common/http/filter_manager.cc:212] return true
[2021-08-03 07:41:41.627][594068][trace][http] [source/common/http/conn_manager_impl.cc:1480] [C0][S12839156143591365990] encoding data via codec (size=0 end_stream=true)
[2021-08-03 07:41:41.627][594068][trace][connection] [source/common/network/connection_impl.cc:354] [C0] readDisable: disable=false disable_count=1 state=0 buffer_length=0
[2021-08-03 07:41:41.628][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host->vm] proxy_on_log(2)
[2021-08-03 07:41:41.629][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host<-vm] proxy_on_log return: void
[2021-08-03 07:41:41.630][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host->vm] proxy_on_done(2)
[2021-08-03 07:41:41.631][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host<-vm] proxy_on_done return: 1
[2021-08-03 07:41:41.631][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host->vm] proxy_on_delete(2)
[2021-08-03 07:41:41.632][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host<-vm] proxy_on_delete return: void
[2021-08-03 07:41:41.632][594068][trace][main] [source/common/event/dispatcher_impl.cc:251] item added to deferred deletion list (size=2)
[2021-08-03 07:41:41.632][594068][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x444afcea0770 for 3600000ms, min is 3600000ms
[2021-08-03 07:41:41.632][594068][debug][pool] [source/common/http/http1/conn_pool.cc:53] [C2] response complete
[2021-08-03 07:41:41.632][594068][debug][pool] [source/common/conn_pool/conn_pool_base.cc:200] [C2] destroying stream: 0 remaining
[2021-08-03 07:41:41.632][594068][trace][http] [source/common/http/http1/codec_impl.cc:613] [C2] parsed 137 bytes
[2021-08-03 07:41:41.632][594068][trace][main] [source/common/event/dispatcher_impl.cc:115] clearing deferred deletion list (size=2)
[2021-08-03 07:41:41.632][594068][trace][connection] [source/common/network/connection_impl.cc:552] [C0] socket event: 2
[2021-08-03 07:41:41.632][594068][trace][connection] [source/common/network/connection_impl.cc:661] [C0] write ready
[2021-08-03 07:41:41.632][594068][trace][connection] [source/common/network/raw_buffer_socket.cc:67] [C0] write returns: 187
[2021-08-03 07:41:41.632][594068][trace][connection] [source/common/network/connection_impl.cc:552] [C0] socket event: 3
[2021-08-03 07:41:41.632][594068][trace][connection] [source/common/network/connection_impl.cc:661] [C0] write ready
[2021-08-03 07:41:41.632][594068][trace][connection] [source/common/network/connection_impl.cc:590] [C0] read ready. dispatch_buffered_data=false
[2021-08-03 07:41:41.633][594068][trace][connection] [source/common/network/raw_buffer_socket.cc:24] [C0] read returns: 0
[2021-08-03 07:41:41.633][594068][debug][connection] [source/common/network/connection_impl.cc:638] [C0] remote close
[2021-08-03 07:41:41.633][594068][debug][connection] [source/common/network/connection_impl.cc:248] [C0] closing socket: 0
[2021-08-03 07:41:41.633][594068][trace][connection] [source/common/network/connection_impl.cc:415] [C0] raising connection event 0
[2021-08-03 07:41:41.633][594068][debug][conn_handler] [source/server/active_tcp_listener.cc:76] [C0] adding to cleanup list
[2021-08-03 07:41:41.633][594068][trace][main] [source/common/event/dispatcher_impl.cc:251] item added to deferred deletion list (size=1)
[2021-08-03 07:41:41.633][594068][trace][main] [source/common/event/dispatcher_impl.cc:251] item added to deferred deletion list (size=2)
[2021-08-03 07:41:41.633][594068][trace][main] [source/common/event/dispatcher_impl.cc:115] clearing deferred deletion list (size=2)
[2021-08-03 07:41:41.670][594068][trace][connection] [source/common/network/connection_impl.cc:552] [C1] socket event: 2
[2021-08-03 07:41:41.670][594068][trace][connection] [source/common/network/connection_impl.cc:661] [C1] write ready
[2021-08-03 07:41:41.670][594068][debug][connection] [source/common/network/connection_impl.cc:670] [C1] connected
[2021-08-03 07:41:41.670][594068][trace][connection] [source/common/network/connection_impl.cc:415] [C1] raising connection event 2
[2021-08-03 07:41:41.670][594068][debug][client] [source/common/http/codec_client.cc:88] [C1] connected
[2021-08-03 07:41:41.671][594068][debug][pool] [source/common/conn_pool/conn_pool_base.cc:285] [C1] attaching to next stream
[2021-08-03 07:41:41.671][594068][debug][pool] [source/common/conn_pool/conn_pool_base.cc:171] [C1] creating stream
[2021-08-03 07:41:41.671][594068][debug][router] [source/common/router/upstream_request.cc:386] [C0][S1704033592469637009] pool ready
[2021-08-03 07:41:41.671][594068][trace][connection] [source/common/network/connection_impl.cc:475] [C1] writing 136 bytes, end_stream false
[2021-08-03 07:41:41.671][594068][trace][connection] [source/common/network/connection_impl.cc:661] [C1] write ready
[2021-08-03 07:41:41.671][594068][trace][connection] [source/common/network/raw_buffer_socket.cc:67] [C1] write returns: 136
[2021-08-03 07:41:41.671][594068][trace][connection] [source/common/network/connection_impl.cc:552] [C1] socket event: 2
[2021-08-03 07:41:41.671][594068][trace][connection] [source/common/network/connection_impl.cc:661] [C1] write ready
[2021-08-03 07:41:41.751][594068][trace][connection] [source/common/network/connection_impl.cc:552] [C1] socket event: 3
[2021-08-03 07:41:41.751][594068][trace][connection] [source/common/network/connection_impl.cc:661] [C1] write ready
[2021-08-03 07:41:41.751][594068][trace][connection] [source/common/network/connection_impl.cc:590] [C1] read ready. dispatch_buffered_data=false
[2021-08-03 07:41:41.751][594068][trace][connection] [source/common/network/raw_buffer_socket.cc:24] [C1] read returns: 237
[2021-08-03 07:41:41.751][594068][trace][connection] [source/common/network/raw_buffer_socket.cc:38] [C1] read error: Resource temporarily unavailable
[2021-08-03 07:41:41.751][594068][trace][http] [source/common/http/http1/codec_impl.cc:564] [C1] parsing 237 bytes
[2021-08-03 07:41:41.751][594068][trace][http] [source/common/http/http1/codec_impl.cc:843] [C1] message begin
[2021-08-03 07:41:41.751][594068][trace][http] [source/common/http/http1/codec_impl.cc:484] [C1] completed header: key=Date value=Tue, 03 Aug 2021 07:41:41 GMT
[2021-08-03 07:41:41.751][594068][trace][http] [source/common/http/http1/codec_impl.cc:484] [C1] completed header: key=Content-Type value=application/octet-stream
[2021-08-03 07:41:41.751][594068][trace][http] [source/common/http/http1/codec_impl.cc:484] [C1] completed header: key=Content-Length value=1
[2021-08-03 07:41:41.751][594068][trace][http] [source/common/http/http1/codec_impl.cc:484] [C1] completed header: key=Connection value=keep-alive
[2021-08-03 07:41:41.751][594068][trace][http] [source/common/http/http1/codec_impl.cc:484] [C1] completed header: key=Server value=gunicorn/19.9.0
[2021-08-03 07:41:41.751][594068][trace][http] [source/common/http/http1/codec_impl.cc:484] [C1] completed header: key=Access-Control-Allow-Origin value=*
[2021-08-03 07:41:41.751][594068][trace][http] [source/common/http/http1/codec_impl.cc:694] [C1] onHeadersCompleteBase
[2021-08-03 07:41:41.751][594068][trace][http] [source/common/http/http1/codec_impl.cc:484] [C1] completed header: key=Access-Control-Allow-Credentials value=true
[2021-08-03 07:41:41.751][594068][trace][http] [source/common/http/http1/codec_impl.cc:1268] [C1] status_code 200
[2021-08-03 07:41:41.751][594068][trace][http] [source/common/http/http1/codec_impl.cc:1278] [C1] Client: onHeadersComplete size=7
[2021-08-03 07:41:41.751][594068][debug][router] [source/common/router/router.cc:1234] [C0][S1704033592469637009] upstream headers complete: end_stream=false
[2021-08-03 07:41:41.753][594068][debug][http] [source/common/http/async_client_impl.cc:104] async http request response headers (end_stream=false):
':status', '200'
'date', 'Tue, 03 Aug 2021 07:41:41 GMT'
'content-type', 'application/octet-stream'
'content-length', '1'
'connection', 'keep-alive'
'server', 'gunicorn/19.9.0'
'access-control-allow-origin', '*'
'access-control-allow-credentials', 'true'
'x-envoy-upstream-service-time', '155'

[2021-08-03 07:41:41.753][594068][trace][http] [source/common/http/http1/codec_impl.cc:821] [C1] message complete
[2021-08-03 07:41:41.753][594068][trace][http] [source/common/http/async_client_impl.cc:121] async http request response data (length=1 end_stream=false)
[2021-08-03 07:41:41.753][594068][trace][http] [source/common/http/http1/codec_impl.cc:1350] [C1] message complete
[2021-08-03 07:41:41.753][594068][debug][client] [source/common/http/codec_client.cc:130] [C1] response complete
[2021-08-03 07:41:41.753][594068][trace][main] [source/common/event/dispatcher_impl.cc:251] item added to deferred deletion list (size=1)
[2021-08-03 07:41:41.754][594068][trace][http] [source/common/http/async_client_impl.cc:121] async http request response data (length=0 end_stream=true)
[2021-08-03 07:41:41.754][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host->vm] proxy_on_http_call_response(1, 1, 9, 1, 0)
[2021-08-03 07:41:41.757][594068][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host<-vm] proxy_on_http_call_response return: void
[2021-08-03 07:41:41.757][594068][trace][main] [source/common/event/dispatcher_impl.cc:251] item added to deferred deletion list (size=2)
[2021-08-03 07:41:41.757][594068][debug][pool] [source/common/http/http1/conn_pool.cc:53] [C1] response complete
[2021-08-03 07:41:41.757][594068][debug][pool] [source/common/conn_pool/conn_pool_base.cc:200] [C1] destroying stream: 0 remaining
[2021-08-03 07:41:41.757][594068][trace][http] [source/common/http/http1/codec_impl.cc:613] [C1] parsed 237 bytes
[2021-08-03 07:41:41.757][594068][trace][main] [source/common/event/dispatcher_impl.cc:115] clearing deferred deletion list (size=2)
[2021-08-03 07:41:45.944][594044][debug][main] [source/server/server.cc:215] flushing stats
[2021-08-03 07:41:50.947][594044][debug][main] [source/server/server.cc:215] flushing stats
[2021-08-03 07:41:55.955][594044][debug][main] [source/server/server.cc:215] flushing stats
[2021-08-03 07:42:00.938][594044][debug][upstream] [source/common/upstream/logical_dns_cluster.cc:107] starting async DNS resolution for httpbin.org
[2021-08-03 07:42:00.939][594044][trace][upstream] [source/common/network/dns_impl.cc:219] Setting DNS resolution timer for 5000 milliseconds
[2021-08-03 07:42:00.954][594044][debug][upstream] [source/common/upstream/logical_dns_cluster.cc:115] async DNS resolution complete for httpbin.org
[2021-08-03 07:42:00.954][594044][debug][upstream] [source/common/upstream/logical_dns_cluster.cc:161] DNS refresh rate reset for httpbin.org, refresh rate 30000 ms
[2021-08-03 07:42:00.959][594044][debug][main] [source/server/server.cc:215] flushing stats
[2021-08-03 07:42:05.963][594044][debug][main] [source/server/server.cc:215] flushing stats

And below is my filter code in rust, which is based on https://github.com/proxy-wasm/proxy-wasm-rust-sdk/blob/master/examples/http_auth_random.rs

use log::*;
use proxy_wasm::traits::*;
use proxy_wasm::types::*;
use std::time::Duration;

#[no_mangle]
pub fn _start() {
    proxy_wasm::set_log_level(LogLevel::Trace);
    proxy_wasm::set_http_context(|_, _| -> Box<dyn HttpContext> { Box::new(HttpAuthRandom) });
}

struct HttpAuthRandom;

impl HttpContext for HttpAuthRandom {
    fn on_http_request_headers(&mut self, _: usize) -> Action {
        debug!(
            "on_http_request_headers: {:?}",
            self.get_http_request_headers()
        );
        Action::Continue
    }

    fn on_http_request_body(&mut self, body_size: usize, end_of_stream: bool) -> Action {
        debug!(
            "on_http_request_body: body_size {} end_of_stream {}",
            body_size, end_of_stream
        );
        if !end_of_stream {
            // Wait -- we'll be called again when the complete body is buffered
            // at the host side.
            return Action::Pause;
        }
        self.dispatch_http_call(
            "httpbin",
            vec![
                (":method", "GET"),
                (":path", "/bytes/1"),
                (":authority", "httpbin.org"),
            ],
            None,
            vec![],
            Duration::from_secs(5),
        )
        .unwrap();
        trace!("pause request body");
        Action::Pause
    }
}

impl Context for HttpAuthRandom {
    fn on_http_call_response(&mut self, _: u32, _: usize, _body_size: usize, _: usize) {
        trace!("on_http_call_response. block it");
        self.send_http_response(403, vec![], Some(b"Access forbidden.\n"));
    }
}

[alyssawilk]

I'm no wasm expert but I think the DFP is doing the correct thing here, so maybe @mathetake or @PiotrSikora can take a look at the rust?

From a C++ perspective, DFP does call commonContinue() when it gets the DNS resolution, but commonContinue should detect that the wasm filter returned StopIterationAndSomething and continue to not forward data. I believe https://github.com/envoyproxy/envoy/pull/17580 regression tests that DFP is working as expected.

[PiotrSikora]

From a C++ perspective, DFP does call commonContinue() when it gets the DNS resolution, but commonContinue should detect that the wasm filter returned StopIterationAndSomething and continue to not forward data. I believe #17580 regression tests that DFP is working as expected.

DFP calls decoder_callbacks_->continueDecoding(), which is the same call that Wasm is using to resume processing.

I'm not sure how DFP could continue, but not forward data?

[PiotrSikora]

@dandlake do you have DFP configured after or before Wasm? I think it should work if you put DFP before Wasm, since then DFP will pause and resume before passing request to the next filter, so it won't interfere with the Wasm code.

Basically, I think (but I didn't verify) that with HTTP filters Wasm -> DFP -> router, the flow is:

1. HTTP request headers -> Wasm (forward) -> DFP (pause on headers).
2. HTTP request body -> Wasm (pause on body).
3. DNS resolved -> continue.
4. HTTP request headers -> DFP (continued from 3.),
5. HTTP request body -> Wasm (continued from 3.).

But with HTTP filters DFP -> Wasm -> router, the flow would be:

1. HTTP request headers -> DFP (pause on headers),
2. DNS resolved -> continue,
3. HTTP request headers -> DFP (continued from 2.) -> Wasm (forward) -> router (forward).
4. HTTP request body -> DFP (forward, no-op) -> Wasm (pause on body).

[dandlake]

I had Wasm filter before DFP, and yes, reversing the wasm and DFP filters works. Thank you for the suggestion, @PiotrSikora!

While this works, do you see any downside of putting Wasm after DFP? I tested a few cases on my side and it seems fine, but want to see if you foresee any potential issue.

On the other hand, do you think step 5 above can be fixed so that request headers are continued(in step 4) but request body remains paused(since an earlier filter paused it)? Not sure if this question is for @alyssawilk or @PiotrSikora. Any other non-wasm filter can potentially return StopIterationAndSomething for request body. Do you want to support this case? or do you require other filters stay after DFP?

[PiotrSikora]

@dandlake yeah, it's definitely a bug (so please leave this open) and the reverse order should be supported, I just wanted to unblock you, since I imagine that putting DFP first should work for 95% of use cases.

[alyssawilk]

continueDecoding is a complicated function. It's a per filter call* so should undo the pause of that specific filter. In this case if WASM paused the body and DFP paused headers and DFP resumed headers, it shouldn't result in body heading past WASM. Again I think my regression test verifies that all that logic works as intended so I'm fairly confused what's causing the issue you're experiencing. cc @mattklein123 @snowp

*hhttps://github.com/envoyproxy/envoy/blob/main/source/common/http/filter_manager.cc#L69

[PiotrSikora]

@alyssawilk right, but the "per filter" doHeaders, doData, doTrailers all call functions on the parent object: https://github.com/envoyproxy/envoy/blob/79ade4aebd02cf15bd934d6d58e90aa03ef6909e/source/common/http/filter_manager.cc#L321-L332

[github-actions[bot]]

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.

[dandlake]

@alyssawilk, @PiotrSikora Should I keep this issue open or should I leave it and let github close it?

[PiotrSikora]

Definitely leave it open, but I'm not sure if @alyssawilk or anybody else is actively working on it.

[alyssawilk]

yeah it's backburner for me so left it unassigned but I'll tag no-stalebot.