Skip to content

Rework how tests deal with future timeout #496

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

Open
wants to merge 22 commits into
base: main
Choose a base branch
from
Open

Rework how tests deal with future timeout #496

Show file tree
Hide file tree
Changes from 6 commits
Commits
Show all changes
22 commits
Select commit Hold shift + click to select a range
66f36f0
Initial commit
var-const Jun 26, 2021
560d56d
style
var-const Jun 26, 2021
7998543
Fixes
var-const Jun 29, 2021
c86d850
style
var-const Jun 29, 2021
3629636
Simplify
var-const Jun 29, 2021
4644cb6
Fix comment
var-const Jun 29, 2021
5759044
Fix linkage
var-const Jun 30, 2021
886a452
Merge branch 'main' into varconst/await
var-const Jun 30, 2021
da3aba9
Fix
var-const Jul 1, 2021
477e012
Feedback
var-const Jul 13, 2021
9759b3b
Fix typo
var-const Jul 15, 2021
94e46a3
Merge branch 'main' into varconst/await
var-const Jul 15, 2021
86124c8
Merge branch 'main' into varconst/await
var-const Jul 22, 2021
0e98a9c
Fix PrintTo
var-const Jul 22, 2021
baa79d3
Merge branch 'main' into varconst/await
var-const Jul 22, 2021
a26cc96
Fix some transaction tests timing out
var-const Jul 22, 2021
49add61
updating vcpkg submodule
vimanyu Jul 23, 2021
59c8492
Updated submodule
var-const Jul 23, 2021
dd187e3
Merge branch 'varconst/await' of https://github.com/firebase/firebase…
var-const Jul 23, 2021
4684e79
Review
var-const Jul 23, 2021
80f6e63
Merge branch 'main' into varconst/await
var-const Jul 23, 2021
dc10d7e
Merge `main` branch at 0379ec4d12d15bbcbefed15ad512a3565d250c85
dconeybe Jan 4, 2022
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
12 changes: 2 additions & 10 deletions firestore/integration_test_internal/src/android/firestore_integration_test_android.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -71,17 +71,9 @@ Local<Throwable> FirestoreAndroidIntegrationTest::CreateException(
}

void FirestoreAndroidIntegrationTest::Await(Env& env, const Task& task) {
int cycles = kTimeOutMillis / kCheckIntervalMillis;
while (env.ok() && !task.IsComplete(env)) {
if (ProcessEvents(kCheckIntervalMillis)) {
std::cout << "WARNING: app receives an event requesting exit."
<< std::endl;
break;
}
--cycles;
}
bool success = WaitUntil([&] { return env.ok() && task.IsComplete(env); });
if (env.ok()) {
EXPECT_GT(cycles, 0) << "Waiting for Task timed out.";
EXPECT_TRUE(success) << "Waiting for Task timed out.";
}
}

Expand Down
34 changes: 10 additions & 24 deletions firestore/integration_test_internal/src/android/promise_android_test.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -119,24 +119,10 @@ class TestCompletionBase : public Promise<PublicType,
// Waits for `CompleteWith()` to be invoked. Returns `true` if an invocation
// occurred prior to timing out or `false` otherwise.
bool AwaitCompletion() {
int cycles_remaining = kTimeOutMillis / kCheckIntervalMillis;
while (true) {
{
MutexLock lock(mutex_);
if (invocation_count_ > 0) {
return true;
}
}

if (ProcessEvents(kCheckIntervalMillis)) {
return false;
}

cycles_remaining--;
if (cycles_remaining == 0) {
return false;
}
}
return WaitFor([&] {
MutexLock lock(mutex_);
return invocation_count_ > 0;
});
}

