upstream: fix for race condition in tcp conn management by cpakulski · Pull Request #30807 · envoyproxy/envoy

cpakulski · 2023-11-09T14:42:45Z

Commit Message:
fix for race condition in tcp conn management

Additional Description:
I discovered this race in very simple setup:
2 clients -> [listener->tcp_proxy->cluster->endpoint] -> server
clients runs in a loop and open short lived tcp sessions.
Envoy debug build triggers assertion. Release build does not crash, but as explained below, it may lead to unexpected behaviour.

Here is analysis of the problem. As with any race condition it is hard to describe without going to details.
The root cause of the race is that when upstream tcp session terminates, ConnPoolImplBase::checkForIdleAndNotify is run twice.

It is run first time when Local/RemoteClose happens in https://github.com/envoyproxy/envoy/blob/release/v1.28/source/common/conn_pool/conn_pool_base.cc#L549.
ConnPoolImplBase::checkForIdleAndNotify iterates through registered idle_callbacks_. The callback is a lambda with captured host and hash_key which removes the tcp connection pool: source/common/upstream/cluster_manager_impl.cc.

The second time ConnPoolImplBase::checkForIdleAndNotify is called from Envoy::Tcp::ActiveTcpClient::~ActiveTcpClient via ConnPoolImplBase::checkForIdleAndCloseIdleConnsIfDraining. It again will go through registered idle callbacks. It will try to remove the tcp connection pool based on hash_key, but it was already removed when the ConnPoolImplBase::checkForIdleAndNotify was called the first time, so it is no-op.

The problem happens when a new connection comes between first and second call to ConnPoolImplBase::checkForIdleAndNotify. The new connection will allocate a new tcp connection pool with the same hash_key as the one just deleted in the first call to ConnPoolImplBase::checkForIdleAndNotify. Then, the second call to ConnPoolImplBase::checkForIdleAndNotify invokes registered callbacks the second time. The callback basically tries to delete a connection pool indexed by hash_key. It finds the newly allocated session which was created between calls to ConnPoolImplBase::checkForIdleAndNotify.

There are few ways to make sure that callbacks are run only once when upstream tcp session terminates. A boolean flag is one possibility or clearing the list of callbacks after they have been called.

@alyssawilk @ggreenway

Risk Level: Low
Testing: Manual. Before the fix assertion triggered within 5 minutes. After the fix crash does not happen.
Docs Changes: No
Release Notes: No
Platform Specific Features: No
Fixes: #22583

Signed-off-by: Christoph Pakulski <paker8848@gmail.com>

adisuissa · 2023-11-14T15:04:11Z

@ggreenway can you PTAL?

ggreenway

Thank you for the detailed description of what's happening!

I think the fix you have here makes sense and is straightforward.

Is it possible to create a test to validate that the idle callback cannot be called multiple times?

Also, can you add a comment with your analysis of this bug next to the fix so a future reader understands the issue? I don't want this knowledge to be lost.

/wait

ggreenway · 2023-11-15T16:39:03Z

@alyssawilk can you also take a look at this fix and double-check that it is the correct fix?

cpakulski · 2023-11-15T23:17:37Z

@ggreenway thanks for reviewing. I will try add a unit test to make sure that callbacks are called exactly once regardless of path taken (Local/RemoteClose) or destructor.

alyssawilk

LGTM though yeah it'd be good to have a unit test especially as I'm not sure if there's a non-bug situation where it should get called twice so we may just be masking a larger issue.

alyssawilk · 2023-11-16T16:44:50Z

/wait on test

kyessenov · 2023-11-17T23:17:05Z

The root cause is the same for #22583 and istio/proxy#5151.

cpakulski · 2023-11-17T23:27:17Z

I will finish this PR by Monday and we can do final review.

cpakulski · 2023-11-17T23:31:06Z

Updated PR description with "Fixes ...". Thanks for linking those issues @kyessenov.

kyessenov · 2023-11-18T00:25:56Z

      cb();
    }
+    // Clear callbacks, so they are not executed if checkForIdleAndNotify is called again.
+    idle_callbacks_.clear();


My fix was to put

if (deferred_deleting_) { return; }

since it was protecting against future accidents. Either way SGTM. Can I suggest to change the debug log to indicate whether it's firing or not? It's useful for debugging.

Yeah, makes sense. I will change the log.

Updated comments. Signed-off-by: Christoph Pakulski <paker8848@gmail.com>

Signed-off-by: Christoph Pakulski <paker8848@gmail.com>

cpakulski · 2023-11-20T01:16:24Z

/retest

cpakulski · 2023-11-20T16:03:25Z

I have added new unit test to verify that callbacks are called exactly once regardless whether upstream connection has been fully established (Connected, Local/Remote Reset events) or partially created (ActiveTcp client constructor and destructor have been called only).

I think this PR is finished and ready for the final review.

alyssawilk · 2023-11-20T16:07:36Z

+                                                                    concurrent_streams_, false);
+
+  testing::MockFunction<void()> idle_pool_callback;
+  EXPECT_CALL(idle_pool_callback, Call());


