Proposal: Support for New Processing Mode in Ext-proc Filter for Large Payloads Processing

[xr]

I want to propose adding supporting for a new processing mode in ext-proc (sth like STREAM_TO_BUFFER), this mode would enable streaming the request body to an external server in sync mode, where the side stream server would buffer the whole payload then stream back to envoy in chunks.

Motivation

1. Keep the iteration stopped while streaming the chunks to the side stream server so that side stream server could cover the case that required buffering/processing the whole payload externally before determining whether the request should proceed further in the filter chain or not.
2. Provide support for 1:N mapping or N:1 mapping between the request and response message ratio to enhance flexibility. This capability can address use cases, such as enabling the side stream server to respond in chunks.

Expected Behavior for the new mode

1. The ext-proc filter sends chunks to the external server as soon as they arrive.
2. Corresponding responses for each chunk are expected from the external server to confirm receipt.
3. Even if a response is received for each chunk, the ext-proc keep stoping iteration in the filter chain while continue streaming all the chunks to external server.
4. The external server will buffer the whole payload and process it externally.
5. After processing the payload, the server starts sending back the processed payload in chunks.
6. The ext-proc is expected to receive in stream mode and immediately inject each chunks into the filter chain.

What we have tried so far

We currently utilize the "STREAM" mode to send chunks; however, it fails to meet our use case due to the following reasons:

1. The "STREAM" mode chunks operates on a 1:1 mapping, where each chunk sent to the external server corresponds to a chunk sent back. The ext_proc injects each chunk immediately into the filter chain upon receipt, preventing it from blocking while streaming all the chunks to the external server.

2. Attempting to address the issue, we experimented with responding using the clear_body mutation for early chunks and only response the whole payload back in the last chunk, intending to avoid upstream servers from receiving early chunks as ext_proc is not in blocking mode while streaming chunks. Unfortunately, this approach presented challenges. The ext_proc will eventually receive the entire body in the last single message:

   • This will cause gRPC size limitation, for example, when using the Google gRPC client, there are limitations on the maximum message size for gRPC responses.
   • Even without these limitations, ext_proc replaces the last buffered chunk with the entire response body and injects them in a single batch. This behavior results in buffering the entire payload in Envoy again. like here: https://github.com/envoyproxy/envoy/blob/5d2f3ae3daf78b9e4001993f25d0d7a6082f04f0/source/extensions/filters/http/ext_proc/processor_state.cc#L271

Hope this highlights the reason behind the proposal, and we believe that the new mode could further empower the ext_proc ability to cover such use case to process large payloads externally, thanks!

[jmarantz]

I'd like to generalize this slightly to make sure we consider a similar use-case. The journey described above suggests the sidestream server will want to buffer the entire response before responding to any of it. This makes sense to me for the use-case of image processing. You might have a 10 megabyte image that you want to stream into the sidestream server, which requires the entire image in memory before it processes it, reducing it to 100k (say a lossy PNG to WEBP transformation). It may then stream the data back, and the processed data may have a much different size.

Another use-case is non-lossy compression (gzip, brotli). In this case the sidestream server may choose settings that involve buffering some amount of data, say 64k. As the data streams in (say 4k at a time), once 64k is collected in the sidestream server, it runs this through a streaming gzip optimizer and streams the data back, also 4k at a time. This may not correspond to the chunks that get streamed in because gzip may vary in compression ratio based on the data.

The difference is that in the case described above, the data is fully collected before it streams back. In the lossless gzip example the data streams in both directions concurrently.

[yanjunxiang-google]

It looks like case 1) is a special case for case 2), which allow side stream server buffering random amount of chunks received from Envoy before sending a response. And the response may or may not contain end_of_stream = true (indicates the whole body responded). And the request:response message ratio can be 1:N, or N:1.

[jmarantz]

Agreed -- I think the original description stated the requirement but then gave a more constrained example, and I just wanted a more general example.

[yanjunxiang-google]

Adding @htuch @yanavlasov @gbrail

[yanjunxiang-google]

I am thinking adding a new proto field "more_chunks" in the BodyMutation message as below can resolve the issue with minimum ext_proc filter state machine change:

https://github.com/envoyproxy/envoy/blob/5c821febbbba530315295a3c3dd3481364f89890/api/envoy/service/ext_proc/v3/external_processor.proto#L366

message BodyMutation { oneof mutation { // The entire body to replace bytes body = 1;

// Clear the corresponding body chunk
bool clear_body = 2;

}

// In STREAMED mode, sometimes, when side stream server receives a body chunk, call it received_chunk, it may send multiple chunks back to Envoy. // This more_chunks field tells Envoy whether there will be more body response back for that received_chunk. // When Envoy receives this response message, if more_chunks is false, which is the default case, // it does normal body mutation processing. When it is true, which indicates there are more pieces for this received_chunk // coming, Envoy ext_proc filter will not pop up that received_chunk from the queue. It just inject the body in the response to the filter chain. // The side stream server must set multiple_chunks* to false when the last piece response data for this received_chunk is heading back. And with that, // Envoy ext_proc filter will now pop up that received_chunk from the queue, and inject the body in response to the filter chain

• bool more_chunks }

In Envoy side, the code change is in this block: https://github.com/envoyproxy/envoy/blob/5c821febbbba530315295a3c3dd3481364f89890/source/extensions/filters/http/ext_proc/processor_state.cc#L266

[yanjunxiang-google]

So, for case 1), i.e, @xr 's original issue, the side stream server sends a "clear_body" response for each chunk received (not for the last_chunk), with "more_chunks" set to false. This "clear_body" response will reduce the ext_proc queue, also disable the ext_proc request timer. Then when the side stream server receive the last_chunk, it process it, then send multiple chunks back, with the first a few chunks with "body" contains actual data, and "more_chunks" to true. When Envoy receives such response, it will inject the data to filter chain. The side stream server sends the last response chunk with "body" contains data, and more_chunks to false. Envoy will inject the data to filter chain then continue the filter iteration.

[yanjunxiang-google]

For case 2), it follows the same logic as above, except that the side_stream server start sending response with "body" contains data not just for the last_chunk, but any time when it deems it received enough data and ready to send back response.

[yanjunxiang-google]

Adding more ext_proc owners @tyxia @stevenzzzz

[stevenzzzz]

I'd ping even more folks here. :)

summon @rshriram

[htuch]

I think I'm still a bit stuck on motivation:

The "STREAM" mode chunks operates on a 1:1 mapping, where each chunk sent to the external server corresponds to a chunk sent back. The ext_proc injects each chunk immediately into the filter chain upon receipt, preventing it from blocking while streaming all the chunks to the external server.

Why is this an issue for Envoy OOM? I think I'm missing something there, because, you shouldn't have to block the pipeline while streaming chunks to the ext_proc server if you've received a response for a chunk, that bit seems WAI?

[tyxia]