// Returns the number of times that `CompleteWith()` has been invoked.
Expand Down Expand Up @@ -226,7 +212,7 @@ TEST_F(PromiseTest, FutureVoidShouldSucceedWhenTaskSucceeds) {

SetTaskResult(0);

EXPECT_GT(WaitFor(future), 0);
EXPECT_TRUE(WaitUntilFutureCompletes(future));
EXPECT_EQ(future.status(), FutureStatus::kFutureStatusComplete);
EXPECT_EQ(future.error(), 0);
EXPECT_EQ(future.result(), nullptr);
Expand All @@ -240,7 +226,7 @@ TEST_F(PromiseTest, FutureNonVoidShouldSucceedWhenTaskSucceeds) {

SetTaskResult(42);

EXPECT_GT(WaitFor(future), 0);
EXPECT_TRUE(WaitUntilFutureCompletes(future));
EXPECT_EQ(future.status(), FutureStatus::kFutureStatusComplete);
EXPECT_EQ(future.error(), 0);
EXPECT_EQ(*future.result(), "42");
Expand All @@ -253,7 +239,7 @@ TEST_F(PromiseTest, FutureVoidShouldFailWhenTaskFails) {

SetTaskException(Error::kErrorFailedPrecondition, "Simulated failure");

EXPECT_GT(WaitFor(future), 0);
EXPECT_TRUE(WaitUntilFutureCompletes(future));
EXPECT_EQ(future.status(), FutureStatus::kFutureStatusComplete);
EXPECT_EQ(future.error(), Error::kErrorFailedPrecondition);
EXPECT_EQ(future.error_message(), std::string("Simulated failure"));
Expand All @@ -268,7 +254,7 @@ TEST_F(PromiseTest, FutureNonVoidShouldFailWhenTaskFails) {

SetTaskException(Error::kErrorFailedPrecondition, "Simulated failure");

EXPECT_GT(WaitFor(future), 0);
EXPECT_TRUE(WaitUntilFutureCompletes(future));
EXPECT_EQ(future.status(), FutureStatus::kFutureStatusComplete);
EXPECT_EQ(future.error(), Error::kErrorFailedPrecondition);
EXPECT_EQ(future.error_message(), std::string("Simulated failure"));
Expand All @@ -282,7 +268,7 @@ TEST_F(PromiseTest, FutureVoidShouldCancelWhenTaskCancels) {

CancelTask();

EXPECT_GT(WaitFor(future), 0);
EXPECT_TRUE(WaitUntilFutureCompletes(future));
EXPECT_EQ(future.status(), FutureStatus::kFutureStatusComplete);
EXPECT_EQ(future.error(), Error::kErrorCancelled);
EXPECT_EQ(future.error_message(), std::string("cancelled"));
Expand All @@ -297,7 +283,7 @@ TEST_F(PromiseTest, FutureNonVoidShouldCancelWhenTaskCancels) {

CancelTask();

EXPECT_GT(WaitFor(future), 0);
EXPECT_TRUE(WaitUntilFutureCompletes(future));
EXPECT_EQ(future.status(), FutureStatus::kFutureStatusComplete);
EXPECT_EQ(future.error(), Error::kErrorCancelled);
EXPECT_EQ(future.error_message(), std::string("cancelled"));
Expand Down
26 changes: 4 additions & 22 deletions firestore/integration_test_internal/src/firestore_integration_test.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -91,18 +91,9 @@ std::string ToFirestoreErrorCodeName(int error_code) {
}
}

int WaitFor(const FutureBase& future) {
// Instead of getting a clock, we count the cycles instead.
int cycles = kTimeOutMillis / kCheckIntervalMillis;
while (future.status() == FutureStatus::kFutureStatusPending && cycles > 0) {
if (ProcessEvents(kCheckIntervalMillis)) {
std::cout << "WARNING: app receives an event requesting exit."
<< std::endl;
break;
}
--cycles;
}
return cycles;
bool WaitUntilFutureCompletes(const FutureBase& future) {
return WaitUntil(
[&] { return future.status() != FutureStatus::kFutureStatusPending; });
}

FirestoreIntegrationTest::FirestoreIntegrationTest() {
Expand Down Expand Up @@ -274,18 +265,10 @@ FirestoreIntegrationTest::QuerySnapshotToMap(
return result;
}

/* static */
void FirestoreIntegrationTest::Await(const Future<void>& future) {
while (future.status() == FutureStatus::kFutureStatusPending) {
Copy link
Contributor Author

Choose a reason for hiding this comment

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

Previously, the overload of Await taking a Future<void> didn't have a timeout, unlike its Future<T> counterpart. Adding a timeout revealed that some of our transaction tests that do retries can take a varying amount of time, depending on the exact values of exponential backoff during that run, that just happens to be within a range of 11-18 seconds. The default timeout is 15 seconds, so that resulted in flaky tests. Adding a way to override the default timeout fixes the issue.

if (ProcessEvents(kCheckIntervalMillis)) {
std::cout << "WARNING: app received an event requesting exit."
<< std::endl;
break;
}
}
EXPECT_TRUE(WaitUntilFutureCompletes(future)) << "Future<void> timed out.";
}

/* static */
bool FirestoreIntegrationTest::FailIfUnsuccessful(const char* operation,
const FutureBase& future) {
if (future.status() != FutureStatus::kFutureStatusComplete) {
Expand All @@ -301,7 +284,6 @@ bool FirestoreIntegrationTest::FailIfUnsuccessful(const char* operation,
}
}

/* static */
std::string FirestoreIntegrationTest::DescribeFailedFuture(
const FutureBase& future) {
return "Future failed: " + ToFirestoreErrorCodeName(future.error()) + " (" +
Expand Down
69 changes: 41 additions & 28 deletions firestore/integration_test_internal/src/firestore_integration_test.h
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
#ifndef FIREBASE_FIRESTORE_CLIENT_CPP_SRC_TESTS_FIRESTORE_INTEGRATION_TEST_H_
#define FIREBASE_FIRESTORE_CLIENT_CPP_SRC_TESTS_FIRESTORE_INTEGRATION_TEST_H_

#include <chrono> // NOLINT(build/c++11)
#include <cstdio>
#include <iostream>
#include <map>
Expand Down Expand Up @@ -43,11 +44,15 @@ bool ProcessEvents(int msec);
// enum, but this function will gracefully handle the case where it is not.
std::string ToFirestoreErrorCodeName(int error_code);

// Waits for a Future to complete. If a timeout is reached then this method
// returns as if successful; therefore, the caller should verify the status of
// the given Future after this function returns. Returns the number of cycles
// that were left before a timeout would have occurred.
int WaitFor(const FutureBase& future);
// Blocks until either the given predicate `pred` returns `true` or timeout
// occurs. Returns `true` on success, `false` on timeout or if exit signal was
// received.
template <typename PredT>
bool WaitUntil(const PredT& pred, int timeout_ms = kTimeOutMillis);
Copy link
Contributor

Choose a reason for hiding this comment

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

Consider returning an enum from WaitUntil() and WaitUntilFutureCompletes() instead of conflating timeout and exit signal with a false return value. This will improve readability at the call sites since it is not immediately obvious without reading the function's documentation or implementation what the return value means and will avoid misleading "timeout" error messages when the exit signal occurs.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I thought about this but was leaning towards not doing it. It seems to complicate the common case for the sake of a very rare occurrence. I'm not sure this even works correctly -- e.g. on Linux the integration tests seem to completely ignore Ctrl-C.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I'm not sure this even works correctly -- e.g. on Linux the integration tests seem to completely ignore Ctrl-C.

Please disregard -- this is actually working correctly. I'm still hesitant to complicate the common case, though.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Hmm, it seems like it actually works in some tests and doesn't work in others.

Copy link
Contributor

Choose a reason for hiding this comment

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

My concern still stands, that returning a bool detracts from readability at the call sites. And confounding exit signal with timeout could lead to misleading test failure messages. When tests timeout they are already hard enough to debug and unclear error messages can further make that harder. This doesn't block my approval of this PR though.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

It seems to me that the root cause here is that these functions just don't have a great way of reporting this event, which really seems more akin to an exception. There also isn't much tests can do about it, so I'm not sure they need the ability to check for this condition. I think that this type of exit usually happens due to user input, so it shouldn't be confusing to the user, at least in the general case.

Copy link
Contributor

Choose a reason for hiding this comment

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

Maybe we should throw an exception now that exceptions are enabled in tests, especially once #561 is merged. In any case, that's out of scope for this PR so I'm fine with this code as-is.


// Blocks until either the future completes or timeout occurs. Returns `true`
// on success, `false` on timeout or if exit signal was received.
bool WaitUntilFutureCompletes(const FutureBase& future);

template <typename T>
class EventAccumulator;
Expand Down Expand Up @@ -280,37 +285,27 @@ class FirestoreIntegrationTest : public testing::Test {

// TODO(zxu): add a helper function to block on signal.

// A helper function to block until the future completes.
// Blocks until the future completes and returns the future result.
Copy link
Contributor

Choose a reason for hiding this comment

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

ultranit: Consider adding a comma after "completes".

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Hmm, my understanding is that this is a compound predicate (Blocks... and returns) and thus doesn't require a comma. I can't dig up a very authoritative reference quickly but the few links that come up in a search seem to agree -- see e.g. this.

Copy link
Contributor

Choose a reason for hiding this comment

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

You may be technically correct. For me, every time I read this sentence I read "Blocks until the future completes and returns" which implies that the future "completes and returns" but "returns" actually gets associated with the text that follows. Totally up to you though :)

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Ah, I see what you mean, and I fully agree. How about Blocks until the future is completed and returns...? I think it could still be read the wrong way but it seems like an improvement. What do you think?

Copy link
Contributor

Choose a reason for hiding this comment

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

Or, you could add a comma after "completes" ;) I think without the comma any wording has some ambiguity.

template <typename T>
static const T* Await(const Future<T>& future) {
int cycles = WaitFor(future);
EXPECT_GT(cycles, 0) << "Waiting future timed out.";
if (future.status() == FutureStatus::kFutureStatusComplete) {
if (future.result() == nullptr) {
std::cout << "WARNING: " << DescribeFailedFuture(future) << std::endl;
}
} else {
std::cout << "WARNING: Future is not completed." << std::endl;
}
EXPECT_TRUE(WaitUntilFutureCompletes(future)) << "Future<T> timed out.";

EXPECT_EQ(future.status(), FutureStatus::kFutureStatusComplete)
<< DescribeFailedFuture(future);
EXPECT_NE(future.result(), nullptr) << DescribeFailedFuture(future);

return future.result();
}

// Blocks until the future completes.
static void Await(const Future<void>& future);

// A helper function to block until there is at least n event.
// Blocks until there is at least `event_count` events.
template <typename T>
static void Await(const TestEventListener<T>& listener, int n = 1) {
// Instead of getting a clock, we count the cycles instead.
int cycles = kTimeOutMillis / kCheckIntervalMillis;
while (listener.event_count() < n && cycles > 0) {
if (ProcessEvents(kCheckIntervalMillis)) {
std::cout << "WARNING: app receives an event requesting exit."
<< std::endl;
return;
}
--cycles;
}
EXPECT_GT(cycles, 0) << "Waiting listener timed out.";
static void Await(const TestEventListener<T>& listener, int event_count = 1) {
bool success =
WaitUntil([&] { return listener.event_count() >= event_count; });
EXPECT_TRUE(success) << "Waiting listener timed out.";
}

// Fails the current test if the given future did not complete or contained an
Expand Down Expand Up @@ -355,6 +350,24 @@ class FirestoreIntegrationTest : public testing::Test {
mutable std::unordered_map<Firestore*, FirestoreInfo> firestores_;
};

template <typename PredT>
bool WaitUntil(const PredT& pred, int timeout_ms) {
auto now = std::chrono::steady_clock::now();
auto timeout_time = now + std::chrono::milliseconds(timeout_ms);

while (!pred() && now < timeout_time) {
if (ProcessEvents(kCheckIntervalMillis)) {
std::cout << "WARNING: app received an event requesting exit."
<< std::endl;
return false;
}

now = std::chrono::steady_clock::now();
}

return now < timeout_time;
}

} // namespace firestore
} // namespace firebase

Expand Down
15 changes: 7 additions & 8 deletions firestore/integration_test_internal/src/util/future_test_util.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -13,25 +13,24 @@ void PrintTo(std::ostream* os,
FutureStatus future_status,
int error,
const char* error_message = nullptr) {
*os << "Future<void>{status=" << ToEnumeratorName(future_status)
*os << "Future{status=" << ToEnumeratorName(future_status)
<< " error=" << firestore::ToFirestoreErrorCodeName(error);
if (error_message != nullptr) {
*os << " error_message=" << error_message;
}
*os << "}";
}

class FutureSucceedsImpl
: public testing::MatcherInterface<const Future<void>&> {
class FutureSucceedsImpl : public testing::MatcherInterface<const FutureBase&> {
public:
void DescribeTo(std::ostream* os) const override {
PrintTo(os, FutureStatus::kFutureStatusComplete,
firestore::Error::kErrorOk);
}

bool MatchAndExplain(const Future<void>& future,
bool MatchAndExplain(const FutureBase& future,
testing::MatchResultListener*) const override {
firestore::WaitFor(future);
firestore::WaitUntilFutureCompletes(future);
return future.status() == FutureStatus::kFutureStatusComplete &&
future.error() == firestore::Error::kErrorOk;
}
Expand All @@ -52,12 +51,12 @@ std::string ToEnumeratorName(FutureStatus status) {
}
}

void PrintTo(const Future<void>& future, std::ostream* os) {
void PrintTo(const FutureBase& future, std::ostream* os) {
PrintTo(os, future.status(), future.error(), future.error_message());
}

testing::Matcher<const Future<void>&> FutureSucceeds() {
return testing::Matcher<const Future<void>&>(new FutureSucceedsImpl());
testing::Matcher<const FutureBase&> FutureSucceeds() {
return testing::Matcher<const FutureBase&>(new FutureSucceedsImpl());
}

} // namespace firebase
2 changes: 1 addition & 1 deletion firestore/integration_test_internal/src/util/future_test_util.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -21,7 +21,7 @@ void PrintTo(const Future<void>& future, std::ostream* os);
//
// Here is an example of how this function could be used:
// EXPECT_THAT(TestFirestore()->Terminate(), FutureSucceeds());
testing::Matcher<const Future<void>&> FutureSucceeds();
testing::Matcher<const FutureBase&> FutureSucceeds();

// Converts a `FutureStatus` value to its enumerator name, and returns it. For
// example, if `kFutureStatusComplete` is specified then "kFutureStatusComplete"
Expand Down