test: hds_integration_test failures with tsan

[jmarantz]

On master as of today, about 20% failure rate. They may have a common root cause but there are different classes of symptoms. E.g. here are 4 different ones: a short assert-failure and some very lengthy tsan reports that are in gist.

[2020-07-20 18:10:50.211][313][critical][assert] [./test/integration/fake_upstream.h:365] assert failure: parented_ || allow_unexpected_disconnects_. Details: An queued upstream connection was torn down without being associated with a fake connection. Either manage the connection via waitForRawConnection() or waitForHttpConnection(), or set_allow_unexpected_disconnects(true).
 See https://github.com/envoyproxy/envoy/blob/master/test/integration/README.md#unparented-upstream-connections

tsan failures:

• https://gist.github.com/jmarantz/15b5d396c2c34f0b4b0aa672300b25de
• https://gist.github.com/jmarantz/edc6a4349344c7620f98b00180e69ed7
• https://gist.github.com/jmarantz/3b2c2e5397d577e4f89adbe9ac4920b3

[jmarantz]

Repro instructions:

bazel test --config=libc++ //test/integration:hds_integration_test  --runs_per_test=100

[mattklein123]

From a very quick look at this test, it seems like there is a race condition where after calling cleanupHdsConnection Envoy can make a new HDS connection so we have to either handle spurious connections there or shutdown HDS somehow? @htuch @alyssawilk do you have any context here?

[mattklein123]

Hmm nevermind I see hds_upstream_->set_allow_unexpected_disconnects(true);, will keep looking.

[jmarantz]

FWIW I find this fails 98% of the time if I switch to simulated time, via:

diff --git a/test/integration/hds_integration_test.cc b/test/integration/hds_integration_test.cc
index f5fc80cdd5..7aa3b2b658 100644
--- a/test/integration/hds_integration_test.cc
+++ b/test/integration/hds_integration_test.cc
@@ -26,7 +26,8 @@ namespace Envoy {
 namespace {
 
 // TODO(jmarantz): switch this to simulated-time after debugging flakes.
-class HdsIntegrationTest : public Grpc::VersionedGrpcClientIntegrationParamTest,
+class HdsIntegrationTest : public Event::TestUsingSimulatedTime,
+                           public Grpc::VersionedGrpcClientIntegrationParamTest,
                            public HttpIntegrationTest {
 public:
   HdsIntegrationTest() : HttpIntegrationTest(Http::CodecClient::Type::HTTP1, ipVersion()) {}

I think this might be because this test uses gRPC which does not (afaik) have injectable time. But maybe this change offers a way to get more consistent failures, which might be easier to repro and debug.

[mattklein123]

Yeah I'm having trouble reproing. I will try again tomorrow.

[mattklein123]

In looking at the traces, I think the problem has to be:

envoy/test/integration/hds_integration_test.cc

Lines 298 to 305 in 796a674

	server_health_check_specifier_.mutable_cluster_health_checks(0)
	->mutable_health_checks(0)
	->mutable_timeout()
	->set_seconds(0);
	server_health_check_specifier_.mutable_cluster_health_checks(0)
	->mutable_health_checks(0)
	->mutable_timeout()
	->set_nanos(100000000); // 0.1 seconds

Envoy can close the connection while the connection is being popped off of the connection queue. There must be some race condition in the framework here. I can look more tomorrow unless @alyssawilk has any quick ideas. It's possible that recent event loop changes from @antoniovicente have made this race more likely though IIRC the events in question here aren't getting delayed to the next event loop iteration but I don't remember the details.

[mattklein123]

(Most relevant tsan trace: https://gist.github.com/jmarantz/edc6a4349344c7620f98b00180e69ed7)

[antoniovicente]

I think that the Envoy::Event::FileEventImpl::assignEvents in the call stack indicates that we are dealing with real events, not fake events.

I think the sequence here is something along the lines of:

1. proxy creates upstream connection
2. main thread calls waitForHttpConnection to capture the fake http upstream connection
3. proxy times out the connection and sends a fin
4. fake upstream detects the FIN and closes the fake connection

There are no synchronization primitives protecting the fake http upstream and its IO handle. TSAN detects a cross thread read/write interaction between steps 2 and 4 above.

The cross thread interactions in FakeUpstream are complex. We end up doing a fair number of operations in the main test thread while other operations happen in the backend thread. IIRC mutex use in FakeUpstream is very minimal.

[mattklein123]

Yeah agreed this is complicated. From looking at the TSAN trace it actually seems like to fix this we would need to block the fake upstream event loop from running or we have to do more operations on the fake upstream thread. I don't think there is an easy fix here. I will think about it more tomorrow.

[mattklein123]

(The best fix would be to switch the timeout tests to simulated time @jmarantz :) )

[jmarantz]

I think most of the tests I saw fail in real time involved direct calls to do timed waits on condvars from grpc, which lacks injectable time, afaict.

[alyssawilk]

FWIW many tsan failures are just because an assertion fails, and the test doesn't handle things if the unexpected thing occurs.
Looks like something is non-deterministic about the healthcheckEndpoints waitForHttpConnection on 79, but I'm not sure what.

Josh since you can repro, can you dump trace logs of a failure or two?

[mattklein123]

@alyssawilk see #12184 (comment) and #12184 (comment). It's a race condition around connection timeout/close. I think I have an idea on how to fix. I will try to do it today.

[htuch]

CC @drewsortega

[mattklein123]

@drewsortega I think you are being volunteered to work on this further. :)

I'm able to repro more issues under TSAN that I haven't had a chance to fix yet:

envoy/test/integration/hds_integration_test.cc

Line 634 in ae11ba2

TEST_P(HdsIntegrationTest, TestUpdateMessage) {

This one is getting stuck in the wait loop in the test. I haven't debugged it.

envoy/test/integration/hds_integration_test.cc

Line 714 in ae11ba2

TEST_P(HdsIntegrationTest, TestUpdateChangesTimer) {

This test is fundamentally broken. It relies on real time guarantees which are not satisfied in CI and under the sanitizers. We either need to switch to SimTime, drop the test, or test it some other way.

I also suspect

envoy/test/integration/hds_integration_test.cc

Line 753 in ae11ba2

TEST_P(HdsIntegrationTest, TestDefaultTimer) {

is broken in a similar way but I haven't seen it flake.

cc @htuch

[htuch]

FWIW, I think we discussed in at least one PR the desire for simulated time, there was some 10x slowdown that prevented this from being used at the time, see #5977.

[drewsortega]

Sure, I can work on this one further. :)
I'm touching a lot of hds code right now, so it seems reasonable for me to work on this alongside.

[xdzhai]

Drew tries many times, but was not able to reproduce the flakiness even if run 1000 times with tsan.
I also had a try and seems not reproducible. But I was able to reproduce it with the code at 2020-07-27, the log shows failure in waitForGrpcMessage().

There was a commit on 8/13: testing: fix multiple race conditions in simulated time tests (#12527) which improved the code of fake_upstream and probably has fixed the flakiness.

[mattklein123]

FWIW I've seen failures on main branch since the above fix, on ARM release, which tends to run very fast. I will take a look and see if I can repro.