[end2end] Better logging, and a fix (by increasing timeout) on disappearing_server_test (#33444)

I've had local runs with a 10 second gap between creating the call and
issuing the first batch client side.

---------

Co-authored-by: ctiller <ctiller@users.noreply.github.com>

test/core/end2end/cq_verifier.cc

@@ -24,6 +24,7 @@
 
 #include <algorithm>
 #include <initializer_list>
+#include <limits>
 #include <string>
 #include <utility>
 #include <vector>
@@ -182,7 +183,9 @@ int byte_buffer_eq_string(grpc_byte_buffer* bb, const char* str) {
 
 namespace {
 bool IsProbablyInteger(void* p) {
-  return reinterpret_cast<uintptr_t>(p) < 1000000;
+  return reinterpret_cast<uintptr_t>(p) < 1000000 ||
+         (reinterpret_cast<uintptr_t>(p) >
+          std::numeric_limits<uintptr_t>::max() - 10);
 }
 
 std::string TagStr(void* tag) {
@@ -224,6 +227,21 @@ std::string CqVerifier::Expectation::ToString() const {
           }));
 }
 
+std::string CqVerifier::Expectation::ToShortString() const {
+  return absl::StrCat(
+      TagStr(tag),
+      Match(
+          result,
+          [](bool success) -> std::string {
+            if (!success) return "-❌";
+            return "-✅";
+          },
+          [](Maybe) { return std::string("-❓"); },
+          [](AnyStatus) { return std::string("-🤷"); },
+          [](const PerformAction&) { return std::string("-🎬"); },
+          [](const MaybePerformAction&) { return std::string("-🎬❓"); }));
+}
+
 std::vector<std::string> CqVerifier::ToStrings() const {
   std::vector<std::string> expectations;
   expectations.reserve(expectations_.size());
@@ -237,6 +255,19 @@ std::string CqVerifier::ToString() const {
   return absl::StrJoin(ToStrings(), "\n");
 }
 
+std::vector<std::string> CqVerifier::ToShortStrings() const {
+  std::vector<std::string> expectations;
+  expectations.reserve(expectations_.size());
+  for (const auto& e : expectations_) {
+    expectations.push_back(e.ToShortString());
+  }
+  return expectations;
+}
+
+std::string CqVerifier::ToShortString() const {
+  return absl::StrJoin(ToShortStrings(), " ");
+}
+
 void CqVerifier::FailNoEventReceived(const SourceLocation& location) const {
   fail_(Failure{location, "No event received", ToStrings()});
 }
@@ -248,7 +279,8 @@ void CqVerifier::FailUnexpectedEvent(grpc_event* ev,
                 ToStrings()});
 }
 