+1 I also think that OOM is probably not motivation here. Please note, in STREAMED mode, we still do buffering in ext_proc while streaming out the data. We need it for applying body mutation and it also help to prevent OOM on that path. So if your downstream payload is too large or it is too fast, it will be flow-controlled rather than being offload i think. Otherwise, I feel such free streaming actually will cause OOM. (e.g., OOM during offload.)

I see the motivation here is actually more about a new mode that does not have strict 1:1 mapping restriction, which i agree it make sense for some use cases mentioned here. But still, i think for case like payload/mutation is too large or processing rate difference causing data backup etc, we should flow-control to prevent OOM.

[xr]

So, for case 1), i.e, @xr 's original issue, the side stream server sends a "clear_body" response for each chunk received (not for the last_chunk), with "more_chunks" set to false. This "clear_body" response will reduce the ext_proc queue, also disable the ext_proc request timer. Then when the side stream server receive the last_chunk, it process it, then send multiple chunks back, with the first a few chunks with "body" contains actual data, and "more_chunks" to true. When Envoy receives such response, it will inject the data to filter chain. The side stream server sends the last response chunk with "body" contains data, and more_chunks to false. Envoy will inject the data to filter chain then continue the filter iteration.

@yanjunxiang-google thanks! this looks promising and it will allow 1:N (request/response) mapping, hope we could move forward with this if possible.

[xr]

I think I'm still a bit stuck on motivation:

The "STREAM" mode chunks operates on a 1:1 mapping, where each chunk sent to the external server corresponds to a chunk sent back. The ext_proc injects each chunk immediately into the filter chain upon receipt, preventing it from blocking while streaming all the chunks to the external server.

Why is this an issue for Envoy OOM? I think I'm missing something there, because, you shouldn't have to block the pipeline while streaming chunks to the ext_proc server if you've received a response for a chunk, that bit seems WAI?

The use case is that:

1. our side stream server need to buffer the whole payload before processing it and decide whether or not the request is allowed to move forward to the upstream or not, this is why we want to block the pipeline while streaming.
2. we don't want to use the BUFFER MODE and let envoy to buffer all the payload for us, as the payload could be large + high throughput, so we prefer to offloading the buffering/processing work externally.

[xr]

+1 I also think that OOM is probably not motivation here. Please note, in STREAMED mode, we still do buffering in ext_proc while streaming out the data. We need it for applying body mutation and it also help to prevent OOM on that path. So if your downstream payload is too large or it is too fast, it will be flow-controlled rather than being offload i think. Otherwise, I feel such free streaming actually will cause OOM. (e.g., OOM during offload.)

I see the motivation here is actually more about a new mode that does not have strict 1:1 mapping restriction, which i agree it make sense for some use cases mentioned here. But still, i think for case like payload/mutation is too large or processing rate difference causing data backup etc, we should flow-control to prevent OOM.

Thanks, good points, a new mode does not have strict 1:1 mapping is clearly a motivation, i'll edit to my original post

[tyxia]

Furthermore, I think the mode actually proposed here is a complete streaming mode with no Envoy buffering during the callout to sidecar server, @jmarantz is my understanding correct?

If so, then it can not be achieved by justing adding proto field, as both STREAM and BUFFER mode are still buffering. Actually there is probably no need to buffer in this case as it is not 1:1 mutating the mainstream data.

It is a bit similar to async mode. I think robust side stream flow control (e.g. buffer accounting still should be in place to prevent OOM) is the first thing to make such mode possible. We also need to evaluate the state machine. Besides, we need to be very careful about vulnerability, reliability aspects that could be exploited by sidecar server in this mode.

[yanjunxiang-google]

The issue is not OOM. The issue is that if the side stream server send the entire response body in one shot, it will over gRPC channel limits. Thus the side stream server has to split the response body into smaller chunks and stream them back. So, it is 1:N case.

[jmarantz]

RE "no envoy buffering" -- I think that can be implementation dependent. Like if the filter-chain provides a bunch of 1 byte messages maybe envoy might want to buffer up to (say) 64k before sending to ext_proc, idk. But it should have bounded buffering.

[yanjunxiang-google]

"Like if the filter-chain provides a bunch of 1 byte messages maybe envoy might want to buffer up to (say) 64k before sending to ext_proc", yeah this is a good point. We had discussed this before. Such buffering can reduce the amount of gRPC calls in STREAMED mode. We do not have this kind of buffering at this moment and plan to add that. But that's a separate issue.

[xr]

Thanks for the comments! @tyxia @jmarantz @yanjunxiang-google

Actually, the proposal is not intended for a "complete stream" mode. I believe that a buffering mechanism is necessary. However, the chunk/buffer size could be optional for configuration, allowing for fine-tuning on a case-by-case basis.

In this sense, the current STREAM mode is good; however, the missing part is the 1:N/N:1 request/response ratio, providing more flexibility for the side stream server beyond current support:

• Allowing it to buffer the entire payload while stopping iteration to cover those use cases.
• Streaming back in chunks to avoid one-shot big chunk back.

In fact, the intended behavior of the proposal could be implemented based on the current STREAM mode with a new field more_chunks as @yanjunxiang-google suggested above. It would be great if we could move forward with this solution.

[tyxia]

I think there is a misunderstanding about my previous comment: no Envoy buffering as I mentioned in this comment is no buffering during callout.

More specifically, i meant this chunk_queue. when you have 1:N ratio or N:1 ratio, your enqueue and dequeue will not be matched. Basically you need to handle case that enqueue 1 time, dequeue n times or enqueue n times, dequeue 1 time . IMHO, this is not currently handled by more_chunk proto change (or we need more changes in implementation).

Regarding @jmarantz's comment, I agree it is good point. we can buffer it before sending out to external processor, actually my point is do we still need to keep it in ext_proc filter after/during callout?

Taking one step back, since we are now not 1:1 mutating the chunk_queue anymore, do we still need to have this chunk_queue? Currently it is needed because it also help us to push back when it is over limit. But what if we have robust flow control in the sidestream as well, do we still need this queue in non 1:1 ratio case.

[jmarantz]

I suppose the chunk queue (which I had not been aware of till now) is needed if we can't back-pressure in any way. In an HTTP context I think back-pressuring is done by readDisable and I realize this is complex to get right. In a gRPC context I thought there could be flow-control protocol of some sort to avoid the need for unbounded buffering (and the memory pressure resulting from that).

I'm not sure exactly what's needed from an implementation perspective. I am just trying to understand a path where it's at least possible for an implementation to use bounded memory in the context of a sidestream that may greatly change the structure of the response chunks.

[yanjunxiang-google]

From implementation perspective, the chunk queue is used for the following cases: 1) Flow control in the fast downstream and slow side stream scenario, i.e, to stop downstream client sending too much data to Envoy. 2) When response coming back, knows which data to mutate, for example, if response is "clear_body", the chunk queue provides the corresponding data to be cleared. 3) In future the 1:N case, it is needed to map that "N" to "1".

