From ed5893120e16e018e4e4efc029dd000c30443c42 Mon Sep 17 00:00:00 2001 From: Tanvi Jagtap <139093547+tanvi-jagtap@users.noreply.github.com> Date: Thu, 16 May 2024 00:34:38 -0700 Subject: [PATCH] [grpc][Gpr_To_Absl_Logging] Migrating from gpr to absl logging - gpr_log (#36608) [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 #36608 COPYBARA_INTEGRATE_REVIEW=https://github.com/grpc/grpc/pull/36608 from tanvi-jagtap:regex_test_core_misc e6b9481dac3db7ca4cda900eef6c44031680cb8b PiperOrigin-RevId: 634246311 --- .../posix/oracle_event_engine_posix.cc | 21 ++-- test/core/event_engine/windows/iocp_test.cc | 9 +- test/core/gprpp/mpscq_test.cc | 12 +-- test/core/gprpp/single_set_ptr_test.cc | 3 +- test/core/handshake/client_ssl.cc | 20 ++-- test/core/handshake/server_ssl_common.cc | 12 +-- test/core/handshake/verify_peer_options.cc | 4 +- test/core/http/httpcli_test_util.cc | 8 +- test/core/load_balancing/lb_policy_test_lib.h | 98 +++++++++---------- .../load_balancing/outlier_detection_test.cc | 38 +++---- .../weighted_round_robin_test.cc | 26 ++--- .../load_balancing/xds_override_host_test.cc | 29 +++--- .../network_benchmarks/low_level_ping_pong.cc | 76 +++++++------- test/core/promise/party_test.cc | 7 +- test/core/slice/slice_test.cc | 5 +- test/core/surface/completion_queue_test.cc | 6 +- .../completion_queue_threading_test.cc | 42 ++++---- .../surface/concurrent_connectivity_test.cc | 8 +- test/core/test_util/cmdline.h | 4 +- test/core/test_util/reconnect_server.cc | 17 ++-- test/core/test_util/test_config.cc | 17 ++-- .../fake_handshaker/fake_handshaker_server.cc | 10 +- .../alts_concurrent_connectivity_test.cc | 34 +++---- .../alts_handshaker_service_api_test_lib.cc | 9 +- test/core/tsi/ssl_transport_security_test.cc | 69 ++++++------- test/core/xds/xds_client_fuzzer.cc | 70 ++++++------- 26 files changed, 315 insertions(+), 339 deletions(-) diff --git a/test/core/event_engine/test_suite/posix/oracle_event_engine_posix.cc b/test/core/event_engine/test_suite/posix/oracle_event_engine_posix.cc index 86e0a6ac033..52eff1798ec 100644 --- a/test/core/event_engine/test_suite/posix/oracle_event_engine_posix.cc +++ b/test/core/event_engine/test_suite/posix/oracle_event_engine_posix.cc @@ -24,6 +24,7 @@ #include #include "absl/log/check.h" +#include "absl/log/log.h" #include "absl/status/status.h" #include "absl/strings/str_cat.h" #include "absl/strings/str_format.h" @@ -32,7 +33,6 @@ #include #include -#include #include "src/core/lib/address_utils/sockaddr_utils.h" #include "src/core/lib/gprpp/crash.h" @@ -255,7 +255,7 @@ bool PosixOracleEndpoint::Write( } void PosixOracleEndpoint::ProcessReadOperations() { - gpr_log(GPR_INFO, "Starting thread to process read ops ..."); + LOG(INFO) << "Starting thread to process read ops ..."; while (true) { read_op_signal_->WaitForNotification(); read_op_signal_ = std::make_unique(); @@ -273,11 +273,11 @@ void PosixOracleEndpoint::ProcessReadOperations() { grpc_core::StrError(saved_errno))) : absl::OkStatus()); } - gpr_log(GPR_INFO, "Shutting down read ops thread ..."); + LOG(INFO) << "Shutting down read ops thread ..."; } void PosixOracleEndpoint::ProcessWriteOperations() { - gpr_log(GPR_INFO, "Starting thread to process write ops ..."); + LOG(INFO) << "Starting thread to process write ops ..."; while (true) { write_op_signal_->WaitForNotification(); write_op_signal_ = std::make_unique(); @@ -293,7 +293,7 @@ void PosixOracleEndpoint::ProcessWriteOperations() { grpc_core::StrError(saved_errno))) : absl::OkStatus()); } - gpr_log(GPR_INFO, "Shutting down write ops thread ..."); + LOG(INFO) << "Shutting down write ops thread ..."; } PosixOracleListener::PosixOracleListener( @@ -341,7 +341,7 @@ PosixOracleListener::~PosixOracleListener() { } void PosixOracleListener::HandleIncomingConnections() { - gpr_log(GPR_INFO, "Starting accept thread ..."); + LOG(INFO) << "Starting accept thread ..."; CHECK(!listener_fds_.empty()); int nfds = listener_fds_.size(); // Add one extra file descriptor to poll the pipe fd. @@ -371,17 +371,16 @@ void PosixOracleListener::HandleIncomingConnections() { // pfds[i].fd has a readable event. int client_sock_fd = accept(pfds[i].fd, nullptr, nullptr); if (client_sock_fd < 0) { - gpr_log(GPR_ERROR, - "Error accepting new connection: %s. Ignoring connection " - "attempt ...", - grpc_core::StrError(errno).c_str()); + LOG(ERROR) << "Error accepting new connection: " + << grpc_core::StrError(errno) + << ". Ignoring connection attempt ..."; continue; } on_accept_(PosixOracleEndpoint::Create(client_sock_fd), memory_allocator_factory_->CreateMemoryAllocator("test")); } } - gpr_log(GPR_INFO, "Shutting down accept thread ..."); + LOG(INFO) << "Shutting down accept thread ..."; gpr_free(pfds); } diff --git a/test/core/event_engine/windows/iocp_test.cc b/test/core/event_engine/windows/iocp_test.cc index 787ca180cb0..e96b8d3816d 100644 --- a/test/core/event_engine/windows/iocp_test.cc +++ b/test/core/event_engine/windows/iocp_test.cc @@ -19,6 +19,7 @@ #include #include +#include "absl/log/log.h" #include "absl/status/status.h" #include "absl/time/time.h" #include "absl/types/variant.h" @@ -49,7 +50,7 @@ using ::grpc_event_engine::experimental::WinSocket; // `ASSERT_OK(...) << GetErrorMessage(error, context);` void LogErrorMessage(int messageid, absl::string_view context) { char* utf8_message = gpr_format_message(messageid); - gpr_log(GPR_ERROR, "Error in %s: %s", context, utf8_message); + LOG(ERROR) << "Error in " << context << ": " << utf8_message; gpr_free(utf8_message); } } // namespace @@ -77,7 +78,7 @@ TEST_F(IOCPTest, ClientReceivesNotificationOfServerSend) { DWORD bytes_rcvd; on_read = new AnyInvocableClosure([win_socket = wrapped_client_socket.get(), &read_called, &read_wsabuf]() { - gpr_log(GPR_DEBUG, "Notified on read"); + VLOG(2) << "Notified on read"; EXPECT_GE(win_socket->read_info()->result().bytes_transferred, 10u); EXPECT_STREQ(read_wsabuf.buf, "hello!"); read_called.Notify(); @@ -96,7 +97,7 @@ TEST_F(IOCPTest, ClientReceivesNotificationOfServerSend) { } { on_write = new AnyInvocableClosure([&write_called] { - gpr_log(GPR_DEBUG, "Notified on write"); + VLOG(2) << "Notified on write"; write_called.Notify(); }); wrapped_server_socket->NotifyOnWrite(on_write); @@ -153,7 +154,7 @@ TEST_F(IOCPTest, IocpWorkTimeoutDueToNoNotificationRegistered) { wrapped_client_socket->NotifyOnRead( SelfDeletingClosure::Create([win_socket = wrapped_client_socket.get(), &read_called, &read_wsabuf]() { - gpr_log(GPR_DEBUG, "Notified on read"); + VLOG(2) << "Notified on read"; EXPECT_GE(win_socket->read_info()->result().bytes_transferred, 10u); EXPECT_STREQ(read_wsabuf.buf, "hello!"); read_called.Notify(); diff --git a/test/core/gprpp/mpscq_test.cc b/test/core/gprpp/mpscq_test.cc index 9e2cb410234..1bf92acd189 100644 --- a/test/core/gprpp/mpscq_test.cc +++ b/test/core/gprpp/mpscq_test.cc @@ -23,9 +23,9 @@ #include +#include "absl/log/log.h" #include "gtest/gtest.h" -#include #include #include @@ -49,7 +49,7 @@ static test_node* new_node(size_t i, size_t* ctr) { } TEST(MpscqTest, Serial) { - gpr_log(GPR_DEBUG, "test_serial"); + VLOG(2) << "test_serial"; MultiProducerSingleConsumerQueue q; for (size_t i = 0; i < 10000000; i++) { q.Push(&new_node(i, nullptr)->node); @@ -79,7 +79,7 @@ static void test_thread(void* args) { } TEST(MpscqTest, Mt) { - gpr_log(GPR_DEBUG, "test_mt"); + VLOG(2) << "test_mt"; gpr_event start; gpr_event_init(&start); grpc_core::Thread thds[100]; @@ -106,7 +106,7 @@ TEST(MpscqTest, Mt) { if (tn->i == THREAD_ITERATIONS) num_done++; delete tn; } - gpr_log(GPR_DEBUG, "spins: %" PRIdPTR, spins); + VLOG(2) << "spins: " << spins; for (auto& th : thds) { th.Join(); } @@ -146,7 +146,7 @@ static void pull_thread(void* arg) { } TEST(MpscqTest, MtMultipop) { - gpr_log(GPR_DEBUG, "test_mt_multipop"); + VLOG(2) << "test_mt_multipop"; gpr_event start; gpr_event_init(&start); grpc_core::Thread thds[50]; @@ -176,7 +176,7 @@ TEST(MpscqTest, MtMultipop) { for (auto& pth : pull_thds) { pth.Join(); } - gpr_log(GPR_DEBUG, "spins: %" PRIdPTR, pa.spins); + VLOG(2) << "spins: " << pa.spins; for (auto& th : thds) { th.Join(); } diff --git a/test/core/gprpp/single_set_ptr_test.cc b/test/core/gprpp/single_set_ptr_test.cc index 62108e3df59..b93aa14c3e8 100644 --- a/test/core/gprpp/single_set_ptr_test.cc +++ b/test/core/gprpp/single_set_ptr_test.cc @@ -18,6 +18,7 @@ #include #include +#include "absl/log/log.h" #include "gtest/gtest.h" namespace grpc_core { @@ -28,7 +29,7 @@ TEST(SingleSetPtrTest, NoOp) { SingleSetPtr(); } TEST(SingleSetPtrTest, CanSet) { SingleSetPtr p; EXPECT_FALSE(p.is_set()); - EXPECT_DEATH_IF_SUPPORTED(gpr_log(GPR_ERROR, "%d", *p), ""); + EXPECT_DEATH_IF_SUPPORTED({ LOG(ERROR) << *p; }, ""); p.Set(new int(42)); EXPECT_EQ(*p, 42); } diff --git a/test/core/handshake/client_ssl.cc b/test/core/handshake/client_ssl.cc index 5445b7b402e..d59018f3a65 100644 --- a/test/core/handshake/client_ssl.cc +++ b/test/core/handshake/client_ssl.cc @@ -24,6 +24,7 @@ #include #include "absl/base/thread_annotations.h" +#include "absl/strings/str_format.h" #include "gtest/gtest.h" #include @@ -49,12 +50,12 @@ #include #include +#include "absl/log/log.h" #include "absl/strings/str_cat.h" #include #include #include -#include #include "src/core/lib/debug/trace.h" #include "src/core/lib/gprpp/crash.h" @@ -119,7 +120,7 @@ static int create_socket(int* out_port) { if (bind(s, reinterpret_cast(&addr), sizeof(addr)) < 0) { perror("Unable to bind"); - gpr_log(GPR_ERROR, "%s", "Unable to bind to any port"); + LOG(ERROR) << "Unable to bind to any port"; close(s); return -1; } @@ -135,7 +136,7 @@ static int create_socket(int* out_port) { 0 || addr_len > sizeof(addr)) { perror("getsockname"); - gpr_log(GPR_ERROR, "%s", "Unable to get socket local address"); + LOG(ERROR) << "Unable to get socket local address"; close(s); return -1; } @@ -176,14 +177,15 @@ static void ssl_log_where_info(const SSL* ssl, int where, int flag, const char* msg) { if ((where & flag) && GRPC_TRACE_FLAG_ENABLED(client_ssl_tsi_tracing_enabled)) { - gpr_log(GPR_INFO, "%20.20s - %30.30s - %5.10s", msg, - SSL_state_string_long(ssl), SSL_state_string(ssl)); + LOG(INFO) << absl::StrFormat("%20.20s - %30.30s - %5.10s", msg, + SSL_state_string_long(ssl), + SSL_state_string(ssl)); } } static void ssl_server_info_callback(const SSL* ssl, int where, int ret) { if (ret == 0) { - gpr_log(GPR_ERROR, "ssl_server_info_callback: error occurred.\n"); + LOG(ERROR) << "ssl_server_info_callback: error occurred.\n"; return; } @@ -251,7 +253,7 @@ static void server_thread(void* arg) { // bind/listen/accept at TCP layer. const int sock = args->socket; - gpr_log(GPR_INFO, "Server listening"); + LOG(INFO) << "Server listening"; struct sockaddr_in addr; socklen_t len = sizeof(addr); const int client = @@ -268,9 +270,9 @@ static void server_thread(void* arg) { SSL_set_fd(ssl, client); if (SSL_accept(ssl) <= 0) { ERR_print_errors_fp(stderr); - gpr_log(GPR_ERROR, "Handshake failed."); + LOG(ERROR) << "Handshake failed."; } else { - gpr_log(GPR_INFO, "Handshake successful."); + LOG(INFO) << "Handshake successful."; } // Send out the settings frame. diff --git a/test/core/handshake/server_ssl_common.cc b/test/core/handshake/server_ssl_common.cc index aefa17d5223..0bebf83ed2e 100644 --- a/test/core/handshake/server_ssl_common.cc +++ b/test/core/handshake/server_ssl_common.cc @@ -35,6 +35,7 @@ #include "absl/base/thread_annotations.h" #include "absl/log/check.h" +#include "absl/log/log.h" #include "absl/strings/str_cat.h" #include @@ -42,7 +43,6 @@ #include #include #include -#include #include #include @@ -152,7 +152,7 @@ void server_thread(void* arg) { CHECK(ev.type == GRPC_QUEUE_TIMEOUT); } - gpr_log(GPR_INFO, "Shutting down server"); + LOG(INFO) << "Shutting down server"; grpc_server_shutdown_and_notify(server, cq, nullptr); grpc_completion_queue_shutdown(cq); @@ -246,7 +246,7 @@ bool server_ssl_test(const char* alpn_list[], unsigned int alpn_list_len, } } CHECK_GT(sock, 0); - gpr_log(GPR_INFO, "Connected to server on port %d", s.port()); + LOG(INFO) << "Connected to server on port " << s.port(); // Establish a SSL* and connect at SSL layer. SSL* ssl = SSL_new(ctx); @@ -254,10 +254,10 @@ bool server_ssl_test(const char* alpn_list[], unsigned int alpn_list_len, SSL_set_fd(ssl, sock); if (SSL_connect(ssl) <= 0) { ERR_print_errors_fp(stderr); - gpr_log(GPR_ERROR, "Handshake failed."); + LOG(ERROR) << "Handshake failed."; success = false; } else { - gpr_log(GPR_INFO, "Handshake successful."); + LOG(INFO) << "Handshake successful."; // Validate ALPN preferred by server matches alpn_expected. const unsigned char* alpn_selected; unsigned int alpn_selected_len; @@ -265,7 +265,7 @@ bool server_ssl_test(const char* alpn_list[], unsigned int alpn_list_len, if (strlen(alpn_expected) != alpn_selected_len || strncmp(reinterpret_cast(alpn_selected), alpn_expected, alpn_selected_len) != 0) { - gpr_log(GPR_ERROR, "Unexpected ALPN protocol preference"); + LOG(ERROR) << "Unexpected ALPN protocol preference"; success = false; } } diff --git a/test/core/handshake/verify_peer_options.cc b/test/core/handshake/verify_peer_options.cc index b7680cc7897..3e5e2b1590d 100644 --- a/test/core/handshake/verify_peer_options.cc +++ b/test/core/handshake/verify_peer_options.cc @@ -33,13 +33,13 @@ #include #include "absl/log/check.h" +#include "absl/log/log.h" #include "absl/strings/str_cat.h" #include #include #include #include -#include #include "src/core/lib/gprpp/crash.h" #include "src/core/lib/gprpp/thd.h" @@ -89,7 +89,7 @@ static void server_thread(void* arg) { CHECK(ev.type == GRPC_QUEUE_TIMEOUT); } - gpr_log(GPR_INFO, "Shutting down server"); + LOG(INFO) << "Shutting down server"; grpc_server_shutdown_and_notify(server, cq, nullptr); grpc_server_cancel_all_calls(server); grpc_completion_queue_shutdown(cq); diff --git a/test/core/http/httpcli_test_util.cc b/test/core/http/httpcli_test_util.cc index e70c42858d6..f47bb1d61a8 100644 --- a/test/core/http/httpcli_test_util.cc +++ b/test/core/http/httpcli_test_util.cc @@ -23,11 +23,11 @@ #include #include "absl/log/check.h" +#include "absl/log/log.h" #include "absl/strings/str_cat.h" #include "absl/types/optional.h" #include -#include #include #include #include @@ -86,10 +86,10 @@ HttpRequestTestServer StartHttpRequestTestServer(int argc, char** argv, absl::StrCat(root, "/src/core/tsi/test_creds/ca.pem"); ConfigVars::SetOverrides(overrides); } - gpr_log(GPR_INFO, "starting HttpRequest test server subprocess:"); + LOG(INFO) << "starting HttpRequest test server subprocess:"; for (size_t i = 0; i < args.size(); i++) { - gpr_log(GPR_INFO, " HttpRequest test server subprocess argv[%ld]: %s", i, - args[i]); + LOG(INFO) << " HttpRequest test server subprocess argv[" << i + << "]: " << args[i]; } gpr_subprocess* server = gpr_subprocess_create(args.size(), const_cast(args.data())); diff --git a/test/core/load_balancing/lb_policy_test_lib.h b/test/core/load_balancing/lb_policy_test_lib.h index 3c57342e5d4..46e0e7d4fec 100644 --- a/test/core/load_balancing/lb_policy_test_lib.h +++ b/test/core/load_balancing/lb_policy_test_lib.h @@ -36,6 +36,7 @@ #include "absl/base/thread_annotations.h" #include "absl/functional/any_invocable.h" #include "absl/log/check.h" +#include "absl/log/log.h" #include "absl/status/status.h" #include "absl/status/statusor.h" #include "absl/strings/str_format.h" @@ -51,7 +52,6 @@ #include #include #include -#include #include #include "src/core/client_channel/client_channel_internal.h" @@ -152,8 +152,8 @@ class LoadBalancingPolicyTest : public ::testing::Test { void OnConnectivityStateChange(grpc_connectivity_state new_state, const absl::Status& status) override { - gpr_log(GPR_INFO, "notifying watcher: state=%s status=%s", - ConnectivityStateName(new_state), status.ToString().c_str()); + LOG(INFO) << "notifying watcher: state=" + << ConnectivityStateName(new_state) << " status=" << status; watcher_->OnConnectivityStateChange(new_state, status); } @@ -212,11 +212,10 @@ class LoadBalancingPolicyTest : public ::testing::Test { health_watcher_wrapper_ = watcher_wrapper.get(); state_->state_tracker_.AddWatcher(GRPC_CHANNEL_SHUTDOWN, std::move(watcher_wrapper)); - gpr_log(GPR_INFO, - "AddDataWatcher(): added HealthWatch=%p " - "connectivity_watcher=%p watcher_wrapper=%p", - health_watcher_.get(), connectivity_watcher_ptr, - health_watcher_wrapper_); + LOG(INFO) << "AddDataWatcher(): added HealthWatch=" + << health_watcher_.get() + << " connectivity_watcher=" << connectivity_watcher_ptr + << " watcher_wrapper=" << health_watcher_wrapper_; } } @@ -232,10 +231,9 @@ class LoadBalancingPolicyTest : public ::testing::Test { if (health_watcher_.get() != static_cast(watcher)) { return; } - gpr_log(GPR_INFO, - "CancelDataWatcher(): cancelling HealthWatch=%p " - "watcher_wrapper=%p", - health_watcher_.get(), health_watcher_wrapper_); + LOG(INFO) << "CancelDataWatcher(): cancelling HealthWatch=" + << health_watcher_.get() + << " watcher_wrapper=" << health_watcher_wrapper_; state_->state_tracker_.RemoveWatcher(health_watcher_wrapper_); health_watcher_wrapper_ = nullptr; health_watcher_.reset(); @@ -327,18 +325,16 @@ class LoadBalancingPolicyTest : public ::testing::Test { AssertValidConnectivityStateTransition(state_tracker_.state(), state, location); } - gpr_log(GPR_INFO, "Setting state on tracker"); + LOG(INFO) << "Setting state on tracker"; state_tracker_.SetState(state, status, "set from test"); // SetState() enqueued the connectivity state notifications for // the subchannel, so we add another callback to the queue to be // executed after that state notifications has been delivered. - gpr_log(GPR_INFO, - "Waiting for state notifications to be delivered"); + LOG(INFO) << "Waiting for state notifications to be delivered"; test_->work_serializer_->Run( [&]() { - gpr_log(GPR_INFO, - "State notifications delivered, waiting for health " - "notifications"); + LOG(INFO) << "State notifications delivered, waiting for " + "health notifications"; // Now the connectivity state notifications has been // delivered. If the state reported was READY, then the // pick_first leaf policy will have started a health watch, so @@ -351,7 +347,7 @@ class LoadBalancingPolicyTest : public ::testing::Test { }, DEBUG_LOCATION); notification.WaitForNotification(); - gpr_log(GPR_INFO, "Health notifications delivered"); + LOG(INFO) << "Health notifications delivered"; } // Indicates if any of the associated SubchannelInterface objects @@ -472,8 +468,7 @@ class LoadBalancingPolicyTest : public ::testing::Test { << location.file() << ":" << location.line(); if (update == nullptr) return absl::nullopt; StateUpdate result = std::move(*update); - gpr_log(GPR_INFO, "dequeued next state update: %s", - result.ToString().c_str()); + LOG(INFO) << "dequeued next state update: " << result.ToString(); queue_.pop_front(); return std::move(result); } @@ -506,8 +501,8 @@ class LoadBalancingPolicyTest : public ::testing::Test { PickerWrapper(LoadBalancingPolicyTest* test, RefCountedPtr picker) : test_(test), picker_(std::move(picker)) { - gpr_log(GPR_INFO, "creating wrapper %p for picker %p", this, - picker_.get()); + LOG(INFO) << "creating wrapper " << this << " for picker " + << picker_.get(); } void Orphaned() override { @@ -579,8 +574,8 @@ class LoadBalancingPolicyTest : public ::testing::Test { StateUpdate update{ state, status, MakeRefCounted(test_, std::move(picker))}; - gpr_log(GPR_INFO, "enqueuing state update from LB policy: %s", - update.ToString().c_str()); + LOG(INFO) << "enqueuing state update from LB policy: " + << update.ToString(); queue_.push_back(std::move(update)); } @@ -847,14 +842,12 @@ class LoadBalancingPolicyTest : public ::testing::Test { // notifications for the subchannels, so we add another // callback to the queue to be executed after those initial // state notifications have been delivered. - gpr_log(GPR_INFO, - "Applied update, waiting for initial connectivity state " - "notifications"); + LOG(INFO) << "Applied update, waiting for initial connectivity state " + "notifications"; work_serializer_->Run( [&]() { - gpr_log(GPR_INFO, - "Initial connectivity state notifications delivered; " - "waiting for health notifications"); + LOG(INFO) << "Initial connectivity state notifications " + "delivered; waiting for health notifications"; // Now that the initial state notifications have been // delivered, the queue will contain the health watch // notifications for any subchannels in state READY, @@ -868,7 +861,7 @@ class LoadBalancingPolicyTest : public ::testing::Test { }, DEBUG_LOCATION); notification.WaitForNotification(); - gpr_log(GPR_INFO, "health notifications delivered"); + LOG(INFO) << "health notifications delivered"; return status; } @@ -900,15 +893,15 @@ class LoadBalancingPolicyTest : public ::testing::Test { bool WaitForStateUpdate( std::function continue_predicate, SourceLocation location = SourceLocation()) { - gpr_log(GPR_INFO, "==> WaitForStateUpdate()"); + LOG(INFO) << "==> WaitForStateUpdate()"; while (true) { auto update = helper_->GetNextStateUpdate(location); if (!update.has_value()) { - gpr_log(GPR_INFO, "WaitForStateUpdate() returning false"); + LOG(INFO) << "WaitForStateUpdate() returning false"; return false; } if (!continue_predicate(std::move(*update))) { - gpr_log(GPR_INFO, "WaitForStateUpdate() returning true"); + LOG(INFO) << "WaitForStateUpdate() returning true"; return true; } } @@ -945,7 +938,7 @@ class LoadBalancingPolicyTest : public ::testing::Test { // update for state READY, whose picker is returned. RefCountedPtr WaitForConnected( SourceLocation location = SourceLocation()) { - gpr_log(GPR_INFO, "==> WaitForConnected()"); + LOG(INFO) << "==> WaitForConnected()"; RefCountedPtr final_picker; WaitForStateUpdate( [&](FakeHelper::StateUpdate update) { @@ -1022,7 +1015,7 @@ class LoadBalancingPolicyTest : public ::testing::Test { const CallAttributes& call_attributes = {}, size_t num_iterations = 3, SourceLocation location = SourceLocation()) { - gpr_log(GPR_INFO, "Waiting for expected RR addresses..."); + LOG(INFO) << "Waiting for expected RR addresses..."; RefCountedPtr retval; size_t num_picks = std::max(new_addresses.size(), old_addresses.size()) * num_iterations; @@ -1038,7 +1031,7 @@ class LoadBalancingPolicyTest : public ::testing::Test { EXPECT_TRUE(picks.has_value()) << location.file() << ":" << location.line(); if (!picks.has_value()) return false; - gpr_log(GPR_INFO, "PICKS: %s", absl::StrJoin(*picks, " ").c_str()); + LOG(INFO) << "PICKS: " << absl::StrJoin(*picks, " "); // If the picks still match the old list, then keep going. if (PicksAreRoundRobin(old_addresses, *picks)) return true; // Otherwise, the picks should match the new list. @@ -1053,7 +1046,7 @@ class LoadBalancingPolicyTest : public ::testing::Test { return false; // Stop. }, location); - gpr_log(GPR_INFO, "done waiting for expected RR addresses"); + LOG(INFO) << "done waiting for expected RR addresses"; return retval; } @@ -1307,7 +1300,7 @@ class LoadBalancingPolicyTest : public ::testing::Test { RefCountedPtr DrainRoundRobinPickerUpdates(absl::Span addresses, SourceLocation location = SourceLocation()) { - gpr_log(GPR_INFO, "Draining RR picker updates..."); + LOG(INFO) << "Draining RR picker updates..."; RefCountedPtr picker; while (!helper_->QueueEmpty()) { auto update = helper_->GetNextStateUpdate(location); @@ -1322,17 +1315,17 @@ class LoadBalancingPolicyTest : public ::testing::Test { location); picker = std::move(update->picker); } - gpr_log(GPR_INFO, "Done draining RR picker updates"); + LOG(INFO) << "Done draining RR picker updates"; return picker; } // Expects zero or more CONNECTING updates. void DrainConnectingUpdates(SourceLocation location = SourceLocation()) { - gpr_log(GPR_INFO, "Draining CONNECTING updates..."); + LOG(INFO) << "Draining CONNECTING updates..."; while (!helper_->QueueEmpty()) { ASSERT_TRUE(ExpectConnectingUpdate(location)); } - gpr_log(GPR_INFO, "Done draining CONNECTING updates"); + LOG(INFO) << "Done draining CONNECTING updates"; } // Triggers a connection failure for the current address for an @@ -1341,10 +1334,10 @@ class LoadBalancingPolicyTest : public ::testing::Test { absl::Span addresses, size_t current_index, size_t new_index, absl::AnyInvocable expect_after_disconnect, SourceLocation location = SourceLocation()) { - gpr_log(GPR_INFO, - "Expecting endpoint address change: addresses={%s}, " - "current_index=%" PRIuPTR ", new_index=%" PRIuPTR, - absl::StrJoin(addresses, ", ").c_str(), current_index, new_index); + LOG(INFO) << "Expecting endpoint address change: addresses={" + << absl::StrJoin(addresses, ", ") + << "}, current_index=" << current_index + << ", new_index=" << new_index; ASSERT_LT(current_index, addresses.size()); ASSERT_LT(new_index, addresses.size()); // Find all subchannels. @@ -1385,7 +1378,7 @@ class LoadBalancingPolicyTest : public ::testing::Test { // interacts with it again. subchannel->SetConnectivityState(GRPC_CHANNEL_IDLE); } - gpr_log(GPR_INFO, "Done with endpoint address change"); + LOG(INFO) << "Done with endpoint address change"; } // Requests a picker on picker and expects a Fail result. @@ -1451,19 +1444,18 @@ class LoadBalancingPolicyTest : public ::testing::Test { void WaitForWorkSerializerToFlush() { ExecCtx exec_ctx; - gpr_log(GPR_INFO, "waiting for WorkSerializer to flush..."); + LOG(INFO) << "waiting for WorkSerializer to flush..."; absl::Notification notification; work_serializer_->Run([&]() { notification.Notify(); }, DEBUG_LOCATION); notification.WaitForNotification(); - gpr_log(GPR_INFO, "WorkSerializer flush complete"); + LOG(INFO) << "WorkSerializer flush complete"; } void IncrementTimeBy(Duration duration) { ExecCtx exec_ctx; - gpr_log(GPR_INFO, "Incrementing time by %s...", - duration.ToString().c_str()); + LOG(INFO) << "Incrementing time by " << duration; fuzzing_ee_->TickForDuration(duration); - gpr_log(GPR_INFO, "Done incrementing time"); + LOG(INFO) << "Done incrementing time"; // Flush WorkSerializer, in case the timer callback enqueued anything. WaitForWorkSerializerToFlush(); } diff --git a/test/core/load_balancing/outlier_detection_test.cc b/test/core/load_balancing/outlier_detection_test.cc index ba60dce52eb..db425e666fa 100644 --- a/test/core/load_balancing/outlier_detection_test.cc +++ b/test/core/load_balancing/outlier_detection_test.cc @@ -25,6 +25,7 @@ #include #include +#include "absl/log/log.h" #include "absl/status/status.h" #include "absl/strings/string_view.h" #include "absl/types/optional.h" @@ -33,7 +34,6 @@ #include #include -#include #include "src/core/lib/gprpp/orphanable.h" #include "src/core/lib/gprpp/ref_counted_ptr.h" @@ -215,14 +215,14 @@ TEST_F(OutlierDetectionTest, FailurePercentage) { // Expect normal startup. auto picker = ExpectRoundRobinStartup(kAddresses); ASSERT_NE(picker, nullptr); - gpr_log(GPR_INFO, "### RR startup complete"); + LOG(INFO) << "### RR startup complete"; // Do a pick and report a failed call. auto address = DoPickWithFailedCall(picker.get()); ASSERT_TRUE(address.has_value()); - gpr_log(GPR_INFO, "### failed RPC on %s", address->c_str()); + LOG(INFO) << "### failed RPC on " << *address; // Advance time and run the timer callback to trigger ejection. IncrementTimeBy(Duration::Seconds(10)); - gpr_log(GPR_INFO, "### ejection complete"); + LOG(INFO) << "### ejection complete"; // Expect a picker update. std::vector remaining_addresses; for (const auto& addr : kAddresses) { @@ -231,7 +231,7 @@ TEST_F(OutlierDetectionTest, FailurePercentage) { WaitForRoundRobinListChange(kAddresses, remaining_addresses); // Advance time and run the timer callback to trigger un-ejection. IncrementTimeBy(Duration::Seconds(10)); - gpr_log(GPR_INFO, "### un-ejection complete"); + LOG(INFO) << "### un-ejection complete"; // Expect a picker update. WaitForRoundRobinListChange(remaining_addresses, kAddresses); } @@ -265,11 +265,11 @@ TEST_F(OutlierDetectionTest, MultipleAddressesPerEndpoint) { // Expect normal startup. auto picker = ExpectRoundRobinStartup(kEndpoints); ASSERT_NE(picker, nullptr); - gpr_log(GPR_INFO, "### RR startup complete"); + LOG(INFO) << "### RR startup complete"; // Do a pick and report a failed call. auto address = DoPickWithFailedCall(picker.get()); ASSERT_TRUE(address.has_value()); - gpr_log(GPR_INFO, "### failed RPC on %s", address->c_str()); + LOG(INFO) << "### failed RPC on " << *address; // Based on the address that the failed call went to, we determine // which addresses to use in the subsequent steps. absl::Span ejected_endpoint_addresses; @@ -297,12 +297,12 @@ TEST_F(OutlierDetectionTest, MultipleAddressesPerEndpoint) { } // Advance time and run the timer callback to trigger ejection. IncrementTimeBy(Duration::Seconds(10)); - gpr_log(GPR_INFO, "### ejection complete"); + LOG(INFO) << "### ejection complete"; // Expect a picker that removes the ejected address. WaitForRoundRobinListChange( {kEndpoint1Addresses[0], kEndpoint2Addresses[0], kEndpoint3Addresses[0]}, {sentinel_endpoint_addresses[0], unmodified_endpoint_address}); - gpr_log(GPR_INFO, "### ejected endpoint removed"); + LOG(INFO) << "### ejected endpoint removed"; // Cause the connection to the ejected endpoint to fail, and then // have it reconnect to a different address. The endpoint is still // ejected, so the new address should not be used. @@ -312,7 +312,7 @@ TEST_F(OutlierDetectionTest, MultipleAddressesPerEndpoint) { // re-resolution request in the queue. DrainRoundRobinPickerUpdates( {sentinel_endpoint_addresses[0], unmodified_endpoint_address}); - gpr_log(GPR_INFO, "### done changing address of ejected endpoint"); + LOG(INFO) << "### done changing address of ejected endpoint"; // Do the same thing for the sentinel endpoint, so that we // know that the LB policy has seen the address change for the ejected // endpoint. @@ -324,10 +324,10 @@ TEST_F(OutlierDetectionTest, MultipleAddressesPerEndpoint) { WaitForRoundRobinListChange( {unmodified_endpoint_address}, {sentinel_endpoint_addresses[1], unmodified_endpoint_address}); - gpr_log(GPR_INFO, "### done changing address of ejected endpoint"); + LOG(INFO) << "### done changing address of ejected endpoint"; // Advance time and run the timer callback to trigger un-ejection. IncrementTimeBy(Duration::Seconds(10)); - gpr_log(GPR_INFO, "### un-ejection complete"); + LOG(INFO) << "### un-ejection complete"; // The ejected endpoint should come back using the new address. WaitForRoundRobinListChange( {sentinel_endpoint_addresses[1], unmodified_endpoint_address}, @@ -363,11 +363,11 @@ TEST_F(OutlierDetectionTest, EjectionStateResetsWhenEndpointAddressesChange) { // Expect normal startup. auto picker = ExpectRoundRobinStartup(kEndpoints); ASSERT_NE(picker, nullptr); - gpr_log(GPR_INFO, "### RR startup complete"); + LOG(INFO) << "### RR startup complete"; // Do a pick and report a failed call. auto ejected_address = DoPickWithFailedCall(picker.get()); ASSERT_TRUE(ejected_address.has_value()); - gpr_log(GPR_INFO, "### failed RPC on %s", ejected_address->c_str()); + LOG(INFO) << "### failed RPC on " << *ejected_address; // Based on the address that the failed call went to, we determine // which addresses to use in the subsequent steps. std::vector expected_round_robin_while_ejected; @@ -393,12 +393,12 @@ TEST_F(OutlierDetectionTest, EjectionStateResetsWhenEndpointAddressesChange) { } // Advance time and run the timer callback to trigger ejection. IncrementTimeBy(Duration::Seconds(10)); - gpr_log(GPR_INFO, "### ejection complete"); + LOG(INFO) << "### ejection complete"; // Expect a picker that removes the ejected address. WaitForRoundRobinListChange( {kEndpoint1Addresses[0], kEndpoint2Addresses[0], kEndpoint3Addresses[0]}, expected_round_robin_while_ejected); - gpr_log(GPR_INFO, "### ejected endpoint removed"); + LOG(INFO) << "### ejected endpoint removed"; // Send an update that removes the other address from the ejected endpoint. status = ApplyUpdate(BuildUpdate(new_endpoints, kConfig), lb_policy_.get()); EXPECT_TRUE(status.ok()) << status; @@ -447,14 +447,14 @@ TEST_F(OutlierDetectionTest, DoesNotWorkWithPickFirst) { for (size_t i = 0; i < 3; ++i) { EXPECT_EQ(ExpectPickComplete(picker.get()), kAddresses[0]); } - gpr_log(GPR_INFO, "### PF startup complete"); + LOG(INFO) << "### PF startup complete"; // Now have an RPC to that subchannel fail. auto address = DoPickWithFailedCall(picker.get()); ASSERT_TRUE(address.has_value()); - gpr_log(GPR_INFO, "### failed RPC on %s", address->c_str()); + LOG(INFO) << "### failed RPC on " << *address; // Advance time and run the timer callback to trigger ejection. IncrementTimeBy(Duration::Seconds(10)); - gpr_log(GPR_INFO, "### ejection timer pass complete"); + LOG(INFO) << "### ejection timer pass complete"; // Subchannel should not be ejected. ExpectQueueEmpty(); // Subchannel should not see a reconnection request. diff --git a/test/core/load_balancing/weighted_round_robin_test.cc b/test/core/load_balancing/weighted_round_robin_test.cc index 9a5eebba751..58a3be1fa14 100644 --- a/test/core/load_balancing/weighted_round_robin_test.cc +++ b/test/core/load_balancing/weighted_round_robin_test.cc @@ -27,6 +27,7 @@ #include #include +#include "absl/log/log.h" #include "absl/status/status.h" #include "absl/strings/str_join.h" #include "absl/strings/string_view.h" @@ -38,7 +39,6 @@ #include #include -#include #include "src/core/lib/gprpp/debug_location.h" #include "src/core/lib/gprpp/orphanable.h" @@ -98,7 +98,7 @@ class WeightedRoundRobinTest : public LoadBalancingPolicyTest { RefCountedPtr Build() { Json config = Json::FromArray({Json::FromObject( {{"weighted_round_robin", Json::FromObject(json_)}})}); - gpr_log(GPR_INFO, "CONFIG: %s", JsonDump(config).c_str()); + LOG(INFO) << "CONFIG: " << JsonDump(config); return MakeConfig(config); } @@ -247,10 +247,10 @@ class WeightedRoundRobinTest : public LoadBalancingPolicyTest { auto picks = GetCompletePicks(picker, NumPicksNeeded(expected), {}, &subchannel_call_trackers, location); ASSERT_TRUE(picks.has_value()) << location.file() << ":" << location.line(); - gpr_log(GPR_INFO, "PICKS: %s", absl::StrJoin(*picks, " ").c_str()); + LOG(INFO) << "PICKS: " << absl::StrJoin(*picks, " "); ReportBackendMetrics(*picks, subchannel_call_trackers, backend_metrics); auto actual = MakePickMap(*picks); - gpr_log(GPR_INFO, "Pick map: %s", PickMapString(actual).c_str()); + LOG(INFO) << "Pick map: " << PickMapString(actual); EXPECT_EQ(expected, actual) << "Expected: " << PickMapString(expected) << "\nActual: " << PickMapString(actual) << "\nat " << location.file() @@ -265,17 +265,17 @@ class WeightedRoundRobinTest : public LoadBalancingPolicyTest { absl::Duration timeout = absl::Seconds(5), bool run_timer_callbacks = true, SourceLocation location = SourceLocation()) { - gpr_log(GPR_INFO, "==> WaitForWeightedRoundRobinPicks(): Expecting %s", - PickMapString(expected).c_str()); + LOG(INFO) << "==> WaitForWeightedRoundRobinPicks(): Expecting " + << PickMapString(expected); size_t num_picks = NumPicksNeeded(expected); absl::Time deadline = absl::Now() + timeout; while (true) { - gpr_log(GPR_INFO, "TOP OF LOOP"); + LOG(INFO) << "TOP OF LOOP"; // We need to see the expected weights for 3 consecutive passes, just // to make sure we're consistently returning the right weights. size_t num_passes = 0; for (; num_passes < 3; ++num_passes) { - gpr_log(GPR_INFO, "PASS %" PRIuPTR ": DOING PICKS", num_passes); + LOG(INFO) << "PASS " << num_passes << ": DOING PICKS"; std::vector> subchannel_call_trackers; @@ -284,13 +284,13 @@ class WeightedRoundRobinTest : public LoadBalancingPolicyTest { EXPECT_TRUE(picks.has_value()) << location.file() << ":" << location.line(); if (!picks.has_value()) return false; - gpr_log(GPR_INFO, "PICKS: %s", absl::StrJoin(*picks, " ").c_str()); + LOG(INFO) << "PICKS: " << absl::StrJoin(*picks, " "); // Report backend metrics to the LB policy. ReportBackendMetrics(*picks, subchannel_call_trackers, backend_metrics); // Check the observed weights. auto actual = MakePickMap(*picks); - gpr_log(GPR_INFO, "Pick map:\nExpected: %s\n Actual: %s", - PickMapString(expected).c_str(), PickMapString(actual).c_str()); + LOG(INFO) << "Pick map:\nExpected: " << PickMapString(expected) + << "\n Actual: " << PickMapString(actual); if (expected != actual) { // Make sure each address is one of the expected addresses, // even if the weights aren't as expected. @@ -321,7 +321,7 @@ class WeightedRoundRobinTest : public LoadBalancingPolicyTest { << location.file() << ":" << location.line(); if (*picker == nullptr) return false; } else if (run_timer_callbacks) { - gpr_log(GPR_INFO, "running timer callback..."); + LOG(INFO) << "running timer callback..."; // Increment time and run any timer callbacks. IncrementTimeBy(Duration::Seconds(1)); } @@ -1150,7 +1150,7 @@ TEST_F(WeightedRoundRobinTest, MetricValues) { ::testing::Optional(0)); // Advance time to make weights stale and trigger the timer callback // to recompute weights. - gpr_log(GPR_INFO, "advancing time to trigger staleness..."); + LOG(INFO) << "advancing time to trigger staleness..."; IncrementTimeBy(Duration::Seconds(2)); // Picker should now be falling back to round-robin. ExpectWeightedRoundRobinPicks( diff --git a/test/core/load_balancing/xds_override_host_test.cc b/test/core/load_balancing/xds_override_host_test.cc index 0e8f11cc46e..e75581f720e 100644 --- a/test/core/load_balancing/xds_override_host_test.cc +++ b/test/core/load_balancing/xds_override_host_test.cc @@ -23,6 +23,7 @@ #include #include +#include "absl/log/log.h" #include "absl/status/status.h" #include "absl/status/statusor.h" #include "absl/strings/str_join.h" @@ -35,7 +36,6 @@ #include #include -#include #include "src/core/ext/filters/stateful_session/stateful_session_filter.h" #include "src/core/lib/channel/channel_args.h" @@ -295,21 +295,20 @@ TEST_F(XdsOverrideHostTest, auto* address1_attribute = MakeOverrideHostAttribute(kAddresses[1]); ExpectOverridePicks(picker.get(), address1_attribute, kAddresses[1]); // Subchannel for address 1 becomes disconnected. - gpr_log(GPR_INFO, "### subchannel 1 reporting IDLE"); + LOG(INFO) << "### subchannel 1 reporting IDLE"; auto subchannel = FindSubchannel(kAddresses[1]); ASSERT_NE(subchannel, nullptr); subchannel->SetConnectivityState(GRPC_CHANNEL_IDLE); EXPECT_TRUE(subchannel->ConnectionRequested()); - gpr_log(GPR_INFO, "### expecting re-resolution request"); + LOG(INFO) << "### expecting re-resolution request"; ExpectReresolutionRequest(); - gpr_log(GPR_INFO, - "### expecting RR picks to exclude the disconnected subchannel"); + LOG(INFO) << "### expecting RR picks to exclude the disconnected subchannel"; picker = WaitForRoundRobinListChange(kAddresses, {kAddresses[0], kAddresses[2]}); // Picks with the override will be queued. ExpectPickQueued(picker.get(), {address1_attribute}); // The subchannel starts trying to reconnect. - gpr_log(GPR_INFO, "### subchannel 1 reporting CONNECTING"); + LOG(INFO) << "### subchannel 1 reporting CONNECTING"; subchannel->SetConnectivityState(GRPC_CHANNEL_CONNECTING); picker = ExpectState(GRPC_CHANNEL_READY); ASSERT_NE(picker, nullptr); @@ -317,15 +316,15 @@ TEST_F(XdsOverrideHostTest, // Picks with the override will still be queued. ExpectPickQueued(picker.get(), {address1_attribute}); // The connection attempt fails. - gpr_log(GPR_INFO, "### subchannel 1 reporting TRANSIENT_FAILURE"); + LOG(INFO) << "### subchannel 1 reporting TRANSIENT_FAILURE"; subchannel->SetConnectivityState(GRPC_CHANNEL_TRANSIENT_FAILURE, absl::ResourceExhaustedError("Hmmmm")); - gpr_log(GPR_INFO, "### expecting re-resolution request"); + LOG(INFO) << "### expecting re-resolution request"; ExpectReresolutionRequest(); picker = ExpectState(GRPC_CHANNEL_READY); ExpectRoundRobinPicks(picker.get(), {kAddresses[0], kAddresses[2]}); // The host override is not used. - gpr_log(GPR_INFO, "### checking that host override is not used"); + LOG(INFO) << "### checking that host override is not used"; ExpectRoundRobinPicksWithAttribute(picker.get(), address1_attribute, {kAddresses[0], kAddresses[2]}); } @@ -376,7 +375,7 @@ TEST_F(XdsOverrideHostTest, DrainingSubchannelIsConnecting) { // The picker should use the DRAINING host when a call's override // points to that hose, but the host should not be used if there is no // override pointing to it. - gpr_log(GPR_INFO, "### sending update with DRAINING host"); + LOG(INFO) << "### sending update with DRAINING host"; ApplyUpdateWithHealthStatuses({{kAddresses[0], XdsHealthStatus::kUnknown}, {kAddresses[1], XdsHealthStatus::kDraining}, {kAddresses[2], XdsHealthStatus::kHealthy}}, @@ -391,7 +390,7 @@ TEST_F(XdsOverrideHostTest, DrainingSubchannelIsConnecting) { // Now the connection to the draining host gets dropped. // The picker should queue picks where the override host is IDLE. // All picks without an override host should not use this host. - gpr_log(GPR_INFO, "### closing connection to DRAINING host"); + LOG(INFO) << "### closing connection to DRAINING host"; subchannel->SetConnectivityState(GRPC_CHANNEL_IDLE); picker = ExpectState(GRPC_CHANNEL_READY); ExpectPickQueued(picker.get(), {address1_attribute}); @@ -401,7 +400,7 @@ TEST_F(XdsOverrideHostTest, DrainingSubchannelIsConnecting) { // The pick behavior is the same as above: The picker should queue // picks where the override host is CONNECTING. All picks without an // override host should not use this host. - gpr_log(GPR_INFO, "### subchannel starts reconnecting"); + LOG(INFO) << "### subchannel starts reconnecting"; WaitForWorkSerializerToFlush(); EXPECT_TRUE(subchannel->ConnectionRequested()); ExpectQueueEmpty(); @@ -412,7 +411,7 @@ TEST_F(XdsOverrideHostTest, DrainingSubchannelIsConnecting) { // The subchannel now becomes connected again. // Now picks with this override host can be completed again. // Picks without an override host still don't use the draining host. - gpr_log(GPR_INFO, "### subchannel becomes reconnected"); + LOG(INFO) << "### subchannel becomes reconnected"; subchannel->SetConnectivityState(GRPC_CHANNEL_READY); picker = ExpectState(GRPC_CHANNEL_READY); ExpectOverridePicks(picker.get(), address1_attribute, kAddresses[1]); @@ -644,7 +643,7 @@ TEST_F(XdsOverrideHostTest, IdleTimer) { }); const std::array kAddresses = { "ipv4:127.0.0.1:441", "ipv4:127.0.0.1:442", "ipv4:127.0.0.1:443"}; - gpr_log(GPR_INFO, "### sending initial update"); + LOG(INFO) << "### sending initial update"; EXPECT_EQ(UpdateXdsOverrideHostPolicy(kAddresses, {"UNKNOWN", "HEALTHY"}, Duration::Minutes(1)), absl::OkStatus()); @@ -663,7 +662,7 @@ TEST_F(XdsOverrideHostTest, IdleTimer) { ExpectOverridePicks(picker.get(), address2_attribute, kAddresses[2]); // Increment time by 5 seconds and send an update that moves endpoints 1 // and 2 to state DRAINING. - gpr_log(GPR_INFO, "### moving endpoints 1 and 2 to state DRAINING"); + LOG(INFO) << "### moving endpoints 1 and 2 to state DRAINING"; IncrementTimeBy(Duration::Seconds(5)); ApplyUpdateWithHealthStatuses({{kAddresses[0], XdsHealthStatus::kUnknown}, {kAddresses[1], XdsHealthStatus::kDraining}, diff --git a/test/core/network_benchmarks/low_level_ping_pong.cc b/test/core/network_benchmarks/low_level_ping_pong.cc index 69b5228b362..49bd712bb7a 100644 --- a/test/core/network_benchmarks/low_level_ping_pong.cc +++ b/test/core/network_benchmarks/low_level_ping_pong.cc @@ -36,9 +36,9 @@ #include #include "absl/log/check.h" +#include "absl/log/log.h" #include -#include #include #include "src/core/lib/gprpp/strerror.h" @@ -84,8 +84,7 @@ static int read_bytes(int fd, char* buf, size_t read_size, int spin) { if (errno == EAGAIN && spin == 1) { continue; } - gpr_log(GPR_ERROR, "Read failed: %s", - grpc_core::StrError(errno).c_str()); + LOG(ERROR) << "Read failed: " << grpc_core::StrError(errno); return -1; } } else { @@ -118,8 +117,7 @@ static int poll_read_bytes(int fd, char* buf, size_t read_size, int spin) { if (errno == EINTR) { continue; } else { - gpr_log(GPR_ERROR, "Poll failed: %s", - grpc_core::StrError(errno).c_str()); + LOG(ERROR) << "Poll failed: " << grpc_core::StrError(errno); return -1; } } @@ -130,7 +128,7 @@ static int poll_read_bytes(int fd, char* buf, size_t read_size, int spin) { err2 = read(fd, buf + bytes_read, read_size - bytes_read); } while (err2 < 0 && errno == EINTR); if (err2 < 0 && errno != EAGAIN) { - gpr_log(GPR_ERROR, "Read failed: %s", grpc_core::StrError(errno).c_str()); + LOG(ERROR) << "Read failed: " << grpc_core::StrError(errno); return -1; } bytes_read += static_cast(err2); @@ -159,8 +157,7 @@ static int epoll_read_bytes(struct thread_args* args, char* buf, int spin) { err = epoll_wait(args->epoll_fd, &ev, 1, spin ? 0 : -1); if (err < 0) { if (errno == EINTR) continue; - gpr_log(GPR_ERROR, "epoll_wait failed: %s", - grpc_core::StrError(errno).c_str()); + LOG(ERROR) << "epoll_wait failed: " << grpc_core::StrError(errno); return -1; } if (err == 0 && spin) continue; @@ -206,8 +203,7 @@ static int blocking_write_bytes(struct thread_args* args, char* buf) { if (errno == EINTR) { continue; } else { - gpr_log(GPR_ERROR, "Read failed: %s", - grpc_core::StrError(errno).c_str()); + LOG(ERROR) << "Read failed: " << grpc_core::StrError(errno); return -1; } } else { @@ -245,7 +241,7 @@ static int epoll_setup(thread_args* args) { set_socket_nonblocking(args); epoll_fd = epoll_create(1); if (epoll_fd < 0) { - gpr_log(GPR_ERROR, "epoll_create: %s", grpc_core::StrError(errno).c_str()); + LOG(ERROR) << "epoll_create: " << grpc_core::StrError(errno); return -1; } @@ -254,7 +250,7 @@ static int epoll_setup(thread_args* args) { ev.events = EPOLLIN | EPOLLET; ev.data.fd = args->fds.read_fd; if (epoll_ctl(epoll_fd, EPOLL_CTL_ADD, args->fds.read_fd, &ev) < 0) { - gpr_log(GPR_ERROR, "epoll_ctl: %s", grpc_core::StrError(errno).c_str()); + LOG(ERROR) << "epoll_ctl: " << grpc_core::StrError(errno); } return 0; } @@ -263,16 +259,16 @@ static int epoll_setup(thread_args* args) { static void server_thread(thread_args* args) { char* buf = static_cast(gpr_malloc(args->msg_size)); if (args->setup(args) < 0) { - gpr_log(GPR_ERROR, "Setup failed"); + LOG(ERROR) << "Setup failed"; } for (;;) { if (args->read_bytes(args, buf) < 0) { - gpr_log(GPR_ERROR, "Server read failed"); + LOG(ERROR) << "Server read failed"; gpr_free(buf); return; } if (args->write_bytes(args, buf) < 0) { - gpr_log(GPR_ERROR, "Server write failed"); + LOG(ERROR) << "Server write failed"; gpr_free(buf); return; } @@ -287,11 +283,11 @@ static void server_thread_wrap(void* arg) { static void print_histogram(grpc_histogram* histogram) { // TODO(klempner): Print more detailed information, such as detailed histogram // buckets - gpr_log(GPR_INFO, "latency (50/95/99/99.9): %f/%f/%f/%f", - grpc_histogram_percentile(histogram, 50), - grpc_histogram_percentile(histogram, 95), - grpc_histogram_percentile(histogram, 99), - grpc_histogram_percentile(histogram, 99.9)); + LOG(INFO) << "latency (50/95/99/99.9): " + << grpc_histogram_percentile(histogram, 50) << "/" + << grpc_histogram_percentile(histogram, 95) << "/" + << grpc_histogram_percentile(histogram, 99) << "/" + << grpc_histogram_percentile(histogram, 99.9); } static double now(void) { @@ -310,16 +306,16 @@ static void client_thread(thread_args* args) { int i; if (args->setup(args) < 0) { - gpr_log(GPR_ERROR, "Setup failed"); + LOG(ERROR) << "Setup failed"; } for (i = 0; i < kNumIters; ++i) { start_time = now(); if (args->write_bytes(args, buf) < 0) { - gpr_log(GPR_ERROR, "Client write failed"); + LOG(ERROR) << "Client write failed"; goto error; } if (args->read_bytes(args, buf) < 0) { - gpr_log(GPR_ERROR, "Client read failed"); + LOG(ERROR) << "Client read failed"; goto error; } end_time = now(); @@ -338,8 +334,7 @@ error: static int create_listening_socket(struct sockaddr* port, socklen_t len) { int fd = socket(port->sa_family, SOCK_STREAM, 0); if (fd < 0) { - gpr_log(GPR_ERROR, "Unable to create socket: %s", - grpc_core::StrError(errno).c_str()); + LOG(ERROR) << "Unable to create socket: " << grpc_core::StrError(errno); goto error; } @@ -357,17 +352,17 @@ static int create_listening_socket(struct sockaddr* port, socklen_t len) { } if (bind(fd, port, len) < 0) { - gpr_log(GPR_ERROR, "bind: %s", grpc_core::StrError(errno).c_str()); + LOG(ERROR) << "bind: " << grpc_core::StrError(errno); goto error; } if (listen(fd, 1) < 0) { - gpr_log(GPR_ERROR, "listen: %s", grpc_core::StrError(errno).c_str()); + LOG(ERROR) << "listen: " << grpc_core::StrError(errno); goto error; } if (getsockname(fd, port, &len) < 0) { - gpr_log(GPR_ERROR, "getsockname: %s", grpc_core::StrError(errno).c_str()); + LOG(ERROR) << "getsockname: " << grpc_core::StrError(errno); goto error; } @@ -384,8 +379,7 @@ static int connect_client(struct sockaddr* addr, socklen_t len) { int fd = socket(addr->sa_family, SOCK_STREAM, 0); int err; if (fd < 0) { - gpr_log(GPR_ERROR, "Unable to create socket: %s", - grpc_core::StrError(errno).c_str()); + LOG(ERROR) << "Unable to create socket: " << grpc_core::StrError(errno); goto error; } @@ -403,7 +397,7 @@ static int connect_client(struct sockaddr* addr, socklen_t len) { } while (err < 0 && errno == EINTR); if (err < 0) { - gpr_log(GPR_ERROR, "connect error: %s", grpc_core::StrError(errno).c_str()); + LOG(ERROR) << "connect error: " << grpc_core::StrError(errno); goto error; } return fd; @@ -418,7 +412,7 @@ error: static int accept_server(int listen_fd) { int fd = accept(listen_fd, nullptr, nullptr); if (fd < 0) { - gpr_log(GPR_ERROR, "Accept failed: %s", grpc_core::StrError(errno).c_str()); + LOG(ERROR) << "Accept failed: " << grpc_core::StrError(errno); return -1; } return fd; @@ -438,19 +432,19 @@ static int create_sockets_tcp(fd_pair* client_fds, fd_pair* server_fds) { listen_fd = create_listening_socket(sa_port, sizeof(port)); if (listen_fd == -1) { - gpr_log(GPR_ERROR, "Listen failed"); + LOG(ERROR) << "Listen failed"; goto error; } client_fd = connect_client(sa_port, sizeof(port)); if (client_fd == -1) { - gpr_log(GPR_ERROR, "Connect failed"); + LOG(ERROR) << "Connect failed"; goto error; } server_fd = accept_server(listen_fd); if (server_fd == -1) { - gpr_log(GPR_ERROR, "Accept failed"); + LOG(ERROR) << "Accept failed"; goto error; } @@ -477,7 +471,7 @@ error: static int create_sockets_socketpair(fd_pair* client_fds, fd_pair* server_fds) { int fds[2]; if (socketpair(AF_UNIX, SOCK_STREAM, 0, fds) < 0) { - gpr_log(GPR_ERROR, "socketpair: %s", grpc_core::StrError(errno).c_str()); + LOG(ERROR) << "socketpair: " << grpc_core::StrError(errno); return -1; } @@ -492,12 +486,12 @@ static int create_sockets_pipe(fd_pair* client_fds, fd_pair* server_fds) { int cfds[2]; int sfds[2]; if (pipe(cfds) < 0) { - gpr_log(GPR_ERROR, "pipe: %s", grpc_core::StrError(errno).c_str()); + LOG(ERROR) << "pipe: " << grpc_core::StrError(errno); return -1; } if (pipe(sfds) < 0) { - gpr_log(GPR_ERROR, "pipe: %s", grpc_core::StrError(errno).c_str()); + LOG(ERROR) << "pipe: " << grpc_core::StrError(errno); return -1; } @@ -592,8 +586,8 @@ static int run_benchmark(const char* socket_type, thread_args* client_args, return rv; } - gpr_log(GPR_INFO, "Starting test %s %s %zu", client_args->strategy_name, - socket_type, client_args->msg_size); + LOG(INFO) << "Starting test " << client_args->strategy_name << " " + << socket_type << " " << client_args->msg_size; grpc_core::Thread server("server_thread", server_thread_wrap, server_args); server.Start(); @@ -663,7 +657,7 @@ int main(int argc, char** argv) { } if (read_strategy == nullptr) { - gpr_log(GPR_INFO, "No strategy specified, running all benchmarks"); + LOG(INFO) << "No strategy specified, running all benchmarks"; return run_all_benchmarks(static_cast(msg_size)); } diff --git a/test/core/promise/party_test.cc b/test/core/promise/party_test.cc index 077fdfa39d1..3afe59b755d 100644 --- a/test/core/promise/party_test.cc +++ b/test/core/promise/party_test.cc @@ -23,6 +23,7 @@ #include #include "absl/base/thread_annotations.h" +#include "absl/log/log.h" #include "gtest/gtest.h" #include @@ -114,8 +115,7 @@ TYPED_TEST(PartySyncTest, AddAndRemoveParticipant) { participants[slot].exchange(nullptr, std::memory_order_acquire); if (participant == done.get()) run_me = true; if (participant == nullptr) { - gpr_log(GPR_ERROR, - "Participant was null (spurious wakeup observed)"); + LOG(ERROR) << "Participant was null (spurious wakeup observed)"; return false; } participant->store(true, std::memory_order_release); @@ -165,8 +165,7 @@ TYPED_TEST(PartySyncTest, AddAndRemoveTwoParticipants) { participants[slot].exchange(nullptr, std::memory_order_acquire); if (participant == done.get()) run_me++; if (participant == nullptr) { - gpr_log(GPR_ERROR, - "Participant was null (spurious wakeup observed)"); + LOG(ERROR) << "Participant was null (spurious wakeup observed)"; return false; } participant->fetch_sub(1, std::memory_order_release); diff --git a/test/core/slice/slice_test.cc b/test/core/slice/slice_test.cc index f21781ee48d..44c139d8c07 100644 --- a/test/core/slice/slice_test.cc +++ b/test/core/slice/slice_test.cc @@ -28,6 +28,7 @@ #include #include +#include "absl/log/log.h" #include "absl/strings/string_view.h" #include "gtest/gtest.h" @@ -182,7 +183,7 @@ TEST_P(GrpcSliceSizedTest, SliceSplitHeadWorks) { grpc_slice head, tail; size_t i; - gpr_log(GPR_INFO, "length=%" PRIuPTR, length); + LOG(INFO) << "length=" << length; // Create a slice in which each byte is equal to the distance from it to the // beginning of the slice. @@ -211,7 +212,7 @@ TEST_P(GrpcSliceSizedTest, SliceSplitTailWorks) { grpc_slice head, tail; size_t i; - gpr_log(GPR_INFO, "length=%" PRIuPTR, length); + LOG(INFO) << "length=" << length; // Create a slice in which each byte is equal to the distance from it to the // beginning of the slice. diff --git a/test/core/surface/completion_queue_test.cc b/test/core/surface/completion_queue_test.cc index 0cb90259fa0..82dbaed6dd6 100644 --- a/test/core/surface/completion_queue_test.cc +++ b/test/core/surface/completion_queue_test.cc @@ -22,11 +22,11 @@ #include +#include "absl/log/log.h" #include "absl/status/status.h" #include "gtest/gtest.h" #include -#include #include #include @@ -34,7 +34,7 @@ #include "src/core/util/useful.h" #include "test/core/test_util/test_config.h" -#define LOG_TEST(x) gpr_log(GPR_INFO, "%s", x) +#define LOG_TEST(x) LOG(INFO) << x static void* create_test_tag(void) { static intptr_t i = 0; @@ -65,7 +65,7 @@ static void shutdown_and_destroy(grpc_completion_queue* cc) { break; } default: { - gpr_log(GPR_ERROR, "Unknown completion type"); + LOG(ERROR) << "Unknown completion type"; break; } } diff --git a/test/core/surface/completion_queue_threading_test.cc b/test/core/surface/completion_queue_threading_test.cc index 3aebf747c13..ad81f5194f9 100644 --- a/test/core/surface/completion_queue_threading_test.cc +++ b/test/core/surface/completion_queue_threading_test.cc @@ -21,12 +21,12 @@ #include +#include "absl/log/log.h" #include "absl/status/status.h" #include "gtest/gtest.h" #include #include -#include #include #include @@ -37,7 +37,7 @@ #include "src/core/util/useful.h" #include "test/core/test_util/test_config.h" -#define LOG_TEST(x) gpr_log(GPR_INFO, "%s", x) +#define LOG_TEST(x) LOG(INFO) << x static void* create_test_tag(void) { static intptr_t i = 0; @@ -61,7 +61,7 @@ static void shutdown_and_destroy(grpc_completion_queue* cc) { break; } default: { - gpr_log(GPR_ERROR, "Unknown completion type"); + LOG(ERROR) << "Unknown completion type"; break; } } @@ -155,20 +155,20 @@ static void producer_thread(void* arg) { test_thread_options* opt = static_cast(arg); int i; - gpr_log(GPR_INFO, "producer %d started", opt->id); + LOG(INFO) << "producer " << opt->id << " started"; gpr_event_set(&opt->on_started, reinterpret_cast(1)); ASSERT_TRUE(gpr_event_wait(opt->phase1, ten_seconds_time())); - gpr_log(GPR_INFO, "producer %d phase 1", opt->id); + LOG(INFO) << "producer " << opt->id << " phase 1"; for (i = 0; i < TEST_THREAD_EVENTS; i++) { ASSERT_TRUE(grpc_cq_begin_op(opt->cc, (void*)(intptr_t)1)); } - gpr_log(GPR_INFO, "producer %d phase 1 done", opt->id); + LOG(INFO) << "producer " << opt->id << " phase 1 done"; gpr_event_set(&opt->on_phase1_done, reinterpret_cast(1)); ASSERT_TRUE(gpr_event_wait(opt->phase2, ten_seconds_time())); - gpr_log(GPR_INFO, "producer %d phase 2", opt->id); + LOG(INFO) << "producer " << opt->id << " phase 2"; for (i = 0; i < TEST_THREAD_EVENTS; i++) { grpc_core::ExecCtx exec_ctx; grpc_cq_end_op(opt->cc, reinterpret_cast(1), absl::OkStatus(), @@ -178,7 +178,7 @@ static void producer_thread(void* arg) { opt->events_triggered++; } - gpr_log(GPR_INFO, "producer %d phase 2 done", opt->id); + LOG(INFO) << "producer " << opt->id << " phase 2 done"; gpr_event_set(&opt->on_finished, reinterpret_cast(1)); } @@ -186,17 +186,17 @@ static void consumer_thread(void* arg) { test_thread_options* opt = static_cast(arg); grpc_event ev; - gpr_log(GPR_INFO, "consumer %d started", opt->id); + LOG(INFO) << "consumer " << opt->id << " started"; gpr_event_set(&opt->on_started, reinterpret_cast(1)); ASSERT_TRUE(gpr_event_wait(opt->phase1, ten_seconds_time())); - gpr_log(GPR_INFO, "consumer %d phase 1", opt->id); + LOG(INFO) << "consumer " << opt->id << " phase 1"; - gpr_log(GPR_INFO, "consumer %d phase 1 done", opt->id); + LOG(INFO) << "consumer " << opt->id << " phase 1 done"; gpr_event_set(&opt->on_phase1_done, reinterpret_cast(1)); ASSERT_TRUE(gpr_event_wait(opt->phase2, ten_seconds_time())); - gpr_log(GPR_INFO, "consumer %d phase 2", opt->id); + LOG(INFO) << "consumer " << opt->id << " phase 2"; for (;;) { ev = grpc_completion_queue_next( opt->cc, gpr_inf_future(GPR_CLOCK_MONOTONIC), nullptr); @@ -206,7 +206,7 @@ static void consumer_thread(void* arg) { opt->events_triggered++; break; case GRPC_QUEUE_SHUTDOWN: - gpr_log(GPR_INFO, "consumer %d phase 2 done", opt->id); + LOG(INFO) << "consumer " << opt->id << " phase 2 done"; gpr_event_set(&opt->on_finished, reinterpret_cast(1)); return; case GRPC_QUEUE_TIMEOUT: @@ -225,8 +225,8 @@ static void test_threading(size_t producers, size_t consumers) { size_t total_consumed = 0; static int optid = 101; - gpr_log(GPR_INFO, "%s: %" PRIuPTR " producers, %" PRIuPTR " consumers", - "test_threading", producers, consumers); + LOG(INFO) << "test_threading: " << producers << " producers, " << consumers + << " consumers"; // start all threads: they will wait for phase1 grpc_core::Thread* threads = static_cast( @@ -252,17 +252,17 @@ static void test_threading(size_t producers, size_t consumers) { // start phase1: producers will pre-declare all operations they will // complete - gpr_log(GPR_INFO, "start phase 1"); + LOG(INFO) << "start phase 1"; gpr_event_set(&phase1, reinterpret_cast(1)); - gpr_log(GPR_INFO, "wait phase 1"); + LOG(INFO) << "wait phase 1"; for (i = 0; i < producers + consumers; i++) { ASSERT_TRUE(gpr_event_wait(&options[i].on_phase1_done, ten_seconds_time())); } - gpr_log(GPR_INFO, "done phase 1"); + LOG(INFO) << "done phase 1"; // start phase2: operations will complete, and consumers will consume them - gpr_log(GPR_INFO, "start phase 2"); + LOG(INFO) << "start phase 2"; gpr_event_set(&phase2, reinterpret_cast(1)); // in parallel, we shutdown the completion channel - all events should still @@ -270,11 +270,11 @@ static void test_threading(size_t producers, size_t consumers) { grpc_completion_queue_shutdown(cc); // join all threads - gpr_log(GPR_INFO, "wait phase 2"); + LOG(INFO) << "wait phase 2"; for (i = 0; i < producers + consumers; i++) { ASSERT_TRUE(gpr_event_wait(&options[i].on_finished, ten_seconds_time())); } - gpr_log(GPR_INFO, "done phase 2"); + LOG(INFO) << "done phase 2"; // destroy the completion channel grpc_completion_queue_destroy(cc); diff --git a/test/core/surface/concurrent_connectivity_test.cc b/test/core/surface/concurrent_connectivity_test.cc index 090d0ba1f5a..33bc43d2752 100644 --- a/test/core/surface/concurrent_connectivity_test.cc +++ b/test/core/surface/concurrent_connectivity_test.cc @@ -23,6 +23,7 @@ #include #include +#include "absl/log/log.h" #include "absl/strings/str_cat.h" #include "gtest/gtest.h" @@ -30,7 +31,6 @@ #include #include #include -#include #include #include @@ -192,7 +192,7 @@ TEST(ConcurrentConnectivityTest, RunConcurrentConnectivityTest) { // First round, no server { - gpr_log(GPR_DEBUG, "Wave 1"); + VLOG(2) << "Wave 1"; grpc_core::Thread threads[NUM_THREADS]; args.addr = "localhost:54321"; for (auto& th : threads) { @@ -207,7 +207,7 @@ TEST(ConcurrentConnectivityTest, RunConcurrentConnectivityTest) { // Second round, actual grpc server { - gpr_log(GPR_DEBUG, "Wave 2"); + VLOG(2) << "Wave 2"; int port = grpc_pick_unused_port_or_die(); args.addr = absl::StrCat("localhost:", port); args.server = grpc_server_create(nullptr, nullptr); @@ -239,7 +239,7 @@ TEST(ConcurrentConnectivityTest, RunConcurrentConnectivityTest) { // Third round, bogus tcp server { - gpr_log(GPR_DEBUG, "Wave 3"); + VLOG(2) << "Wave 3"; auto* pollset = static_cast(gpr_zalloc(grpc_pollset_size())); grpc_pollset_init(pollset, &args.mu); args.pollset.push_back(pollset); diff --git a/test/core/test_util/cmdline.h b/test/core/test_util/cmdline.h index 4be2fa6dbad..d118d6a9412 100644 --- a/test/core/test_util/cmdline.h +++ b/test/core/test_util/cmdline.h @@ -21,6 +21,8 @@ #include +#include "absl/log/log.h" + #include /// Simple command line parser. @@ -43,7 +45,7 @@ /// gpr_cmdline_destroy(cl); /// if (verbose) { -/// gpr_log(GPR_INFO, "Goodbye cruel world!"); +/// LOG(INFO) << "Goodbye cruel world!"; /// } /// return 0; diff --git a/test/core/test_util/reconnect_server.cc b/test/core/test_util/reconnect_server.cc index 036ee3d1e52..68031263f52 100644 --- a/test/core/test_util/reconnect_server.cc +++ b/test/core/test_util/reconnect_server.cc @@ -20,10 +20,10 @@ #include +#include "absl/log/log.h" #include "absl/strings/string_view.h" #include -#include #include #include "src/core/lib/iomgr/endpoint.h" @@ -37,14 +37,14 @@ static void pretty_print_backoffs(reconnect_server* server) { int i = 1; double expected_backoff = 1000.0, backoff; timestamp_list* head = server->head; - gpr_log(GPR_INFO, "reconnect server: new connection"); + LOG(INFO) << "reconnect server: new connection"; for (head = server->head; head && head->next; head = head->next, i++) { diff = gpr_time_sub(head->next->timestamp, head->timestamp); backoff = gpr_time_to_millis(diff); - gpr_log(GPR_INFO, - "retry %2d:backoff %6.2fs,expected backoff %6.2fs, jitter %4.2f%%", - i, backoff / 1000.0, expected_backoff / 1000.0, - (backoff - expected_backoff) * 100.0 / expected_backoff); + LOG(INFO) << absl::StrFormat( + "retry %2d:backoff %6.2fs,expected backoff %6.2fs, jitter %4.2f%%", i, + backoff / 1000.0, expected_backoff / 1000.0, + (backoff - expected_backoff) * 100.0 / expected_backoff); expected_backoff *= 1.6; int max_reconnect_backoff_ms = 120 * 1000; if (server->max_reconnect_backoff_ms > 0) { @@ -73,11 +73,10 @@ static void on_connect(void* arg, grpc_endpoint* tcp, server->peer = new std::string(peer); } else { if (last_colon == std::string::npos) { - gpr_log(GPR_ERROR, "peer does not contain a ':'"); + LOG(ERROR) << "peer does not contain a ':'"; } else if (peer.compare(0, static_cast(last_colon), *server->peer) != 0) { - gpr_log(GPR_ERROR, "mismatched peer! %s vs %s", server->peer->c_str(), - std::string(peer).c_str()); + LOG(ERROR) << "mismatched peer! " << *server->peer << " vs " << peer; } } new_tail = static_cast(gpr_malloc(sizeof(timestamp_list))); diff --git a/test/core/test_util/test_config.cc b/test/core/test_util/test_config.cc index 11c74d2a36c..b816f5f1b10 100644 --- a/test/core/test_util/test_config.cc +++ b/test/core/test_util/test_config.cc @@ -22,6 +22,7 @@ #include #include "absl/debugging/failure_signal_handler.h" +#include "absl/log/log.h" #include "absl/status/status.h" #include "absl/strings/match.h" #include "absl/strings/str_format.h" @@ -126,11 +127,11 @@ void grpc_test_init(int* argc, char** argv) { grpc_core::testing::InitializeStackTracer(argv[0]); absl::FailureSignalHandlerOptions options; absl::InstallFailureSignalHandler(options); - gpr_log(GPR_DEBUG, - "test slowdown factor: sanitizer=%" PRId64 ", fixture=%" PRId64 - ", poller=%" PRId64 ", total=%" PRId64, - grpc_test_sanitizer_slowdown_factor(), g_fixture_slowdown_factor, - g_poller_slowdown_factor, grpc_test_slowdown_factor()); + VLOG(2) << "test slowdown factor: sanitizer=" + << grpc_test_sanitizer_slowdown_factor() + << ", fixture=" << g_fixture_slowdown_factor + << ", poller=" << g_poller_slowdown_factor + << ", total=" << grpc_test_slowdown_factor(); // seed rng with pid, so we don't end up with the same random numbers as a // concurrently running test binary srand(seed()); @@ -160,7 +161,7 @@ TestEnvironment::~TestEnvironment() { // This will wait until gRPC shutdown has actually happened to make sure // no gRPC resources (such as thread) are active. (timeout = 10s) if (!grpc_wait_until_shutdown(10)) { - gpr_log(GPR_ERROR, "Timeout in waiting for gRPC shutdown"); + LOG(ERROR) << "Timeout in waiting for gRPC shutdown"; } if (BuiltUnderMsan()) { // This is a workaround for MSAN. MSAN doesn't like having shutdown thread @@ -171,7 +172,7 @@ TestEnvironment::~TestEnvironment() { gpr_sleep_until(gpr_time_add(gpr_now(GPR_CLOCK_REALTIME), gpr_time_from_millis(500, GPR_TIMESPAN))); } - gpr_log(GPR_INFO, "TestEnvironment ends"); + LOG(INFO) << "TestEnvironment ends"; } TestGrpcScope::TestGrpcScope() { grpc_init(); } @@ -179,7 +180,7 @@ TestGrpcScope::TestGrpcScope() { grpc_init(); } TestGrpcScope::~TestGrpcScope() { grpc_shutdown(); if (!grpc_wait_until_shutdown(10)) { - gpr_log(GPR_ERROR, "Timeout in waiting for gRPC shutdown"); + LOG(ERROR) << "Timeout in waiting for gRPC shutdown"; } } diff --git a/test/core/tsi/alts/fake_handshaker/fake_handshaker_server.cc b/test/core/tsi/alts/fake_handshaker/fake_handshaker_server.cc index a333fd85417..e7f58d93c94 100644 --- a/test/core/tsi/alts/fake_handshaker/fake_handshaker_server.cc +++ b/test/core/tsi/alts/fake_handshaker/fake_handshaker_server.cc @@ -22,10 +22,10 @@ #include #include "absl/log/check.h" +#include "absl/log/log.h" #include "absl/strings/str_format.h" #include -#include #include #include #include @@ -69,7 +69,7 @@ class FakeHandshakerService : public HandshakerService::Service { HandshakerContext context; HandshakerReq request; HandshakerResp response; - gpr_log(GPR_DEBUG, "Start a new handshake."); + VLOG(2) << "Start a new handshake."; while (stream->Read(&request)) { status = ProcessRequest(&context, request, &response); if (!status.ok()) return WriteErrorResponse(stream, status); @@ -101,13 +101,13 @@ class FakeHandshakerService : public HandshakerService::Service { CHECK_NE(response, nullptr); response->Clear(); if (request.has_client_start()) { - gpr_log(GPR_DEBUG, "Process client start request."); + VLOG(2) << "Process client start request."; return ProcessClientStart(context, request.client_start(), response); } else if (request.has_server_start()) { - gpr_log(GPR_DEBUG, "Process server start request."); + VLOG(2) << "Process server start request."; return ProcessServerStart(context, request.server_start(), response); } else if (request.has_next()) { - gpr_log(GPR_DEBUG, "Process next request."); + VLOG(2) << "Process next request."; return ProcessNext(context, request.next(), response); } return Status(StatusCode::INVALID_ARGUMENT, "Request is empty."); diff --git a/test/core/tsi/alts/handshaker/alts_concurrent_connectivity_test.cc b/test/core/tsi/alts/handshaker/alts_concurrent_connectivity_test.cc index 1b9bbe894dd..65a32533d42 100644 --- a/test/core/tsi/alts/handshaker/alts_concurrent_connectivity_test.cc +++ b/test/core/tsi/alts/handshaker/alts_concurrent_connectivity_test.cc @@ -32,6 +32,7 @@ #include #include "absl/log/check.h" +#include "absl/log/log.h" #include "absl/memory/memory.h" #include "absl/strings/str_cat.h" @@ -40,7 +41,6 @@ #include #include #include -#include #include #include #include @@ -113,8 +113,7 @@ class FakeHandshakeServer { // TODO(apolcyn): when removing the global concurrent handshake limiting // queue, set MAX_CONCURRENT_STREAMS on this server. server_ = builder.BuildAndStart(); - gpr_log(GPR_INFO, "Fake handshaker server listening on %s", - address_.c_str()); + LOG(INFO) << "Fake handshaker server listening on " << address_; } ~FakeHandshakeServer() { @@ -148,13 +147,12 @@ class TestServer { server_creds)); grpc_server_credentials_release(server_creds); grpc_server_start(server_); - gpr_log(GPR_DEBUG, "Start TestServer %p. listen on %s", this, - server_addr_.c_str()); + VLOG(2) << "Start TestServer " << this << ". listen on " << server_addr_; server_thd_ = std::make_unique(PollUntilShutdown, this); } ~TestServer() { - gpr_log(GPR_DEBUG, "Begin dtor of TestServer %p", this); + VLOG(2) << "Begin dtor of TestServer " << this; grpc_server_shutdown_and_notify(server_, server_cq_, this); server_thd_->join(); grpc_server_destroy(server_); @@ -170,7 +168,7 @@ class TestServer { self->server_cq_, gpr_inf_future(GPR_CLOCK_REALTIME), nullptr); CHECK(ev.type == GRPC_OP_COMPLETE); CHECK(ev.tag == self); - gpr_log(GPR_DEBUG, "TestServer %p stop polling", self); + VLOG(2) << "TestServer " << self << " stop polling"; } private: @@ -210,7 +208,7 @@ class ConnectLoopRunner { static void ConnectLoop(const ConnectLoopRunner* self) { for (size_t i = 0; i < self->loops_; i++) { - gpr_log(GPR_DEBUG, "runner:%p connect_loop begin loop %ld", self, i); + VLOG(2) << "runner:" << self << " connect_loop begin loop " << i; grpc_completion_queue* cq = grpc_completion_queue_create_for_next(nullptr); grpc_channel* channel = create_secure_channel_for_test( @@ -259,7 +257,7 @@ class ConnectLoopRunner { grpc_completion_queue_shutdown(cq); drain_cq(cq); grpc_completion_queue_destroy(cq); - gpr_log(GPR_DEBUG, "runner:%p connect_loop finished loop %ld", self, i); + VLOG(2) << "runner:" << self << " connect_loop finished loop " << i; } } @@ -296,8 +294,7 @@ TEST(AltsConcurrentConnectivityTest, TestConcurrentClientServerHandshakes) { TestServer test_server; size_t num_concurrent_connects = 50; std::vector> connect_loop_runners; - gpr_log(GPR_DEBUG, - "start performing concurrent expected-to-succeed connects"); + VLOG(2) << "start performing concurrent expected-to-succeed connects"; for (size_t i = 0; i < num_concurrent_connects; i++) { connect_loop_runners.push_back(std::make_unique( test_server.address(), fake_handshake_server.address(), @@ -306,8 +303,7 @@ TEST(AltsConcurrentConnectivityTest, TestConcurrentClientServerHandshakes) { 0 /* reconnect_backoff_ms unset */)); } connect_loop_runners.clear(); - gpr_log(GPR_DEBUG, - "done performing concurrent expected-to-succeed connects"); + VLOG(2) << "done performing concurrent expected-to-succeed connects"; } } @@ -336,7 +332,7 @@ TEST(AltsConcurrentConnectivityTest, { std::vector> connect_loop_runners; size_t num_concurrent_connects = 100; - gpr_log(GPR_DEBUG, "start performing concurrent expected-to-fail connects"); + VLOG(2) << "start performing concurrent expected-to-fail connects"; for (size_t i = 0; i < num_concurrent_connects; i++) { connect_loop_runners.push_back(std::make_unique( fake_backend_server.address(), fake_handshake_server.address(), @@ -345,7 +341,7 @@ TEST(AltsConcurrentConnectivityTest, 0 /* reconnect_backoff_ms unset */)); } connect_loop_runners.clear(); - gpr_log(GPR_DEBUG, "done performing concurrent expected-to-fail connects"); + VLOG(2) << "done performing concurrent expected-to-fail connects"; } } @@ -368,7 +364,7 @@ TEST(AltsConcurrentConnectivityTest, { std::vector> connect_loop_runners; size_t num_concurrent_connects = 100; - gpr_log(GPR_DEBUG, "start performing concurrent expected-to-fail connects"); + VLOG(2) << "start performing concurrent expected-to-fail connects"; for (size_t i = 0; i < num_concurrent_connects; i++) { connect_loop_runners.push_back(std::make_unique( fake_backend_server.address(), fake_handshake_server.address(), @@ -377,7 +373,7 @@ TEST(AltsConcurrentConnectivityTest, 0 /* reconnect_backoff_ms unset */)); } connect_loop_runners.clear(); - gpr_log(GPR_DEBUG, "done performing concurrent expected-to-fail connects"); + VLOG(2) << "done performing concurrent expected-to-fail connects"; } } @@ -400,7 +396,7 @@ TEST(AltsConcurrentConnectivityTest, { std::vector> connect_loop_runners; size_t num_concurrent_connects = 100; - gpr_log(GPR_DEBUG, "start performing concurrent expected-to-fail connects"); + VLOG(2) << "start performing concurrent expected-to-fail connects"; for (size_t i = 0; i < num_concurrent_connects; i++) { connect_loop_runners.push_back(std::make_unique( fake_backend_server.address(), fake_handshake_server.address(), @@ -409,7 +405,7 @@ TEST(AltsConcurrentConnectivityTest, 100 /* reconnect_backoff_ms */)); } connect_loop_runners.clear(); - gpr_log(GPR_DEBUG, "done performing concurrent expected-to-fail connects"); + VLOG(2) << "done performing concurrent expected-to-fail connects"; } } diff --git a/test/core/tsi/alts/handshaker/alts_handshaker_service_api_test_lib.cc b/test/core/tsi/alts/handshaker/alts_handshaker_service_api_test_lib.cc index dbf65518e56..1afa79ca951 100644 --- a/test/core/tsi/alts/handshaker/alts_handshaker_service_api_test_lib.cc +++ b/test/core/tsi/alts/handshaker/alts_handshaker_service_api_test_lib.cc @@ -18,13 +18,14 @@ #include "test/core/tsi/alts/handshaker/alts_handshaker_service_api_test_lib.h" +#include "absl/log/log.h" + bool grpc_gcp_handshaker_resp_set_peer_rpc_versions( grpc_gcp_HandshakerResp* resp, upb_Arena* arena, uint32_t max_major, uint32_t max_minor, uint32_t min_major, uint32_t min_minor) { if (resp == nullptr) { - gpr_log(GPR_ERROR, - "Invalid nullptr argument to " - "grpc_gcp_handshaker_resp_set_peer_rpc_versions()."); + LOG(ERROR) << "Invalid nullptr argument to " + "grpc_gcp_handshaker_resp_set_peer_rpc_versions()."; return false; } grpc_gcp_rpc_protocol_versions versions; @@ -50,7 +51,7 @@ grpc_gcp_HandshakerReq* grpc_gcp_handshaker_req_decode(grpc_slice slice, grpc_gcp_HandshakerReq* resp = grpc_gcp_HandshakerReq_parse( reinterpret_cast(buf), buf_size, arena); if (!resp) { - gpr_log(GPR_ERROR, "grpc_gcp_HandshakerReq decode error"); + LOG(ERROR) << "grpc_gcp_HandshakerReq decode error"; return nullptr; } return resp; diff --git a/test/core/tsi/ssl_transport_security_test.cc b/test/core/tsi/ssl_transport_security_test.cc index ff1e0dcfa58..a66720e0ca0 100644 --- a/test/core/tsi/ssl_transport_security_test.cc +++ b/test/core/tsi/ssl_transport_security_test.cc @@ -27,11 +27,11 @@ #include #include +#include "absl/log/log.h" #include "absl/strings/str_cat.h" #include #include -#include #include #include "src/core/lib/gprpp/memory.h" @@ -710,7 +710,7 @@ INSTANTIATE_TEST_SUITE_P( }); TEST_P(SslTransportSecurityTest, DoHandshakeTinyHandshakeBuffer) { - gpr_log(GPR_INFO, "ssl_tsi_test_do_handshake_tiny_handshake_buffer"); + LOG(INFO) << "ssl_tsi_test_do_handshake_tiny_handshake_buffer"; SetUpSslFixture(/*tls_version=*/std::get<0>(GetParam()), /*send_client_ca_list=*/std::get<1>(GetParam())); ssl_tsi_test_fixture_->handshake_buffer_size = @@ -722,7 +722,7 @@ TEST_P(SslTransportSecurityTest, DoHandshakeTinyHandshakeBuffer) { } TEST_P(SslTransportSecurityTest, DoHandshakeSmallHandshakeBuffer) { - gpr_log(GPR_INFO, "ssl_tsi_test_do_handshake_small_handshake_buffer"); + LOG(INFO) << "ssl_tsi_test_do_handshake_small_handshake_buffer"; SetUpSslFixture(/*tls_version=*/std::get<0>(GetParam()), /*send_client_ca_list=*/std::get<1>(GetParam())); ssl_tsi_test_fixture_->handshake_buffer_size = @@ -731,14 +731,14 @@ TEST_P(SslTransportSecurityTest, DoHandshakeSmallHandshakeBuffer) { } TEST_P(SslTransportSecurityTest, DoHandshake) { - gpr_log(GPR_INFO, "ssl_tsi_test_do_handshake"); + LOG(INFO) << "ssl_tsi_test_do_handshake"; SetUpSslFixture(/*tls_version=*/std::get<0>(GetParam()), /*send_client_ca_list=*/std::get<1>(GetParam())); DoHandshake(); } TEST_P(SslTransportSecurityTest, DoHandshakeWithRootStore) { - gpr_log(GPR_INFO, "ssl_tsi_test_do_handshake_with_root_store"); + LOG(INFO) << "ssl_tsi_test_do_handshake_with_root_store"; SetUpSslFixture(/*tls_version=*/std::get<0>(GetParam()), /*send_client_ca_list=*/std::get<1>(GetParam())); ssl_fixture_->MutableKeyCertLib()->use_root_store = true; @@ -749,8 +749,8 @@ TEST_P(SslTransportSecurityTest, DoHandshakeWithRootStore) { #if OPENSSL_VERSION_NUMBER >= 0x10100000 TEST_P(SslTransportSecurityTest, DoHandshakeSkippingServerCertificateVerification) { - gpr_log(GPR_INFO, - "ssl_tsi_test_do_handshake_skipping_server_certificate_verification"); + LOG(INFO) + << "ssl_tsi_test_do_handshake_skipping_server_certificate_verification"; SetUpSslFixture(/*tls_version=*/std::get<0>(GetParam()), /*send_client_ca_list=*/std::get<1>(GetParam())); ssl_fixture_->SetVerifyRootCertSubject(false); @@ -763,8 +763,7 @@ TEST_P(SslTransportSecurityTest, #endif TEST_P(SslTransportSecurityTest, DoHandshakeWithLargeServerHandshakeMessages) { - gpr_log(GPR_INFO, - "ssl_tsi_test_do_handshake_with_large_server_handshake_messages"); + LOG(INFO) << "ssl_tsi_test_do_handshake_with_large_server_handshake_messages"; std::string trust_bundle = GenerateTrustBundle(); SetUpSslFixture(/*tls_version=*/std::get<0>(GetParam()), /*send_client_ca_list=*/std::get<1>(GetParam())); @@ -792,7 +791,7 @@ TEST_P(SslTransportSecurityTest, DoHandshakeWithLargeServerHandshakeMessages) { } TEST_P(SslTransportSecurityTest, DoHandshakeWithClientAuthentication) { - gpr_log(GPR_INFO, "ssl_tsi_test_do_handshake_with_client_authentication"); + LOG(INFO) << "ssl_tsi_test_do_handshake_with_client_authentication"; SetUpSslFixture(/*tls_version=*/std::get<0>(GetParam()), /*send_client_ca_list=*/std::get<1>(GetParam())); ssl_fixture_->SetForceClientAuth(true); @@ -801,9 +800,8 @@ TEST_P(SslTransportSecurityTest, DoHandshakeWithClientAuthentication) { TEST_P(SslTransportSecurityTest, DoHandshakeWithClientAuthenticationAndRootStore) { - gpr_log( - GPR_INFO, - "ssl_tsi_test_do_handshake_with_client_authentication_and_root_store"); + LOG(INFO) + << "ssl_tsi_test_do_handshake_with_client_authentication_and_root_store"; SetUpSslFixture(/*tls_version=*/std::get<0>(GetParam()), /*send_client_ca_list=*/std::get<1>(GetParam())); ssl_fixture_->SetForceClientAuth(true); @@ -813,8 +811,8 @@ TEST_P(SslTransportSecurityTest, TEST_P(SslTransportSecurityTest, DoHandshakeWithServerNameIndicationExactDomain) { - gpr_log(GPR_INFO, - "ssl_tsi_test_do_handshake_with_server_name_indication_exact_domain"); + LOG(INFO) + << "ssl_tsi_test_do_handshake_with_server_name_indication_exact_domain"; SetUpSslFixture(/*tls_version=*/std::get<0>(GetParam()), /*send_client_ca_list=*/std::get<1>(GetParam())); // server1 cert contains "waterzooi.test.google.be" in SAN. @@ -825,9 +823,8 @@ TEST_P(SslTransportSecurityTest, TEST_P(SslTransportSecurityTest, DoHandshakeWithServerNameIndicationWildStarDomain) { - gpr_log( - GPR_INFO, - "ssl_tsi_test_do_handshake_with_server_name_indication_wild_star_domain"); + LOG(INFO) << "ssl_tsi_test_do_handshake_with_server_name_indication_wild_" + "star_domain"; SetUpSslFixture(/*tls_version=*/std::get<0>(GetParam()), /*send_client_ca_list=*/std::get<1>(GetParam())); // server1 cert contains "*.test.google.fr" in SAN. @@ -837,8 +834,7 @@ TEST_P(SslTransportSecurityTest, } TEST_P(SslTransportSecurityTest, DoHandshakeWithWrongServerNameIndication) { - gpr_log(GPR_INFO, - "ssl_tsi_test_do_handshake_with_wrong_server_name_indication"); + LOG(INFO) << "ssl_tsi_test_do_handshake_with_wrong_server_name_indication"; SetUpSslFixture(/*tls_version=*/std::get<0>(GetParam()), /*send_client_ca_list=*/std::get<1>(GetParam())); // server certs do not contain "test.google.cn". @@ -849,9 +845,8 @@ TEST_P(SslTransportSecurityTest, DoHandshakeWithWrongServerNameIndication) { TEST_P(SslTransportSecurityTest, DoHandshakeWithInvalidAndIgnoredServerNameIndication) { - gpr_log(GPR_INFO, - "ssl_tsi_test_do_handshake_with_invalid_and_ignored_server_name_" - "indication"); + LOG(INFO) << "ssl_tsi_test_do_handshake_with_invalid_and_ignored_server_name_" + "indication"; SetUpSslFixture(/*tls_version=*/std::get<0>(GetParam()), /*send_client_ca_list=*/std::get<1>(GetParam())); // SNI that's an IP address will be ignored. @@ -861,7 +856,7 @@ TEST_P(SslTransportSecurityTest, } TEST_P(SslTransportSecurityTest, DoHandshakeWithBadServerCert) { - gpr_log(GPR_INFO, "ssl_tsi_test_do_handshake_with_bad_server_cert"); + LOG(INFO) << "ssl_tsi_test_do_handshake_with_bad_server_cert"; SetUpSslFixture(/*tls_version=*/std::get<0>(GetParam()), /*send_client_ca_list=*/std::get<1>(GetParam())); ssl_fixture_->MutableKeyCertLib()->use_bad_server_cert = true; @@ -869,7 +864,7 @@ TEST_P(SslTransportSecurityTest, DoHandshakeWithBadServerCert) { } TEST_P(SslTransportSecurityTest, DoHandshakeWithBadClientCert) { - gpr_log(GPR_INFO, "ssl_tsi_test_do_handshake_with_bad_client_cert"); + LOG(INFO) << "ssl_tsi_test_do_handshake_with_bad_client_cert"; SetUpSslFixture(/*tls_version=*/std::get<0>(GetParam()), /*send_client_ca_list=*/std::get<1>(GetParam())); ssl_fixture_->MutableKeyCertLib()->use_bad_client_cert = true; @@ -880,7 +875,7 @@ TEST_P(SslTransportSecurityTest, DoHandshakeWithBadClientCert) { #ifdef OPENSSL_IS_BORINGSSL // BoringSSL and OpenSSL have different behaviors on mismatched ALPN. TEST_P(SslTransportSecurityTest, DoHandshakeAlpnClientNoServer) { - gpr_log(GPR_INFO, "ssl_tsi_test_do_handshake_alpn_client_no_server"); + LOG(INFO) << "ssl_tsi_test_do_handshake_alpn_client_no_server"; SetUpSslFixture(/*tls_version=*/std::get<0>(GetParam()), /*send_client_ca_list=*/std::get<1>(GetParam())); ssl_fixture_->SetAlpnMode(ALPN_CLIENT_NO_SERVER); @@ -888,7 +883,7 @@ TEST_P(SslTransportSecurityTest, DoHandshakeAlpnClientNoServer) { } TEST_P(SslTransportSecurityTest, DoHandshakeAlpnClientServerMismatch) { - gpr_log(GPR_INFO, "ssl_tsi_test_do_handshake_alpn_client_server_mismatch"); + LOG(INFO) << "ssl_tsi_test_do_handshake_alpn_client_server_mismatch"; SetUpSslFixture(/*tls_version=*/std::get<0>(GetParam()), /*send_client_ca_list=*/std::get<1>(GetParam())); ssl_fixture_->SetAlpnMode(ALPN_CLIENT_SERVER_MISMATCH); @@ -896,7 +891,7 @@ TEST_P(SslTransportSecurityTest, DoHandshakeAlpnClientServerMismatch) { } TEST_P(SslTransportSecurityTest, DoRoundTripForAllConfigs) { - gpr_log(GPR_INFO, "ssl_tsi_test_do_round_trip_for_all_configs"); + LOG(INFO) << "ssl_tsi_test_do_round_trip_for_all_configs"; unsigned int* bit_array = static_cast( gpr_zalloc(sizeof(unsigned int) * TSI_TEST_NUM_OF_ARGUMENTS)); const unsigned int mask = 1U << (TSI_TEST_NUM_OF_ARGUMENTS - 1); @@ -919,7 +914,7 @@ TEST_P(SslTransportSecurityTest, DoRoundTripForAllConfigs) { } TEST_P(SslTransportSecurityTest, DoRoundTripWithErrorOnStack) { - gpr_log(GPR_INFO, "ssl_tsi_test_do_round_trip_with_error_on_stack"); + LOG(INFO) << "ssl_tsi_test_do_round_trip_with_error_on_stack"; // Invoke an SSL function that causes an error, and ensure the error // makes it to the stack. ASSERT_FALSE(EC_KEY_new_by_curve_name(NID_rsa)); @@ -930,7 +925,7 @@ TEST_P(SslTransportSecurityTest, DoRoundTripWithErrorOnStack) { } TEST_P(SslTransportSecurityTest, DoRoundTripOddBufferSize) { - gpr_log(GPR_INFO, "ssl_tsi_test_do_round_trip_odd_buffer_size"); + LOG(INFO) << "ssl_tsi_test_do_round_trip_odd_buffer_size"; const size_t odd_sizes[] = {1025, 2051, 4103, 8207, 16409}; size_t size = sizeof(odd_sizes) / sizeof(size_t); // 1. This test is extremely slow under MSAN and TSAN. @@ -962,7 +957,7 @@ TEST_P(SslTransportSecurityTest, DoRoundTripOddBufferSize) { } TEST_P(SslTransportSecurityTest, DoHandshakeSessionCache) { - gpr_log(GPR_INFO, "ssl_tsi_test_do_handshake_session_cache"); + LOG(INFO) << "ssl_tsi_test_do_handshake_session_cache"; tsi_ssl_session_cache* session_cache = tsi_ssl_session_cache_create_lru(16); char session_ticket_key[kSessionTicketEncryptionKeySize]; auto do_handshake = [this, &session_ticket_key, @@ -995,7 +990,7 @@ TEST_P(SslTransportSecurityTest, DoHandshakeSessionCache) { #endif // OPENSSL_IS_BORINGSSL TEST_P(SslTransportSecurityTest, DoHandshakeAlpnServerNoClient) { - gpr_log(GPR_INFO, "ssl_tsi_test_do_handshake_alpn_server_no_client"); + LOG(INFO) << "ssl_tsi_test_do_handshake_alpn_server_no_client"; SetUpSslFixture(/*tls_version=*/std::get<0>(GetParam()), /*send_client_ca_list=*/std::get<1>(GetParam())); ssl_fixture_->SetAlpnMode(ALPN_SERVER_NO_CLIENT); @@ -1003,7 +998,7 @@ TEST_P(SslTransportSecurityTest, DoHandshakeAlpnServerNoClient) { } TEST_P(SslTransportSecurityTest, DoHandshakeAlpnClientServerOk) { - gpr_log(GPR_INFO, "ssl_tsi_test_do_handshake_alpn_client_server_ok"); + LOG(INFO) << "ssl_tsi_test_do_handshake_alpn_client_server_ok"; SetUpSslFixture(/*tls_version=*/std::get<0>(GetParam()), /*send_client_ca_list=*/std::get<1>(GetParam())); ssl_fixture_->SetAlpnMode(ALPN_CLIENT_SERVER_OK); @@ -1011,7 +1006,7 @@ TEST_P(SslTransportSecurityTest, DoHandshakeAlpnClientServerOk) { } TEST_P(SslTransportSecurityTest, DoHandshakeWithCustomBioPair) { - gpr_log(GPR_INFO, "ssl_tsi_test_do_handshake_with_custom_bio_pair"); + LOG(INFO) << "ssl_tsi_test_do_handshake_with_custom_bio_pair"; SetUpSslFixture(/*tls_version=*/std::get<0>(GetParam()), /*send_client_ca_list=*/std::get<1>(GetParam())); #if OPENSSL_VERSION_NUMBER >= 0x10100000 @@ -1143,7 +1138,7 @@ TEST(SslTransportSecurityTest, TestClientHandshakerFactoryBadParams) { } TEST(SslTransportSecurityTest, DuplicateRootCertificates) { - gpr_log(GPR_INFO, "ssl_tsi_test_duplicate_root_certificates"); + LOG(INFO) << "ssl_tsi_test_duplicate_root_certificates"; char* root_cert = load_file(SSL_TSI_TEST_CREDENTIALS_DIR "ca.pem"); char* dup_root_cert = static_cast( gpr_zalloc(sizeof(char) * (strlen(root_cert) * 2 + 1))); @@ -1159,7 +1154,7 @@ TEST(SslTransportSecurityTest, DuplicateRootCertificates) { } TEST(SslTransportSecurityTest, ExtractX509SubjectNames) { - gpr_log(GPR_INFO, "ssl_tsi_test_extract_x509_subject_names"); + LOG(INFO) << "ssl_tsi_test_extract_x509_subject_names"; char* cert = load_file(SSL_TSI_TEST_CREDENTIALS_DIR "multi-domain.pem"); tsi_peer peer; ASSERT_EQ(tsi_ssl_extract_x509_subject_names_from_pem_cert(cert, &peer), @@ -1263,7 +1258,7 @@ TEST(SslTransportSecurityTest, ExtractX509SubjectNames) { } TEST(SslTransportSecurityTest, ExtractCertChain) { - gpr_log(GPR_INFO, "ssl_tsi_test_extract_cert_chain"); + LOG(INFO) << "ssl_tsi_test_extract_cert_chain"; char* cert = load_file(SSL_TSI_TEST_CREDENTIALS_DIR "server1.pem"); char* ca = load_file(SSL_TSI_TEST_CREDENTIALS_DIR "ca.pem"); char* chain = static_cast( diff --git a/test/core/xds/xds_client_fuzzer.cc b/test/core/xds/xds_client_fuzzer.cc index 4653d545713..f7b3e2fc48e 100644 --- a/test/core/xds/xds_client_fuzzer.cc +++ b/test/core/xds/xds_client_fuzzer.cc @@ -20,6 +20,7 @@ #include #include +#include "absl/log/log.h" #include "absl/status/status.h" #include "absl/status/statusor.h" #include "absl/strings/str_cat.h" @@ -28,7 +29,6 @@ #include "absl/types/optional.h" #include -#include #include "src/core/lib/event_engine/default_event_engine.h" #include "src/core/lib/gprpp/orphanable.h" @@ -53,8 +53,7 @@ class Fuzzer { explicit Fuzzer(absl::string_view bootstrap_json) { auto bootstrap = GrpcXdsBootstrap::Create(bootstrap_json); if (!bootstrap.ok()) { - gpr_log(GPR_ERROR, "error creating bootstrap: %s", - bootstrap.status().ToString().c_str()); + LOG(ERROR) << "error creating bootstrap: " << bootstrap.status(); // Leave xds_client_ unset, so Act() will be a no-op. return; } @@ -122,20 +121,18 @@ class Fuzzer { [](const testing::XdsClientTestPeer::ResourceCountLabels& labels, uint64_t count) { - gpr_log(GPR_INFO, - "xds_authority=\"%s\", resource_type=\"%s\", " - "cache_state=\"%s\" count=%" PRIu64, - std::string(labels.xds_authority).c_str(), - std::string(labels.resource_type).c_str(), - std::string(labels.cache_state).c_str(), count); + LOG(INFO) << "xds_authority=\"" << labels.xds_authority + << "\", resource_type=\"" << labels.resource_type + << "\", cache_state=\"" << labels.cache_state + << "\" count=" << count; }); break; case xds_client_fuzzer::Action::kReportServerConnections: testing::XdsClientTestPeer(xds_client_.get()) .TestReportServerConnections( [](absl::string_view xds_server, bool connected) { - gpr_log(GPR_INFO, "xds_server=\"%s\" connected=%d", - std::string(xds_server).c_str(), connected); + LOG(INFO) << "xds_server=\"" << xds_server + << "\" connected=" << connected; }); break; case xds_client_fuzzer::Action::kTriggerConnectionFailure: @@ -174,26 +171,24 @@ class Fuzzer { std::shared_ptr resource, RefCountedPtr /* read_delay_handle */) override { - gpr_log(GPR_INFO, "==> OnResourceChanged(%s %s): %s", - std::string(ResourceType::Get()->type_url()).c_str(), - resource_name_.c_str(), resource->ToString().c_str()); + LOG(INFO) << "==> OnResourceChanged(" << ResourceType::Get()->type_url() + << " " << resource_name_ << "): " << resource->ToString(); } void OnError( absl::Status status, RefCountedPtr /* read_delay_handle */) override { - gpr_log(GPR_INFO, "==> OnError(%s %s): %s", - std::string(ResourceType::Get()->type_url()).c_str(), - resource_name_.c_str(), status.ToString().c_str()); + LOG(INFO) << "==> OnError(" << ResourceType::Get()->type_url() << " " + << resource_name_ << "): " << status; } void OnResourceDoesNotExist( RefCountedPtr /* read_delay_handle */) override { - gpr_log(GPR_INFO, "==> OnResourceDoesNotExist(%s %s)", - std::string(ResourceType::Get()->type_url()).c_str(), - resource_name_.c_str()); + LOG(INFO) << "==> OnResourceDoesNotExist(" + << ResourceType::Get()->type_url() << " " << resource_name_ + << ")"; } private: @@ -208,9 +203,9 @@ class Fuzzer { template void StartWatch(std::map>* watchers, std::string resource_name) { - gpr_log(GPR_INFO, "### StartWatch(%s %s)", - std::string(WatcherType::ResourceType::Get()->type_url()).c_str(), - resource_name.c_str()); + LOG(INFO) << "### StartWatch(" + << WatcherType::ResourceType::Get()->type_url() << " " + << resource_name << ")"; auto watcher = MakeRefCounted(resource_name); (*watchers)[resource_name].insert(watcher.get()); WatcherType::ResourceType::Get()->StartWatch( @@ -220,9 +215,9 @@ class Fuzzer { template void StopWatch(std::map>* watchers, std::string resource_name) { - gpr_log(GPR_INFO, "### StopWatch(%s %s)", - std::string(WatcherType::ResourceType::Get()->type_url()).c_str(), - resource_name.c_str()); + LOG(INFO) << "### StopWatch(" + << WatcherType::ResourceType::Get()->type_url() << " " + << resource_name << ")"; auto& watchers_set = (*watchers)[resource_name]; auto it = watchers_set.begin(); if (it == watchers_set.end()) return; @@ -252,8 +247,8 @@ class Fuzzer { void TriggerConnectionFailure(const std::string& authority, absl::Status status) { - gpr_log(GPR_INFO, "### TriggerConnectionFailure(%s): %s", authority.c_str(), - status.ToString().c_str()); + LOG(INFO) << "### TriggerConnectionFailure(" << authority + << "): " << status; const auto* xds_server = GetServer(authority); if (xds_server == nullptr) return; transport_factory_->TriggerConnectionFailure(*xds_server, @@ -290,14 +285,14 @@ class Fuzzer { void ReadMessageFromClient(const xds_client_fuzzer::StreamId& stream_id, bool ok) { - gpr_log(GPR_INFO, "### ReadMessageFromClient(%s): %s", - StreamIdString(stream_id).c_str(), ok ? "true" : "false"); + LOG(INFO) << "### ReadMessageFromClient(" << StreamIdString(stream_id) + << "): " << (ok ? "true" : "false"); auto stream = GetStream(stream_id); if (stream == nullptr) return; - gpr_log(GPR_INFO, " stream=%p", stream.get()); + LOG(INFO) << " stream=" << stream.get(); auto message = stream->WaitForMessageFromClient(absl::ZeroDuration()); if (message.has_value()) { - gpr_log(GPR_INFO, " completing send_message"); + LOG(INFO) << " completing send_message"; stream->CompleteSendMessageFromClient(ok); } } @@ -305,21 +300,20 @@ class Fuzzer { void SendMessageToClient( const xds_client_fuzzer::StreamId& stream_id, const envoy::service::discovery::v3::DiscoveryResponse& response) { - gpr_log(GPR_INFO, "### SendMessageToClient(%s)", - StreamIdString(stream_id).c_str()); + LOG(INFO) << "### SendMessageToClient(" << StreamIdString(stream_id) << ")"; auto stream = GetStream(stream_id); if (stream == nullptr) return; - gpr_log(GPR_INFO, " stream=%p", stream.get()); + LOG(INFO) << " stream=" << stream.get(); stream->SendMessageToClient(response.SerializeAsString()); } void SendStatusToClient(const xds_client_fuzzer::StreamId& stream_id, absl::Status status) { - gpr_log(GPR_INFO, "### SendStatusToClient(%s): %s", - StreamIdString(stream_id).c_str(), status.ToString().c_str()); + LOG(INFO) << "### SendStatusToClient(" << StreamIdString(stream_id) + << "): " << status; auto stream = GetStream(stream_id); if (stream == nullptr) return; - gpr_log(GPR_INFO, " stream=%p", stream.get()); + LOG(INFO) << " stream=" << stream.get(); stream->MaybeSendStatusToClient(std::move(status)); }