thrift filter: support skip decoding data after metadata in the thrift message

[caitong93]

For an explanation of how to fill out the fields, please see the relevant section
in PULL_REQUESTS.md

Commit Message:

Fixes #13082

Support skip decoding data after metadata in the thrift message.

API change:

message ThriftProxy {
  option (udpa.annotations.versioning).previous_message_type =
      "envoy.config.filter.network.thrift_proxy.v2alpha1.ThriftProxy";

  ...

  // If set to true, Envoy will try to skip decode data after metadata in the Thrift message.
  // This mode will only work if the upstream and downstream protocols are the same and the transport
  // is the same, the transport type is framed and the protocol is not Twitter. Otherwise Envoy will
  // fallback to decode the data.
  bool payload_passthrough = 6;
}

Additional Description:

In payload_passthrough mode, there are some issues:

• Envoy cannot detect some errors and exceptions ( e.g. a reply that contains exceptions ). It's possible to improve this by peeking beginning of the payload.

• payload_passthrough controls both request and response path. It can be split into two options if we want more fine-grained control.

• FilterStatus passthroughData(Buffer::Instance& data, uint64_t bytes_to_passthrough) will not prohibit custom filters to modify buffer. Now it is assumed custom filters won't do that, otherwise behavior is undefined.

TODO:

• add unit tests to conn_manager
• update doc

Risk Level: Medium
Testing:

• unit test:

  • config
  • decoder
  • router
  • conn_manager

• integration:

  • add an parameter payload_passthrough

• manual:

  • send requests and verify responses

Docs Changes:

TODO

Release Notes:

TODO

