From 133640507bc6191ee74bf76602b64ee5631c96b6 Mon Sep 17 00:00:00 2001 From: Craig Tiller Date: Thu, 15 Jun 2023 08:26:27 -0700 Subject: [PATCH] [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 --- test/core/end2end/cq_verifier.cc | 52 +++++++++++++++++-- test/core/end2end/cq_verifier.h | 4 ++ test/core/end2end/end2end_tests.cc | 22 ++++++++ test/core/end2end/end2end_tests.h | 9 +++- .../core/end2end/tests/disappearing_server.cc | 14 ++++- test/core/end2end/tests/no_logging.cc | 7 +++ 6 files changed, 103 insertions(+), 5 deletions(-) diff --git a/test/core/end2end/cq_verifier.cc b/test/core/end2end/cq_verifier.cc index ceeb1c9e2d9..50b700ab77b 100644 --- a/test/core/end2end/cq_verifier.cc +++ b/test/core/end2end/cq_verifier.cc @@ -24,6 +24,7 @@ #include #include +#include #include #include #include @@ -182,7 +183,9 @@ int byte_buffer_eq_string(grpc_byte_buffer* bb, const char* str) { namespace { bool IsProbablyInteger(void* p) { - return reinterpret_cast(p) < 1000000; + return reinterpret_cast(p) < 1000000 || + (reinterpret_cast(p) > + std::numeric_limits::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 CqVerifier::ToStrings() const { std::vector expectations; expectations.reserve(expectations_.size()); @@ -237,6 +255,19 @@ std::string CqVerifier::ToString() const { return absl::StrJoin(ToStrings(), "\n"); } +std::vector CqVerifier::ToShortStrings() const { + std::vector 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()); diff --git a/test/core/end2end/cq_verifier.h b/test/core/end2end/cq_verifier.h index 862cf718f48..8283f57c97e 100644 --- a/test/core/end2end/cq_verifier.h +++ b/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 ToStrings() const; + std::string ToShortString() const; + std::vector ToShortStrings() const; static void* tag(intptr_t t) { return reinterpret_cast(t); } @@ -116,6 +119,7 @@ class CqVerifier { ExpectedResult result; std::string ToString() const; + std::string ToShortString() const; }; void FailNoEventReceived(const SourceLocation& location) const; diff --git a/test/core/end2end/end2end_tests.cc b/test/core/end2end/end2end_tests.cc index ded327caf44..5eef7f6fbe6 100644 --- a/test/core/end2end/end2end_tests.cc +++ b/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)); diff --git a/test/core/end2end/end2end_tests.h b/test/core/end2end/end2end_tests.h index 23a350ec861..49d005aa2e4 100644 --- a/test/core/end2end/end2end_tests.h +++ b/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 metadata_ = std::make_unique( @@ -297,6 +299,8 @@ class CoreEnd2endTest : public ::testing::Test { absl::optional 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( - 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_; } diff --git a/test/core/end2end/tests/disappearing_server.cc b/test/core/end2end/tests/disappearing_server.cc index f8a1db8a0de..098762619f5 100644 --- a/test/core/end2end/tests/disappearing_server.cc +++ b/test/core/end2end/tests/disappearing_server.cc @@ -16,11 +16,14 @@ // // +#include "absl/strings/str_cat.h" #include "gtest/gtest.h" #include +#include #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; diff --git a/test/core/end2end/tests/no_logging.cc b/test/core/end2end/tests/no_logging.cc index 47d710e8829..f5acbe507d2 100644 --- a/test/core/end2end/tests/no_logging.cc +++ b/test/core/end2end/tests/no_logging.cc @@ -17,7 +17,9 @@ // #include +#include #include +#include #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);