test(bigtable): log more to deflake a test (#12094)

googleapis · Jul 14, 2023 · c8a58a0 · c8a58a0
1 parent 0d0fa69
commit c8a58a0
Show file tree

Hide file tree

Showing 5 changed files with 39 additions and 25 deletions.
diff --git a/google/cloud/bigtable/polling_policy_test.cc b/google/cloud/bigtable/polling_policy_test.cc
@@ -51,29 +51,30 @@ auto const kLimitedTimeTolerance = 20_ms;
  * @test Verify that a polling policy configured to run for 50ms
  * works correctly.
  */
-void CheckLimitedTime(PollingPolicy& tested) {
+void CheckLimitedTime(PollingPolicy& tested, char const* where) {
   testing_util::CheckPredicateBecomesFalse(
       [&tested] { return tested.OnFailure(GrpcTransientError()); },
       std::chrono::system_clock::now() + kLimitedTimeTestPeriod,
-      kLimitedTimeTolerance);
+      kLimitedTimeTolerance, where);
 }
 
-void CheckLimitedTime(std::unique_ptr<google::cloud::PollingPolicy> common) {
+void CheckLimitedTime(std::unique_ptr<google::cloud::PollingPolicy> common,
+                      char const* where) {
   testing_util::CheckPredicateBecomesFalse(
       [&common] { return common->OnFailure(TransientError()); },
       std::chrono::system_clock::now() + kLimitedTimeTestPeriod,
-      kLimitedTimeTolerance);
+      kLimitedTimeTolerance, where);
 }
 
 /// @test A simple test for the GenericPollingPolicy.
 TEST(GenericPollingPolicy, Simple) {
   LimitedTimeRetryPolicy retry(kLimitedTimeTestPeriod);
   ExponentialBackoffPolicy backoff(10_ms, 50_ms);
   GenericPollingPolicy<> tested(retry, backoff);
-  CheckLimitedTime(tested);
+  CheckLimitedTime(tested, __func__);
 
   auto common = bigtable_internal::MakeCommonPollingPolicy(tested.clone());
-  CheckLimitedTime(std::move(common));
+  CheckLimitedTime(std::move(common), __func__);
 }
 
 /// @test Test cloning for GenericPollingPolicy.

diff --git a/google/cloud/bigtable/rpc_retry_policy_test.cc b/google/cloud/bigtable/rpc_retry_policy_test.cc
@@ -56,29 +56,30 @@ auto const kLimitedTimeTolerance = 20_ms;
  *
  * This eliminates some amount of code duplication in the following tests.
  */
-void CheckLimitedTime(RPCRetryPolicy& tested) {
+void CheckLimitedTime(RPCRetryPolicy& tested, char const* where) {
   google::cloud::testing_util::CheckPredicateBecomesFalse(
       [&tested] { return tested.OnFailure(GrpcTransientError()); },
       std::chrono::system_clock::now() + kLimitedTimeTestPeriod,
-      kLimitedTimeTolerance);
+      kLimitedTimeTolerance, where);
 }
 
 void CheckLimitedTime(
-    std::unique_ptr<bigtable_admin::BigtableInstanceAdminRetryPolicy> common) {
+    std::unique_ptr<bigtable_admin::BigtableInstanceAdminRetryPolicy> common,
+    char const* where) {
   google::cloud::testing_util::CheckPredicateBecomesFalse(
       [&common] { return common->OnFailure(TransientError()); },
       std::chrono::system_clock::now() + kLimitedTimeTestPeriod,
-      kLimitedTimeTolerance);
+      kLimitedTimeTolerance, where);
 }
 
 /// @test A simple test for the LimitedTimeRetryPolicy.
 TEST(LimitedTimeRetryPolicy, Simple) {
   LimitedTimeRetryPolicy tested(kLimitedTimeTestPeriod);
-  CheckLimitedTime(tested);
+  CheckLimitedTime(tested, __func__);
 
   auto common = bigtable_internal::MakeCommonRetryPolicy<
       bigtable_admin::BigtableInstanceAdminRetryPolicy>(tested.clone());
-  CheckLimitedTime(std::move(common));
+  CheckLimitedTime(std::move(common), __func__);
 }
 
 /// @test A simple test for grpc::StatusCode::OK is not Permanent Error.
