Firestore: Improve logging of timeouts in integration tests (#1030)

Author: dconeybe

firestore/integration_test_internal/src/firestore_integration_test.cc

@@ -18,6 +18,7 @@
 
 #include <cstdlib>
 #include <fstream>
+#include <iomanip>
 #include <memory>
 #include <sstream>
 
@@ -125,6 +126,16 @@ int WaitFor(const FutureBase& future) {
   return cycles;
 }
 
+std::ostream& operator<<(std::ostream& out, const Stopwatch& stopwatch) {
+  // Use a temporary ostream instead of writing directly to the given `out`
+  // stream because std::setprecision has effects that extend beyond the
+  // lifetime of this function and we shouldn't be changing the state of the
+  // given stream.
+  std::ostringstream oss;
+  oss << std::setprecision(3) << stopwatch.elapsed_time().count() << " seconds";
+  return out << oss.str();
+}
+
 FirestoreIntegrationTest::FirestoreIntegrationTest() {
   // Allocate the default Firestore eagerly.
   TestFirestore();
@@ -227,8 +238,10 @@ DocumentReference FirestoreIntegrationTest::DocumentWithData(
 void FirestoreIntegrationTest::WriteDocument(DocumentReference reference,
                                              const MapFieldValue& data) const {
   Future<void> future = reference.Set(data);
+  Stopwatch stopwatch;
   Await(future);
-  FailIfUnsuccessful("WriteDocument", future);
+  stopwatch.stop();
+  FailIfUnsuccessful("WriteDocument", future, stopwatch);
 }
 
 void FirestoreIntegrationTest::WriteDocuments(
@@ -242,8 +255,10 @@ void FirestoreIntegrationTest::WriteDocuments(
 DocumentSnapshot FirestoreIntegrationTest::ReadDocument(
     const DocumentReference& reference) const {
   Future<DocumentSnapshot> future = reference.Get();
+  Stopwatch stopwatch;
   const DocumentSnapshot* result = Await(future);
-  if (FailIfUnsuccessful("ReadDocument", future)) {
+  stopwatch.stop();
+  if (FailIfUnsuccessful("ReadDocument", future, stopwatch)) {
     return {};
   } else {
     return *result;
@@ -253,8 +268,10 @@ DocumentSnapshot FirestoreIntegrationTest::ReadDocument(
 QuerySnapshot FirestoreIntegrationTest::ReadDocuments(
     const Query& reference) const {
   Future<QuerySnapshot> future = reference.Get();
+  Stopwatch stopwatch;
   const QuerySnapshot* result = Await(future);
-  if (FailIfUnsuccessful("ReadDocuments", future)) {
+  stopwatch.stop();
+  if (FailIfUnsuccessful("ReadDocuments", future, stopwatch)) {
     return {};
   } else {
     return *result;
@@ -264,8 +281,10 @@ QuerySnapshot FirestoreIntegrationTest::ReadDocuments(
 void FirestoreIntegrationTest::DeleteDocument(
     DocumentReference reference) const {
   Future<void> future = reference.Delete();
+  Stopwatch stopwatch;
   Await(future);
-  FailIfUnsuccessful("DeleteDocument", future);
+  stopwatch.stop();
+  FailIfUnsuccessful("DeleteDocument", future, stopwatch);
 }
 
 std::vector<std::string> FirestoreIntegrationTest::QuerySnapshotToIds(
@@ -309,14 +328,15 @@ void FirestoreIntegrationTest::Await(const Future<void>& future) {
 
 /* static */
 bool FirestoreIntegrationTest::FailIfUnsuccessful(const char* operation,
-                                                  const FutureBase& future) {
+                                                  const FutureBase& future,
+                                                  const Stopwatch& stopwatch) {
   if (future.status() != FutureStatus::kFutureStatusComplete) {
-    ADD_FAILURE() << operation << " timed out: " << DescribeFailedFuture(future)
-                  << std::endl;
+    ADD_FAILURE() << operation << " timed out after " << stopwatch << ": "
+                  << DescribeFailedFuture(future) << std::endl;
     return true;
   } else if (future.error() != Error::kErrorOk) {
-    ADD_FAILURE() << operation << " failed: " << DescribeFailedFuture(future)
-                  << std::endl;
+    ADD_FAILURE() << operation << " failed after " << stopwatch << ": "
+                  << DescribeFailedFuture(future) << std::endl;
     return true;
   } else {
     return false;

firestore/integration_test_internal/src/firestore_integration_test.h

@@ -17,10 +17,12 @@
 #ifndef FIREBASE_FIRESTORE_INTEGRATION_TEST_INTERNAL_SRC_FIRESTORE_INTEGRATION_TEST_H_
 #define FIREBASE_FIRESTORE_INTEGRATION_TEST_INTERNAL_SRC_FIRESTORE_INTEGRATION_TEST_H_
 
+#include <chrono>
 #include <cstdio>
 #include <iostream>
 #include <map>
 #include <memory>
+#include <mutex>
 #include <string>
 #include <unordered_map>
 #include <vector>
@@ -174,6 +176,37 @@ class TestEventListener {
   bool print_debug_info_ = false;
 };
 
+// A stopwatch that can calculate the runtime of some operation.
+//
+// The motivating use case for this class is to include the elapsed time of
+// an operation that timed out in the timeout error message.
+class Stopwatch {
+ public:
+  Stopwatch() : start_time_(std::chrono::steady_clock::now()) {}
+
+  std::chrono::duration<double> elapsed_time() const {
+    std::lock_guard<std::mutex> lock(mutex_);
+    const auto t =
+        stop_time_valid_ ? stop_time_ : std::chrono::steady_clock::now();
+    return t - start_time_;
+  }
+
+  void stop() {
+    std::lock_guard<std::mutex> lock(mutex_);
+    assert(!stop_time_valid_);
+    stop_time_ = std::chrono::steady_clock::now();
+    stop_time_valid_ = true;
+  }
+
+ private:
+  mutable std::mutex mutex_;
+  decltype(std::chrono::steady_clock::now()) start_time_;
+  decltype(std::chrono::steady_clock::now()) stop_time_;
+  bool stop_time_valid_ = false;
+};
+
+std::ostream& operator<<(std::ostream&, const Stopwatch&);
+
 // A RAII wrapper that enables Firestore debug logging and then disables it
 // upon destruction.
 //
@@ -318,8 +351,9 @@ class FirestoreIntegrationTest : public testing::Test {
   // A helper function to block until the future completes.
   template <typename T>
   static const T* Await(const Future<T>& future) {
+    Stopwatch stopwatch;
     int cycles = WaitFor(future);
-    EXPECT_GT(cycles, 0) << "Waiting future timed out.";
+    EXPECT_GT(cycles, 0) << "Waiting future timed out after " << stopwatch;
     if (future.status() == FutureStatus::kFutureStatusComplete) {
       if (future.result() == nullptr) {
         std::cout << "WARNING: " << DescribeFailedFuture(future) << std::endl;
@@ -336,6 +370,7 @@ class FirestoreIntegrationTest : public testing::Test {
   template <typename T>
   static void Await(const TestEventListener<T>& listener, int n = 1) {
     // Instead of getting a clock, we count the cycles instead.
+    Stopwatch stopwatch;
     int cycles = kTimeOutMillis / kCheckIntervalMillis;
     while (listener.event_count() < n && cycles > 0) {
       if (ProcessEvents(kCheckIntervalMillis)) {
@@ -345,13 +380,15 @@ class FirestoreIntegrationTest : public testing::Test {
       }
       --cycles;
     }
-    EXPECT_GT(cycles, 0) << "Waiting listener timed out.";
+    EXPECT_GT(cycles, 0) << "Waiting listener timed out after " << stopwatch;
   }
 
   // Fails the current test if the given future did not complete or contained an
-  // error. Returns true if the future has failed.
+  // error. Returns true if the future has failed. The given Stopwatch will be
+  // used to include the elapsed time in any failure message.
   static bool FailIfUnsuccessful(const char* operation,
-                                 const FutureBase& future);
+                                 const FutureBase& future,
+                                 const Stopwatch& stopwatch);
 
   static std::string DescribeFailedFuture(const FutureBase& future);
 

firestore/integration_test_internal/src/firestore_test.cc

@@ -1494,8 +1494,10 @@ TEST_F(FirestoreIntegrationTest, AuthWorks) {
 
   // Signing in should trigger an AuthStateListener event.
   auto signin = auth->SignInAnonymously();
+  Stopwatch stopwatch;
   Await(signin);
-  FailIfUnsuccessful("SignInAnonymously", signin);
+  stopwatch.stop();
+  FailIfUnsuccessful("SignInAnonymously", signin, stopwatch);
 
   // Writing again will trigger another pull of the token.
   WriteDocument(doc, MapFieldValue{{"foo", FieldValue::Integer(43)}});

firestore/integration_test_internal/src/numeric_transforms_test.cc

@@ -65,6 +65,8 @@ const char* TypeName(Type type) {
       return "kIncrementInteger";
     case Type::kIncrementDouble:
       return "kIncrementDouble";
+    default:
+      return "Unknown Type";
   }
 }
 
@@ -81,6 +83,7 @@ void PrintTo(const FieldValue& f, std::ostream* os) {
 class NumericTransformsTest : public FirestoreIntegrationTest {
  public:
   NumericTransformsTest() {
+    SCOPED_TRACE("NumericTransformsTest constructor");
     doc_ref_ = Document();
     listener_ =
         accumulator_.listener()->AttachTo(&doc_ref_, MetadataChanges::kInclude);
@@ -96,18 +99,20 @@ class NumericTransformsTest : public FirestoreIntegrationTest {
   /** Writes values and waits for the corresponding snapshot. */
   void WriteInitialData(const MapFieldValue& doc) {
     WriteDocument(doc_ref_, doc);
-
+    SCOPED_TRACE("WriteInitialData");
     accumulator_.AwaitRemoteEvent();
   }
 
   void ExpectLocalAndRemoteValue(int value) {
+    SCOPED_TRACE("ExpectLocalAndRemoteValue");
     DocumentSnapshot snap = accumulator_.AwaitLocalEvent();
     ASSERT_EQ(snap.Get("sum"), FieldValue::Integer(value));
     snap = accumulator_.AwaitRemoteEvent();
     ASSERT_EQ(snap.Get("sum"), FieldValue::Integer(value));
   }
 
   void ExpectLocalAndRemoteValue(double value) {
+    SCOPED_TRACE("ExpectLocalAndRemoteValue");
     DocumentSnapshot snap = accumulator_.AwaitLocalEvent();
     ASSERT_EQ(snap.Get("sum"), FieldValue::Double(value));
     snap = accumulator_.AwaitRemoteEvent();

firestore/integration_test_internal/src/util/event_accumulator.h

@@ -17,6 +17,8 @@
 #ifndef FIREBASE_FIRESTORE_INTEGRATION_TEST_INTERNAL_SRC_UTIL_EVENT_ACCUMULATOR_H_
 #define FIREBASE_FIRESTORE_INTEGRATION_TEST_INTERNAL_SRC_UTIL_EVENT_ACCUMULATOR_H_
 
+#include <vector>
+
 #include "firestore_integration_test.h"
 
 namespace firebase {
@@ -31,6 +33,8 @@ class EventAccumulator {
   TestEventListener<T>* listener() { return &listener_; }
 
   std::vector<T> Await(int num_events) {
+    SCOPED_TRACE("EventAccumulator::Await() num_events=" +
+                 std::to_string(num_events));
     int old_num_events = num_events_consumed_;
     int desired_events = num_events_consumed_ + num_events;
     FirestoreIntegrationTest::Await(listener_, desired_events);
@@ -54,6 +58,7 @@ class EventAccumulator {
 
   /** Awaits 1 event. */
   T Await() {
+    SCOPED_TRACE("EventAccumulator::Await()");
     auto events = Await(1);
     if (events.empty()) {
       return {};
@@ -64,6 +69,7 @@ class EventAccumulator {
 
   /** Waits for a snapshot with pending writes. */
   T AwaitLocalEvent() {
+    SCOPED_TRACE("EventAccumulator::AwaitLocalEvent()");
     T event;
     do {
       event = Await();
@@ -73,6 +79,7 @@ class EventAccumulator {
 
   /** Waits for a snapshot that has no pending writes. */
   T AwaitRemoteEvent() {
+    SCOPED_TRACE("EventAccumulator::AwaitRemoteEvent()");
     T event;
     do {
       event = Await();
@@ -85,6 +92,7 @@ class EventAccumulator {
    * NOTE: Helper exists only in C++ test. Not in native SDK test yet.
    */
   T AwaitCacheEvent() {
+    SCOPED_TRACE("EventAccumulator::AwaitCacheEvent()");
     T event;
     do {
       event = Await();
@@ -97,6 +105,7 @@ class EventAccumulator {
    * NOTE: Helper exists only in C++ test. Not in native SDK test yet.
    */
   T AwaitServerEvent() {
+    SCOPED_TRACE("EventAccumulator::AwaitServerEvent()");
     T event;
     do {
       event = Await();