Just to check this failed befre? not sure if with nice mocks calling twice would pass. If so, LGTM

No, it did not failed before. This test verifies that callbacks are called when a client does not go through full connect cycle (Connected, Local/Remote Reset). If callbacks have not been called here, it would leave "hanging" conn pool. This is just a safeguard if logic is modified in the future and for some reason callbacks are not called for partially created upstream clients.
Other tests failed because callbacks have been called twice and those tests have been corrected: https://github.com/envoyproxy/envoy/pull/30807/files/a1e37c378b6d16d1323bba6ec61d8fd06800adb5#diff-66377346b7f86ba261b6008401df93fbc31e0036d98f225f7ce1a0ee2198afebL500

alyssawilk

hm, it's a clear improvement and I guess as long as it's tested

alyssawilk · 2023-11-20T19:52:45Z

@ggreenway has my LGTM but auto-merge blocked by your requested changes. resolve when you have a few?

1 day timeout =P

zirain · 2023-11-21T23:31:28Z

@alyssawilk need backport?

alyssawilk · 2023-11-29T15:41:14Z

I'd say if this fixes istio's issue then yes. They said they'd confirm this/next week

Fixed race in tcp conn management.

a4decf7

Signed-off-by: Christoph Pakulski <paker8848@gmail.com>

cpakulski marked this pull request as draft November 9, 2023 15:47

cpakulski added 2 commits November 9, 2023 16:06

Adjusted unit tests to reflect that idle callbacks are called only once.

0630257

Signed-off-by: Christoph Pakulski <paker8848@gmail.com>

Fixed typo in name of callback function.

2ae99e7

Signed-off-by: Christoph Pakulski <paker8848@gmail.com>

cpakulski marked this pull request as ready for review November 9, 2023 18:40

mattklein123 assigned ggreenway Nov 10, 2023

ggreenway previously requested changes Nov 15, 2023

View reviewed changes

repokitteh-read-only Bot added the waiting label Nov 15, 2023

ggreenway assigned alyssawilk Nov 15, 2023

alyssawilk previously approved these changes Nov 16, 2023

View reviewed changes

kyessenov reviewed Nov 18, 2023

View reviewed changes

cpakulski added 2 commits November 18, 2023 01:39

Added unit test.

ba86616

Updated comments. Signed-off-by: Christoph Pakulski <paker8848@gmail.com>

Merge remote-tracking branch 'upstream/main' into tcp_pool_race

a1e37c3

Signed-off-by: Christoph Pakulski <paker8848@gmail.com>

cpakulski dismissed alyssawilk’s stale review via a1e37c3 November 18, 2023 01:45

repokitteh-read-only Bot removed the waiting label Nov 18, 2023

alyssawilk reviewed Nov 20, 2023

View reviewed changes

alyssawilk approved these changes Nov 20, 2023

View reviewed changes

alyssawilk enabled auto-merge (squash) November 20, 2023 19:37

kyessenov mentioned this pull request Nov 20, 2023

TestStackdriverRbacTCPDryRun flake istio/istio#47910

Closed

alyssawilk merged commit fb7598b into envoyproxy:main Nov 21, 2023

zirain mentioned this pull request Nov 22, 2023

enable TestStackdriverRbacTCPDryRun istio/proxy#5166

Merged

zmiklank mentioned this pull request Jan 28, 2025

tcp conn pool: fix wrong connection pool deletion #37944

Closed

zmiklank mentioned this pull request Feb 25, 2025

ActiveTcpClient destructor deletes the wrong connection pool #37679

Closed

Conversation

cpakulski commented Nov 9, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

adisuissa commented Nov 14, 2023

Uh oh!

ggreenway left a comment

Choose a reason for hiding this comment

Uh oh!

ggreenway commented Nov 15, 2023

Uh oh!

cpakulski commented Nov 15, 2023

Uh oh!

alyssawilk left a comment

Choose a reason for hiding this comment

Uh oh!

alyssawilk commented Nov 16, 2023

Uh oh!

kyessenov commented Nov 17, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

cpakulski commented Nov 17, 2023

Uh oh!

cpakulski commented Nov 17, 2023

Uh oh!

kyessenov Nov 18, 2023

Choose a reason for hiding this comment

Uh oh!

cpakulski Nov 18, 2023

Choose a reason for hiding this comment

Uh oh!

cpakulski commented Nov 20, 2023

Uh oh!

cpakulski commented Nov 20, 2023

Uh oh!

alyssawilk Nov 20, 2023

Choose a reason for hiding this comment

Uh oh!

cpakulski Nov 20, 2023

Choose a reason for hiding this comment

Uh oh!

alyssawilk left a comment

Choose a reason for hiding this comment

Uh oh!

alyssawilk commented Nov 20, 2023

Uh oh!

zirain commented Nov 21, 2023

Uh oh!

alyssawilk commented Nov 29, 2023

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

6 participants

cpakulski commented Nov 9, 2023 •

edited

Loading

kyessenov commented Nov 17, 2023 •

edited

Loading