-void CqVerifier::FailUsingGprCrash(const Failure& failure) {
+namespace {
+std::string CrashMessage(const CqVerifier::Failure& failure) {
   std::string message =
       absl::StrCat(failure.message, "\nexpectation checked @ ",
                    failure.location.file(), ":", failure.location.line());
@@ -260,7 +292,16 @@ void CqVerifier::FailUsingGprCrash(const Failure& failure) {
   } else {
     absl::StrAppend(&message, "\nexpected nothing");
   }
-  CrashWithStdio(message);
+  return message;
+}
+}  // namespace
+
+void CqVerifier::FailUsingGprCrashWithStdio(const Failure& failure) {
+  CrashWithStdio(CrashMessage(failure));
+}
+
+void CqVerifier::FailUsingGprCrash(const Failure& failure) {
+  Crash(CrashMessage(failure));
 }
 
 void CqVerifier::FailUsingGtestFail(const Failure& failure) {
@@ -302,6 +343,9 @@ grpc_event CqVerifier::Step(gpr_timespec deadline) {
 }
 
 void CqVerifier::Verify(Duration timeout, SourceLocation location) {
+  if (expectations_.empty()) return;
+  gpr_log(GPR_ERROR, "Verify %s for %s", ToShortString().c_str(),
+          timeout.ToString().c_str());
   const gpr_timespec deadline =
       grpc_timeout_milliseconds_to_deadline(timeout.millis());
   while (!expectations_.empty()) {
@@ -358,6 +402,8 @@ bool CqVerifier::AllMaybes() const {
 }
 
 void CqVerifier::VerifyEmpty(Duration timeout, SourceLocation location) {
+  gpr_log(GPR_ERROR, "Verify empty completion queue for %s",
+          timeout.ToString().c_str());
   const gpr_timespec deadline =
       gpr_time_add(gpr_now(GPR_CLOCK_MONOTONIC), timeout.as_timespec());
   GPR_ASSERT(expectations_.empty());

test/core/end2end/cq_verifier.h

@@ -71,6 +71,7 @@ class CqVerifier {
   };
 
   static void FailUsingGprCrash(const Failure& failure);
+  static void FailUsingGprCrashWithStdio(const Failure& failure);
   static void FailUsingGtestFail(const Failure& failure);
 
   // Allow customizing the failure handler
@@ -106,6 +107,8 @@ class CqVerifier {
 
   std::string ToString() const;
   std::vector<std::string> ToStrings() const;
+  std::string ToShortString() const;
+  std::vector<std::string> ToShortStrings() const;
 
   static void* tag(intptr_t t) { return reinterpret_cast<void*>(t); }
 
@@ -116,6 +119,7 @@ class CqVerifier {
     ExpectedResult result;
 
     std::string ToString() const;
+    std::string ToShortString() const;
   };
 
   void FailNoEventReceived(const SourceLocation& location) const;

test/core/end2end/end2end_tests.cc

@@ -136,6 +136,15 @@ grpc_op CoreEnd2endTest::IncomingMetadata::MakeOp() {
   return op;
 }
 
+std::string CoreEnd2endTest::IncomingMetadata::ToString() {
+  std::string out = "{";
+  for (size_t i = 0; i < metadata_->count; i++) {
+    absl::StrAppend(&out, StringViewFromSlice(metadata_->metadata[i].key), ":",
+                    StringViewFromSlice(metadata_->metadata[i].value), ",");
+  }
+  return out + "}";
+}
+
 std::string CoreEnd2endTest::IncomingMessage::payload() const {
   Slice out;
   if (payload_->data.raw.compression > GRPC_COMPRESS_NONE) {
@@ -175,6 +184,19 @@ CoreEnd2endTest::IncomingStatusOnClient::GetTrailingMetadata(
   return FindInMetadataArray(data_->trailing_metadata, key);
 }
 
+std::string CoreEnd2endTest::IncomingStatusOnClient::ToString() {
+  std::string out =
+      absl::StrCat("{status:", data_->status,
+                   " msg:", data_->status_details.as_string_view(), " ");
+  for (size_t i = 0; i < data_->trailing_metadata.count; i++) {
+    absl::StrAppend(
+        &out, StringViewFromSlice(data_->trailing_metadata.metadata[i].key),
+        ": ", StringViewFromSlice(data_->trailing_metadata.metadata[i].value),
+        ",");
+  }
+  return out + "}";
+}
+
 grpc_op CoreEnd2endTest::IncomingStatusOnClient::MakeOp() {
   grpc_op op;
   memset(&op, 0, sizeof(op));

test/core/end2end/end2end_tests.h

@@ -231,6 +231,8 @@ class CoreEnd2endTest : public ::testing::Test {
     // for tests.
     grpc_op MakeOp();
 
+    std::string ToString();
+
    private:
     std::unique_ptr<grpc_metadata_array> metadata_ =
         std::make_unique<grpc_metadata_array>(
@@ -297,6 +299,8 @@ class CoreEnd2endTest : public ::testing::Test {
     absl::optional<std::string> GetTrailingMetadata(
         absl::string_view key) const;
 
+    std::string ToString();
+
     // Make a GRPC_OP_RECV_STATUS_ON_CLIENT op - intended for the framework, not
     // for tests.
     grpc_op MakeOp();
@@ -692,7 +696,10 @@ class CoreEnd2endTest : public ::testing::Test {
     if (cq_verifier_ == nullptr) {
       fixture();  // ensure cq_ present
       cq_verifier_ = absl::make_unique<CqVerifier>(
-          cq_, CqVerifier::FailUsingGprCrash, std::move(step_fn_));
+          cq_,
+          g_is_fuzzing_core_e2e_tests ? CqVerifier::FailUsingGprCrashWithStdio
+                                      : CqVerifier::FailUsingGprCrash,
+          std::move(step_fn_));
     }
     return *cq_verifier_;
   }

test/core/end2end/tests/disappearing_server.cc

@@ -16,11 +16,14 @@
 //
 //
 
+#include "absl/strings/str_cat.h"
 #include "gtest/gtest.h"
 
 #include <grpc/status.h>
+#include <grpc/support/log.h>
 
 #include "src/core/lib/channel/channel_args.h"
+#include "src/core/lib/gprpp/crash.h"
 #include "src/core/lib/gprpp/time.h"
 #include "test/core/end2end/end2end_tests.h"
 
@@ -28,11 +31,13 @@
 namespace grpc_core {
 
 static void OneRequestAndShutdownServer(CoreEnd2endTest& test) {
+  gpr_log(GPR_ERROR, "Create client side call");
   auto c = test.NewClientCall("/service/method")
-               .Timeout(Duration::Seconds(5))
+               .Timeout(Duration::Seconds(30))
                .Create();
   CoreEnd2endTest::IncomingMetadata server_initial_md;
   CoreEnd2endTest::IncomingStatusOnClient server_status;
+  gpr_log(GPR_ERROR, "Start initial batch");
   c.NewBatch(1)
       .SendInitialMetadata({})
       .SendCloseFromClient()
@@ -40,6 +45,13 @@ static void OneRequestAndShutdownServer(CoreEnd2endTest& test) {
       .RecvStatusOnClient(server_status);
   auto s = test.RequestCall(101);
   test.Expect(101, true);
+  test.Expect(
+      1, CoreEnd2endTest::MaybePerformAction{[&](bool success) {
+        Crash(absl::StrCat(
+            "Unexpected completion of client side call: success=",
+            success ? "true" : "false", " status=", server_status.ToString(),
+            " initial_md=", server_initial_md.ToString()));
+      }});
   test.Step();
   test.ShutdownServerAndNotify(1000);
   CoreEnd2endTest::IncomingCloseOnServer client_closed;

test/core/end2end/tests/no_logging.cc

@@ -17,7 +17,9 @@
 //
 
 #include <atomic>
+#include <regex>
 #include <string>
+#include <vector>
 
 #include "absl/strings/str_cat.h"
 #include "absl/types/optional.h"
@@ -67,6 +69,11 @@ class Verifier {
   static void DispatchLog(gpr_log_func_args* args) { g_log_func_.load()(args); }
 
   static void NoLog(gpr_log_func_args* args) {
+    static const auto* const re = new std::regex("^Verify .* for [0-9]+ms");
+    if (std::regex_match(args->message, *re)) {
+      gpr_default_log(args);
+      return;
+    }
     std::string message = absl::StrCat("Unwanted log: ", args->message);
     args->message = message.c_str();
     gpr_default_log(args);