[yanjunxiang-google]

@xr we are prototyping and will send out a PR once it is ready.

[tyxia]

How about N:1 or random M:N case? Basically there is no determined mapping between the chunk_queue and response from external processor.

From design perspective, side-stream response now is not targeted to any particular 1 chunk or X chunks now.

From implementation perspective, ext_proc should/can not decide how many chunks corresponds to 1 response. We probably can start from 1:1 and with more_chunks flag we know the end_of_response, but it could leads to following cases (still needs to be handled):

• no more sidecar response + many chunks left in the queue : we need to discard those chunks.
• more sidecar response + no chunks left in the queue: we need to allocate buffer to inject the data.

chunk queue currently is must to have for flow control which could be improved in the future.

[xr]

Regardless of the purpose for flow control of chunk_queue, if I only consider the need for handling body_mutation based on the response from the side stream server in a request/response 1:N scenario, will it still buffer the response "N" somewhere with the help of more_chunks, then dequeue the request 1 chunk once all N are received then move forward?

I was thinking Envoy would stream immediately down to the filter chain as soon as received every single N response chunks. In this scenario, the side stream server could handle the mutation by itself and simply stream back whatever mutated payload, potentially eliminating the need for Envoy to perform the mutation?

In this context, and without knowledge of other constraints, could the chunk queue be maintained only for flow control purposes, with the option of discarding the chunks after calling out to the side stream server, as they are not required for mutation thereafter? Also no need to concern the mapping afterward? @yanjunxiang-google @tyxia

[tyxia]

I was thinking Envoy would stream immediately down to the filter chain as soon as received every single N response chunks. In this scenario, the side stream server could handle the mutation by itself and simply stream back whatever mutated payload, potentially eliminating the need for Envoy to perform the mutation?

This is exactly why I understand this proposal as complete streaming mode :) Technically sidestream responses are independent of downstream bodies(or chunks in queue) in this mode and chunk_queue is redundant from this perspective.
Note, we should still have buffering for small downstream data before callout as @jmarantz suggested for performance optimization.

I just want to clarify: I just feel it is not 100% ideal, but if there is need to kick off this mode right away, I am not against using chunk queue since we don't have complete sidestream flow control yet. Though I think we need to handle some cases i mentioned here

[gbrail]

If I recall, we needed the chunk queue because there wasn't a guaranteed way to stop Envoy from sending the ext_proc filter a new chunk while we waited for the current chunk to be processed by the remote processor -- and even if there was, the performance impact would be huge without some amount of a "sliding window" kind of a protocol. If I recall, ext _proc tries not to tell Envoy to initiate flow control until some memory limits are reached so that we can be transmitting new chunks while still waiting for existing chunks to be processed -- that reduces latency a ton.

I think what you're proposing is indeed a "total streaming" mode, in which the ext_proc processor totally replaces the stream coming from the upstream/downstream with its own stream.

In other words, today the algorithm is something like this, for each chunk:

1. Receive chunk from filter stream
2. Save chunk on chunk queue and transmit to processor over gRPC stream
3. When matching response comes back from processor, find the right chunk that we saved on the chunk queue
4. Depending on the instructions from the processor, we may clear the chunk and turn it into an empty chunk, replace the contents of the chunk, or leave it alone
5. Let the chunk continue processing in the filter stream

And all of steps 2-5 are repeated for every chunk and can be interleaved for individual chunks.

That supports all streaming use cases including the one that you describe, as long as a single chunk is never larger than all the various buffer limits, including gRPC payload size.

I think you're proposing something more like:

1. Receive chunk from filter stream
2. Send it over gRPC stream to external processor
3. Throw the chunk away

and then in parallel, inject every chunk from the processor back in to the filter stream as soon as you get it.

This would not support all use cases, but would be better for processors that will always replace the complete stream.

I don't know how to make the Envoy filter stream do this, but I'm sure it's possible.

This leads to another problem I had, and one that I think will eventually impact you all if you start working with trailers -- there is no way in Envoy to distinguish between "end of stream" and "end of body, but there are trailers coming." I think that this will bite you if you are trying to implement this algorithm and also stick a trailer on the end -- for example, if you're trying to transform a JSON request to gRPC, or vice versa, or transform a gRPC message...

[gbrail]

And having made that long comment, my proposal would not help with flow control -- if the proxy sent chunks to the processor faster than the processor can handle, I'm not sure what happens -- there would be no flow control unless we add it to the gRPC protocol, and that would complicate things.

The original proposal, which would change step "4" above to allow the processor to send multiple chunks back instead of a single chunk, might work better.

[jmarantz]

By "gRPC protocol" I assume you mean the way in which we use gRPC between sidestream server and ext_proc, and not the implementation of gRPC itself. Is that right? [edit] I am thinking this would not even impose an extra round-trip per chunk. To send data to the sidestream, ext_proc will send a chunk to the sidestream and will not send the next one until it gets a response from the first one. When receiving, ext_proc will request a chunk and the sidestream server should then just send one chunk back. ext_proc can then pace its requests to the sidestream.

I think fundamental to my thinking here is the ability for the proxy to stream through a sidestream response that's larger than available memory, at least as an option. In this case of course the sidestream would need to commit to passing through all content even if it is not going to change any of it. Obviously this mode needs to be chunked.

Clearly also a separate mode is called for with (a) bounded sizes we are comfortable buffering in memory (b) sidestream able to opt out of modifying the content so ext_proc can just pass it to the next filter in this case. Whether this mode requires chunking or not is unclear to me.

[htuch]

Based on what I'm seeing with ext_proc use cases, there are a variety of streaming scenarios, e.g. ones in which there are predominantly no mutations (e.g. DLP scanning), ones in which every chunk is mutated (e.g. compression). There are also streaming optimizations like short circuiting to only observe and rewrite some stream prefix.

and then in parallel, inject every chunk from the processor back in to the filter stream as soon as you get it.

This would need to come with the strict contract that ordering is preserved, to avoid needing to queue / reorder on the receiving side.

if the proxy sent chunks to the processor faster than the processor can handle, I'm not sure what happens -- there would be no flow control unless we add it to the gRPC protocol, and that would complicate things.

I think the original motivation isn't driven by protecting the processor, it can buffer the entire body in OP. Practically speaking though, there must be some memory constraint on the external processor in most situations, and at that point I'm not sure what it does (drop, stream some chunks backs, as you say there is no flow control).

I agree with the above observations that this is a new parallel streaming mode. I think it's simpler to implement than the existing one since there is no queueing, and seems to fit use cases that sit somewhere between BUFFERED And STREAMED; you want the external processor to be able to fully buffer the body (presumably where there is lots of memory) and want to tightly bound the memory use on the Envoy side (where there is presumably more scarce memory).

We'd probably benefit from a doc or some writeup of all these use cases and resource limits that ext_proc is going to support. I don't think the existing streaming mode semantics can sensibly support sending a relatively unbounded size of payload to the external processor before continuing processing.