Platform Specific Features:
[Optional Runtime guard:]
[Optional Fixes #Issue]
[Optional Deprecated:]

[repokitteh-read-only]

CC @envoyproxy/api-shepherds: Your approval is needed for changes made to api/envoy/.
CC @envoyproxy/api-watchers: FYI only for changes made to api/envoy/.

🐱

Caused by: #13592 was synchronize by caitong93.

see: more, trace.

[repokitteh-read-only]

CC @envoyproxy/api-shepherds: Your approval is needed for changes made to (api/envoy[\w/]*/(v1alpha\d?|v1|v2alpha\d?|v2))|(api/envoy/type/(matcher/)?\w+.proto).

🐱

Caused by: #13592 was synchronize by caitong93.

see: more, trace.

[caitong93]

The pr is basically ready for review.

cc @rgs1 @zuercher

[caitong93]

/retest

[repokitteh-read-only]

Retrying Azure Pipelines.
Retried failed jobs in: envoy-presubmit

🐱

Caused by: a #13592 (comment) was created by @caitong93.

see: more, trace.

[zuercher]

Adding the extra parameter on the integration test doubled the test time, so I think you probably need to add shard_count = 4 to the test definition in the BUILD file. I think that will split it up into multiple tests that should all finish within the timeout.

[caitong93]

Adding the extra parameter on the integration test doubled the test time, so I think you probably need to add shard_count = 4 to the test definition in the BUILD file. I think that will split it up into multiple tests that should all finish within the timeout.

Thanks! It works. But still one check timeout. And It seems like not related to the PR?

[rgs1]

generally LGTM, just a few nits. Thanks!

[rgs1]

nit:bool payloadPassthrough() const

[rgs1]

nit: bool payloadPassthrough() const

[rgs1]

nit: const auto total

[rgs1]

nit: const auto

[rgs1]

virtual bool passthroughEnabled() const

[rgs1]

nit: drop this label?

[caitong93]

It's copied from existing code, and it's used in many places, not sure if there is any particular reason for keeping this label.

[rgs1]

nit const

[wbpcode]

This is great. The Thrift proxy does introduce a lot of latency when the body is large. But in reality a lot of parsing is completely unnecessary.

[rgs1]

@caitong93 any updates?

[caitong93]

@caitong93 any updates?

will update in this week, trying to add some tests for conn_manager

[caitong93]

Updated.

changes:

1. refine DecoderStateMachine::passthroughData(Buffer::Instance& buffer) to be consist with other methods of DecoderStateMachine ( buffer should be drained by decoder )
2. add some tests for conn_manager, just copy and modify existing test cases

[zuercher]

I had some trouble following the logic and one of comments offers a suggestion for making it clearer.

Otherwise, I'm not sure why unit tests didn't run on your change. I think some CI stuff has been changed recently so it might be that you need to merge master to get the tests to even run again.

[zuercher]

Does this still need to be added or is this a future improvement? If the latter, we use the format TODO(github-username): ... to help keep track of these.

[caitong93]

It's already done, will remove this line.

[zuercher]

This function is a bit confusing to me. I think the trouble is that in ConnectionManager::ActiveRpc it indicates whether passthrough was configured (and is allowed based on the filter chain), but for filters themselves it indicates whether or not the filter can support passthrough.

I think a way to resolve this is to move bool passthroughEnabled() to the DecoderCallbacks interface, and to add a reference to the DecoderCallbacks to Decoder::ActiveRequest alongside the DecoderEventHandler. That allows access to the callbacks from the DecoderStateMachine. Second, add bool passthroughSupported() (feel free to pick a different name, just not passthroughEnabled) to ThriftFilters::DecoderFilter to indicate whether a filter itself supports passthrough. The contrat of that method is that it's called once, right messageBegin. That allows allows moving the enabled bool out of ProtocolConverter and keeping it in the Router, or perhaps just computing the result at the time the method is called.

Provided it all the visibility works out, I think that makes clearer which method does what. What do you think?

[caitong93]

Sounds very reasonable, just to make sure i understand correctly, does this mean bool passthroughSupported() should also be added to DecoderEventHandler, and DecoderStateMachine checks decoder_callbacks_.passthroughEnabled () and handler_.passthroughSupported() in messageBegin ?

[zuercher]

I think the passThroughSupported goes in the DecoderFilter interface (in source/extensions/filters/network/thrift_proxy/filters/filter.h). So filters indicate whether they support pass through and the DecoderCallbacks can tell the state machine whether or not passthrough is in use (enabled).

DecoderEventHandler just gets the passthroughData method.

[caitong93]

I understand the changes in the interface. I'm trying to figure out how DecoderStateMachine knows whether filter chain support passthrough. DecoderStateMachine calls decoder_callbacks_.passthroughEnabled() In messageBegin, the result indicates whether passthrough was configured (and is allowed based on the filter chain), and ConnectionManager implements passthroughEnabled by checking config option and rpcs_.begin(), then ActiveRpc calls passThroughSupported on every filter. Is that right ?

[caitong93]

updated

[caitong93]

Thanks for all the reviews !

[rgs1]

@caitong93 I finally got to test this with real traffic and we are getting a crash. Stack trace looks like this:

(gdb) bt
#0  raise (sig=<optimized out>) at ../sysdeps/unix/sysv/linux/raise.c:51
#1  0x000055b8a7b33943 in Envoy::SignalAction::sigHandler(int, siginfo_t*, void*) () at external/envoy/source/common/signal/signal_action.cc:53
#2  <signal handler called>
#3  0x000055b8a74f8ec3 in Envoy::Extensions::NetworkFilters::ThriftProxy::ConnectionManager::passthroughEnabled() const () at /usr/lib/gcc/x86_64-linux-gnu/7.5.0/../../../../include/c++/7.5.0/bits/unique_ptr.h:147
#4  0x000055b8a750269f in Envoy::Extensions::NetworkFilters::ThriftProxy::DecoderStateMachine::messageBegin(Envoy::Buffer::Instance&) () at external/envoy/source/extensions/filters/network/thrift_proxy/decoder.cc:41
#5  0x000055b8a7503119 in Envoy::Extensions::NetworkFilters::ThriftProxy::DecoderStateMachine::handleState(Envoy::Buffer::Instance&) () at external/envoy/source/extensions/filters/network/thrift_proxy/decoder.cc:321
#6  0x000055b8a75036b4 in Envoy::Extensions::NetworkFilters::ThriftProxy::DecoderStateMachine::run(Envoy::Buffer::Instance&) () at external/envoy/source/extensions/filters/network/thrift_proxy/decoder.cc:371
#7  0x000055b8a7503d99 in Envoy::Extensions::NetworkFilters::ThriftProxy::Decoder::onData(Envoy::Buffer::Instance&, bool&) () at external/envoy/source/extensions/filters/network/thrift_proxy/decoder.cc:455

This fixes the issue for us:

diff --git a/source/extensions/filters/network/thrift_proxy/conn_manager.cc b/source/extensions/filters/network/thrift_proxy/conn_manager.cc
index 7f7129715..7196a33c7 100644
--- a/source/extensions/filters/network/thrift_proxy/conn_manager.cc
+++ b/source/extensions/filters/network/thrift_proxy/conn_manager.cc
@@ -181,9 +181,10 @@ bool ConnectionManager::passthroughEnabled() const {
     return false;
   }

-  // This is called right after the metadata has been parsed, and the ActiveRpc being processed must
-  // be in the rpcs_ list.
-  ASSERT(!rpcs_.empty());
+  if (rpcs_.empty()) {
+    return false;
+  }
+
   return (*rpcs_.begin())->passthroughSupported();
 }

