[end2end] Explain failures a little better (#33621)

I'd been adding the following stanza regularly to debug flakes/fuzz failures: ``` 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_metadata.ToString())); }}); ``` it was helpful because it indicated why a call batch finished successfully and helped quickly identify next steps. It occurred to me however that this would better be done inside of the framework, and for *all* ops that have outputs, so this PR does just that. Any time a batch with an op that outputs information finishes successfully but unexpectedly we now display those outputs in human readable form in the error message. Sample output: ``` [ RUN ] CorpusExamples/FuzzerCorpusTest.RunOneExample/0 RUN TEST: Http2SingleHopTest.SimpleDelayedRequestShort/Chttp2SimpleSslFullstack E0101 00:00:05.000000000 396633 simple_delayed_request.cc:37] Create client side call E0101 00:00:05.000000000 396633 simple_delayed_request.cc:41] Start initial batch E0101 00:00:05.000000000 396633 simple_delayed_request.cc:47] Start server E0101 00:00:05.000000000 396633 cq_verifier.cc:364] Verify tag(101)-✅ for 600000ms test/core/end2end/cq_verifier.cc:316: Unexpected event: OP_COMPLETE: tag:0x1 OK with: incoming_metadata: {} status_on_client: status=4 msg=Deadline Exceeded trailing_metadata={} checked @ test/core/end2end/tests/simple_delayed_request.cc:51 expected: test/core/end2end/tests/simple_delayed_request.cc:50: tag(101) success=true ```
2 years ago · 08f1cc3ba8
parent 1e465cac91
commit 08f1cc3ba8
10 changed files with 102 additions and 73 deletions
--- a/test/core/end2end/BUILD
+++ b/test/core/end2end/BUILD
@ -25,6 +25,7 @@ grpc_cc_library(
    srcs = ["cq_verifier.cc"],
    hdrs = ["cq_verifier.h"],
    external_deps = [
+        "absl/container:flat_hash_map",
        "absl/functional:any_invocable",
        "absl/strings",
        "absl/strings:str_format",
--- a/test/core/end2end/cq_verifier.cc
+++ b/test/core/end2end/cq_verifier.cc
@ -269,21 +269,36 @@ std::string CqVerifier::ToShortString() const {
 }

 void CqVerifier::FailNoEventReceived(const SourceLocation& location) const {
-  fail_(Failure{location, "No event received", ToStrings()});
+  fail_(Failure{location, "No event received", ToStrings(), {}});
 }

 void CqVerifier::FailUnexpectedEvent(grpc_event* ev,
                                     const SourceLocation& location) const {
+  std::vector<std::string> message_details;
+  if (ev->type == GRPC_OP_COMPLETE && ev->success) {
+    auto successful_state_strings = successful_state_strings_.find(ev->tag);
+    if (successful_state_strings != successful_state_strings_.end()) {
+      for (SuccessfulStateString* sss : successful_state_strings->second) {
+        message_details.push_back(sss->GetSuccessfulStateString());
+      }
+    }
+  }
  fail_(Failure{location,
                absl::StrCat("Unexpected event: ", grpc_event_string(ev)),
-                ToStrings()});
+                ToStrings(), std::move(message_details)});
 }

 namespace {
 std::string CrashMessage(const CqVerifier::Failure& failure) {
-  std::string message =
-      absl::StrCat(failure.message, "\nexpectation checked @ ",
-                   failure.location.file(), ":", failure.location.line());
+  std::string message = failure.message;
+  if (!failure.message_details.empty()) {
+    absl::StrAppend(&message, "\nwith:");
+    for (const auto& detail : failure.message_details) {
+      absl::StrAppend(&message, "\n  ", detail);
+    }
+  }
+  absl::StrAppend(&message, "\nchecked @ ", failure.location.file(), ":",
+                  failure.location.line());
  if (!failure.expected.empty()) {
    absl::StrAppend(&message, "\nexpected:\n");
    for (const auto& line : failure.expected) {
@ -422,4 +437,13 @@ void CqVerifier::Expect(void* tag, ExpectedResult result,
  expectations_.push_back(Expectation{location, tag, std::move(result)});
 }

+void CqVerifier::AddSuccessfulStateString(
+    void* tag, SuccessfulStateString* successful_state_string) {
+  successful_state_strings_[tag].push_back(successful_state_string);
+}
+
+void CqVerifier::ClearSuccessfulStateStrings(void* tag) {
+  successful_state_strings_.erase(tag);
+}
+
 }  // namespace grpc_core
--- a/test/core/end2end/cq_verifier.h
+++ b/test/core/end2end/cq_verifier.h
@ -25,6 +25,7 @@
 #include <string>
 #include <vector>

+#include "absl/container/flat_hash_map.h"
 #include "absl/functional/any_invocable.h"
 #include "absl/types/variant.h"

@ -64,10 +65,22 @@ class CqVerifier {
  using ExpectedResult =
      absl::variant<bool, Maybe, AnyStatus, PerformAction, MaybePerformAction>;

+  // Captures information about one failure
  struct Failure {
    SourceLocation location;
    std::string message;
    std::vector<std::string> expected;
+    std::vector<std::string> message_details;
+  };
+
+  // Produces a string upon the successful (but unexpected) completion of an
+  // expectation.
+  class SuccessfulStateString {
+   public:
+    virtual std::string GetSuccessfulStateString() = 0;
+
+   protected:
+    ~SuccessfulStateString() = default;
  };

  static void FailUsingGprCrash(const Failure& failure);
@ -98,6 +111,10 @@ class CqVerifier {
  void VerifyEmpty(Duration timeout = Duration::Seconds(1),
                   SourceLocation location = SourceLocation());

+  void ClearSuccessfulStateStrings(void* tag);
+  void AddSuccessfulStateString(void* tag,
+                                SuccessfulStateString* successful_state_string);
+
  // Match an expectation about a status.
  // location must be DEBUG_LOCATION.
  // result can be any of the types in ExpectedResult - a plain bool means
@ -141,6 +158,8 @@ class CqVerifier {
  absl::AnyInvocable<void(
      grpc_event_engine::experimental::EventEngine::Duration) const>
      step_fn_;
+  absl::flat_hash_map<void*, std::vector<SuccessfulStateString*>>
+      successful_state_strings_;
  bool log_verifications_ = true;
 };

--- a/test/core/end2end/end2end_tests.cc
+++ b/test/core/end2end/end2end_tests.cc
@ -136,8 +136,8 @@ grpc_op CoreEnd2endTest::IncomingMetadata::MakeOp() {
  return op;
 }

-std::string CoreEnd2endTest::IncomingMetadata::ToString() {
-  std::string out = "{";
+std::string CoreEnd2endTest::IncomingMetadata::GetSuccessfulStateString() {
+  std::string out = "incoming_metadata: {";
  for (size_t i = 0; i < metadata_->count; i++) {
    absl::StrAppend(&out, StringViewFromSlice(metadata_->metadata[i].key), ":",
                    StringViewFromSlice(metadata_->metadata[i].value), ",");
@ -184,10 +184,11 @@ 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(), " ");
+std::string
+CoreEnd2endTest::IncomingStatusOnClient::GetSuccessfulStateString() {
+  std::string out = absl::StrCat(
+      "status_on_client: status=", data_->status,
+      " msg=", data_->status_details.as_string_view(), " trailing_metadata={");
  for (size_t i = 0; i < data_->trailing_metadata.count; i++) {
    absl::StrAppend(
        &out, StringViewFromSlice(data_->trailing_metadata.metadata[i].key),
@ -197,6 +198,11 @@ std::string CoreEnd2endTest::IncomingStatusOnClient::ToString() {
  return out + "}";
 }

+std::string CoreEnd2endTest::IncomingMessage::GetSuccessfulStateString() {
+  if (payload_ == nullptr) return "message: empty";
+  return absl::StrCat("message: ", payload().size(), "b uncompressed");
+}
+
 grpc_op CoreEnd2endTest::IncomingStatusOnClient::MakeOp() {
  grpc_op op;
  memset(&op, 0, sizeof(op));
@ -298,19 +304,22 @@ CoreEnd2endTest::Call CoreEnd2endTest::ClientCallBuilder::Create() {
    absl::optional<Slice> host;
    if (u->host.has_value()) host = Slice::FromCopiedString(*u->host);
    test_.ForceInitialized();
-    return Call(grpc_channel_create_call(
-        test_.client(), parent_call_, propagation_mask_, test_.cq(),
-        Slice::FromCopiedString(u->method).c_slice(),
-        host.has_value() ? &host->c_slice() : nullptr, deadline_, nullptr));
+    return Call(
+        grpc_channel_create_call(
+            test_.client(), parent_call_, propagation_mask_, test_.cq(),
+            Slice::FromCopiedString(u->method).c_slice(),
+            host.has_value() ? &host->c_slice() : nullptr, deadline_, nullptr),
+        &test_);
  } else {
    return Call(grpc_channel_create_registered_call(
-        test_.client(), parent_call_, propagation_mask_, test_.cq(),
-        absl::get<void*>(call_selector_), deadline_, nullptr));
+                    test_.client(), parent_call_, propagation_mask_, test_.cq(),
+                    absl::get<void*>(call_selector_), deadline_, nullptr),
+                &test_);
  }
 }

 CoreEnd2endTest::IncomingCall::IncomingCall(CoreEnd2endTest& test, int tag)
-    : impl_(std::make_unique<Impl>()) {
+    : impl_(std::make_unique<Impl>(&test)) {
  test.ForceInitialized();
  grpc_server_request_call(test.server(), impl_->call.call_ptr(),
                           &impl_->call_details, &impl_->request_metadata,
--- a/test/core/end2end/end2end_tests.h
+++ b/test/core/end2end/end2end_tests.h
@ -34,6 +34,7 @@
 #include "absl/functional/any_invocable.h"
 #include "absl/memory/memory.h"
 #include "absl/meta/type_traits.h"
+#include "absl/strings/str_cat.h"
 #include "absl/strings/string_view.h"
 #include "absl/types/optional.h"
 #include "absl/types/variant.h"
@ -217,7 +218,7 @@ class CoreEnd2endTest : public ::testing::Test {
  };

  // Receiving container for incoming metadata.
-  class IncomingMetadata {
+  class IncomingMetadata final : public CqVerifier::SuccessfulStateString {
   public:
    IncomingMetadata() = default;
    ~IncomingMetadata() {
@ -231,7 +232,7 @@ class CoreEnd2endTest : public ::testing::Test {
    // for tests.
    grpc_op MakeOp();

-    std::string ToString();
+    std::string GetSuccessfulStateString() override;

   private:
    std::unique_ptr<grpc_metadata_array> metadata_ =
@ -240,7 +241,7 @@ class CoreEnd2endTest : public ::testing::Test {
  };

  // Receiving container for one incoming message.
-  class IncomingMessage {
+  class IncomingMessage final : public CqVerifier::SuccessfulStateString {
   public:
    IncomingMessage() = default;
    IncomingMessage(const IncomingMessage&) = delete;
@ -260,6 +261,7 @@ class CoreEnd2endTest : public ::testing::Test {
    grpc_compression_algorithm compression() const {
      return payload_->data.raw.compression;
    }
+    std::string GetSuccessfulStateString() override;

    // Make a GRPC_OP_RECV_MESSAGE op - intended for the framework, not for
    // tests.
@ -270,7 +272,8 @@ class CoreEnd2endTest : public ::testing::Test {
  };

  // Receiving container for incoming status on the client from the server.
-  class IncomingStatusOnClient {
+  class IncomingStatusOnClient final
+      : public CqVerifier::SuccessfulStateString {
   public:
    IncomingStatusOnClient() = default;
    IncomingStatusOnClient(const IncomingStatusOnClient&) = delete;
@ -299,7 +302,7 @@ class CoreEnd2endTest : public ::testing::Test {
    absl::optional<std::string> GetTrailingMetadata(
        absl::string_view key) const;

-    std::string ToString();
+    std::string GetSuccessfulStateString() override;

    // Make a GRPC_OP_RECV_STATUS_ON_CLIENT op - intended for the framework, not
    // for tests.
@ -316,7 +319,7 @@ class CoreEnd2endTest : public ::testing::Test {
  };

  // Receiving container for incoming status on the server from the client.
-  class IncomingCloseOnServer {
+  class IncomingCloseOnServer final : public CqVerifier::SuccessfulStateString {
   public:
    IncomingCloseOnServer() = default;
    IncomingCloseOnServer(const IncomingCloseOnServer&) = delete;
@ -329,6 +332,10 @@ class CoreEnd2endTest : public ::testing::Test {
    // for tests.
    grpc_op MakeOp();

+    std::string GetSuccessfulStateString() override {
+      return absl::StrCat("close_on_server: cancelled=", cancelled_);
+    }
+
   private:
    int cancelled_;
  };
@ -338,7 +345,10 @@ class CoreEnd2endTest : public ::testing::Test {
  // added batches.
  class BatchBuilder {
   public:
-    BatchBuilder(grpc_call* call, int tag) : call_(call), tag_(tag) {}
+    BatchBuilder(grpc_call* call, CoreEnd2endTest* test, int tag)
+        : call_(call), tag_(tag), cq_verifier_(&test->cq_verifier()) {
+      cq_verifier_->ClearSuccessfulStateStrings(CqVerifier::tag(tag_));
+    }
    ~BatchBuilder();

    BatchBuilder(const BatchBuilder&) = delete;
@ -371,24 +381,28 @@ class CoreEnd2endTest : public ::testing::Test {

    // Add a GRPC_OP_RECV_INITIAL_METADATA op.
    BatchBuilder& RecvInitialMetadata(IncomingMetadata& md) {
+      cq_verifier_->AddSuccessfulStateString(CqVerifier::tag(tag_), &md);
      ops_.emplace_back(md.MakeOp());
      return *this;
    }

    // Add a GRPC_OP_RECV_MESSAGE op.
    BatchBuilder& RecvMessage(IncomingMessage& msg) {
+      cq_verifier_->AddSuccessfulStateString(CqVerifier::tag(tag_), &msg);
      ops_.emplace_back(msg.MakeOp());
      return *this;
    }

    // Add a GRPC_OP_RECV_STATUS_ON_CLIENT op.
    BatchBuilder& RecvStatusOnClient(IncomingStatusOnClient& status) {
+      cq_verifier_->AddSuccessfulStateString(CqVerifier::tag(tag_), &status);
      ops_.emplace_back(status.MakeOp());
      return *this;
    }

    // Add a GRPC_OP_RECV_CLOSE_ON_SERVER op.
    BatchBuilder& RecvCloseOnServer(IncomingCloseOnServer& close) {
+      cq_verifier_->AddSuccessfulStateString(CqVerifier::tag(tag_), &close);
      ops_.emplace_back(close.MakeOp());
      return *this;
    }
@ -427,6 +441,7 @@ class CoreEnd2endTest : public ::testing::Test {
    const int tag_;
    std::vector<grpc_op> ops_;
    std::vector<std::unique_ptr<Thing>> things_;
+    CqVerifier* const cq_verifier_;
  };

  // Wrapper around a grpc_call.
@ -434,16 +449,18 @@ class CoreEnd2endTest : public ::testing::Test {
  // Wrapped by IncomingCall for server calls.
  class Call {
   public:
-    explicit Call(grpc_call* call) : call_(call) {}
+    Call(grpc_call* call, CoreEnd2endTest* test) : call_(call), test_(test) {}
    Call(const Call&) = delete;
    Call& operator=(const Call&) = delete;
-    Call(Call&& other) noexcept : call_(std::exchange(other.call_, nullptr)) {}
+    Call(Call&& other) noexcept
+        : call_(std::exchange(other.call_, nullptr)),
+          test_(std::exchange(other.test_, nullptr)) {}
    ~Call() {
      if (call_ != nullptr) grpc_call_unref(call_);
    }
    // Construct a batch with a tag - upon destruction of the BatchBuilder the
    // operation will occur.
-    BatchBuilder NewBatch(int tag) { return BatchBuilder(call_, tag); }
+    BatchBuilder NewBatch(int tag) { return BatchBuilder(call_, test_, tag); }
    // Cancel the call
    void Cancel() { grpc_call_cancel(call_, nullptr); }
    void CancelWithStatus(grpc_status_code status, const char* message) {
@ -478,6 +495,7 @@ class CoreEnd2endTest : public ::testing::Test {

   private:
    grpc_call* call_ = nullptr;
+    CoreEnd2endTest* test_;
  };

  // Wrapper around a server call.
@ -526,7 +544,7 @@ class CoreEnd2endTest : public ::testing::Test {

   private:
    struct Impl {
-      Impl() {
+      explicit Impl(CoreEnd2endTest* test) : call(nullptr, test) {
        grpc_call_details_init(&call_details);
        grpc_metadata_array_init(&request_metadata);
      }
@ -534,7 +552,7 @@ class CoreEnd2endTest : public ::testing::Test {
        grpc_call_details_destroy(&call_details);
        grpc_metadata_array_destroy(&request_metadata);
      }
-      Call call{nullptr};
+      Call call;
      grpc_call_details call_details;
      grpc_metadata_array request_metadata;
    };
@ -561,7 +579,7 @@ class CoreEnd2endTest : public ::testing::Test {
  // Expect a tag with some result.
  void Expect(int tag, ExpectedResult result, SourceLocation whence = {}) {
    expectations_++;
-    cq_verifier().Expect(CqVerifier::tag(tag), result, whence);
+    cq_verifier().Expect(CqVerifier::tag(tag), std::move(result), whence);
  }
  // Step the system until expectations are met or until timeout is reached.
  // If there are no expectations logged, then step for 1 second and verify that
--- a/test/core/end2end/tests/call_host_override.cc
+++ b/test/core/end2end/tests/call_host_override.cc
@ -16,7 +16,6 @@
 //
 //

-#include "absl/strings/str_cat.h"
 #include "absl/types/optional.h"
 #include "gtest/gtest.h"

@ -24,7 +23,6 @@
 #include <grpc/status.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"

@ -49,12 +47,6 @@ CORE_END2END_TEST(CoreClientChannelTest, CallHostOverride) {
      .RecvStatusOnClient(server_status);
  auto s = RequestCall(101);
  Expect(101, true);
-  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_metadata.ToString()));
-         }});
  Step();
  EXPECT_NE(s.GetPeer(), absl::nullopt);
  EXPECT_NE(c.GetPeer(), absl::nullopt);
--- a/test/core/end2end/tests/disappearing_server.cc
+++ b/test/core/end2end/tests/disappearing_server.cc
@ -16,14 +16,12 @@
 //
 //

-#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"

@ -45,13 +43,6 @@ 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;
--- a/test/core/end2end/tests/request_with_payload.cc
+++ b/test/core/end2end/tests/request_with_payload.cc
@ -16,12 +16,10 @@
 //
 //

-#include "absl/strings/str_cat.h"
 #include "gtest/gtest.h"

 #include <grpc/status.h>

-#include "src/core/lib/gprpp/crash.h"
 #include "src/core/lib/gprpp/time.h"
 #include "test/core/end2end/end2end_tests.h"

@ -40,12 +38,6 @@ CORE_END2END_TEST(CoreEnd2endTest, RequestWithPayload) {
      .RecvStatusOnClient(server_status);
  auto s = RequestCall(101);
  Expect(101, true);
-  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_metadata.ToString()));
-         }});
  Step();
  IncomingMessage client_message;
  s.NewBatch(102).SendInitialMetadata({}).RecvMessage(client_message);
--- a/test/core/end2end/tests/simple_delayed_request.cc
+++ b/test/core/end2end/tests/simple_delayed_request.cc
@ -16,7 +16,6 @@
 //
 //

-#include "absl/strings/str_cat.h"
 #include "gtest/gtest.h"

 #include <grpc/grpc.h>
@ -24,7 +23,6 @@
 #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"

@ -50,12 +48,6 @@ CORE_END2END_TEST(Http2SingleHopTest, SimpleDelayedRequestShort) {
  InitServer(ChannelArgs());
  auto s = RequestCall(101);
  Expect(101, true);
-  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_metadata.ToString()));
-         }});
  Step();
  IncomingCloseOnServer client_close;
  s.NewBatch(102)
--- a/test/core/end2end/tests/simple_request.cc
+++ b/test/core/end2end/tests/simple_request.cc
@ -23,7 +23,6 @@
 #include <string>

 #include "absl/strings/match.h"
-#include "absl/strings/str_cat.h"
 #include "absl/types/optional.h"
 #include "gmock/gmock.h"
 #include "gtest/gtest.h"
@ -33,7 +32,6 @@

 #include "src/core/lib/debug/stats.h"
 #include "src/core/lib/debug/stats_data.h"
-#include "src/core/lib/gprpp/crash.h"
 #include "src/core/lib/gprpp/time.h"
 #include "test/core/end2end/end2end_tests.h"

@ -62,13 +60,6 @@ void SimpleRequestBody(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_metadata.ToString()));
-      }});
  test.Step();
  EXPECT_NE(s.GetPeer(), absl::nullopt);
  CheckPeer(*s.GetPeer());