[yanjunxiang-google]

I created this PR: https://github.com/envoyproxy/envoy/pull/32171 to address the original issue, which is to enable the side stream server be able to streaming back multiple chunks for any individual received chunk. The change to support this actually is pretty small.

I don't think we want to remove the Envoy ext_proc chunk_queue at this moment.

[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.

[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.

[xr]

Hello, i noticed the draft PR was closed, I'm wondering any chances if we could move forward with it? Thank you!

[yanjunxiang-google]

This work is left aside due to some internal priorities. We are going to resume this work soon.

[yanjunxiang-google]

I created https://github.com/envoyproxy/envoy/pull/34942 to wrap up this.
@xr , could you please patch the PR and test in your case. I listed the steps in the PR about how to make this work.

[xr]

@yanjunxiang-google thanks, will try and get back to you soon!

[yanjunxiang-google]

@xr Please let us know the result. Thanks!

[xr]

@yanjunxiang-google sorry, was busy and on vacation, taking a look now, any standard/quick way to sync your proto changes to https://github.com/envoyproxy/go-control-plane/tree/main/envoy/service/ext_proc/v3 as our ext-proc are building on top it?

[xr]

@yanjunxiang-google nvm, I compiled the new proto by myself and tested it with the patch in your PR. It looks promising and fits our use cases perfectly! Thanks for the contribution, and I hope this PR can land in the release soon! 🚀

here is the commit I used for building the envoy:

/mnt/envoy  version: 12bf1cb1e7311d88fd6eaa56e04d3a18944c1017/1.31.0-dev/Modified/RELEASE/BoringSSL

here are the concrete steps I tried to e2e test:

1. when receiving M chunks from envoy, respond (1 ~ M-1) -th with

resp := &extProcProto.ProcessingResponse{
    Response: &extProcProto.ProcessingResponse_RequestBody{
        RequestBody: &extProcProto.BodyResponse{
            Response: &extProcProto.CommonResponse{
                BodyMutation: &extProcProto.BodyMutation{
                    Mutation: &extProcProto.BodyMutation_ClearBody{
                        ClearBody: true,
                    },
                    MoreChunks: false,
                },
            },
        },
    },
}

2. when received the last M chunk, start responding in multiple responses from side server:

resp := &extProcProto.ProcessingResponse{
    Response: &extProcProto.ProcessingResponse_RequestBody{
        RequestBody: &extProcProto.BodyResponse{
            Response: &extProcProto.CommonResponse{
                BodyMutation: &extProcProto.BodyMutation{
                    Mutation: &extProcProto.BodyMutation_Body{
                        Body: []byte("AAAAAA"),
                    },
                    MoreChunks: true,
                },
            },
        },
    },
}

resp2 := &extProcProto.ProcessingResponse{
    Response: &extProcProto.ProcessingResponse_RequestBody{
        RequestBody: &extProcProto.BodyResponse{
            Response: &extProcProto.CommonResponse{
                BodyMutation: &extProcProto.BodyMutation{
                    Mutation: &extProcProto.BodyMutation_Body{
                        Body: []byte("BBBBB"),
                    },
                    MoreChunks: true,
                },
            },
        },
    },
}

resp3 := &extProcProto.ProcessingResponse{
    Response: &extProcProto.ProcessingResponse_RequestBody{
        RequestBody: &extProcProto.BodyResponse{
            Response: &extProcProto.CommonResponse{
                BodyMutation: &extProcProto.BodyMutation{
                    Mutation: &extProcProto.BodyMutation_Body{
                        Body: []byte("CCCCCC"),
                    },
                    MoreChunks: false,
                },
            },
        },
    },
}

Then 🎉, from the upstream service I got multiple chunks:

request headers.
request body:
Received chunk: 6 AAAAAA
Received chunk: 5 BBBBB
Received chunk: 6 CCCCCC
Complete body received! total length: 17

Good thing that I noticed is that whenever chunk is sent back from the side server, the upstream will get the chunk instantly, this is required by us. Will also follow the discussions in the PR regarding the internal buffer.

trace Logs from envoy:

[2024-07-26 08:53:25.310][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:442] decodeHeaders: end_stream = false
[2024-07-26 08:53:25.311][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1324] Overriding grpc initial metadata from per-route configuration
[2024-07-26 08:53:25.311][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1328] Setting grpc initial metadata value =
[2024-07-26 08:53:25.311][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:339] Opening gRPC stream to external processor
[2024-07-26 08:53:25.318][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 0 true
[2024-07-26 08:53:25.325][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/matching_utils.cc:62] error parsing cel expression upstream.address
[2024-07-26 08:53:25.325][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction INBOUND: 30000 ms timer enabled
[2024-07-26 08:53:25.325][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:434] Sending headers message
[2024-07-26 08:53:25.326][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:268] Queued message to write (507 bytes)
[2024-07-26 08:53:25.326][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:462] onHeaders returning 1
[2024-07-26 08:53:25.326][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:716] decodeData(45482): end_stream = false
[2024-07-26 08:53:25.326][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:492] Header processing still in progress -- holding body data
[2024-07-26 08:53:25.326][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:443] Watermark raised on decoding
[2024-07-26 08:53:25.326][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:718] decodeData returning 2
[2024-07-26 08:53:25.326][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=0 ok=true inflight=1
[2024-07-26 08:53:25.328][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:314] Write op dispatched
[2024-07-26 08:53:25.328][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 3 true
[2024-07-26 08:53:25.328][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=3 ok=true inflight=2
[2024-07-26 08:53:25.328][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 1 true
[2024-07-26 08:53:25.329][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=1 ok=true inflight=1
[2024-07-26 08:53:25.329][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 2 true
[2024-07-26 08:53:25.329][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=2 ok=true inflight=1
[2024-07-26 08:53:25.329][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1075] Received request headers response
[2024-07-26 08:53:25.329][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:87] applying headers response. body mode = STREAMED
[2024-07-26 08:53:25.329][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:195] Setting header x-test-stream append = false
[2024-07-26 08:53:25.329][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction INBOUND: timer disabled
[2024-07-26 08:53:25.329][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:159] Sending first chunk using buffered data (45482)
[2024-07-26 08:53:25.329][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:863] Sending a body chunk of 45482 bytes, end_stream false
[2024-07-26 08:53:25.329][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction INBOUND: 30000 ms timer enabled
[2024-07-26 08:53:25.329][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:268] Queued message to write (45492 bytes)
[2024-07-26 08:53:25.330][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:314] Write op dispatched
[2024-07-26 08:53:25.330][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:451] Watermark lowered on decoding
[2024-07-26 08:53:25.330][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:386] Continuing processing
[2024-07-26 08:53:25.330][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 3 true
[2024-07-26 08:53:25.331][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=3 ok=true inflight=2
[2024-07-26 08:53:25.331][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:716] decodeData(183894): end_stream = false
[2024-07-26 08:53:25.331][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:863] Sending a body chunk of 183894 bytes, end_stream false
[2024-07-26 08:53:25.331][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction INBOUND: 30000 ms timer enabled
[2024-07-26 08:53:25.331][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:268] Queued message to write (183904 bytes)
[2024-07-26 08:53:25.331][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:314] Write op dispatched
[2024-07-26 08:53:25.331][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:718] decodeData returning 0
[2024-07-26 08:53:25.332][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:716] decodeData(8688): end_stream = false
[2024-07-26 08:53:25.332][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:863] Sending a body chunk of 8688 bytes, end_stream false
[2024-07-26 08:53:25.332][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction INBOUND: 30000 ms timer enabled
[2024-07-26 08:53:25.332][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:268] Queued message to write (8696 bytes)
[2024-07-26 08:53:25.332][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:718] decodeData returning 0
[2024-07-26 08:53:25.333][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:716] decodeData(2896): end_stream = false
[2024-07-26 08:53:25.333][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:863] Sending a body chunk of 2896 bytes, end_stream false
[2024-07-26 08:53:25.333][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction INBOUND: 30000 ms timer enabled
[2024-07-26 08:53:25.333][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:268] Queued message to write (2904 bytes)
[2024-07-26 08:53:25.333][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:718] decodeData returning 0
[2024-07-26 08:53:25.333][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:716] decodeData(32768): end_stream = false
[2024-07-26 08:53:25.333][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:863] Sending a body chunk of 32768 bytes, end_stream false
[2024-07-26 08:53:25.333][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction INBOUND: 30000 ms timer enabled
[2024-07-26 08:53:25.333][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:268] Queued message to write (32778 bytes)
[2024-07-26 08:53:25.333][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:718] decodeData returning 0
[2024-07-26 08:53:25.334][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:716] decodeData(72776): end_stream = false
[2024-07-26 08:53:25.335][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:863] Sending a body chunk of 72776 bytes, end_stream false
[2024-07-26 08:53:25.335][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction INBOUND: 30000 ms timer enabled
[2024-07-26 08:53:25.335][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:268] Queued message to write (72786 bytes)
[2024-07-26 08:53:25.335][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:718] decodeData returning 0
[2024-07-26 08:53:25.335][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:716] decodeData(7240): end_stream = false
[2024-07-26 08:53:25.335][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:863] Sending a body chunk of 7240 bytes, end_stream false
[2024-07-26 08:53:25.335][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction INBOUND: 30000 ms timer enabled
[2024-07-26 08:53:25.335][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:268] Queued message to write (7248 bytes)
[2024-07-26 08:53:25.335][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:718] decodeData returning 0
[2024-07-26 08:53:25.336][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:716] decodeData(59744): end_stream = false
[2024-07-26 08:53:25.336][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:863] Sending a body chunk of 59744 bytes, end_stream false
[2024-07-26 08:53:25.336][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction INBOUND: 30000 ms timer enabled
[2024-07-26 08:53:25.336][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:268] Queued message to write (59754 bytes)
[2024-07-26 08:53:25.336][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:718] decodeData returning 0
[2024-07-26 08:53:25.338][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:716] decodeData(108440): end_stream = false
[2024-07-26 08:53:25.338][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:863] Sending a body chunk of 108440 bytes, end_stream false
[2024-07-26 08:53:25.338][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction INBOUND: 30000 ms timer enabled
[2024-07-26 08:53:25.338][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:268] Queued message to write (108450 bytes)
[2024-07-26 08:53:25.338][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:718] decodeData returning 0
[2024-07-26 08:53:25.339][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:716] decodeData(83824): end_stream = false
[2024-07-26 08:53:25.339][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:863] Sending a body chunk of 83824 bytes, end_stream false
[2024-07-26 08:53:25.339][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction INBOUND: 30000 ms timer enabled
[2024-07-26 08:53:25.339][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:268] Queued message to write (83834 bytes)
[2024-07-26 08:53:25.339][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:718] decodeData returning 0
[2024-07-26 08:53:25.339][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:716] decodeData(85272): end_stream = false
[2024-07-26 08:53:25.339][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:863] Sending a body chunk of 85272 bytes, end_stream false
[2024-07-26 08:53:25.339][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction INBOUND: 30000 ms timer enabled
[2024-07-26 08:53:25.340][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:268] Queued message to write (85282 bytes)
[2024-07-26 08:53:25.340][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:718] decodeData returning 0
[2024-07-26 08:53:25.340][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:716] decodeData(2896): end_stream = false
[2024-07-26 08:53:25.340][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:863] Sending a body chunk of 2896 bytes, end_stream false
[2024-07-26 08:53:25.340][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction INBOUND: 30000 ms timer enabled
[2024-07-26 08:53:25.340][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:268] Queued message to write (2904 bytes)
[2024-07-26 08:53:25.340][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:718] decodeData returning 0
[2024-07-26 08:53:25.340][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:716] decodeData(85808): end_stream = false
[2024-07-26 08:53:25.341][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:863] Sending a body chunk of 85808 bytes, end_stream false
[2024-07-26 08:53:25.341][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction INBOUND: 30000 ms timer enabled
[2024-07-26 08:53:25.341][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:268] Queued message to write (85818 bytes)
[2024-07-26 08:53:25.341][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:718] decodeData returning 0
[2024-07-26 08:53:25.341][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:716] decodeData(62640): end_stream = false
[2024-07-26 08:53:25.341][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:863] Sending a body chunk of 62640 bytes, end_stream false
[2024-07-26 08:53:25.341][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction INBOUND: 30000 ms timer enabled
[2024-07-26 08:53:25.341][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:268] Queued message to write (62650 bytes)
[2024-07-26 08:53:25.341][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:718] decodeData returning 0
[2024-07-26 08:53:25.342][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:716] decodeData(66984): end_stream = false
[2024-07-26 08:53:25.342][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:863] Sending a body chunk of 66984 bytes, end_stream false
[2024-07-26 08:53:25.342][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction INBOUND: 30000 ms timer enabled
[2024-07-26 08:53:25.342][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:268] Queued message to write (66994 bytes)
[2024-07-26 08:53:25.342][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:718] decodeData returning 0
[2024-07-26 08:53:25.343][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:716] decodeData(64088): end_stream = false
[2024-07-26 08:53:25.343][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:863] Sending a body chunk of 64088 bytes, end_stream false
[2024-07-26 08:53:25.343][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction INBOUND: 30000 ms timer enabled
[2024-07-26 08:53:25.343][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:268] Queued message to write (64098 bytes)
[2024-07-26 08:53:25.343][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:718] decodeData returning 0
[2024-07-26 08:53:25.343][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:716] decodeData(22632): end_stream = false
[2024-07-26 08:53:25.343][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:863] Sending a body chunk of 22632 bytes, end_stream false
[2024-07-26 08:53:25.343][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction INBOUND: 30000 ms timer enabled
[2024-07-26 08:53:25.343][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:268] Queued message to write (22642 bytes)
[2024-07-26 08:53:25.343][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:718] decodeData returning 0
[2024-07-26 08:53:25.343][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:716] decodeData(52504): end_stream = false
[2024-07-26 08:53:25.343][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:863] Sending a body chunk of 52504 bytes, end_stream false
[2024-07-26 08:53:25.343][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction INBOUND: 30000 ms timer enabled
[2024-07-26 08:53:25.343][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:268] Queued message to write (52514 bytes)
[2024-07-26 08:53:25.343][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:718] decodeData returning 0
[2024-07-26 08:53:25.343][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:716] decodeData(0): end_stream = true
[2024-07-26 08:53:25.343][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:863] Sending a body chunk of 0 bytes, end_stream true
[2024-07-26 08:53:25.343][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction INBOUND: 30000 ms timer enabled
[2024-07-26 08:53:25.344][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:268] Queued message to write (6 bytes)
[2024-07-26 08:53:25.344][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:718] decodeData returning 3
[2024-07-26 08:53:25.433][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 2 true
[2024-07-26 08:53:25.433][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 3 true
[2024-07-26 08:53:25.433][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=2 ok=true inflight=2
[2024-07-26 08:53:25.434][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1075] Received request body response
[2024-07-26 08:53:25.434][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:225] Processing body response
[2024-07-26 08:53:25.434][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:397] Applying body response to chunk of data. Size = 45482
[2024-07-26 08:53:25.434][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:222] Clearing HTTP body
[2024-07-26 08:53:25.434][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction INBOUND: timer disabled
[2024-07-26 08:53:25.434][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=3 ok=true inflight=2
[2024-07-26 08:53:25.434][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:314] Write op dispatched
[2024-07-26 08:53:25.434][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 3 true
[2024-07-26 08:53:25.435][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=3 ok=true inflight=2
[2024-07-26 08:53:25.435][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:314] Write op dispatched
[2024-07-26 08:53:25.435][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 3 true
[2024-07-26 08:53:25.435][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=3 ok=true inflight=2
[2024-07-26 08:53:25.436][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:314] Write op dispatched
[2024-07-26 08:53:25.436][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 3 true
[2024-07-26 08:53:25.436][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=3 ok=true inflight=2
[2024-07-26 08:53:25.437][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:314] Write op dispatched
[2024-07-26 08:53:25.437][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 3 true
[2024-07-26 08:53:25.437][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=3 ok=true inflight=2
[2024-07-26 08:53:25.437][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:314] Write op dispatched
[2024-07-26 08:53:25.536][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 2 true
[2024-07-26 08:53:25.536][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=2 ok=true inflight=2
[2024-07-26 08:53:25.536][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1075] Received request body response
[2024-07-26 08:53:25.536][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:225] Processing body response
[2024-07-26 08:53:25.536][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:397] Applying body response to chunk of data. Size = 183894
[2024-07-26 08:53:25.536][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:222] Clearing HTTP body
[2024-07-26 08:53:25.536][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction INBOUND: timer disabled
[2024-07-26 08:53:25.637][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 2 true
[2024-07-26 08:53:25.637][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=2 ok=true inflight=2
[2024-07-26 08:53:25.637][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1075] Received request body response
[2024-07-26 08:53:25.637][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:225] Processing body response
[2024-07-26 08:53:25.637][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:397] Applying body response to chunk of data. Size = 8688
[2024-07-26 08:53:25.637][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:222] Clearing HTTP body
[2024-07-26 08:53:25.637][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction INBOUND: timer disabled
[2024-07-26 08:53:25.738][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 2 true
[2024-07-26 08:53:25.738][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 3 true
[2024-07-26 08:53:25.738][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=2 ok=true inflight=2
[2024-07-26 08:53:25.738][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1075] Received request body response
[2024-07-26 08:53:25.738][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:225] Processing body response
[2024-07-26 08:53:25.738][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:397] Applying body response to chunk of data. Size = 2896
[2024-07-26 08:53:25.738][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:222] Clearing HTTP body
[2024-07-26 08:53:25.738][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction INBOUND: timer disabled
[2024-07-26 08:53:25.738][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=3 ok=true inflight=2
[2024-07-26 08:53:25.738][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:314] Write op dispatched
[2024-07-26 08:53:25.839][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 2 true
[2024-07-26 08:53:25.839][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 3 true
[2024-07-26 08:53:25.839][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=2 ok=true inflight=2
[2024-07-26 08:53:25.839][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1075] Received request body response
[2024-07-26 08:53:25.839][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:225] Processing body response
[2024-07-26 08:53:25.839][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:397] Applying body response to chunk of data. Size = 32768
[2024-07-26 08:53:25.839][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:222] Clearing HTTP body
[2024-07-26 08:53:25.839][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction INBOUND: timer disabled
[2024-07-26 08:53:25.839][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=3 ok=true inflight=2
[2024-07-26 08:53:25.840][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:314] Write op dispatched
[2024-07-26 08:53:25.940][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 2 true
[2024-07-26 08:53:25.940][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=2 ok=true inflight=2
[2024-07-26 08:53:25.940][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1075] Received request body response
[2024-07-26 08:53:25.940][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:225] Processing body response
[2024-07-26 08:53:25.940][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:397] Applying body response to chunk of data. Size = 72776
[2024-07-26 08:53:25.940][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:222] Clearing HTTP body
[2024-07-26 08:53:25.940][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction INBOUND: timer disabled
[2024-07-26 08:53:26.041][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 2 true
[2024-07-26 08:53:26.041][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 3 true
[2024-07-26 08:53:26.041][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=2 ok=true inflight=2
[2024-07-26 08:53:26.041][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1075] Received request body response
[2024-07-26 08:53:26.041][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:225] Processing body response
[2024-07-26 08:53:26.041][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:397] Applying body response to chunk of data. Size = 7240
[2024-07-26 08:53:26.041][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:222] Clearing HTTP body
[2024-07-26 08:53:26.041][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction INBOUND: timer disabled
[2024-07-26 08:53:26.041][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=3 ok=true inflight=2
[2024-07-26 08:53:26.041][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:314] Write op dispatched
[2024-07-26 08:53:26.141][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 2 true
[2024-07-26 08:53:26.141][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 3 true
[2024-07-26 08:53:26.141][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=2 ok=true inflight=2
[2024-07-26 08:53:26.141][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1075] Received request body response
[2024-07-26 08:53:26.141][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:225] Processing body response
[2024-07-26 08:53:26.141][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:397] Applying body response to chunk of data. Size = 59744
[2024-07-26 08:53:26.141][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:222] Clearing HTTP body
[2024-07-26 08:53:26.141][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction INBOUND: timer disabled
[2024-07-26 08:53:26.142][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=3 ok=true inflight=2
[2024-07-26 08:53:26.142][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:314] Write op dispatched
[2024-07-26 08:53:26.242][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 2 true
[2024-07-26 08:53:26.242][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 3 true
[2024-07-26 08:53:26.242][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=2 ok=true inflight=2
[2024-07-26 08:53:26.242][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1075] Received request body response
[2024-07-26 08:53:26.242][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:225] Processing body response
[2024-07-26 08:53:26.242][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:397] Applying body response to chunk of data. Size = 108440
[2024-07-26 08:53:26.243][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:222] Clearing HTTP body
[2024-07-26 08:53:26.243][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction INBOUND: timer disabled
[2024-07-26 08:53:26.243][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=3 ok=true inflight=2
[2024-07-26 08:53:26.243][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:314] Write op dispatched
[2024-07-26 08:53:26.243][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 3 true
[2024-07-26 08:53:26.243][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=3 ok=true inflight=2
[2024-07-26 08:53:26.244][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:314] Write op dispatched
[2024-07-26 08:53:26.343][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 2 true
[2024-07-26 08:53:26.343][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 3 true
[2024-07-26 08:53:26.343][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=2 ok=true inflight=2
[2024-07-26 08:53:26.343][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1075] Received request body response
[2024-07-26 08:53:26.343][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:225] Processing body response
[2024-07-26 08:53:26.343][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:397] Applying body response to chunk of data. Size = 83824
[2024-07-26 08:53:26.343][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:222] Clearing HTTP body
[2024-07-26 08:53:26.343][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction INBOUND: timer disabled
[2024-07-26 08:53:26.343][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=3 ok=true inflight=2
[2024-07-26 08:53:26.343][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:314] Write op dispatched
[2024-07-26 08:53:26.443][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 2 true
[2024-07-26 08:53:26.443][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=2 ok=true inflight=2
[2024-07-26 08:53:26.443][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1075] Received request body response
[2024-07-26 08:53:26.443][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:225] Processing body response
[2024-07-26 08:53:26.443][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:397] Applying body response to chunk of data. Size = 85272
[2024-07-26 08:53:26.443][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:222] Clearing HTTP body
[2024-07-26 08:53:26.443][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction INBOUND: timer disabled
[2024-07-26 08:53:26.543][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 2 true
[2024-07-26 08:53:26.543][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 3 true
[2024-07-26 08:53:26.543][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=2 ok=true inflight=2
[2024-07-26 08:53:26.544][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1075] Received request body response
[2024-07-26 08:53:26.544][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:225] Processing body response
[2024-07-26 08:53:26.544][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:397] Applying body response to chunk of data. Size = 2896
[2024-07-26 08:53:26.544][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:222] Clearing HTTP body
[2024-07-26 08:53:26.544][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction INBOUND: timer disabled
[2024-07-26 08:53:26.544][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=3 ok=true inflight=2
[2024-07-26 08:53:26.544][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:314] Write op dispatched
[2024-07-26 08:53:26.545][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 3 true
[2024-07-26 08:53:26.546][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=3 ok=true inflight=2
[2024-07-26 08:53:26.546][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:314] Write op dispatched
[2024-07-26 08:53:26.546][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 3 true
[2024-07-26 08:53:26.546][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=3 ok=true inflight=2
[2024-07-26 08:53:26.546][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:314] Write op dispatched
[2024-07-26 08:53:26.546][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 3 true
[2024-07-26 08:53:26.546][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=3 ok=true inflight=2
[2024-07-26 08:53:26.546][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:314] Write op dispatched
[2024-07-26 08:53:26.643][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 2 true
[2024-07-26 08:53:26.644][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 3 true
[2024-07-26 08:53:26.644][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=2 ok=true inflight=2
[2024-07-26 08:53:26.644][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1075] Received request body response
[2024-07-26 08:53:26.644][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:225] Processing body response
[2024-07-26 08:53:26.644][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:397] Applying body response to chunk of data. Size = 85808
[2024-07-26 08:53:26.644][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:222] Clearing HTTP body
[2024-07-26 08:53:26.644][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction INBOUND: timer disabled
[2024-07-26 08:53:26.644][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=3 ok=true inflight=2
[2024-07-26 08:53:26.644][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:314] Write op dispatched
[2024-07-26 08:53:26.644][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 3 true
[2024-07-26 08:53:26.644][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=3 ok=true inflight=2
[2024-07-26 08:53:26.744][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 2 true
[2024-07-26 08:53:26.744][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=2 ok=true inflight=1
[2024-07-26 08:53:26.744][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1075] Received request body response
[2024-07-26 08:53:26.744][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:225] Processing body response
[2024-07-26 08:53:26.744][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:397] Applying body response to chunk of data. Size = 62640
[2024-07-26 08:53:26.744][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:222] Clearing HTTP body
[2024-07-26 08:53:26.744][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction INBOUND: timer disabled
[2024-07-26 08:53:26.844][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 2 true
[2024-07-26 08:53:26.844][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=2 ok=true inflight=1
[2024-07-26 08:53:26.844][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1075] Received request body response
[2024-07-26 08:53:26.844][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:225] Processing body response
[2024-07-26 08:53:26.844][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:397] Applying body response to chunk of data. Size = 66984
[2024-07-26 08:53:26.844][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:222] Clearing HTTP body
[2024-07-26 08:53:26.845][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction INBOUND: timer disabled
[2024-07-26 08:53:26.947][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 2 true
[2024-07-26 08:53:26.948][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=2 ok=true inflight=1
[2024-07-26 08:53:26.948][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1075] Received request body response
[2024-07-26 08:53:26.948][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:225] Processing body response
[2024-07-26 08:53:26.948][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:397] Applying body response to chunk of data. Size = 64088
[2024-07-26 08:53:26.948][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:222] Clearing HTTP body
[2024-07-26 08:53:26.948][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction INBOUND: timer disabled
[2024-07-26 08:53:27.048][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 2 true
[2024-07-26 08:53:27.049][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=2 ok=true inflight=1
[2024-07-26 08:53:27.049][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1075] Received request body response
[2024-07-26 08:53:27.049][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:225] Processing body response
[2024-07-26 08:53:27.049][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:397] Applying body response to chunk of data. Size = 22632
[2024-07-26 08:53:27.049][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:222] Clearing HTTP body
[2024-07-26 08:53:27.049][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction INBOUND: timer disabled
[2024-07-26 08:53:27.148][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 2 true
[2024-07-26 08:53:27.149][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=2 ok=true inflight=1
[2024-07-26 08:53:27.149][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1075] Received request body response
[2024-07-26 08:53:27.149][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:225] Processing body response
[2024-07-26 08:53:27.149][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:397] Applying body response to chunk of data. Size = 52504
[2024-07-26 08:53:27.149][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:222] Clearing HTTP body
[2024-07-26 08:53:27.149][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction INBOUND: timer disabled
[2024-07-26 08:53:32.251][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 2 true
[2024-07-26 08:53:32.251][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=2 ok=true inflight=1
[2024-07-26 08:53:32.251][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1075] Received request body response
[2024-07-26 08:53:32.251][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:225] Processing body response
[2024-07-26 08:53:32.251][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:270] Streamed mode body response has more_chunks set to true. enableMoreChunks true
[2024-07-26 08:53:32.251][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:424] Injecting 6 bytes of data to filter stream with more data coming
[2024-07-26 08:53:32.251][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction INBOUND: timer disabled
[2024-07-26 08:53:32.251][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction INBOUND: 30000 ms timer enabled
[2024-07-26 08:53:37.251][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 2 true
[2024-07-26 08:53:37.252][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=2 ok=true inflight=1
[2024-07-26 08:53:37.252][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1075] Received request body response
[2024-07-26 08:53:37.252][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:225] Processing body response
[2024-07-26 08:53:37.252][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:270] Streamed mode body response has more_chunks set to true. enableMoreChunks true
[2024-07-26 08:53:37.252][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:424] Injecting 5 bytes of data to filter stream with more data coming
[2024-07-26 08:53:37.252][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction INBOUND: timer disabled
[2024-07-26 08:53:37.252][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction INBOUND: 30000 ms timer enabled
[2024-07-26 08:53:42.252][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 2 true
[2024-07-26 08:53:42.252][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=2 ok=true inflight=1
[2024-07-26 08:53:42.252][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1075] Received request body response
[2024-07-26 08:53:42.252][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:225] Processing body response
[2024-07-26 08:53:42.252][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:397] Applying body response to chunk of data. Size = 0
[2024-07-26 08:53:42.252][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:228] Replacing body of 0 bytes with new body of 6 bytes
[2024-07-26 08:53:42.252][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:402] Injecting 6 bytes of data to filter stream
[2024-07-26 08:53:42.252][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction INBOUND: timer disabled
[2024-07-26 08:53:42.252][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:386] Continuing processing
[2024-07-26 08:53:42.254][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:815] encodeHeaders end_stream = false
[2024-07-26 08:53:42.254][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction OUTBOUND: 30000 ms timer enabled
[2024-07-26 08:53:42.254][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:434] Sending headers message
[2024-07-26 08:53:42.254][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:268] Queued message to write (324 bytes)
[2024-07-26 08:53:42.255][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:314] Write op dispatched
[2024-07-26 08:53:42.255][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:831] onHeaders returns 1
[2024-07-26 08:53:42.255][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:848] encodeData(17): end_stream = false
[2024-07-26 08:53:42.255][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:492] Header processing still in progress -- holding body data
[2024-07-26 08:53:42.255][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 3 true
[2024-07-26 08:53:42.255][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:509] Watermark raised on encoding
[2024-07-26 08:53:42.255][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:850] encodeData returning 2
[2024-07-26 08:53:42.255][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:848] encodeData(0): end_stream = true
[2024-07-26 08:53:42.255][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:492] Header processing still in progress -- holding body data
[2024-07-26 08:53:42.255][20][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:850] encodeData returning 2
[2024-07-26 08:53:42.255][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=3 ok=true inflight=2
[2024-07-26 08:53:42.256][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 2 true
[2024-07-26 08:53:42.256][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=2 ok=true inflight=1
[2024-07-26 08:53:42.256][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1075] Received response headers response
[2024-07-26 08:53:42.256][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:87] applying headers response. body mode = STREAMED
[2024-07-26 08:53:42.256][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction OUTBOUND: timer disabled
[2024-07-26 08:53:42.256][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:863] Sending a body chunk of 17 bytes, end_stream true
[2024-07-26 08:53:42.256][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:29] Traffic direction OUTBOUND: 30000 ms timer enabled
[2024-07-26 08:53:42.256][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:268] Queued message to write (25 bytes)
[2024-07-26 08:53:42.256][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:314] Write op dispatched
[2024-07-26 08:53:42.257][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:517] Watermark lowered on decoding
[2024-07-26 08:53:42.257][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 3 true
[2024-07-26 08:53:42.257][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=3 ok=true inflight=2
[2024-07-26 08:53:42.257][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 2 true
[2024-07-26 08:53:42.258][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=2 ok=true inflight=1
[2024-07-26 08:53:42.258][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1075] Received response body response
[2024-07-26 08:53:42.258][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:225] Processing body response
[2024-07-26 08:53:42.258][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction OUTBOUND: timer disabled
[2024-07-26 08:53:42.258][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:386] Continuing processing
[2024-07-26 08:53:42.258][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:393] onDestroy
[2024-07-26 08:53:42.258][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction INBOUND: timer disabled
[2024-07-26 08:53:42.258][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:55] Traffic direction OUTBOUND: timer disabled
[2024-07-26 08:53:42.258][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:375] Calling close on stream
[2024-07-26 08:53:42.258][20][debug][ext_proc] [source/extensions/filters/http/ext_proc/client_impl.cc:64] Closing gRPC stream
[2024-07-26 08:53:42.259][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:314] Write op dispatched
[2024-07-26 08:53:42.259][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 4 true
[2024-07-26 08:53:42.259][20][debug][grpc] [source/common/grpc/google_async_client_impl.cc:283] resetStream
[2024-07-26 08:53:42.259][20][debug][grpc] [source/common/grpc/google_async_client_impl.cc:456] Stream cleanup with 2 in-flight tags
[2024-07-26 08:53:42.260][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 5 true
[2024-07-26 08:53:42.260][41][trace][grpc] [source/common/grpc/google_async_client_impl.cc:61] completionThread CQ event 2 false
[2024-07-26 08:53:42.260][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=4 ok=true inflight=3
[2024-07-26 08:53:42.260][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=5 ok=true inflight=2
[2024-07-26 08:53:42.260][20][trace][grpc] [source/common/grpc/google_async_client_impl.cc:339] handleOpCompletion op=2 ok=false inflight=1
[2024-07-26 08:53:42.260][20][debug][grpc] [source/common/grpc/google_async_client_impl.cc:445] Deferred delete
[2024-07-26 08:53:42.260][20][debug][grpc] [source/common/grpc/google_async_client_impl.cc:194] GoogleAsyncStreamImpl destruct
[2024-07-26T08:53:25.298Z] "POST / HTTP/1.1" 200 - 1048576 17 16959 1 "-" "PostmanRuntime/7.36.0" "959ef365-1e29-4edf-bb37-90cfb83a128b" "localhost:10000" "192.168.1.202:4000"

Logs also seems good.

[yanjunxiang-google]

@xr Thanks for testing solution and your detail steps! This is very helpful!

[tyxia]

Will also follow the discussions in the PR regarding the internal buffer.

@xr You probably misunderstood internal buffer in discussion. It is not the one you mentioned above, it is this one ---> the internal buffer during callout.

I did highlight it in the internal discussion but it was my bad that I didn't clarify it in the OSS discussion