After reading the code, my first guess as to how this could happen (rpcs_.empty()) is if we didn't handle StopIteration correctly, so I tried the following patch first:

diff --git a/source/extensions/filters/network/thrift_proxy/decoder.cc b/source/extensions/filters/network/thrift_proxy/decoder.cc
index 55f23af6e..a6b0f9c20 100644
--- a/source/extensions/filters/network/thrift_proxy/decoder.cc
+++ b/source/extensions/filters/network/thrift_proxy/decoder.cc
@@ -38,7 +38,7 @@ DecoderStateMachine::DecoderStatus DecoderStateMachine::messageBegin(Buffer::Ins

   const auto status = handler_.messageBegin(metadata_);

-  if (callbacks_.passthroughEnabled()) {
+  if (status != FilterStatus::StopIteration && callbacks_.passthroughEnabled()) {
     body_bytes_ = metadata_->frameSize() - (total - buffer.length());
     return {ProtocolState::PassthroughData, status};
   }

but I still got the crash. Then I tried the rpcs_.empty() check and that fixed it for us.

I am going to read this with a bit more care, but essentially there has to be a call to resetAllRpcs() somewhere in messageBegin(). One possibility would be via sendLocalReply, which I thought would be guarded against by checking for StopIteration... but apparently there's some other way of clearing the rpcs_ list.

[rgs1]

Two other possibilities I can think of:

1. something within the decoding state machine not correctly returning StopIteration
2. embedded messageBegin in a message, after a local reply was sent

cc: @fishcakez

[rgs1]

Ok, after chatting with @fishcakez I think we know what's going on:

https://github.com/envoyproxy/envoy/blob/master/source/extensions/filters/network/thrift_proxy/conn_manager.cc#L325

we are returning FilterStatus::Continue after a local response... thus my initial attempt at a fix didn't work:

diff --git a/source/extensions/filters/network/thrift_proxy/decoder.cc b/source/extensions/filters/network/thrift_proxy/decoder.cc
index 55f23af6e..a6b0f9c20 100644
--- a/source/extensions/filters/network/thrift_proxy/decoder.cc
+++ b/source/extensions/filters/network/thrift_proxy/decoder.cc
@@ -38,7 +38,7 @@ DecoderStateMachine::DecoderStatus DecoderStateMachine::messageBegin(Buffer::Ins

   const auto status = handler_.messageBegin(metadata_);

-  if (callbacks_.passthroughEnabled()) {
+  if (status != FilterStatus::StopIteration && callbacks_.passthroughEnabled()) {
     body_bytes_ = metadata_->frameSize() - (total - buffer.length());
     return {ProtocolState::PassthroughData, status};
   }

Will follow-up with a fix for that, tests, etc.

[rgs1]

So to clarify, the right behavior I think is to bubble up the right FilterStatus so that the decoder knows what's going on (e.g.: that the list of active rpcs has been cleared, etc).

[caitong93]

@rgs1 Thanks for the fix !! I have run this with real traffic for several months, and i guess that i didn't come across this probably because my use case is simpler(no other filters than router).

[rgs1]

@caitong93 possible fix here: #14723.