Chiebot-Mirror
/
grpc
mirror of https://github.com/grpc/grpc.git
8
0
Fork 0
Code Issues Projects Releases Wiki Activity

[grpc][Gpr_To_Absl_Logging] Migrating from gpr to absl logging - gpr_log (#36526)

Browse Source 
[grpc][Gpr_To_Absl_Logging] Migrating from gpr to absl logging - gpr_log

In this CL we are migrating from gRPCs own gpr logging mechanism to absl logging mechanism. The intention is to deprecate gpr_log in the future.

We have the following mapping
1. gpr_log(GPR_INFO,...) -> LOG(INFO)
2. gpr_log(GPR_ERROR,...) -> LOG(ERROR)
3. gpr_log(GPR_DEBUG,...) -> VLOG(2)

Reviewers need to check :
1. If the above mapping is correct.
2. The content of the log is as before.

gpr_log format strings did not use string_view or std::string . absl LOG accepts these. So there will be some elimination of string_view and std::string related conversions. This is expected.

Closes #36526

COPYBARA_INTEGRATE_REVIEW=https://github.com/grpc/grpc/pull/36526 from tanvi-jagtap:test_large_interop_client_gpr_log 46a657fe20
PiperOrigin-RevId: 630993244
pull/36536/head
Tanvi Jagtap 7 months ago committed by Copybara-Service
parent a20f020fb8
commit 7cc547dfd9
2 changed files with 157 additions and 183 deletions
Whitespace
Show all changes Ignore whitespace when comparing lines Ignore changes in amount of whitespace Ignore changes in whitespace at EOL
Split View
Diff Options
Show Stats Download Patch File Download Diff File
  1. 1
      test/cpp/interop/BUILD
  2. 339
      test/cpp/interop/interop_client.cc

1
test/cpp/interop/BUILD
Unescape View File

@ -109,6 +109,7 @@ grpc_cc_library(
external_deps = [
"absl/flags:flag",
"absl/log:check",
"absl/log:log",
],
language = "C++",
deps = [

339
test/cpp/interop/interop_client.cc
Unescape View File

@ -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<bool> 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<ClientWriter<StreamingInputCallRequest>> 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_ptr<ClientReaderWriter<StreamingOutputCallRequest,
@ -717,7 +705,7 @@ bool InteropClient::DoHalfDuplex() {
response_parameter->set_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_ptr<ClientReaderWriter<StreamingOutputCallRequest,
@ -768,12 +756,12 @@ bool InteropClient::DoPingPong() {
payload->set_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<ClientWriter<StreamingInputCallRequest>> 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_ptr<ClientReaderWriter<StreamingOutputCallRequest,
@ -832,27 +820,26 @@ bool InteropClient::DoCancelAfterFirstResponse() {
StreamingOutputCallResponse response;
if (!stream->Write(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_ptr<ClientReaderWriter<StreamingOutputCallRequest,
@ -892,13 +879,12 @@ bool InteropClient::DoEmptyStream() {
return false;
}
gpr_log(GPR_DEBUG, "empty_stream done.");
VLOG(2) << "empty_stream done.";
return true;
}
bool InteropClient::DoStatusWithMessage() {
gpr_log(GPR_DEBUG,
"Sending RPC with a request for status code 2 and message");
VLOG(2) << "Sending RPC with a request for status code 2 and message";
const grpc::StatusCode test_code = grpc::StatusCode::UNKNOWN;
const std::string test_msg = "This is a test message";
@ -938,15 +924,14 @@ bool InteropClient::DoStatusWithMessage() {
}
CHECK(s.error_message() == test_msg);
gpr_log(GPR_DEBUG, "Done testing Status and Message");
VLOG(2) << "Done testing Status and Message";
return true;
}
bool InteropClient::DoSpecialStatusMessage() {
gpr_log(
GPR_DEBUG,
"Sending RPC with a request for status code 2 and message - \\t\\ntest "
"with whitespace\\r\\nand Unicode BMP ☺ and non-BMP 😈\\t\\n");
VLOG(2) << "Sending RPC with a request for status code 2 and message - "
"\\t\\ntest "
"with whitespace\\r\\nand Unicode BMP ☺ and non-BMP 😈\\t\\n";
const grpc::StatusCode test_code = grpc::StatusCode::UNKNOWN;
const std::string test_msg =
"\t\ntest with whitespace\r\nand Unicode BMP ☺ and non-BMP 😈\t\n";
@ -962,7 +947,7 @@ bool InteropClient::DoSpecialStatusMessage() {
return false;
}
CHECK(s.error_message() == test_msg);
gpr_log(GPR_DEBUG, "Done testing Special Status Message");
VLOG(2) << "Done testing Special Status Message";
return true;
}
@ -983,19 +968,19 @@ bool InteropClient::DoPickFirstUnary() {
continue;
}
if (response.server_id() != server_id) {
gpr_log(GPR_ERROR, "#%d rpc hits server_id %s, expect server_id %s", i,
response.server_id().c_str(), server_id.c_str());
LOG(ERROR) << "#" << i << " rpc hits server_id " << response.server_id()
<< ", expect server_id " << server_id;
return false;
}
}
gpr_log(GPR_DEBUG, "pick first unary successfully finished");
VLOG(2) << "pick first unary successfully finished";
return true;
}
bool InteropClient::DoOrcaPerRpc() {
load_report_tracker_.ResetCollectedLoadReports();
grpc_core::CoreConfiguration::RegisterBuilder(RegisterBackendMetricsLbPolicy);
gpr_log(GPR_DEBUG, "testing orca per rpc");
VLOG(2) << "testing orca per rpc";
SimpleRequest request;
SimpleResponse response;
ClientContext context;
@ -1016,13 +1001,13 @@ bool InteropClient::DoOrcaPerRpc() {
gpr_assertion_failed(__FILE__, __LINE__, comparison_result->c_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;
}

Write Preview
Loading…
Cancel
Save