Skip to content

test: deflaking a test, improving debugability #3829

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
mattklein123 merged 3 commits into from
Jul 10, 2018
Merged

test: deflaking a test, improving debugability #3829

Show file tree
Hide file tree
Changes from 2 commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
02639b5
test: deflaking a test, improving debugability
alyssawilk Jul 10, 2018
29ce8f1
unit test and fix_format
alyssawilk Jul 10, 2018
fe102b7
Backing logging changes out, and putting them in their own PR
alyssawilk Jul 10, 2018
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
15 changes: 15 additions & 0 deletions source/common/common/assert.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,21 @@ namespace Envoy {
} \
} while (false)

/**
* A version of RELEASE_ASSERT that allows for ostream style extra data.
*/
#define VERBOSE_RELEASE_ASSERT(X, Y) \

@htuch htuch Jul 10, 2018

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should this just be the RELEASE_ASSERT implementation in the interest of economy of mechanism?

@mattklein123 mattklein123 Jul 10, 2018

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

FWIW, I've wanted something like this for a while, so I would be in favor of adding this.

@alyssawilk alyssawilk Jul 10, 2018

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Cool. If you're up for it, I'm all for doing the more invasive ostream style default-release-assert. And possibly moving the other asserts over as well.

I think at that point I'll probably split it out of the test flake PR though :-)

@ggreenway ggreenway Jul 10, 2018

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Any reason not to use the existing fmtlib-style for this?

@alyssawilk alyssawilk Jul 10, 2018 •
edited
Loading

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

My weak argument is to be consistent with the ASSERT_EQ/EXPECT_EQ code in test but the real reason is I like ostream way better. I believe that fmt is more consistent with the code base so alternately I could look into a variable [1 or 2] argument macro with a fmt string as the second argument.

@ggreenway ggreenway Jul 10, 2018

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I prefer consistency with the code base, but I don't feel strongly about it. Anyone else have an opinion on this?

@htuch htuch Jul 10, 2018

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

An argument in favor of ostream is that if we implement it that way, we can easily add the fmtlib variant as a wrapper on top, e.g.

#define RELEASE_ASSERT(X, Y, ...) RELEASE_ASSERT(X) << fmt::format(Y, __VARARGSTUFF_)

so, doing it ostream provides maximum flexibility.

@mattklein123 mattklein123 Jul 10, 2018

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No strong opinion from me. Whatever you all think is best. Happy to see this land though, there are many times in prod code when I think it would be nice to actually have a more detailed message of a RELEASE_ASSERT() (I would go as far as to say we should ultimately audit all uses and force everyone to use the new version). Agree this can be split out though...

@htuch htuch Jul 10, 2018

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think we want something closer to what happens in gtests, e.g. ASSERT_EQ(foo, bar) << baz;

