diff --git a/test/cpp/end2end/cfstream_test.cc b/test/cpp/end2end/cfstream_test.cc index a075d28e6e5..907622e0b62 100644 --- a/test/cpp/end2end/cfstream_test.cc +++ b/test/cpp/end2end/cfstream_test.cc @@ -25,11 +25,11 @@ #include #include "absl/log/check.h" +#include "absl/log/log.h" #include #include #include -#include #include #include #include @@ -102,13 +102,13 @@ class CFStreamTest : public ::testing::TestWithParam { } void NetworkUp() { - gpr_log(GPR_DEBUG, "Bringing network up"); + VLOG(2) << "Bringing network up"; InterfaceUp(); DNSUp(); } void NetworkDown() { - gpr_log(GPR_DEBUG, "Bringing network down"); + VLOG(2) << "Bringing network down"; InterfaceDown(); DNSDown(); } @@ -156,10 +156,10 @@ class CFStreamTest : public ::testing::TestWithParam { ClientContext context; Status status = stub->Echo(&context, request, response.get()); if (status.ok()) { - gpr_log(GPR_DEBUG, "RPC with succeeded"); + VLOG(2) << "RPC with succeeded"; EXPECT_EQ(msg, response->message()); } else { - gpr_log(GPR_DEBUG, "RPC failed: %s", status.error_message().c_str()); + VLOG(2) << "RPC failed: " << status.error_message(); } if (expect_success) { EXPECT_TRUE(status.ok()); @@ -241,7 +241,7 @@ class CFStreamTest : public ::testing::TestWithParam { : port_(port), creds_(creds) {} void Start(const std::string& server_host) { - gpr_log(GPR_INFO, "starting server on port %d", port_); + LOG(INFO) << "starting server on port " << port_; std::mutex mu; std::unique_lock lock(mu); std::condition_variable cond; @@ -249,7 +249,7 @@ class CFStreamTest : public ::testing::TestWithParam { std::bind(&ServerData::Serve, this, server_host, &mu, &cond))); cond.wait(lock, [this] { return server_ready_; }); server_ready_ = false; - gpr_log(GPR_INFO, "server startup complete"); + LOG(INFO) << "server startup complete"; } void Serve(const std::string& server_host, std::mutex* mu, @@ -380,15 +380,14 @@ TEST_P(CFStreamTest, NetworkFlapRpcsInFlight) { CHECK(ok); AsyncClientCall* call = static_cast(got_tag); if (!call->status.ok()) { - gpr_log(GPR_DEBUG, "RPC failed with error: %s", - call->status.error_message().c_str()); + VLOG(2) << "RPC failed with error: " << call->status.error_message(); // Bring network up when RPCs start failing if (network_down) { NetworkUp(); network_down = false; } } else { - gpr_log(GPR_DEBUG, "RPC succeeded"); + VLOG(2) << "RPC succeeded"; } delete call; } @@ -427,11 +426,10 @@ TEST_P(CFStreamTest, ConcurrentRpc) { CHECK(ok); AsyncClientCall* call = static_cast(got_tag); if (!call->status.ok()) { - gpr_log(GPR_DEBUG, "RPC failed with error: %s", - call->status.error_message().c_str()); + VLOG(2) << "RPC failed with error: " << call->status.error_message(); // Bring network up when RPCs start failing } else { - gpr_log(GPR_DEBUG, "RPC succeeded"); + VLOG(2) << "RPC succeeded"; } delete call; } diff --git a/test/cpp/end2end/client_fork_test.cc b/test/cpp/end2end/client_fork_test.cc index 34050872f77..2388e558528 100644 --- a/test/cpp/end2end/client_fork_test.cc +++ b/test/cpp/end2end/client_fork_test.cc @@ -23,11 +23,11 @@ int main(int /* argc */, char** /* argv */) { return 0; } #include +#include "absl/log/log.h" #include "absl/strings/str_cat.h" #include #include -#include #include #include #include @@ -53,10 +53,10 @@ class ServiceImpl final : public EchoTestService::Service { EchoRequest request; EchoResponse response; while (stream->Read(&request)) { - gpr_log(GPR_INFO, "recv msg %s", request.message().c_str()); + LOG(INFO) << "recv msg " << request.message(); response.set_message(request.message()); stream->Write(response); - gpr_log(GPR_INFO, "wrote msg %s", response.message().c_str()); + LOG(INFO) << "wrote msg " << response.message(); } return Status::OK; } @@ -114,7 +114,7 @@ TEST(ClientForkTest, ClientCallsBeforeAndAfterForkSucceed) { GTEST_FAIL() << "fork failed"; case 0: // post-fork child { - gpr_log(GPR_DEBUG, "In post-fork child"); + VLOG(2) << "In post-fork child"; EchoRequest request; EchoResponse response; ClientContext context; @@ -131,7 +131,7 @@ TEST(ClientForkTest, ClientCallsBeforeAndAfterForkSucceed) { } default: // post-fork parent { - gpr_log(GPR_DEBUG, "In post-fork parent"); + VLOG(2) << "In post-fork parent"; EchoRequest request; EchoResponse response; ClientContext context; diff --git a/test/cpp/end2end/connection_attempt_injector.cc b/test/cpp/end2end/connection_attempt_injector.cc index bacfd15e1be..ab285203d8b 100644 --- a/test/cpp/end2end/connection_attempt_injector.cc +++ b/test/cpp/end2end/connection_attempt_injector.cc @@ -17,6 +17,7 @@ #include #include "absl/log/check.h" +#include "absl/log/log.h" #include "absl/memory/memory.h" #include "absl/utility/utility.h" @@ -119,14 +120,14 @@ void ConnectionAttemptInjector::HandleConnection( grpc_pollset_set* interested_parties, const EndpointConfig& config, const grpc_resolved_address* addr, grpc_core::Timestamp deadline) { const int port = grpc_sockaddr_get_port(addr); - gpr_log(GPR_INFO, "==> HandleConnection(): port=%d", port); + LOG(INFO) << "==> HandleConnection(): port=" << port; { grpc_core::MutexLock lock(&mu_); // First, check if there's a hold request for this port. for (auto it = holds_.begin(); it != holds_.end(); ++it) { Hold* hold = *it; if (port == hold->port_) { - gpr_log(GPR_INFO, "*** INTERCEPTING CONNECTION ATTEMPT"); + LOG(INFO) << "*** INTERCEPTING CONNECTION ATTEMPT"; if (hold->intercept_completion_) { hold->original_on_complete_ = closure; closure = GRPC_CLOSURE_INIT(&hold->on_complete_, Hold::OnComplete, @@ -220,16 +221,16 @@ ConnectionAttemptInjector::Hold::Hold(ConnectionAttemptInjector* injector, intercept_completion_(intercept_completion) {} void ConnectionAttemptInjector::Hold::Wait() { - gpr_log(GPR_INFO, "=== WAITING FOR CONNECTION ATTEMPT ON PORT %d ===", port_); + LOG(INFO) << "=== WAITING FOR CONNECTION ATTEMPT ON PORT " << port_ << " ==="; grpc_core::MutexLock lock(&injector_->mu_); while (queued_attempt_ == nullptr) { start_cv_.Wait(&injector_->mu_); } - gpr_log(GPR_INFO, "=== CONNECTION ATTEMPT STARTED ON PORT %d ===", port_); + LOG(INFO) << "=== CONNECTION ATTEMPT STARTED ON PORT " << port_ << " ==="; } void ConnectionAttemptInjector::Hold::Resume() { - gpr_log(GPR_INFO, "=== RESUMING CONNECTION ATTEMPT ON PORT %d ===", port_); + LOG(INFO) << "=== RESUMING CONNECTION ATTEMPT ON PORT " << port_ << " ==="; grpc_core::ExecCtx exec_ctx; std::unique_ptr attempt; { @@ -240,7 +241,7 @@ void ConnectionAttemptInjector::Hold::Resume() { } void ConnectionAttemptInjector::Hold::Fail(grpc_error_handle error) { - gpr_log(GPR_INFO, "=== FAILING CONNECTION ATTEMPT ON PORT %d ===", port_); + LOG(INFO) << "=== FAILING CONNECTION ATTEMPT ON PORT " << port_ << " ==="; grpc_core::ExecCtx exec_ctx; std::unique_ptr attempt; { @@ -251,13 +252,13 @@ void ConnectionAttemptInjector::Hold::Fail(grpc_error_handle error) { } void ConnectionAttemptInjector::Hold::WaitForCompletion() { - gpr_log(GPR_INFO, - "=== WAITING FOR CONNECTION COMPLETION ON PORT %d ===", port_); + LOG(INFO) << "=== WAITING FOR CONNECTION COMPLETION ON PORT " << port_ + << " ==="; grpc_core::MutexLock lock(&injector_->mu_); while (original_on_complete_ != nullptr) { complete_cv_.Wait(&injector_->mu_); } - gpr_log(GPR_INFO, "=== CONNECTION COMPLETED ON PORT %d ===", port_); + LOG(INFO) << "=== CONNECTION COMPLETED ON PORT " << port_ << " ==="; } bool ConnectionAttemptInjector::Hold::IsStarted() { diff --git a/test/cpp/end2end/end2end_test.cc b/test/cpp/end2end/end2end_test.cc index 30db76435c3..543be34226f 100644 --- a/test/cpp/end2end/end2end_test.cc +++ b/test/cpp/end2end/end2end_test.cc @@ -20,6 +20,7 @@ #include #include "absl/log/check.h" +#include "absl/log/log.h" #include "absl/memory/memory.h" #include "absl/strings/ascii.h" #include "absl/strings/match.h" @@ -27,7 +28,6 @@ #include #include -#include #include #include #include @@ -538,7 +538,7 @@ class End2endServerTryCancelTest : public End2endTest { } num_msgs_sent++; } - gpr_log(GPR_INFO, "Sent %d messages", num_msgs_sent); + LOG(INFO) << "Sent " << num_msgs_sent << " messages"; stream->WritesDone(); Status s = stream->Finish(); @@ -566,8 +566,7 @@ class End2endServerTryCancelTest : public End2endTest { break; default: - gpr_log(GPR_ERROR, "Invalid server_try_cancel value: %d", - server_try_cancel); + LOG(ERROR) << "Invalid server_try_cancel value: " << server_try_cancel; EXPECT_TRUE(server_try_cancel > DO_NOT_CANCEL && server_try_cancel <= CANCEL_AFTER_PROCESSING); break; @@ -618,7 +617,7 @@ class End2endServerTryCancelTest : public End2endTest { request.message() + std::to_string(num_msgs_read)); num_msgs_read++; } - gpr_log(GPR_INFO, "Read %d messages", num_msgs_read); + LOG(INFO) << "Read " << num_msgs_read << " messages"; Status s = stream->Finish(); @@ -647,8 +646,7 @@ class End2endServerTryCancelTest : public End2endTest { break; default: { - gpr_log(GPR_ERROR, "Invalid server_try_cancel value: %d", - server_try_cancel); + LOG(ERROR) << "Invalid server_try_cancel value: " << server_try_cancel; EXPECT_TRUE(server_try_cancel > DO_NOT_CANCEL && server_try_cancel <= CANCEL_AFTER_PROCESSING); break; @@ -705,8 +703,8 @@ class End2endServerTryCancelTest : public End2endTest { EXPECT_EQ(response.message(), request.message()); } - gpr_log(GPR_INFO, "Sent %d messages", num_msgs_sent); - gpr_log(GPR_INFO, "Read %d messages", num_msgs_read); + LOG(INFO) << "Sent " << num_msgs_sent << " messages"; + LOG(INFO) << "Read " << num_msgs_read << " messages"; stream->WritesDone(); Status s = stream->Finish(); @@ -735,8 +733,7 @@ class End2endServerTryCancelTest : public End2endTest { break; default: - gpr_log(GPR_ERROR, "Invalid server_try_cancel value: %d", - server_try_cancel); + LOG(ERROR) << "Invalid server_try_cancel value: " << server_try_cancel; EXPECT_TRUE(server_try_cancel > DO_NOT_CANCEL && server_try_cancel <= CANCEL_AFTER_PROCESSING); break; @@ -1353,7 +1350,7 @@ void ReaderThreadFunc(ClientReaderWriter* stream, EchoResponse resp; gpr_event_set(ev, reinterpret_cast(1)); while (stream->Read(&resp)) { - gpr_log(GPR_INFO, "Read message"); + LOG(INFO) << "Read message"; } } diff --git a/test/cpp/end2end/flaky_network_test.cc b/test/cpp/end2end/flaky_network_test.cc index 4211cba13cf..add00a63cca 100644 --- a/test/cpp/end2end/flaky_network_test.cc +++ b/test/cpp/end2end/flaky_network_test.cc @@ -25,12 +25,12 @@ #include +#include "absl/log/log.h" #include "absl/memory/memory.h" #include #include #include -#include #include #include #include @@ -226,9 +226,9 @@ class FlakyNetworkTest : public ::testing::TestWithParam { Status status = stub->Echo(&context, request, response.get()); auto ok = status.ok(); if (ok) { - gpr_log(GPR_DEBUG, "RPC succeeded"); + VLOG(2) << "RPC succeeded"; } else { - gpr_log(GPR_DEBUG, "RPC failed: %s", status.error_message().c_str()); + VLOG(2) << "RPC failed: " << status.error_message(); } return ok; } @@ -245,7 +245,7 @@ class FlakyNetworkTest : public ::testing::TestWithParam { : port_(port), creds_(creds) {} void Start(const std::string& server_host) { - gpr_log(GPR_INFO, "starting server on port %d", port_); + LOG(INFO) << "starting server on port " << port_; std::mutex mu; std::unique_lock lock(mu); std::condition_variable cond; @@ -253,7 +253,7 @@ class FlakyNetworkTest : public ::testing::TestWithParam { std::bind(&ServerData::Serve, this, server_host, &mu, &cond)); cond.wait(lock, [this] { return server_ready_; }); server_ready_ = false; - gpr_log(GPR_INFO, "server startup complete"); + LOG(INFO) << "server startup complete"; } void Serve(const std::string& server_host, std::mutex* mu, @@ -399,7 +399,7 @@ TEST_P(FlakyNetworkTest, ServerUnreachableWithKeepalive) { // max time between reconnect attempts args.SetInt(GRPC_ARG_MAX_RECONNECT_BACKOFF_MS, kReconnectBackoffMs); - gpr_log(GPR_DEBUG, "FlakyNetworkTest.ServerUnreachableWithKeepalive start"); + VLOG(2) << "FlakyNetworkTest.ServerUnreachableWithKeepalive start"; auto channel = BuildChannel("pick_first", args); auto stub = BuildStub(channel); // Channel should be in READY state after we send an RPC @@ -418,18 +418,18 @@ TEST_P(FlakyNetworkTest, ServerUnreachableWithKeepalive) { }); // break network connectivity - gpr_log(GPR_DEBUG, "Adding iptables rule to drop packets"); + VLOG(2) << "Adding iptables rule to drop packets"; DropPackets(); std::this_thread::sleep_for(std::chrono::milliseconds(10000)); EXPECT_TRUE(WaitForChannelNotReady(channel.get())); // bring network interface back up RestoreNetwork(); - gpr_log(GPR_DEBUG, "Removed iptables rule to drop packets"); + VLOG(2) << "Removed iptables rule to drop packets"; EXPECT_TRUE(WaitForChannelReady(channel.get())); EXPECT_EQ(channel->GetState(false), GRPC_CHANNEL_READY); shutdown.store(true); sender.join(); - gpr_log(GPR_DEBUG, "FlakyNetworkTest.ServerUnreachableWithKeepalive end"); + VLOG(2) << "FlakyNetworkTest.ServerUnreachableWithKeepalive end"; } // diff --git a/test/cpp/end2end/orca_service_end2end_test.cc b/test/cpp/end2end/orca_service_end2end_test.cc index 691a3a3448f..bf67dd0bc36 100644 --- a/test/cpp/end2end/orca_service_end2end_test.cc +++ b/test/cpp/end2end/orca_service_end2end_test.cc @@ -17,6 +17,7 @@ #include #include +#include "absl/log/log.h" #include "absl/strings/str_cat.h" #include "absl/types/optional.h" @@ -104,7 +105,7 @@ class OrcaServiceEnd2endTest : public ::testing::Test { builder.AddListeningPort(server_address, grpc::InsecureServerCredentials()); builder.RegisterService(&orca_service_); server_ = builder.BuildAndStart(); - gpr_log(GPR_INFO, "server started on %s", server_address_.c_str()); + LOG(INFO) << "server started on " << server_address_; auto channel = CreateChannel(server_address, InsecureChannelCredentials()); stub_ = OpenRcaService::NewStub(channel); } @@ -129,13 +130,13 @@ TEST_F(OrcaServiceEnd2endTest, Basic) { Stream stream1(stub_.get(), grpc_core::Duration::Milliseconds(5000)); Stream stream2(stub_.get(), grpc_core::Duration::Milliseconds(2500)); auto ReadResponses = [&](std::function checker) { - gpr_log(GPR_INFO, "reading response from stream1"); + LOG(INFO) << "reading response from stream1"; OrcaLoadReport response = stream1.ReadResponse(); checker(response); - gpr_log(GPR_INFO, "reading response from stream2"); + LOG(INFO) << "reading response from stream2"; response = stream2.ReadResponse(); checker(response); - gpr_log(GPR_INFO, "reading response from stream2"); + LOG(INFO) << "reading response from stream2"; response = stream2.ReadResponse(); checker(response); }; diff --git a/test/cpp/end2end/rls_server.cc b/test/cpp/end2end/rls_server.cc index 98928bedc8c..f0b520fe9d6 100644 --- a/test/cpp/end2end/rls_server.cc +++ b/test/cpp/end2end/rls_server.cc @@ -18,6 +18,8 @@ #include +#include "absl/log/log.h" + #include "src/proto/grpc/lookup/v1/rls.grpc.pb.h" #include "src/proto/grpc/lookup/v1/rls.pb.h" #include "test/core/test_util/test_config.h" @@ -31,8 +33,7 @@ namespace testing { ::grpc::Status RlsServiceImpl::RouteLookup(grpc::ServerContext* context, const RouteLookupRequest* request, RouteLookupResponse* response) { - gpr_log(GPR_INFO, "RLS: Received request: %s", - request->DebugString().c_str()); + LOG(INFO) << "RLS: Received request: " << request->DebugString(); if (context_proc_ != nullptr) { context_proc_(context); } @@ -44,7 +45,7 @@ namespace testing { grpc::internal::MutexLock lock(&mu_); auto it = responses_.find(*request); if (it == responses_.end()) { - gpr_log(GPR_INFO, "RLS: no matching request, returning INTERNAL"); + LOG(INFO) << "RLS: no matching request, returning INTERNAL"; unmatched_requests_.push_back(*request); return Status(StatusCode::INTERNAL, "no response entry"); } @@ -57,8 +58,8 @@ namespace testing { } IncreaseResponseCount(); *response = res.response; - gpr_log(GPR_INFO, "RLS: returning configured response: %s", - response->DebugString().c_str()); + LOG(INFO) << "RLS: returning configured response: " + << response->DebugString(); return Status::OK; } diff --git a/test/cpp/end2end/server_load_reporting_end2end_test.cc b/test/cpp/end2end/server_load_reporting_end2end_test.cc index acdafe31f5c..d5e057d386a 100644 --- a/test/cpp/end2end/server_load_reporting_end2end_test.cc +++ b/test/cpp/end2end/server_load_reporting_end2end_test.cc @@ -21,9 +21,10 @@ #include #include +#include "absl/log/log.h" + #include #include -#include #include #include #include @@ -138,11 +139,11 @@ TEST_F(ServerLoadReportingEnd2endTest, BasicReport) { ->mutable_load_report_interval() ->set_seconds(5); stream->Write(request); - gpr_log(GPR_INFO, "Initial request sent."); + LOG(INFO) << "Initial request sent."; grpc::lb::v1::LoadReportResponse response; stream->Read(&response); const std::string& lb_id = response.initial_response().load_balancer_id(); - gpr_log(GPR_INFO, "Initial response received (lb_id: %s).", lb_id.c_str()); + LOG(INFO) << "Initial response received (lb_id: " << lb_id << ")."; ClientMakeEchoCalls(lb_id, "LB_TAG", kOkMessage, 1); unsigned load_count = 0; diff --git a/test/cpp/end2end/service_config_end2end_test.cc b/test/cpp/end2end/service_config_end2end_test.cc index 5efb0cd285b..380ebc2e261 100644 --- a/test/cpp/end2end/service_config_end2end_test.cc +++ b/test/cpp/end2end/service_config_end2end_test.cc @@ -28,13 +28,13 @@ #include #include "absl/log/check.h" +#include "absl/log/log.h" #include "absl/memory/memory.h" #include "absl/strings/str_cat.h" #include #include #include -#include #include #include #include @@ -311,7 +311,7 @@ class ServiceConfigEnd2endTest : public ::testing::Test { : port_(port > 0 ? port : grpc_pick_unused_port_or_die()) {} void Start(const std::string& server_host) { - gpr_log(GPR_INFO, "starting server on port %d", port_); + LOG(INFO) << "starting server on port " << port_; grpc::internal::MutexLock lock(&mu_); started_ = true; thread_ = std::make_unique( @@ -320,7 +320,7 @@ class ServiceConfigEnd2endTest : public ::testing::Test { cond_.Wait(&mu_); } server_ready_ = false; - gpr_log(GPR_INFO, "server startup complete"); + LOG(INFO) << "server startup complete"; } void Serve(const std::string& server_host) { diff --git a/test/cpp/end2end/test_service_impl.cc b/test/cpp/end2end/test_service_impl.cc index b721ed5382a..0c23abc6c51 100644 --- a/test/cpp/end2end/test_service_impl.cc +++ b/test/cpp/end2end/test_service_impl.cc @@ -24,8 +24,8 @@ #include #include "absl/log/check.h" +#include "absl/log/log.h" -#include #include #include #include @@ -96,7 +96,7 @@ int GetIntValueFromMetadataHelper( if (metadata.find(key) != metadata.end()) { std::istringstream iss(ToString(metadata.find(key)->second)); iss >> default_value; - gpr_log(GPR_INFO, "%s : %d", key, default_value); + LOG(INFO) << key << " : " << default_value; } return default_value; @@ -112,7 +112,7 @@ int GetIntValueFromMetadata( void ServerTryCancel(ServerContext* context) { EXPECT_FALSE(context->IsCancelled()); context->TryCancel(); - gpr_log(GPR_INFO, "Server called TryCancel() to cancel the request"); + LOG(INFO) << "Server called TryCancel() to cancel the request"; // Now wait until it's really canceled while (!context->IsCancelled()) { gpr_sleep_until(gpr_time_add(gpr_now(GPR_CLOCK_REALTIME), @@ -123,8 +123,7 @@ void ServerTryCancel(ServerContext* context) { void ServerTryCancelNonblocking(CallbackServerContext* context) { EXPECT_FALSE(context->IsCancelled()); context->TryCancel(); - gpr_log(GPR_INFO, - "Server called TryCancelNonblocking() to cancel the request"); + LOG(INFO) << "Server called TryCancelNonblocking() to cancel the request"; } } // namespace internal @@ -211,7 +210,7 @@ ServerUnaryReactor* CallbackTestServiceImpl::Echo( return; } if (req_->has_param() && req_->param().server_die()) { - gpr_log(GPR_ERROR, "The request should not reach application handler."); + LOG(ERROR) << "The request should not reach application handler."; CHECK(0); } if (req_->has_param() && req_->param().has_expected_error()) { @@ -229,7 +228,7 @@ ServerUnaryReactor* CallbackTestServiceImpl::Echo( // RPC as long as server_try_cancel is not DO_NOT_CANCEL EXPECT_FALSE(ctx_->IsCancelled()); ctx_->TryCancel(); - gpr_log(GPR_INFO, "Server called TryCancel() to cancel the request"); + LOG(INFO) << "Server called TryCancel() to cancel the request"; FinishWhenCancelledAsync(); return; } @@ -398,7 +397,7 @@ ServerReadReactor* CallbackTestServiceImpl::RequestStream( num_msgs_read_++; StartRead(&request_); } else { - gpr_log(GPR_INFO, "Read: %d messages", num_msgs_read_); + LOG(INFO) << "Read: " << num_msgs_read_ << " messages"; if (server_try_cancel_ == CANCEL_DURING_PROCESSING) { // Let OnCancel recover this diff --git a/test/cpp/end2end/test_service_impl.h b/test/cpp/end2end/test_service_impl.h index 3fae2456987..05511373302 100644 --- a/test/cpp/end2end/test_service_impl.h +++ b/test/cpp/end2end/test_service_impl.h @@ -28,9 +28,9 @@ #include #include "absl/log/check.h" +#include "absl/log/log.h" #include -#include #include #include #include @@ -98,35 +98,34 @@ class TestServiceSignaller { // is whatever the number of RPCs waiting for server notification is // at that time. int ClientWaitUntilNRpcsStarted(int desired_rpcs, absl::Duration timeout) { - gpr_log(GPR_DEBUG, "*** enter ClientWaitUntilNRpcsStarted ***"); + VLOG(2) << "*** enter ClientWaitUntilNRpcsStarted ***"; absl::Time deadline = absl::Now() + timeout; std::chrono::system_clock::time_point chrono_deadline = absl::ToChronoTime(deadline); std::unique_lock lock(mu_); cv_rpc_started_.wait_until(lock, chrono_deadline, [this, desired_rpcs] { - gpr_log( - GPR_DEBUG, - "*** desired_rpcs: %d rpcs_waiting_for_server_to_continue_: %d ***", - desired_rpcs, rpcs_waiting_for_server_to_continue_); + VLOG(2) << "*** desired_rpcs: " << desired_rpcs + << " rpcs_waiting_for_server_to_continue_: " + << rpcs_waiting_for_server_to_continue_ << " ***"; return rpcs_waiting_for_server_to_continue_ >= desired_rpcs; }); - gpr_log(GPR_DEBUG, "*** leave ClientWaitUntilNRpcsStarted ***"); + VLOG(2) << "*** leave ClientWaitUntilNRpcsStarted ***"; return rpcs_waiting_for_server_to_continue_; } void ServerWaitToContinue() { - gpr_log(GPR_DEBUG, "*** enter ServerWaitToContinue ***"); + VLOG(2) << "*** enter ServerWaitToContinue ***"; std::unique_lock lock(mu_); cv_server_continue_.wait(lock, [this] { return server_should_continue_; }); - gpr_log(GPR_DEBUG, "*** leave ServerWaitToContinue ***"); + VLOG(2) << "*** leave ServerWaitToContinue ***"; } void SignalClientThatRpcStarted() { - gpr_log(GPR_DEBUG, "*** SignalClientThatRpcStarted ***"); + VLOG(2) << "*** SignalClientThatRpcStarted ***"; std::unique_lock lock(mu_); ++rpcs_waiting_for_server_to_continue_; cv_rpc_started_.notify_all(); } void SignalServerToContinue() { - gpr_log(GPR_DEBUG, "*** SignalServerToContinue ***"); + VLOG(2) << "*** SignalServerToContinue ***"; std::unique_lock lock(mu_); server_should_continue_ = true; cv_server_continue_.notify_all(); @@ -170,7 +169,7 @@ class TestMultipleServiceImpl : public RpcService { } if (request->has_param() && request->param().server_die()) { - gpr_log(GPR_ERROR, "The request should not reach application handler."); + LOG(ERROR) << "The request should not reach application handler."; CHECK(0); } if (request->has_param() && request->param().has_expected_error()) { @@ -330,7 +329,7 @@ class TestMultipleServiceImpl : public RpcService { while (reader->Read(&request)) { response->mutable_message()->append(request.message()); } - gpr_log(GPR_INFO, "Read: %d messages", num_msgs_read); + LOG(INFO) << "Read: " << num_msgs_read << " messages"; if (server_try_cancel_thd != nullptr) { server_try_cancel_thd->join(); @@ -441,7 +440,7 @@ class TestMultipleServiceImpl : public RpcService { int read_counts = 0; while (stream->Read(&request)) { read_counts++; - gpr_log(GPR_INFO, "recv msg %s", request.message().c_str()); + LOG(INFO) << "recv msg " << request.message(); response.set_message(request.message()); if (read_counts == server_write_last) { stream->WriteLast(response, WriteOptions()); diff --git a/test/cpp/end2end/xds/xds_cluster_end2end_test.cc b/test/cpp/end2end/xds/xds_cluster_end2end_test.cc index 07f3fdaf7e3..a162086b69e 100644 --- a/test/cpp/end2end/xds/xds_cluster_end2end_test.cc +++ b/test/cpp/end2end/xds/xds_cluster_end2end_test.cc @@ -20,6 +20,7 @@ #include #include +#include "absl/log/log.h" #include "absl/strings/match.h" #include "absl/strings/str_cat.h" @@ -898,10 +899,10 @@ TEST_P(EdsTest, LocalityMapUpdateChurn) { balancer_->ads_service()->SetEdsResource(BuildEdsResource(args)); // Wait for the first 3 backends to be ready. WaitForAllBackends(DEBUG_LOCATION, 0, 3); - gpr_log(GPR_INFO, "========= BEFORE FIRST BATCH =========="); + LOG(INFO) << "========= BEFORE FIRST BATCH =========="; // Send kNumRpcs RPCs. CheckRpcSendOk(DEBUG_LOCATION, kNumRpcs); - gpr_log(GPR_INFO, "========= DONE WITH FIRST BATCH =========="); + LOG(INFO) << "========= DONE WITH FIRST BATCH =========="; // The picking rates of the first 3 backends should be roughly equal to the // expectation. std::vector locality_picked_rates; @@ -931,10 +932,10 @@ TEST_P(EdsTest, LocalityMapUpdateChurn) { // Wait until the locality update has been processed, as signaled by backend // 3 receiving a request. WaitForAllBackends(DEBUG_LOCATION, 3, 4); - gpr_log(GPR_INFO, "========= BEFORE SECOND BATCH =========="); + LOG(INFO) << "========= BEFORE SECOND BATCH =========="; // Send kNumRpcs RPCs. CheckRpcSendOk(DEBUG_LOCATION, kNumRpcs); - gpr_log(GPR_INFO, "========= DONE WITH SECOND BATCH =========="); + LOG(INFO) << "========= DONE WITH SECOND BATCH =========="; // Backend 0 no longer receives any request. EXPECT_EQ(0U, backends_[0]->backend_service()->request_count()); // The picking rates of the last 3 backends should be roughly equal to the @@ -1091,11 +1092,11 @@ TEST_P(EdsTest, DropConfigUpdate) { args.drop_categories = {{kLbDropType, kDropPerMillionForLb}}; balancer_->ads_service()->SetEdsResource(BuildEdsResource(args)); // Send kNumRpcsLbOnly RPCs and count the drops. - gpr_log(GPR_INFO, "========= BEFORE FIRST BATCH =========="); + LOG(INFO) << "========= BEFORE FIRST BATCH =========="; size_t num_drops = SendRpcsAndCountFailuresWithMessage( DEBUG_LOCATION, kNumRpcsLbOnly, StatusCode::UNAVAILABLE, kStatusMessageDropPrefix); - gpr_log(GPR_INFO, "========= DONE WITH FIRST BATCH =========="); + LOG(INFO) << "========= DONE WITH FIRST BATCH =========="; // The drop rate should be roughly equal to the expectation. double seen_drop_rate = static_cast(num_drops) / kNumRpcsLbOnly; gpr_log(GPR_INFO, "First batch drop rate %f", seen_drop_rate); @@ -1128,11 +1129,11 @@ TEST_P(EdsTest, DropConfigUpdate) { }, /*timeout_ms=*/40000); // Send kNumRpcsBoth RPCs and count the drops. - gpr_log(GPR_INFO, "========= BEFORE SECOND BATCH =========="); + LOG(INFO) << "========= BEFORE SECOND BATCH =========="; num_drops = SendRpcsAndCountFailuresWithMessage(DEBUG_LOCATION, kNumRpcsBoth, StatusCode::UNAVAILABLE, kStatusMessageDropPrefix); - gpr_log(GPR_INFO, "========= DONE WITH SECOND BATCH =========="); + LOG(INFO) << "========= DONE WITH SECOND BATCH =========="; // The new drop rate should be roughly equal to the expectation. seen_drop_rate = static_cast(num_drops) / kNumRpcsBoth; gpr_log(GPR_INFO, "Second batch drop rate %f", seen_drop_rate); @@ -1268,9 +1269,9 @@ TEST_P(FailoverTest, ReportsConnectingDuringFailover) { // Allow the connection attempt to complete. hold->Resume(); // Now the RPC should complete successfully. - gpr_log(GPR_INFO, "=== WAITING FOR RPC TO FINISH ==="); + LOG(INFO) << "=== WAITING FOR RPC TO FINISH ==="; Status status = rpc.GetStatus(); - gpr_log(GPR_INFO, "=== RPC FINISHED ==="); + LOG(INFO) << "=== RPC FINISHED ==="; EXPECT_TRUE(status.ok()) << "code=" << status.error_code() << " message=" << status.error_message(); } diff --git a/test/cpp/end2end/xds/xds_cluster_type_end2end_test.cc b/test/cpp/end2end/xds/xds_cluster_type_end2end_test.cc index 45dced809bc..b87cf9df016 100644 --- a/test/cpp/end2end/xds/xds_cluster_type_end2end_test.cc +++ b/test/cpp/end2end/xds/xds_cluster_type_end2end_test.cc @@ -19,6 +19,7 @@ #include #include "absl/log/check.h" +#include "absl/log/log.h" #include "absl/status/statusor.h" #include "absl/strings/str_cat.h" @@ -367,9 +368,9 @@ TEST_P(AggregateClusterTest, FallBackWithConnectivityChurn) { // Meanwhile, the channel will also start a second attempt for backend // 0, which we have NOT held, so it will complete normally, and the // RPC will finish on backend 0. - gpr_log(GPR_INFO, "=== WAITING FOR RPC TO FINISH === "); + LOG(INFO) << "=== WAITING FOR RPC TO FINISH === "; Status status = rpc.GetStatus(); - gpr_log(GPR_INFO, "=== RPC FINISHED === "); + LOG(INFO) << "=== RPC FINISHED === "; EXPECT_TRUE(status.ok()) << "code=" << status.error_code() << " message=" << status.error_message(); EXPECT_EQ(1UL, backends_[0]->backend_service()->request_count()); diff --git a/test/cpp/end2end/xds/xds_end2end_test.cc b/test/cpp/end2end/xds/xds_end2end_test.cc index ec603b06f06..9a8c8a9c52d 100644 --- a/test/cpp/end2end/xds/xds_end2end_test.cc +++ b/test/cpp/end2end/xds/xds_end2end_test.cc @@ -33,6 +33,7 @@ #include "absl/functional/bind_front.h" #include "absl/log/check.h" +#include "absl/log/log.h" #include "absl/memory/memory.h" #include "absl/strings/match.h" #include "absl/strings/str_cat.h" @@ -45,7 +46,6 @@ #include #include #include -#include #include #include #include @@ -398,8 +398,7 @@ class XdsSecurityTest : public XdsEnd2endTest { DEBUG_LOCATION, [&](const RpcResult& result) { if (result.status.ok()) { - gpr_log(GPR_ERROR, - "RPC succeeded. Failure expected. Trying again."); + LOG(ERROR) << "RPC succeeded. Failure expected. Trying again."; return true; } EXPECT_EQ(result.status.error_code(), StatusCode::UNAVAILABLE); @@ -1051,7 +1050,7 @@ class XdsServerSecurityTest : public XdsEnd2endTest { std::vector expected_client_identity, bool test_expects_failure = false, absl::optional expected_status = absl::nullopt) { - gpr_log(GPR_INFO, "Sending RPC"); + LOG(INFO) << "Sending RPC"; int num_tries = 0; constexpr int kRetryCount = 100; auto overall_deadline = absl::Now() + absl::Seconds(5); @@ -1073,7 +1072,7 @@ class XdsServerSecurityTest : public XdsEnd2endTest { Status status = stub->Echo(&context, request, &response); if (test_expects_failure) { if (status.ok()) { - gpr_log(GPR_ERROR, "RPC succeeded. Failure expected. Trying again."); + LOG(ERROR) << "RPC succeeded. Failure expected. Trying again."; continue; } if (expected_status.has_value() && diff --git a/test/cpp/end2end/xds/xds_server.cc b/test/cpp/end2end/xds/xds_server.cc index ee96dd3f84a..a4019c7fdfe 100644 --- a/test/cpp/end2end/xds/xds_server.cc +++ b/test/cpp/end2end/xds/xds_server.cc @@ -23,10 +23,9 @@ #include #include "absl/log/check.h" +#include "absl/log/log.h" #include "absl/types/optional.h" -#include - #include "src/core/lib/address_utils/parse_address.h" #include "src/core/lib/gprpp/crash.h" #include "src/core/lib/gprpp/sync.h" @@ -51,10 +50,9 @@ void AdsServiceImpl::SetResource(google::protobuf::Any resource, resource_state.resource_type_version = resource_type_state.resource_type_version; resource_state.resource = std::move(resource); - gpr_log(GPR_INFO, - "ADS[%s]: Updating %s resource %s; resource_type_version now %u", - debug_label_.c_str(), type_url.c_str(), name.c_str(), - resource_type_state.resource_type_version); + LOG(INFO) << "ADS[" << debug_label_ << "]: Updating " << type_url + << " resource " << name << "; resource_type_version now " + << resource_type_state.resource_type_version; for (SubscriptionState* subscription : resource_state.subscriptions) { subscription->update_queue->emplace_back(type_url, name); } @@ -69,10 +67,9 @@ void AdsServiceImpl::UnsetResource(const std::string& type_url, resource_state.resource_type_version = resource_type_state.resource_type_version; resource_state.resource.reset(); - gpr_log(GPR_INFO, - "ADS[%s]: Unsetting %s resource %s; resource_type_version now %u", - debug_label_.c_str(), type_url.c_str(), name.c_str(), - resource_type_state.resource_type_version); + LOG(INFO) << "ADS[" << debug_label_ << "]: Unsetting " << type_url + << " resource " << name << "; resource_type_version now " + << resource_type_state.resource_type_version; for (SubscriptionState* subscription : resource_state.subscriptions) { subscription->update_queue->emplace_back(type_url, name); } @@ -101,9 +98,9 @@ bool AdsServiceImpl::MaybeSubscribe(const std::string& resource_type, if (subscription_state->update_queue != nullptr) return false; subscription_state->update_queue = update_queue; resource_state->subscriptions.emplace(subscription_state); - gpr_log(GPR_INFO, "ADS[%s]: subscribe to resource type %s name %s state %p", - debug_label_.c_str(), resource_type.c_str(), resource_name.c_str(), - &subscription_state); + LOG(INFO) << "ADS[" << debug_label_ << "]: subscribe to resource type " + << resource_type << " name " << resource_name << " state " + << &subscription_state; return true; } @@ -123,9 +120,9 @@ void AdsServiceImpl::ProcessUnsubscriptions( ++it; continue; } - gpr_log(GPR_INFO, "ADS[%s]: Unsubscribe to type=%s name=%s state=%p", - debug_label_.c_str(), resource_type.c_str(), resource_name.c_str(), - &subscription_state); + LOG(INFO) << "ADS[" << debug_label_ + << "]: Unsubscribe to type=" << resource_type + << " name=" << resource_name << " state=" << &subscription_state; auto resource_it = resource_name_map->find(resource_name); CHECK(resource_it != resource_name_map->end()); auto& resource_state = resource_it->second; @@ -152,7 +149,7 @@ void AdsServiceImpl::Shutdown() { } resource_type_response_state_.clear(); } - gpr_log(GPR_INFO, "ADS[%s]: shut down", debug_label_.c_str()); + LOG(INFO) << "ADS[" << debug_label_ << "]: shut down"; } // @@ -233,7 +230,7 @@ void LrsServiceImpl::Shutdown() { lrs_cv_.SignalAll(); } } - gpr_log(GPR_INFO, "LRS[%s]: shut down", debug_label_.c_str()); + LOG(INFO) << "LRS[" << debug_label_ << "]: shut down"; } std::vector LrsServiceImpl::WaitForLoadReport( @@ -245,7 +242,7 @@ std::vector LrsServiceImpl::WaitForLoadReport( load_report_cond_ = &cv; while (result_queue_.empty()) { if (cv.WaitWithTimeout(&load_report_mu_, timeout)) { - gpr_log(GPR_ERROR, "timed out waiting for load report"); + LOG(ERROR) << "timed out waiting for load report"; return {}; } }