@@ -99,11 +100,11 @@ TEST(LimitedTimeRetryPolicy, PermanentFailureCheck) {
 TEST(LimitedTimeRetryPolicy, Clone) {
   LimitedTimeRetryPolicy original(kLimitedTimeTestPeriod);
   auto tested = original.clone();
-  CheckLimitedTime(*tested);
+  CheckLimitedTime(*tested, __func__);
 
   auto common = bigtable_internal::MakeCommonRetryPolicy<
       bigtable_admin::BigtableInstanceAdminRetryPolicy>(original.clone());
-  CheckLimitedTime(common->clone());
+  CheckLimitedTime(common->clone(), __func__);
 }
 
 /// @test Verify that non-retryable errors cause an immediate failure.

diff --git a/google/cloud/internal/retry_policy_impl_test.cc b/google/cloud/internal/retry_policy_impl_test.cc
@@ -51,24 +51,24 @@ auto const kLimitedTimeTolerance = std::chrono::milliseconds(20);
  *
  * This eliminates some amount of code duplication in the following tests.
  */
-void CheckLimitedTime(RetryPolicy& tested) {
+void CheckLimitedTime(RetryPolicy& tested, char const* where) {
   google::cloud::testing_util::CheckPredicateBecomesFalse(
       [&tested] { return tested.OnFailure(CreateTransientError()); },
       std::chrono::system_clock::now() + kLimitedTimeTestPeriod,
-      kLimitedTimeTolerance);
+      kLimitedTimeTolerance, where);
 }
 
 /// @test A simple test for the LimitedTimeRetryPolicy.
 TEST(LimitedTimeRetryPolicy, Simple) {
   LimitedTimeRetryPolicyForTest tested(kLimitedTimeTestPeriod);
-  CheckLimitedTime(tested);
+  CheckLimitedTime(tested, __func__);
 }
 
 /// @test Test cloning for LimitedTimeRetryPolicy.
 TEST(LimitedTimeRetryPolicy, Clone) {
   LimitedTimeRetryPolicyForTest original(kLimitedTimeTestPeriod);
   auto cloned = original.clone();
-  CheckLimitedTime(*cloned);
+  CheckLimitedTime(*cloned, __func__);
 }
 
 /// @test Verify that non-retryable errors cause an immediate failure.

diff --git a/google/cloud/polling_policy_test.cc b/google/cloud/polling_policy_test.cc
@@ -48,11 +48,11 @@ auto const kLimitedTimeTolerance = ms(20);
  * @test Verify that a polling policy configured to run for 50ms works
  * correctly.
  */
-void CheckLimitedTime(PollingPolicy& tested) {
+void CheckLimitedTime(PollingPolicy& tested, char const* where) {
   google::cloud::testing_util::CheckPredicateBecomesFalse(
       [&tested] { return tested.OnFailure(TransientError()); },
       std::chrono::system_clock::now() + kLimitedTimeTestPeriod,
-      kLimitedTimeTolerance);
+      kLimitedTimeTolerance, where);
 }
 
 /// @test A simple test for the GenericPollingPolicy.
@@ -62,7 +62,7 @@ TEST(GenericPollingPolicy, Simple) {
   GenericPollingPolicy<LimitedTimeRetryPolicyForTest,
                        internal::ExponentialBackoffPolicy>
       tested(retry, backoff);
-  CheckLimitedTime(tested);
+  CheckLimitedTime(tested, __func__);
   auto delay = tested.WaitPeriod();
   EXPECT_LE(ms(10), delay);
   EXPECT_GE(ms(20), delay);
@@ -75,7 +75,7 @@ TEST(GenericPollingPolicy, SimpleWithPointers) {
   GenericPollingPolicy<std::shared_ptr<RetryPolicyForTest>,
                        std::shared_ptr<internal::BackoffPolicy>>
       tested(retry.clone(), backoff.clone());
-  CheckLimitedTime(tested);
+  CheckLimitedTime(tested, __func__);
   auto delay = tested.WaitPeriod();
   EXPECT_LE(ms(10), delay);
   EXPECT_GE(ms(20), delay);

diff --git a/google/cloud/testing_util/check_predicate_becomes_false.h b/google/cloud/testing_util/check_predicate_becomes_false.h
@@ -15,6 +15,7 @@
 #ifndef GOOGLE_CLOUD_CPP_GOOGLE_CLOUD_TESTING_UTIL_CHECK_PREDICATE_BECOMES_FALSE_H
 #define GOOGLE_CLOUD_CPP_GOOGLE_CLOUD_TESTING_UTIL_CHECK_PREDICATE_BECOMES_FALSE_H
 
+#include "google/cloud/testing_util/chrono_output.h"
 #include "google/cloud/version.h"
 #include <gmock/gmock.h>
 #include <chrono>
@@ -33,7 +34,8 @@ namespace testing_util {
 template <typename Predicate>
 void CheckPredicateBecomesFalse(Predicate&& predicate,
                                 std::chrono::system_clock::time_point deadline,
-                                std::chrono::milliseconds tolerance) {
+                                std::chrono::milliseconds tolerance,
+                                char const* where) {
   // This is one of those tests that can get annoyingly flaky, it is based on
   // time.  Basically we want to know that the policy will accept failures
   // until around its prescribed deadline (50ms in this test).  Instead of
@@ -56,12 +58,22 @@ void CheckPredicateBecomesFalse(Predicate&& predicate,
     auto actual = predicate();
     auto iteration_end = std::chrono::system_clock::now();
     if (iteration_end < must_be_true_before) {
-      EXPECT_TRUE(actual);
+      EXPECT_TRUE(actual) << "deadline=" << deadline
+                          << ", tolerance=" << tolerance
+                          << ", iteration_start=" << iteration_start
+                          << ", iteration_end=" << iteration_end
+                          << ", must_be_true_before=" << must_be_true_before
+                          << ", where=" << where;
       if (actual) {
         ++true_count;
       }
     } else if (must_be_false_after < iteration_start) {
-      EXPECT_FALSE(actual);
+      EXPECT_FALSE(actual) << "deadline=" << deadline
+                           << ", tolerance=" << tolerance
+                           << ", iteration_start=" << iteration_start
+                           << ", iteration_end=" << iteration_end
+                           << ", must_be_true_before=" << must_be_true_before
+                           << ", where=" << where;
       if (!actual) {
         // Terminate the loop early if we can.
         ++false_count;