Closed
Description
Hi, I am facing some issue in response body buffering when the upstream is in http2.
In my test case, the whole response body is 25246B. In the log, looks like it's processed in 4 chunks: CHK1(8192B), CHK2(8192B), CHK3(8192B) and CHK4(670B). In my wasm filter callback, I return Action::Pause for all of them unless end_of_stream is true, so that I can accumulate the whole response body to process. The problem I am seeing is that, the 4 callbacks(with size, end_of_stream) are (8192, 0), (8192, 0), (16384, 0), (24576, 1). With these callbacks, at the last one, I only get 24576B body and missing the last 670B.
I traced into the code a bit to see how buffer accumulation happens(I am looking at the code in 1.26.8. The same behavior happens with latest 1.32 dev code too). In filter_manager.cc:FilterManager::encodeData(), looks like it calls the filter first, then if status is StopIterationAndBuffer it calls commonHandleAfterDataCallback() and commonHandleBufferData() to accumulate the buffer in FilterManager::buffered_request_data_.
FilterDataStatus status = (*entry)->handle_->encodeData(data, (*entry)->end_stream_);
...
(*entry)->commonHandleAfterDataCallback(status, data, state_.encoder_filters_streaming_)
calls (provcommonHandleBufferDataided_data);
This explains the above response body callback behavior, because buffer accumulation happens AFTER the response body callback.
My question is: what's the design here? Should the 4th callback come with end_of_stream false and have a 5th callback with end_of_stream true(after the last 670B chunk is accumulated)?
I tried to make the upstream http1 and the response body callbacks are good and I can receive the whole response body. In this http1 case, I do see an extra callback with end_of_stream true.
Here are some logs that I captured:
# grep "codec_impl\|codec_client\|proxy_on" http2.log
...
[2024-09-19 16:53:46.023][93903][trace][http2] [source/common/http/http2/codec_impl.cc:923] [C1] dispatching 25295 bytes
[2024-09-19 16:53:46.023][93903][trace][http2] [source/common/http/http2/codec_impl.cc:1030] [C1] about to recv frame type=0, flags=0, stream_id=1
[2024-09-19 16:53:46.023][93903][trace][http2] [source/common/http/http2/codec_impl.cc:1056] [C1] recv frame type=0
[2024-09-19 16:53:46.023][93903][trace][http2] [source/common/http/http2/codec_impl.cc:2013] [C1] track inbound frame type=0 flags=0 length=8192 padding_length=0
[2024-09-19 16:53:46.024][93903][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host->vm] proxy_on_response_body(2, 8192, 0)
[2024-09-19 16:53:46.026][93903][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host<-vm] proxy_on_response_body return: 1
[2024-09-19 16:53:46.026][93903][trace][http2] [source/common/http/http2/codec_impl.cc:1030] [C1] about to recv frame type=0, flags=0, stream_id=1
[2024-09-19 16:53:46.026][93903][trace][http2] [source/common/http/http2/codec_impl.cc:1056] [C1] recv frame type=0
[2024-09-19 16:53:46.026][93903][trace][http2] [source/common/http/http2/codec_impl.cc:2013] [C1] track inbound frame type=0 flags=0 length=8192 padding_length=0
[2024-09-19 16:53:46.026][93903][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host->vm] proxy_on_response_body(2, 8192, 0)
[2024-09-19 16:53:46.026][93903][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host<-vm] proxy_on_response_body return: 1
[2024-09-19 16:53:46.026][93903][trace][http2] [source/common/http/http2/codec_impl.cc:1030] [C1] about to recv frame type=0, flags=0, stream_id=1
[2024-09-19 16:53:46.026][93903][trace][http2] [source/common/http/http2/codec_impl.cc:1056] [C1] recv frame type=0
[2024-09-19 16:53:46.026][93903][trace][http2] [source/common/http/http2/codec_impl.cc:2013] [C1] track inbound frame type=0 flags=0 length=8192 padding_length=0
[2024-09-19 16:53:46.026][93903][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host->vm] proxy_on_response_body(2, 16384, 0)
[2024-09-19 16:53:46.027][93903][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host<-vm] proxy_on_response_body return: 1
[2024-09-19 16:53:46.027][93903][trace][http2] [source/common/http/http2/codec_impl.cc:1030] [C1] about to recv frame type=0, flags=1, stream_id=1
[2024-09-19 16:53:46.027][93903][trace][http2] [source/common/http/http2/codec_impl.cc:1056] [C1] recv frame type=0
[2024-09-19 16:53:46.027][93903][trace][http2] [source/common/http/http2/codec_impl.cc:2013] [C1] track inbound frame type=0 flags=1 length=670 padding_length=0
[2024-09-19 16:53:46.027][93903][debug][client] [source/common/http/codec_client.cc:126] [C1] response complete
[2024-09-19 16:53:46.028][93903][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host->vm] proxy_on_response_body(2, 24576, 1)
[2024-09-19 16:53:46.034][93903][trace][http2] [source/common/http/http2/codec_impl.cc:1786] Codec does not have Metadata frame support.
[2024-09-19 16:53:46.034][93903][debug][http2] [source/common/http/http2/codec_impl.cc:1586] [C3] updating connection-level initial window size to 268435456
[2024-09-19 16:53:46.034][93903][debug][client] [source/common/http/codec_client.cc:57] [C3] connecting
[2024-09-19 16:53:46.034][93903][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host<-vm] proxy_on_response_body return: 1
[2024-09-19 16:53:46.034][93903][debug][http2] [source/common/http/http2/codec_impl.cc:1331] [C1] stream 1 closed: 0
[2024-09-19 16:53:46.034][93903][debug][http2] [source/common/http/http2/codec_impl.cc:1395] [C1] Recouping 0 bytes of flow control window for stream 1.
[2024-09-19 16:53:46.034][93903][trace][http2] [source/common/http/http2/codec_impl.cc:1030] [C1] about to recv frame type=3, flags=0, stream_id=1
[2024-09-19 16:53:46.034][93903][trace][http2] [source/common/http/http2/codec_impl.cc:2013] [C1] track inbound frame type=3 flags=0 length=4 padding_length=0
[2024-09-19 16:53:46.034][93903][trace][http2] [source/common/http/http2/codec_impl.cc:1056] [C1] recv frame type=3
[2024-09-19 16:53:46.034][93903][trace][http2] [source/common/http/http2/codec_impl.cc:958] [C1] dispatched 25295 bytes
As a comparison, the log in the good http1 case:
# grep "codec_impl\|codec_client\|proxy_on" http1.log
[2024-09-19 16:32:18.847][93849][debug][client] [source/common/http/codec_client.cc:88] [C1] connected
[2024-09-19 16:32:18.847][93849][debug][client] [source/common/http/codec_client.cc:139] [C1] encode complete
[2024-09-19 16:32:18.850][93849][trace][http] [source/common/http/http1/codec_impl.cc:639] [C1] parsing 15928 bytes
[2024-09-19 16:32:18.850][93849][trace][http] [source/common/http/http1/codec_impl.cc:581] [C1] message begin
[2024-09-19 16:32:18.850][93849][trace][http] [source/common/http/http1/codec_impl.cc:538] [C1] completed header: key=Server value=nginx/1.18.0 (Ubuntu)
...
[2024-09-19 16:32:18.851][93849][trace][http] [source/common/http/http1/codec_impl.cc:832] [C1] onHeadersCompleteBase
...
[2024-09-19 16:32:18.851][93849][trace][http] [source/common/http/http1/codec_impl.cc:1437] [C1] Client: onHeadersComplete size=8
...
[2024-09-19 16:32:18.853][93849][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host->vm] proxy_on_response_headers(2, 10, 0)
[2024-09-19 16:32:18.856][93849][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host<-vm] proxy_on_response_headers return: 0
...
[2024-09-19 16:32:18.857][93849][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host->vm] proxy_on_response_body(2, 15663, 0)
[2024-09-19 16:32:18.860][93849][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host<-vm] proxy_on_response_body return: 1
[2024-09-19 16:32:18.861][93849][trace][http] [source/common/http/http1/codec_impl.cc:689] [C1] parsed 15928 bytes
[2024-09-19 16:32:18.861][93849][trace][http] [source/common/http/http1/codec_impl.cc:639] [C1] parsing 9583 bytes
[2024-09-19 16:32:18.861][93849][trace][http] [source/common/http/http1/codec_impl.cc:936] [C1] message complete
[2024-09-19 16:32:18.861][93849][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host->vm] proxy_on_response_body(2, 15663, 0)
[2024-09-19 16:32:18.862][93849][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host<-vm] proxy_on_response_body return: 1
[2024-09-19 16:32:18.862][93849][trace][http] [source/common/http/http1/codec_impl.cc:1509] [C1] message complete
[2024-09-19 16:32:18.862][93849][debug][client] [source/common/http/codec_client.cc:126] [C1] response complete
[2024-09-19 16:32:18.863][93849][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host->vm] proxy_on_response_body(2, 25246, 1)
[2024-09-19 16:32:18.872][93849][trace][http2] [source/common/http/http2/codec_impl.cc:1786] Codec does not have Metadata frame support.
[2024-09-19 16:32:18.872][93849][debug][http2] [source/common/http/http2/codec_impl.cc:1586] [C3] updating connection-level initial window size to 268435456
[2024-09-19 16:32:18.873][93849][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:39] [host<-vm] proxy_on_response_body return: 1
Activity