diff --git a/test/cpp/interop/BUILD b/test/cpp/interop/BUILD index 1915c957ad6..76b49f88be9 100644 --- a/test/cpp/interop/BUILD +++ b/test/cpp/interop/BUILD @@ -109,6 +109,7 @@ grpc_cc_library( external_deps = [ "absl/flags:flag", "absl/log:check", + "absl/log:log", ], language = "C++", deps = [ diff --git a/test/cpp/interop/interop_client.cc b/test/cpp/interop/interop_client.cc index 6db13b25363..d6b2118fe25 100644 --- a/test/cpp/interop/interop_client.cc +++ b/test/cpp/interop/interop_client.cc @@ -27,6 +27,7 @@ #include "absl/cleanup/cleanup.h" #include "absl/log/check.h" +#include "absl/log/log.h" #include "absl/strings/match.h" #include "absl/strings/str_format.h" #include "absl/strings/str_join.h" @@ -205,11 +206,10 @@ bool InteropClient::AssertStatusCode(const Status& s, StatusCode expected_code, return true; } - gpr_log(GPR_ERROR, - "Error status code: %d (expected: %d), message: %s," - " debug string: %s", - s.error_code(), expected_code, s.error_message().c_str(), - optional_debug_string.c_str()); + LOG(ERROR) << "Error status code: " << s.error_code() + << " (expected: " << expected_code + << "), message: " << s.error_message() + << ", debug string: " << optional_debug_string; // In case of transient transient/retryable failures (like a broken // connection) we may or may not abort (see TransientFailureOrAbort()) @@ -221,7 +221,7 @@ bool InteropClient::AssertStatusCode(const Status& s, StatusCode expected_code, } bool InteropClient::DoEmpty() { - gpr_log(GPR_DEBUG, "Sending an empty rpc..."); + VLOG(2) << "Sending an empty rpc..."; Empty request; Empty response; @@ -233,7 +233,7 @@ bool InteropClient::DoEmpty() { return false; } - gpr_log(GPR_DEBUG, "Empty rpc done."); + VLOG(2) << "Empty rpc done."; return true; } @@ -273,8 +273,7 @@ bool InteropClient::PerformLargeUnary(SimpleRequest* request, bool InteropClient::DoComputeEngineCreds( const std::string& default_service_account, const std::string& oauth_scope) { - gpr_log(GPR_DEBUG, - "Sending a large unary rpc with compute engine credentials ..."); + VLOG(2) << "Sending a large unary rpc with compute engine credentials ..."; SimpleRequest request; SimpleResponse response; request.set_fill_username(true); @@ -284,21 +283,20 @@ bool InteropClient::DoComputeEngineCreds( return false; } - gpr_log(GPR_DEBUG, "Got username %s", response.username().c_str()); - gpr_log(GPR_DEBUG, "Got oauth_scope %s", response.oauth_scope().c_str()); + VLOG(2) << "Got username " << response.username(); + VLOG(2) << "Got oauth_scope " << response.oauth_scope(); CHECK(!response.username().empty()); CHECK(response.username() == default_service_account); CHECK(!response.oauth_scope().empty()); const char* oauth_scope_str = response.oauth_scope().c_str(); CHECK(absl::StrContains(oauth_scope, oauth_scope_str)); - gpr_log(GPR_DEBUG, "Large unary with compute engine creds done."); + VLOG(2) << "Large unary with compute engine creds done."; return true; } bool InteropClient::DoOauth2AuthToken(const std::string& username, const std::string& oauth_scope) { - gpr_log(GPR_DEBUG, - "Sending a unary rpc with raw oauth2 access token credentials ..."); + VLOG(2) << "Sending a unary rpc with raw oauth2 access token credentials ..."; SimpleRequest request; SimpleResponse response; request.set_fill_username(true); @@ -317,12 +315,12 @@ bool InteropClient::DoOauth2AuthToken(const std::string& username, CHECK(username == response.username()); const char* oauth_scope_str = response.oauth_scope().c_str(); CHECK(absl::StrContains(oauth_scope, oauth_scope_str)); - gpr_log(GPR_DEBUG, "Unary with oauth2 access token credentials done."); + VLOG(2) << "Unary with oauth2 access token credentials done."; return true; } bool InteropClient::DoPerRpcCreds(const std::string& json_key) { - gpr_log(GPR_DEBUG, "Sending a unary rpc with per-rpc JWT access token ..."); + VLOG(2) << "Sending a unary rpc with per-rpc JWT access token ..."; SimpleRequest request; SimpleResponse response; request.set_fill_username(true); @@ -342,13 +340,12 @@ bool InteropClient::DoPerRpcCreds(const std::string& json_key) { CHECK(!response.username().empty()); CHECK(json_key.find(response.username()) != std::string::npos); - gpr_log(GPR_DEBUG, "Unary with per-rpc JWT access token done."); + VLOG(2) << "Unary with per-rpc JWT access token done."; return true; } bool InteropClient::DoJwtTokenCreds(const std::string& username) { - gpr_log(GPR_DEBUG, - "Sending a large unary rpc with JWT token credentials ..."); + VLOG(2) << "Sending a large unary rpc with JWT token credentials ..."; SimpleRequest request; SimpleResponse response; request.set_fill_username(true); @@ -359,14 +356,13 @@ bool InteropClient::DoJwtTokenCreds(const std::string& username) { CHECK(!response.username().empty()); CHECK(username.find(response.username()) != std::string::npos); - gpr_log(GPR_DEBUG, "Large unary with JWT token creds done."); + VLOG(2) << "Large unary with JWT token creds done."; return true; } bool InteropClient::DoGoogleDefaultCredentials( const std::string& default_service_account) { - gpr_log(GPR_DEBUG, - "Sending a large unary rpc with GoogleDefaultCredentials..."); + VLOG(2) << "Sending a large unary rpc with GoogleDefaultCredentials..."; SimpleRequest request; SimpleResponse response; request.set_fill_username(true); @@ -375,21 +371,21 @@ bool InteropClient::DoGoogleDefaultCredentials( return false; } - gpr_log(GPR_DEBUG, "Got username %s", response.username().c_str()); + VLOG(2) << "Got username " << response.username(); CHECK(!response.username().empty()); CHECK(response.username() == default_service_account); - gpr_log(GPR_DEBUG, "Large unary rpc with GoogleDefaultCredentials done."); + VLOG(2) << "Large unary rpc with GoogleDefaultCredentials done."; return true; } bool InteropClient::DoLargeUnary() { - gpr_log(GPR_DEBUG, "Sending a large unary rpc..."); + VLOG(2) << "Sending a large unary rpc..."; SimpleRequest request; SimpleResponse response; if (!PerformLargeUnary(&request, &response)) { return false; } - gpr_log(GPR_DEBUG, "Large unary done."); + VLOG(2) << "Large unary done."; return true; } @@ -405,35 +401,32 @@ bool InteropClient::DoClientCompressedUnary() { probe_req.set_response_size(kLargeResponseSize); probe_req.mutable_payload()->set_body(std::string(kLargeRequestSize, '\0')); - gpr_log(GPR_DEBUG, "Sending probe for compressed unary request."); + VLOG(2) << "Sending probe for compressed unary request."; const Status s = serviceStub_.Get()->UnaryCall(&probe_context, probe_req, &probe_res); if (s.error_code() != grpc::StatusCode::INVALID_ARGUMENT) { // The server isn't able to evaluate incoming compression, making the rest // of this test moot. - gpr_log(GPR_DEBUG, "Compressed unary request probe failed"); + VLOG(2) << "Compressed unary request probe failed"; return false; } - gpr_log(GPR_DEBUG, "Compressed unary request probe succeeded. Proceeding."); + VLOG(2) << "Compressed unary request probe succeeded. Proceeding."; const std::vector compressions = {true, false}; for (size_t i = 0; i < compressions.size(); i++) { std::string log_suffix = absl::StrFormat("(compression=%s)", compressions[i] ? "true" : "false"); - gpr_log(GPR_DEBUG, "Sending compressed unary request %s.", - log_suffix.c_str()); + VLOG(2) << "Sending compressed unary request " << log_suffix; SimpleRequest request; SimpleResponse response; request.mutable_expect_compressed()->set_value(compressions[i]); if (!PerformLargeUnary(&request, &response, UnaryCompressionChecks)) { - gpr_log(GPR_ERROR, "Compressed unary request failed %s", - log_suffix.c_str()); + LOG(ERROR) << "Compressed unary request failed " << log_suffix; return false; } - gpr_log(GPR_DEBUG, "Compressed unary request failed %s", - log_suffix.c_str()); + VLOG(2) << "Compressed unary request failed " << log_suffix; } return true; @@ -445,20 +438,17 @@ bool InteropClient::DoServerCompressedUnary() { std::string log_suffix = absl::StrFormat("(compression=%s)", compressions[i] ? "true" : "false"); - gpr_log(GPR_DEBUG, "Sending unary request for compressed response %s.", - log_suffix.c_str()); + VLOG(2) << "Sending unary request for compressed response " << log_suffix; SimpleRequest request; SimpleResponse response; request.mutable_response_compressed()->set_value(compressions[i]); if (!PerformLargeUnary(&request, &response, UnaryCompressionChecks)) { - gpr_log(GPR_ERROR, "Request for compressed unary failed %s", - log_suffix.c_str()); + LOG(ERROR) << "Request for compressed unary failed " << log_suffix; return false; } - gpr_log(GPR_DEBUG, "Request for compressed unary failed %s", - log_suffix.c_str()); + VLOG(2) << "Request for compressed unary failed " << log_suffix; } return true; @@ -475,7 +465,7 @@ bool InteropClient::TransientFailureOrAbort() { } bool InteropClient::DoRequestStreaming() { - gpr_log(GPR_DEBUG, "Sending request steaming rpc ..."); + VLOG(2) << "Sending request steaming rpc ..."; ClientContext context; StreamingInputCallRequest request; @@ -489,7 +479,7 @@ bool InteropClient::DoRequestStreaming() { Payload* payload = request.mutable_payload(); payload->set_body(std::string(request_stream_sizes[i], '\0')); if (!stream->Write(request)) { - gpr_log(GPR_ERROR, "DoRequestStreaming(): stream->Write() failed"); + LOG(ERROR) << "DoRequestStreaming(): stream->Write() failed."; return TransientFailureOrAbort(); } aggregated_payload_size += request_stream_sizes[i]; @@ -506,7 +496,7 @@ bool InteropClient::DoRequestStreaming() { } bool InteropClient::DoResponseStreaming() { - gpr_log(GPR_DEBUG, "Receiving response streaming rpc ..."); + VLOG(2) << "Receiving response streaming rpc ..."; ClientContext context; StreamingOutputCallRequest request; @@ -528,10 +518,9 @@ bool InteropClient::DoResponseStreaming() { if (i < response_stream_sizes.size()) { // stream->Read() failed before reading all the expected messages. This is // most likely due to connection failure. - gpr_log(GPR_ERROR, - "DoResponseStreaming(): Read fewer streams (%d) than " - "response_stream_sizes.size() (%" PRIuPTR ")", - i, response_stream_sizes.size()); + LOG(ERROR) << "DoResponseStreaming(): Read fewer streams (" << i + << ") than response_stream_sizes.size() (" + << response_stream_sizes.size() << ")"; return TransientFailureOrAbort(); } @@ -540,7 +529,7 @@ bool InteropClient::DoResponseStreaming() { return false; } - gpr_log(GPR_DEBUG, "Response streaming done."); + VLOG(2) << "Response streaming done."; return true; } @@ -554,24 +543,23 @@ bool InteropClient::DoClientCompressedStreaming() { probe_req.mutable_expect_compressed()->set_value(true); // lies! probe_req.mutable_payload()->set_body(std::string(27182, '\0')); - gpr_log(GPR_DEBUG, "Sending probe for compressed streaming request."); + VLOG(2) << "Sending probe for compressed streaming request."; std::unique_ptr> probe_stream( serviceStub_.Get()->StreamingInputCall(&probe_context, &probe_res)); if (!probe_stream->Write(probe_req)) { - gpr_log(GPR_ERROR, "%s(): stream->Write() failed", __func__); + LOG(ERROR) << __func__ << "(): stream->Write() failed"; return TransientFailureOrAbort(); } Status s = probe_stream->Finish(); if (s.error_code() != grpc::StatusCode::INVALID_ARGUMENT) { // The server isn't able to evaluate incoming compression, making the rest // of this test moot. - gpr_log(GPR_DEBUG, "Compressed streaming request probe failed"); + VLOG(2) << "Compressed streaming request probe failed"; return false; } - gpr_log(GPR_DEBUG, - "Compressed streaming request probe succeeded. Proceeding."); + VLOG(2) << "Compressed streaming request probe succeeded. Proceeding."; ClientContext context; StreamingInputCallRequest request; @@ -583,9 +571,9 @@ bool InteropClient::DoClientCompressedStreaming() { request.mutable_payload()->set_body(std::string(27182, '\0')); request.mutable_expect_compressed()->set_value(true); - gpr_log(GPR_DEBUG, "Sending streaming request with compression enabled"); + VLOG(2) << "Sending streaming request with compression enabled"; if (!stream->Write(request)) { - gpr_log(GPR_ERROR, "%s(): stream->Write() failed", __func__); + LOG(ERROR) << __func__ << "(): stream->Write() failed."; return TransientFailureOrAbort(); } @@ -593,9 +581,9 @@ bool InteropClient::DoClientCompressedStreaming() { wopts.set_no_compression(); request.mutable_payload()->set_body(std::string(45904, '\0')); request.mutable_expect_compressed()->set_value(false); - gpr_log(GPR_DEBUG, "Sending streaming request with compression disabled"); + VLOG(2) << "Sending streaming request with compression disabled"; if (!stream->Write(request, wopts)) { - gpr_log(GPR_ERROR, "%s(): stream->Write() failed", __func__); + LOG(ERROR) << __func__ << "(): stream->Write() failed"; return TransientFailureOrAbort(); } CHECK(stream->WritesDone()); @@ -618,7 +606,7 @@ bool InteropClient::DoServerCompressedStreaming() { absl::StrFormat("(compression=%s; size=%d)", compressions[i] ? "true" : "false", sizes[i]); - gpr_log(GPR_DEBUG, "Sending request streaming rpc %s.", log_suffix.c_str()); + VLOG(2) << "Sending request streaming rpc " << log_suffix.c_str(); ResponseParameters* const response_parameter = request.add_response_parameters(); @@ -650,10 +638,9 @@ bool InteropClient::DoServerCompressedStreaming() { if (k < sizes.size()) { // stream->Read() failed before reading all the expected messages. This // is most likely due to a connection failure. - gpr_log(GPR_ERROR, - "%s(): Responses read (k=%" PRIuPTR - ") is less than the expected number of messages (%" PRIuPTR ").", - __func__, k, sizes.size()); + LOG(ERROR) << __func__ << "(): Responses read (k=" << k + << ") is less than the expected number of messages (" + << sizes.size() << ")."; return TransientFailureOrAbort(); } @@ -662,7 +649,7 @@ bool InteropClient::DoServerCompressedStreaming() { } bool InteropClient::DoResponseStreamingWithSlowConsumer() { - gpr_log(GPR_DEBUG, "Receiving response streaming rpc with slow consumer ..."); + VLOG(2) << "Receiving response streaming rpc with slow consumer ..."; ClientContext context; StreamingOutputCallRequest request; @@ -678,7 +665,7 @@ bool InteropClient::DoResponseStreamingWithSlowConsumer() { int i = 0; while (stream->Read(&response)) { CHECK(response.payload().body() == std::string(kResponseMessageSize, '\0')); - gpr_log(GPR_DEBUG, "received message %d", i); + VLOG(2) << "received message " << i; gpr_sleep_until(gpr_time_add( gpr_now(GPR_CLOCK_REALTIME), gpr_time_from_millis(kReceiveDelayMilliSeconds, GPR_TIMESPAN))); @@ -686,10 +673,11 @@ bool InteropClient::DoResponseStreamingWithSlowConsumer() { } if (i < kNumResponseMessages) { - gpr_log(GPR_ERROR, - "DoResponseStreamingWithSlowConsumer(): Responses read (i=%d) is " - "less than the expected messages (i.e kNumResponseMessages = %d)", - i, kNumResponseMessages); + LOG(ERROR) << "DoResponseStreamingWithSlowConsumer(): Responses read (i=" + << i + << ") is less than the expected messages (i.e " + "kNumResponseMessages = " + << kNumResponseMessages << ")."; return TransientFailureOrAbort(); } @@ -699,12 +687,12 @@ bool InteropClient::DoResponseStreamingWithSlowConsumer() { return false; } - gpr_log(GPR_DEBUG, "Response streaming done."); + VLOG(2) << "Response streaming done."; return true; } bool InteropClient::DoHalfDuplex() { - gpr_log(GPR_DEBUG, "Sending half-duplex streaming rpc ..."); + VLOG(2) << "Sending half-duplex streaming rpc ..."; ClientContext context; std::unique_ptrset_size(response_stream_sizes[i]); if (!stream->Write(request)) { - gpr_log(GPR_ERROR, "DoHalfDuplex(): stream->Write() failed. i=%d", i); + LOG(ERROR) << "DoHalfDuplex(): stream->Write() failed. i=" << i; return TransientFailureOrAbort(); } } @@ -734,10 +722,10 @@ bool InteropClient::DoHalfDuplex() { if (i < response_stream_sizes.size()) { // stream->Read() failed before reading all the expected messages. This is // most likely due to a connection failure - gpr_log(GPR_ERROR, - "DoHalfDuplex(): Responses read (i=%d) are less than the expected " - "number of messages response_stream_sizes.size() (%" PRIuPTR ")", - i, response_stream_sizes.size()); + LOG(ERROR) << "DoHalfDuplex(): Responses read (i=" << i + << ") are less than the expected number of messages " + "response_stream_sizes.size() (" + << response_stream_sizes.size() << ")."; return TransientFailureOrAbort(); } @@ -746,12 +734,12 @@ bool InteropClient::DoHalfDuplex() { return false; } - gpr_log(GPR_DEBUG, "Half-duplex streaming rpc done."); + VLOG(2) << "Half-duplex streaming rpc done."; return true; } bool InteropClient::DoPingPong() { - gpr_log(GPR_DEBUG, "Sending Ping Pong streaming rpc ..."); + VLOG(2) << "Sending Ping Pong streaming rpc ..."; ClientContext context; std::unique_ptrset_body(std::string(request_stream_sizes[i], '\0')); if (!stream->Write(request)) { - gpr_log(GPR_ERROR, "DoPingPong(): stream->Write() failed. i: %d", i); + LOG(ERROR) << "DoPingPong(): stream->Write() failed. i: " << i; return TransientFailureOrAbort(); } if (!stream->Read(&response)) { - gpr_log(GPR_ERROR, "DoPingPong(): stream->Read() failed. i:%d", i); + LOG(ERROR) << "DoPingPong(): stream->Read() failed. i:" << i; return TransientFailureOrAbort(); } @@ -790,12 +778,12 @@ bool InteropClient::DoPingPong() { return false; } - gpr_log(GPR_DEBUG, "Ping pong streaming done."); + VLOG(2) << "Ping pong streaming done."; return true; } bool InteropClient::DoCancelAfterBegin() { - gpr_log(GPR_DEBUG, "Sending request streaming rpc ..."); + VLOG(2) << "Sending request streaming rpc ..."; ClientContext context; StreamingInputCallRequest request; @@ -804,7 +792,7 @@ bool InteropClient::DoCancelAfterBegin() { std::unique_ptr> stream( serviceStub_.Get()->StreamingInputCall(&context, &response)); - gpr_log(GPR_DEBUG, "Trying to cancel..."); + VLOG(2) << "Trying to cancel..."; context.TryCancel(); Status s = stream->Finish(); @@ -813,12 +801,12 @@ bool InteropClient::DoCancelAfterBegin() { return false; } - gpr_log(GPR_DEBUG, "Canceling streaming done."); + VLOG(2) << "Canceling streaming done."; return true; } bool InteropClient::DoCancelAfterFirstResponse() { - gpr_log(GPR_DEBUG, "Sending Ping Pong streaming rpc ..."); + VLOG(2) << "Sending Ping Pong streaming rpc ..."; ClientContext context; std::unique_ptrWrite(request)) { - gpr_log(GPR_ERROR, "DoCancelAfterFirstResponse(): stream->Write() failed"); + LOG(ERROR) << "DoCancelAfterFirstResponse(): stream->Write() failed"; return TransientFailureOrAbort(); } if (!stream->Read(&response)) { - gpr_log(GPR_ERROR, "DoCancelAfterFirstResponse(): stream->Read failed"); + LOG(ERROR) << "DoCancelAfterFirstResponse(): stream->Read failed"; return TransientFailureOrAbort(); } CHECK(response.payload().body() == std::string(31415, '\0')); - gpr_log(GPR_DEBUG, "Trying to cancel..."); + VLOG(2) << "Trying to cancel..."; context.TryCancel(); Status s = stream->Finish(); - gpr_log(GPR_DEBUG, "Canceling pingpong streaming done."); + VLOG(2) << "Canceling pingpong streaming done."; return true; } bool InteropClient::DoTimeoutOnSleepingServer() { - gpr_log(GPR_DEBUG, - "Sending Ping Pong streaming rpc with a short deadline..."); + VLOG(2) << "Sending Ping Pong streaming rpc with a short deadline..."; ClientContext context; std::chrono::system_clock::time_point deadline = @@ -872,12 +859,12 @@ bool InteropClient::DoTimeoutOnSleepingServer() { return false; } - gpr_log(GPR_DEBUG, "Pingpong streaming timeout done."); + VLOG(2) << "Pingpong streaming timeout done."; return true; } bool InteropClient::DoEmptyStream() { - gpr_log(GPR_DEBUG, "Starting empty_stream."); + VLOG(2) << "Starting empty_stream."; ClientContext context; std::unique_ptrc_str()); } CHECK(!load_report_tracker_.GetNextLoadReport().has_value()); - gpr_log(GPR_DEBUG, "orca per rpc successfully finished"); + VLOG(2) << "orca per rpc successfully finished"; return true; } bool InteropClient::DoOrcaOob() { static constexpr auto kTimeout = absl::Seconds(10); - gpr_log(GPR_INFO, "testing orca oob"); + LOG(INFO) << "testing orca oob"; load_report_tracker_.ResetCollectedLoadReports(); // Make the backup poller poll very frequently in order to pick up // updates from all the subchannels's FDs. @@ -1047,11 +1032,11 @@ bool InteropClient::DoOrcaOob() { orca_report->mutable_utilization()->emplace("util", 0.30499); StreamingOutputCallResponse response; if (!stream->Write(request)) { - gpr_log(GPR_ERROR, "DoOrcaOob(): stream->Write() failed"); + LOG(ERROR) << "DoOrcaOob(): stream->Write() failed"; return TransientFailureOrAbort(); } if (!stream->Read(&response)) { - gpr_log(GPR_ERROR, "DoOrcaOob(): stream->Read failed"); + LOG(ERROR) << "DoOrcaOob(): stream->Read failed"; return TransientFailureOrAbort(); } CHECK(load_report_tracker_ @@ -1059,8 +1044,7 @@ bool InteropClient::DoOrcaOob() { [orca_report](const auto& actual) { auto value = OrcaLoadReportsDiff(*orca_report, actual); if (value.has_value()) { - gpr_log(GPR_DEBUG, "Reports mismatch: %s", - value->c_str()); + VLOG(2) << "Reports mismatch: " << value->c_str(); return false; } return true; @@ -1077,11 +1061,11 @@ bool InteropClient::DoOrcaOob() { orca_report->mutable_utilization()->emplace("util", 0.2039); StreamingOutputCallResponse response; if (!stream->Write(request)) { - gpr_log(GPR_ERROR, "DoOrcaOob(): stream->Write() failed"); + LOG(ERROR) << "DoOrcaOob(): stream->Write() failed"; return TransientFailureOrAbort(); } if (!stream->Read(&response)) { - gpr_log(GPR_ERROR, "DoOrcaOob(): stream->Read failed"); + LOG(ERROR) << "DoOrcaOob(): stream->Read failed"; return TransientFailureOrAbort(); } CHECK( @@ -1093,7 +1077,7 @@ bool InteropClient::DoOrcaOob() { kTimeout, 10) .has_value()); } - gpr_log(GPR_INFO, "orca oob successfully finished"); + LOG(INFO) << "orca oob successfully finished"; return true; } @@ -1105,7 +1089,7 @@ bool InteropClient::DoCustomMetadata() { const std::string kTrailingBinValue("\x0a\x0b\x0a\x0b\x0a\x0b"); { - gpr_log(GPR_DEBUG, "Sending RPC with custom metadata"); + VLOG(2) << "Sending RPC with custom metadata"; ClientContext context; context.AddMetadata(kEchoInitialMetadataKey, kInitialMetadataValue); context.AddMetadata(kEchoTrailingBinMetadataKey, kTrailingBinValue); @@ -1130,11 +1114,11 @@ bool InteropClient::DoCustomMetadata() { CHECK(std::string(iter->second.begin(), iter->second.end()) == kTrailingBinValue); - gpr_log(GPR_DEBUG, "Done testing RPC with custom metadata"); + VLOG(2) << "Done testing RPC with custom metadata"; } { - gpr_log(GPR_DEBUG, "Sending stream with custom metadata"); + VLOG(2) << "Sending stream with custom metadata"; ClientContext context; context.AddMetadata(kEchoInitialMetadataKey, kInitialMetadataValue); context.AddMetadata(kEchoTrailingBinMetadataKey, kTrailingBinValue); @@ -1150,14 +1134,14 @@ bool InteropClient::DoCustomMetadata() { StreamingOutputCallResponse response; if (!stream->Write(request)) { - gpr_log(GPR_ERROR, "DoCustomMetadata(): stream->Write() failed"); + LOG(ERROR) << "DoCustomMetadata(): stream->Write() failed"; return TransientFailureOrAbort(); } stream->WritesDone(); if (!stream->Read(&response)) { - gpr_log(GPR_ERROR, "DoCustomMetadata(): stream->Read() failed"); + LOG(ERROR) << "DoCustomMetadata(): stream->Read() failed"; return TransientFailureOrAbort(); } @@ -1180,7 +1164,7 @@ bool InteropClient::DoCustomMetadata() { CHECK(std::string(iter->second.begin(), iter->second.end()) == kTrailingBinValue); - gpr_log(GPR_DEBUG, "Done testing stream with custom metadata"); + VLOG(2) << "Done testing stream with custom metadata"; } return true; @@ -1254,17 +1238,14 @@ void InteropClient::PerformSoakTest( std::string peer = std::get<3>(result); results.push_back(result); if (!success) { - gpr_log(GPR_INFO, - "soak iteration: %d elapsed_ms: %d peer: %s server_uri: %s " - "failed: %s", - i, elapsed_ms, peer.c_str(), server_uri.c_str(), - debug_string.c_str()); + LOG(INFO) << "soak iteration: " << i << " elapsed_ms: " << elapsed_ms + << " peer: " << peer << " server_uri: " << server_uri + << " failed: " << debug_string; total_failures++; } else { - gpr_log( - GPR_INFO, - "soak iteration: %d elapsed_ms: %d peer: %s server_uri: %s succeeded", - i, elapsed_ms, peer.c_str(), server_uri.c_str()); + LOG(INFO) << "soak iteration: " << i << " elapsed_ms: " << elapsed_ms + << " peer: " << peer << " server_uri: " << server_uri + << " succeeded"; } grpc_histogram_add(latencies_ms_histogram, std::get<1>(result)); iterations_ran++; @@ -1277,48 +1258,40 @@ void InteropClient::PerformSoakTest( double latency_ms_worst = grpc_histogram_maximum(latencies_ms_histogram); grpc_histogram_destroy(latencies_ms_histogram); if (iterations_ran < soak_iterations) { - gpr_log( - GPR_ERROR, - "(server_uri: %s) soak test consumed all %d seconds of time and quit " - "early, only " - "having ran %d out of desired %d iterations. " - "total_failures: %d. " - "max_failures_threshold: %d. " - "median_soak_iteration_latency: %lf ms. " - "90th_soak_iteration_latency: %lf ms. " - "worst_soak_iteration_latency: %lf ms. " - "Some or all of the iterations that did run were unexpectedly slow. " - "See breakdown above for which iterations succeeded, failed, and " - "why for more info.", - server_uri.c_str(), overall_timeout_seconds, iterations_ran, - soak_iterations, total_failures, max_failures, latency_ms_median, - latency_ms_90th, latency_ms_worst); + LOG(ERROR) << "(server_uri: " << server_uri << ") soak test consumed all " + << overall_timeout_seconds + << " seconds of time and quit early, only having ran " + << iterations_ran << " out of desired " << soak_iterations + << " iterations. total_failures: " << total_failures + << ". max_failures_threshold: " << max_failures + << ". median_soak_iteration_latency: " << latency_ms_median + << " ms. 90th_soak_iteration_latency: " << latency_ms_90th + << " ms. worst_soak_iteration_latency: " << latency_ms_worst + << " ms. Some or all of the iterations that did run were " + "unexpectedly slow. See breakdown above for which iterations " + "succeeded, failed, and why for more info."; CHECK(0); } else if (total_failures > max_failures) { - gpr_log(GPR_ERROR, - "(server_uri: %s) soak test ran: %d iterations. total_failures: %d " - "exceeds " - "max_failures_threshold: %d. " - "median_soak_iteration_latency: %lf ms. " - "90th_soak_iteration_latency: %lf ms. " - "worst_soak_iteration_latency: %lf ms. " - "See breakdown above for which iterations succeeded, failed, and " - "why for more info.", - server_uri.c_str(), soak_iterations, total_failures, max_failures, - latency_ms_median, latency_ms_90th, latency_ms_worst); + LOG(ERROR) << "(server_uri: " << server_uri + << ") soak test ran: " << soak_iterations + << " iterations. total_failures: " << total_failures + << " exceeds max_failures_threshold: " << max_failures + << ". median_soak_iteration_latency: " << latency_ms_median + << " ms. 90th_soak_iteration_latency: " << latency_ms_90th + << " ms. worst_soak_iteration_latency: " << latency_ms_worst + << " ms. See breakdown above for which iterations succeeded, " + "failed, and why for more info."; CHECK(0); } else { - gpr_log(GPR_INFO, - "(server_uri: %s) soak test ran: %d iterations. total_failures: %d " - "is within " - "max_failures_threshold: %d. " - "median_soak_iteration_latency: %lf ms. " - "90th_soak_iteration_latency: %lf ms. " - "worst_soak_iteration_latency: %lf ms. " - "See breakdown above for which iterations succeeded, failed, and " - "why for more info.", - server_uri.c_str(), soak_iterations, total_failures, max_failures, - latency_ms_median, latency_ms_90th, latency_ms_worst); + LOG(INFO) << "(server_uri: " << server_uri + << ") soak test ran: " << soak_iterations + << " iterations. total_failures: " << total_failures + << " is within max_failures_threshold: " << max_failures + << ". median_soak_iteration_latency: " << latency_ms_median + << " ms. 90th_soak_iteration_latency: " << latency_ms_90th + << " ms. worst_soak_iteration_latency: " << latency_ms_worst + << " ms. See breakdown above for which iterations succeeded, " + "failed, and why for more info."; } } @@ -1327,14 +1300,14 @@ bool InteropClient::DoRpcSoakTest( int32_t max_failures, int64_t max_acceptable_per_iteration_latency_ms, int32_t soak_min_time_ms_between_rpcs, int32_t overall_timeout_seconds, int32_t request_size, int32_t response_size) { - gpr_log(GPR_DEBUG, "Sending %d RPCs...", soak_iterations); + VLOG(2) << "Sending " << soak_iterations << " RPCs..."; CHECK_GT(soak_iterations, 0); PerformSoakTest(server_uri, false /* reset channel per iteration */, soak_iterations, max_failures, max_acceptable_per_iteration_latency_ms, soak_min_time_ms_between_rpcs, overall_timeout_seconds, request_size, response_size); - gpr_log(GPR_DEBUG, "rpc_soak test done."); + VLOG(2) << "rpc_soak test done."; return true; } @@ -1343,30 +1316,30 @@ bool InteropClient::DoChannelSoakTest( int32_t max_failures, int64_t max_acceptable_per_iteration_latency_ms, int32_t soak_min_time_ms_between_rpcs, int32_t overall_timeout_seconds, int32_t request_size, int32_t response_size) { - gpr_log(GPR_DEBUG, "Sending %d RPCs, tearing down the channel each time...", - soak_iterations); + VLOG(2) << "Sending " << soak_iterations + << " RPCs, tearing down the channel each time..."; CHECK_GT(soak_iterations, 0); PerformSoakTest(server_uri, true /* reset channel per iteration */, soak_iterations, max_failures, max_acceptable_per_iteration_latency_ms, soak_min_time_ms_between_rpcs, overall_timeout_seconds, request_size, response_size); - gpr_log(GPR_DEBUG, "channel_soak test done."); + VLOG(2) << "channel_soak test done."; return true; } bool InteropClient::DoLongLivedChannelTest(int32_t soak_iterations, int32_t iteration_interval) { - gpr_log(GPR_DEBUG, "Sending %d RPCs...", soak_iterations); + VLOG(2) << "Sending " << soak_iterations << " RPCs..."; CHECK_GT(soak_iterations, 0); CHECK_GT(iteration_interval, 0); SimpleRequest request; SimpleResponse response; int num_failures = 0; for (int i = 0; i < soak_iterations; ++i) { - gpr_log(GPR_DEBUG, "Sending RPC number %d...", i); + VLOG(2) << "Sending RPC number " << i << "..."; if (!PerformLargeUnary(&request, &response)) { - gpr_log(GPR_ERROR, "Iteration %d failed.", i); + LOG(ERROR) << "Iteration " << i << " failed."; num_failures++; } gpr_sleep_until( @@ -1374,17 +1347,17 @@ bool InteropClient::DoLongLivedChannelTest(int32_t soak_iterations, gpr_time_from_seconds(iteration_interval, GPR_TIMESPAN))); } if (num_failures == 0) { - gpr_log(GPR_DEBUG, "long_lived_channel test done."); + VLOG(2) << "long_lived_channel test done."; return true; } else { - gpr_log(GPR_DEBUG, "long_lived_channel test failed with %d rpc failures.", - num_failures); + VLOG(2) << "long_lived_channel test failed with " << num_failures + << " rpc failures."; return false; } } bool InteropClient::DoUnimplementedService() { - gpr_log(GPR_DEBUG, "Sending a request for an unimplemented service..."); + VLOG(2) << "Sending a request for an unimplemented service..."; Empty request; Empty response; @@ -1399,12 +1372,12 @@ bool InteropClient::DoUnimplementedService() { return false; } - gpr_log(GPR_DEBUG, "unimplemented service done."); + VLOG(2) << "unimplemented service done."; return true; } bool InteropClient::DoUnimplementedMethod() { - gpr_log(GPR_DEBUG, "Sending a request for an unimplemented rpc..."); + VLOG(2) << "Sending a request for an unimplemented rpc..."; Empty request; Empty response; @@ -1418,7 +1391,7 @@ bool InteropClient::DoUnimplementedMethod() { return false; } - gpr_log(GPR_DEBUG, "unimplemented rpc done."); + VLOG(2) << "unimplemented rpc done."; return true; }