do { \
if (!(X)) { \
std::ostringstream stream; \
stream << Y; \

@htuch htuch Jul 10, 2018

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should this be (Y) for the usual preprocessor reasons?

std::string details = stream.str(); \
ENVOY_LOG_TO_LOGGER(Envoy::Logger::Registry::getLog(Envoy::Logger::Id::assert), critical, \
"assert failure: {}. Details: {} ", #X, details); \
abort(); \
} \
} while (false)

#ifndef NDEBUG
#define ASSERT(X) RELEASE_ASSERT(X)
#else
Expand Down
12 changes: 10 additions & 2 deletions test/common/common/BUILD
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -19,14 +19,22 @@ envoy_cc_test(
)

envoy_cc_test(
name = "base64_test",
srcs = ["base64_test.cc"],
name = "assert_test",
srcs = ["assert_test.cc"],
deps = [
"//source/common/buffer:buffer_lib",
"//source/common/common:base64_lib",
],
)

envoy_cc_test(
name = "base64_test",
srcs = ["base64_test.cc"],
deps = [
"//source/common/common:assert_lib",
],
)

envoy_cc_fuzz_test(
name = "base64_fuzz_test",
srcs = ["base64_fuzz_test.cc"],
Expand Down
15 changes: 15 additions & 0 deletions test/common/common/assert_test.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,15 @@
#include "common/common/assert.h"

#include "gtest/gtest.h"

TEST(Assert, VariousLogs) {
EXPECT_DEATH({ RELEASE_ASSERT(0); }, ".*assert failure: 0.*");
EXPECT_DEATH({ VERBOSE_RELEASE_ASSERT(0, "With some logs"); },
".*assert failure: 0. Details: With some logs.*");
EXPECT_DEATH(
{
VERBOSE_RELEASE_ASSERT(0, "With multiple "
<< "logs");
},
".*assert failure: 0. Details: With multiple logs.*");
}
4 changes: 4 additions & 0 deletions test/integration/fake_upstream.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -119,6 +119,7 @@ void FakeStream::waitForData(Event::Dispatcher& client_dispatcher, uint64_t body
}

void FakeStream::waitForEndStream(Event::Dispatcher& client_dispatcher) {
ENVOY_LOG(trace, "FakeStream waiting for end stream");
Thread::LockGuard lock(lock_);
while (!end_stream_) {
decoder_event_.waitFor(lock_, std::chrono::milliseconds(5));
Expand All @@ -127,6 +128,7 @@ void FakeStream::waitForEndStream(Event::Dispatcher& client_dispatcher) {
client_dispatcher.run(Event::Dispatcher::RunType::NonBlock);
}
}
ENVOY_LOG(trace, "FakeStream done waiting for end stream");
}

void FakeStream::waitForReset() {
Expand Down Expand Up @@ -185,6 +187,7 @@ Http::StreamDecoder& FakeHttpConnection::newStream(Http::StreamEncoder& encoder)
}

void FakeConnectionBase::waitForDisconnect(bool ignore_spurious_events) {
ENVOY_LOG(trace, "FakeConnectionBase waiting for disconnect");
Thread::LockGuard lock(lock_);
while (shared_connection_.connected()) {
connection_event_.wait(lock_); // Safe since CondVar::wait won't throw.
Expand All @@ -199,6 +202,7 @@ void FakeConnectionBase::waitForDisconnect(bool ignore_spurious_events) {
}

ASSERT(!shared_connection_.connected());
ENVOY_LOG(trace, "FakeConnectionBase done waiting for disconnect");
}

void FakeConnectionBase::waitForHalfClose(bool ignore_spurious_events) {
Expand Down
14 changes: 10 additions & 4 deletions test/integration/fake_upstream.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -206,7 +206,9 @@ class SharedConnectionWrapper : public Network::ConnectionCallbacks {
if (connected()) {
f(connection_);
} else {
RELEASE_ASSERT(allow_unexpected_disconnects_);
VERBOSE_RELEASE_ASSERT(
allow_unexpected_disconnects_,
"The connection disconnected unexpectedly, and allow_unexpected_disconnects_ is false");
}
callback_ready_event.notifyOne();
});
Expand Down Expand Up @@ -242,7 +244,11 @@ class QueuedConnectionWrapper : public LinkedObject<QueuedConnectionWrapper> {
allow_unexpected_disconnects_(allow_unexpected_disconnects) {
shared_connection_.addDisconnectCallback([this] {
Thread::LockGuard lock(lock_);
RELEASE_ASSERT(parented_ || allow_unexpected_disconnects_);
VERBOSE_RELEASE_ASSERT(parented_ || allow_unexpected_disconnects_,
"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).");
});
}

Expand All @@ -263,7 +269,7 @@ class QueuedConnectionWrapper : public LinkedObject<QueuedConnectionWrapper> {
/**
* Base class for both fake raw connections and fake HTTP connections.
*/
class FakeConnectionBase {
class FakeConnectionBase : public Logger::Loggable<Logger::Id::testing> {
public:
virtual ~FakeConnectionBase() {
ASSERT(initialized_);
Expand Down Expand Up @@ -341,7 +347,7 @@ typedef std::unique_ptr<FakeHttpConnection> FakeHttpConnectionPtr;
/**
* Fake raw connection for integration testing.
*/
class FakeRawConnection : Logger::Loggable<Logger::Id::testing>, public FakeConnectionBase {
class FakeRawConnection : public FakeConnectionBase {
public:
FakeRawConnection(SharedConnectionWrapper& shared_connection)
: FakeConnectionBase(shared_connection) {}
Expand Down
8 changes: 0 additions & 8 deletions test/integration/hds_integration_test.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -66,14 +66,6 @@ class HdsIntegrationTest : public HttpIntegrationTest,
test_server_->waitForCounterGe("hds_delegate.requests", ++hds_requests_);
}

void cleanupUpstreamConnection() {
codec_client_->close();
if (fake_upstream_connection_ != nullptr) {
fake_upstream_connection_->close();
fake_upstream_connection_->waitForDisconnect();
}
}

void cleanupHdsConnection() {
if (fake_hds_connection_ != nullptr) {
fake_hds_connection_->close();
Expand Down
2 changes: 1 addition & 1 deletion test/integration/http2_integration_test.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -368,11 +368,11 @@ void Http2IntegrationTest::simultaneousRequest(int32_t request1_bytes, int32_t r
EXPECT_EQ(request2_bytes, response1->body().size());

// Cleanup both downstream and upstream
codec_client_->close();
fake_upstream_connection1->close();
fake_upstream_connection1->waitForDisconnect();
fake_upstream_connection2->close();
fake_upstream_connection2->waitForDisconnect();
codec_client_->close();

@htuch htuch Jul 10, 2018

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can you add a comment explaining how the ordering here matters/helps?

@alyssawilk alyssawilk Jul 10, 2018

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This one doesn't actually matter. I added it in case future code copy-pasted and it did matter.

}

TEST_P(Http2IntegrationTest, SimultaneousRequest) { simultaneousRequest(1024, 512); }
Expand Down
10 changes: 7 additions & 3 deletions test/integration/http_integration.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -214,13 +214,17 @@ IntegrationStreamDecoderPtr HttpIntegrationTest::sendRequestAndWaitForResponse(
}

void HttpIntegrationTest::cleanupUpstreamAndDownstream() {
if (codec_client_) {
codec_client_->close();
}
// Close the upstream connection first. If there's an outstanding request,
// closing the client may result in a FIN being sent upstream, and FakeConnectionBase::close
// will interpret that as an unexpected disconnect. The codec client is not
// subject to the same failure mode.

@htuch htuch Jul 10, 2018

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Like this comment ;)

if (fake_upstream_connection_) {
fake_upstream_connection_->close();
fake_upstream_connection_->waitForDisconnect();
}
if (codec_client_) {
codec_client_->close();
}
}

void HttpIntegrationTest::waitForNextUpstreamRequest(uint64_t upstream_index) {
Expand Down
8 changes: 2 additions & 6 deletions test/integration/integration_test.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -277,25 +277,21 @@ TEST_P(IntegrationTest, TestBind) {
initialize();

codec_client_ = makeHttpConnection(lookupPort("http"));
// Request 1.

auto response =
codec_client_->makeRequestWithBody(Http::TestHeaderMapImpl{{":method", "GET"},
{":path", "/test/long/url"},
{":scheme", "http"},
{":authority", "host"}},
1024);

fake_upstream_connection_ = fake_upstreams_[0]->waitForHttpConnection(*dispatcher_);
std::string address =
fake_upstream_connection_->connection().remoteAddress()->ip()->addressAsString();
EXPECT_EQ(address, address_string);
upstream_request_ = fake_upstream_connection_->waitForNewStream(*dispatcher_);
upstream_request_->waitForEndStream(*dispatcher_);
// Cleanup both downstream and upstream
codec_client_->close();
fake_upstream_connection_->close();
fake_upstream_connection_->waitForDisconnect();

cleanupUpstreamAndDownstream();
}

TEST_P(IntegrationTest, TestFailedBind) {
Expand Down
14 changes: 3 additions & 11 deletions test/integration/load_stats_integration_test.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -277,14 +277,6 @@ class LoadStatsIntegrationTest : public HttpIntegrationTest,
return locality_stats;
}

void cleanupUpstreamConnection() {
codec_client_->close();
if (fake_upstream_connection_ != nullptr) {
fake_upstream_connection_->close();
fake_upstream_connection_->waitForDisconnect();
}
}

void cleanupLoadStatsConnection() {
if (fake_loadstats_connection_ != nullptr) {
fake_loadstats_connection_->close();
Expand All @@ -295,7 +287,7 @@ class LoadStatsIntegrationTest : public HttpIntegrationTest,
void sendAndReceiveUpstream(uint32_t endpoint_index, uint32_t response_code = 200) {
initiateClientConnection();
waitForUpstreamResponse(endpoint_index, response_code);
cleanupUpstreamConnection();
cleanupUpstreamAndDownstream();
}

static constexpr uint32_t upstream_endpoints_ = 5;
Expand Down Expand Up @@ -515,7 +507,7 @@ TEST_P(LoadStatsIntegrationTest, InProgress) {
waitForLoadStatsRequest({localityStats("winter", 0, 0, 1)});

waitForUpstreamResponse(0, 503);
cleanupUpstreamConnection();
cleanupUpstreamAndDownstream();

EXPECT_EQ(1, test_server_->counter("load_reporter.requests")->value());
EXPECT_LE(2, test_server_->counter("load_reporter.responses")->value());
Expand Down Expand Up @@ -544,7 +536,7 @@ TEST_P(LoadStatsIntegrationTest, Dropped) {
response_->waitForEndStream();
ASSERT_TRUE(response_->complete());
EXPECT_STREQ("503", response_->headers().Status()->value().c_str());
cleanupUpstreamConnection();
cleanupUpstreamAndDownstream();

waitForLoadStatsRequest({}, 1);

Expand Down
6 changes: 1 addition & 5 deletions test/integration/ratelimit_integration_test.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -130,15 +130,11 @@ class RatelimitIntegrationTest : public HttpIntegrationTest,
}

void cleanup() {
codec_client_->close();
if (fake_ratelimit_connection_ != nullptr) {
fake_ratelimit_connection_->close();
fake_ratelimit_connection_->waitForDisconnect();
}
if (fake_upstream_connection_ != nullptr) {
fake_upstream_connection_->close();
fake_upstream_connection_->waitForDisconnect();
}
cleanupUpstreamAndDownstream();
}

FakeHttpConnectionPtr fake_ratelimit_connection_;
Expand Down