wasm: fix network leak

[kyessenov]

Signed-off-by: Kuat Yessenov kuat@google.com

Commit Message: Remove upstream closure callback to fix the network leak #13806. Confirmed by manually testing under load. I need help fixing the rust test since I don't know rust.
Risk Level:
Testing:
Docs Changes:
Release Notes:
Platform Specific Features:

[PiotrSikora]

This whole change could be basically minimized to this (i.e. on downstream close, close TCP context).

I don't think we can remove upstream close event, since it's a breaking change, or that we even need to remove it in order to fix the issue at hand.

[kyessenov]

1. Who exactly are we breaking? I don't think anyone relies on this callback or they would definitely complain about it before me.

2. What's the difference between upstream close and downstream local close? What does upstream close mean in case of direct response?

[PiotrSikora]

1. I don't know, we don't have an exhaustive list of everybody using Proxy-Wasm extensions. Notably, this seems to be only broken when using clusters with TLS transport socket (see: onUpstreamData(end_stream=true) is never raised when using cluster with TLS transport socket #13856).

2. I think you're confusing downstream/upstream with remote/local close events:

   • downstream local close means that the downstream connection was closed by Envoy,
   • downstream remote close means that the downstream connection was closed by the client,
   • upstream local close means that the upstream connection was closed by Envoy,
   • upstream remote close means that the upstream connection was closed by the backend,

In any case, this bug is not unique to Wasm, and I think the proper fix should emit upstream connection close event (again, see: #13856).

[PiotrSikora]

OK, #13856 is not the root cause for #13806, but it results in the same leak.

For #13806 the issue is that the upstream close event won't be triggered if the connection to upstream was never established (e.g. connection timeout, connection refused), but once #13856 is fixed, then this event is always triggered if the connection to upstream was established, so I don't see the point in removing it.

Like I said originally, this PR should be reduced to "on downstream close event, destroy context" (ideally, we should keep waiting for upstream close if we ever transmitted data in either direction), but without removing the upstream close event.

[kyessenov]

I can reproduce this without TLS.

[PiotrSikora]

I'm not sure how to easily debug this. The issue is that either callback is not called or response flags are empty. It's hard to detect absence.

Could you share the steps to reproduce so that I can try to debug it?

BTW I'm still not convinced about "upstream data". What does that even mean in the upstream network filter? We're using network filters on clusters in istio.

It might work by accident, but Proxy-Wasm plugins don't officially support "upstream network filters", and I suspect that some things will be broken because of flipped direction and related checks. I'm also pretty sure there are no tests for that use case. Please open an issue if you want to use them as "upstream network filters".

[kyessenov]

1. Add this diff:

diff --git a/extensions/stats/plugin.cc b/extensions/stats/plugin.cc
index a051b5d7..2e8dcd87 100644
--- a/extensions/stats/plugin.cc
+++ b/extensions/stats/plugin.cc
@@ -546,6 +546,7 @@ bool PluginRootContext::onDone() {
 }

 void PluginRootContext::onTick() {
+  LOG_INFO(absl::StrCat("connection_count: ", connection_count, " log_count: ", log_count));
   if (request_queue_.empty()) {
     return;
   }
diff --git a/extensions/stats/plugin.h b/extensions/stats/plugin.h
index 8472d6e8..fba522c2 100644
--- a/extensions/stats/plugin.h
+++ b/extensions/stats/plugin.h
@@ -260,6 +260,9 @@ class PluginRootContext : public RootContext {
                          ::Wasm::Common::RequestInfo* request_info);
   void deleteFromRequestQueue(uint32_t context_id);

+  int64_t log_count = 0;
+  int64_t connection_count = 0;
+
  protected:
   const std::vector<MetricTag>& defaultTags();
   const std::vector<MetricFactory>& defaultMetrics();
@@ -333,6 +336,8 @@ class PluginContext : public Context {
     if (request_info_.request_protocol == ::Wasm::Common::Protocol::TCP) {
       request_info_.tcp_connections_closed++;
     }
+
+    rootContext()->log_count++;
     rootContext()->report(request_info_, true);
   };

@@ -361,6 +366,7 @@ class PluginContext : public Context {
     request_info_.request_protocol = ::Wasm::Common::Protocol::TCP;
     request_info_.tcp_connections_opened++;
     rootContext()->addToRequestQueue(id(), &request_info_);
+    rootContext()->connection_count++;
     return FilterStatus::Continue;
   }

2. Start server: fortio server.
3. Start envoy with above config, concurrency 1.
4. Generate load: fortio load -qps 10000 -c 100 -t 10s localhost:8001
5. Terminate ^C server, restart it, and keep doing it until load finishes.
6. Observe mismatched counts.

[kyessenov]

Filed #13929 .

[PiotrSikora]

Thanks for the instructions, I was able to reproduce the issue. There are mid-stream I/O errors that are silently dropped in transport sockets, see: #13939. Once the core issue is fixed (my attempt in #13941), the counters always match.

[kyessenov]

I don't have high confidence that there's some other issue lurking about error propagation. If this happened under trivial config, it's very likely that more complex config can cause the same leak. We should not expect that upstream connection events are correctly emitted.

[PiotrSikora]

@kyessenov could you reduce this PR to calling onCloseTCP() on downstream connection close without waiting for upstream, but without removing all upstream connection close code? i.e. basically only removing this line:

if (upstream_closed_ || getRequestStreamInfo()->hasAnyResponseFlag()) {

This way, we can use this as a temporary fix until proper fix (upstream connection events) is merged.

[kyessenov]

@PiotrSikora how do I fix the rust test:

Unexpected mock function call - returning directly.
    Function call: log_(5, "panicked at 'invalid context_id', external/raze__proxy_wasm__0_1_2/src/dispatcher.rs:255:13")
Google Mock tried the following 2 expectations, but none matched:

[PiotrSikora]

@PiotrSikora how do I fix the rust test:

Unexpected mock function call - returning directly.
    Function call: log_(5, "panicked at 'invalid context_id', external/raze__proxy_wasm__0_1_2/src/dispatcher.rs:255:13")
Google Mock tried the following 2 expectations, but none matched:

You need to remove calls to closeStream in test/extensions/filters/network/wasm/wasm_filter_test.cc in line 182 and 183, since with the changes in this PR, the in-VM context is destroyed upon receiving RemoteClose event in line 181, so those closeStream functions are now called for a non-existing context.

[PiotrSikora]

/retest

[repokitteh-read-only]

Retrying Azure Pipelines:
Check envoy-presubmit didn't fail.

🐱

Caused by: a #13836 (comment) was created by @PiotrSikora.

see: more, trace.

[PiotrSikora]

You need to merge master to fix the CodeQL test on the CI.

[PiotrSikora]

/retest

[repokitteh-read-only]

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

🐱

Caused by: a #13836 (comment) was created by @PiotrSikora.

see: more, trace.

[PiotrSikora]

@lizan could you take a look? Thanks!

[Kyslik]

Is this going to land in Istio 1.6 / Istio 1.7 as its fixing memory leak - istio/istio#24720.

[PiotrSikora]

@cpakulski could you backport this?

/backport

[cpakulski]

@PiotrSikora I am starting backport to 1.16.

[cpakulski]

@PiotrSikora I think that this change cannot be backported to 1.16.
1.16 was cut off on Oct 8 via #13438.

wasm was merged into master one day after 1.16 release - on Oct 9 via #12546.

[PiotrSikora]

@cpakulski Oops, good point, we need to backport this to istio/envoy release branches for Istio. Thanks for checking!