[log][Backport] Reducing log spam (#37253) (#37294)

Backport #37253 to 1.65.x

This PR changes many of the `LOG(INFO)` statements that are not guarded
by TraceFlags to either be -
* guarded by a TraceFlag
* logged under `VLOG(2)`

src/core/ext/transport/chttp2/transport/chttp2_transport.cc

@@ -1735,8 +1735,8 @@ void grpc_chttp2_keepalive_timeout(
     grpc_core::RefCountedPtr<grpc_chttp2_transport> t) {
   t->combiner->Run(
       grpc_core::NewClosure([t](grpc_error_handle) {
-        gpr_log(GPR_INFO, "%s: Keepalive timeout. Closing transport.",
-                std::string(t->peer_string.as_string_view()).c_str());
+        GRPC_TRACE_LOG(http, INFO) << t->peer_string.as_string_view()
+                                   << ": Keepalive timeout. Closing transport.";
         send_goaway(
             t.get(),
             grpc_error_set_int(GRPC_ERROR_CREATE("keepalive_timeout"),
@@ -1756,8 +1756,8 @@ void grpc_chttp2_ping_timeout(
     grpc_core::RefCountedPtr<grpc_chttp2_transport> t) {
   t->combiner->Run(
       grpc_core::NewClosure([t](grpc_error_handle) {
-        gpr_log(GPR_INFO, "%s: Ping timeout. Closing transport.",
-                std::string(t->peer_string.as_string_view()).c_str());
+        GRPC_TRACE_LOG(http, INFO) << t->peer_string.as_string_view()
+                                   << ": Ping timeout. Closing transport.";
         send_goaway(
             t.get(),
             grpc_error_set_int(GRPC_ERROR_CREATE("ping_timeout"),
@@ -1777,8 +1777,8 @@ void grpc_chttp2_settings_timeout(
     grpc_core::RefCountedPtr<grpc_chttp2_transport> t) {
   t->combiner->Run(
       grpc_core::NewClosure([t](grpc_error_handle) {
-        gpr_log(GPR_INFO, "%s: Settings timeout. Closing transport.",
-                std::string(t->peer_string.as_string_view()).c_str());
+        GRPC_TRACE_LOG(http, INFO) << t->peer_string.as_string_view()
+                                   << ": Settings timeout. Closing transport.";
         send_goaway(
             t.get(),
             grpc_error_set_int(GRPC_ERROR_CREATE("settings_timeout"),

src/core/handshaker/http_connect/http_proxy_mapper.cc

@@ -220,13 +220,11 @@ absl::optional<std::string> HttpProxyMapper::MapName(
     return absl::nullopt;
   }
   if (uri->scheme() == "unix") {
-    gpr_log(GPR_INFO, "not using proxy for Unix domain socket '%s'",
-            std::string(server_uri).c_str());
+    VLOG(2) << "not using proxy for Unix domain socket '" << server_uri << "'";
     return absl::nullopt;
   }
   if (uri->scheme() == "vsock") {
-    gpr_log(GPR_INFO, "not using proxy for VSock '%s'",
-            std::string(server_uri).c_str());
+    VLOG(2) << "not using proxy for VSock '" << server_uri << "'";
     return absl::nullopt;
   }
   // Prefer using 'no_grpc_proxy'. Fallback on 'no_proxy' if it is not set.
@@ -239,18 +237,17 @@ absl::optional<std::string> HttpProxyMapper::MapName(
     std::string server_port;
     if (!SplitHostPort(absl::StripPrefix(uri->path(), "/"), &server_host,
                        &server_port)) {
-      gpr_log(GPR_INFO,
-              "unable to split host and port, not checking no_proxy list for "
-              "host '%s'",
-              std::string(server_uri).c_str());
+      VLOG(2) << "unable to split host and port, not checking no_proxy list "
+                 "for host '"
+              << server_uri << "'";
     } else {
       auto address = StringToSockaddr(server_host, 0);
       if (AddressIncluded(address.ok()
                               ? absl::optional<grpc_resolved_address>(*address)
                               : absl::nullopt,
                           server_host, *no_proxy_str)) {
-        gpr_log(GPR_INFO, "not using proxy for host in no_proxy list '%s'",
-                std::string(server_uri).c_str());
+        VLOG(2) << "not using proxy for host in no_proxy list '" << server_uri
+                << "'";
         return absl::nullopt;
       }
     }

src/core/lib/compression/message_compress.cc

@@ -62,17 +62,17 @@ static int zlib_body(z_stream* zs, grpc_slice_buffer* input,
       }
       r = flate(zs, flush);
       if (r < 0 && r != Z_BUF_ERROR /* not fatal */) {
-        LOG(INFO) << "zlib error (" << r << ")";
+        VLOG(2) << "zlib error (" << r << ")";
         goto error;
       }
     } while (zs->avail_out == 0);
     if (zs->avail_in) {
-      LOG(INFO) << "zlib: not all input consumed";
+      VLOG(2) << "zlib: not all input consumed";
       goto error;
     }
   }
   if (r != Z_STREAM_END) {
-    LOG(INFO) << "zlib: Data error";
+    VLOG(2) << "zlib: Data error";
     goto error;
   }
 

src/core/lib/event_engine/posix_engine/posix_endpoint.cc

@@ -1295,9 +1295,9 @@ PosixEndpointImpl::PosixEndpointImpl(EventHandle* handle,
     }
 
     if (zerocopy_enabled) {
-      LOG(INFO) << "Tx-zero copy enabled for gRPC sends. RLIMIT_MEMLOCK value "
-                << "=" << GetRLimitMemLockMax()
-                << ",ulimit hard memlock value = " << GetUlimitHardMemLock();
+      VLOG(2) << "Tx-zero copy enabled for gRPC sends. RLIMIT_MEMLOCK value "
+              << "=" << GetRLimitMemLockMax()
+              << ",ulimit hard memlock value = " << GetUlimitHardMemLock();
     }
   }
 #endif  // GRPC_LINUX_ERRQUEUE

src/core/lib/event_engine/posix_engine/posix_endpoint.h

@@ -184,7 +184,7 @@ class TcpZerocopySendCtx {
     if (send_records_ == nullptr || free_send_records_ == nullptr) {
       gpr_free(send_records_);
       gpr_free(free_send_records_);
-      LOG(INFO) << "Disabling TCP TX zerocopy due to memory pressure.\n";
+      VLOG(2) << "Disabling TCP TX zerocopy due to memory pressure.\n";
       memory_limited_ = true;
       enabled_ = false;
     } else {

src/core/lib/event_engine/posix_engine/posix_engine_listener_utils.cc

@@ -345,14 +345,14 @@ absl::StatusOr<int> ListenerContainerAddWildcardAddresses(
   }
   if (assigned_port > 0) {
     if (!v6_sock.ok()) {
-      LOG(INFO) << "Failed to add :: listener, the environment may not support "
-                   "IPv6: "
-                << v6_sock.status();
+      VLOG(2) << "Failed to add :: listener, the environment may not support "
+                 "IPv6: "
+              << v6_sock.status();
     }
     if (!v4_sock.ok()) {
-      LOG(INFO) << "Failed to add 0.0.0.0 listener, "
-                   "the environment may not support IPv4: "
-                << v4_sock.status();
+      VLOG(2) << "Failed to add 0.0.0.0 listener, "
+                 "the environment may not support IPv4: "
+              << v4_sock.status();
     }
     return assigned_port;
   } else {

src/core/lib/event_engine/posix_engine/tcp_socket_utils.cc

@@ -629,8 +629,9 @@ void PosixSocketWrapper::TrySetSocketTcpUserTimeout(
       if (0 != getsockopt(fd_, IPPROTO_TCP, TCP_USER_TIMEOUT, &newval, &len)) {
         // This log is intentionally not protected behind a flag, so that users
         // know that TCP_USER_TIMEOUT is not being used.
-        LOG(INFO) << "TCP_USER_TIMEOUT is not available. TCP_USER_TIMEOUT "
-                     "won't be used thereafter";
+        GRPC_TRACE_LOG(tcp, INFO)
+            << "TCP_USER_TIMEOUT is not available. TCP_USER_TIMEOUT "
+               "won't be used thereafter";
         g_socket_supports_tcp_user_timeout.store(-1);
       } else {
         GRPC_TRACE_LOG(tcp, INFO)
@@ -684,7 +685,8 @@ bool PosixSocketWrapper::IsIpv6LoopbackAvailable() {
     int fd = socket(AF_INET6, SOCK_STREAM, 0);
     bool loopback_available = false;
     if (fd < 0) {
-      LOG(INFO) << "Disabling AF_INET6 sockets because socket() failed.";
+      GRPC_TRACE_LOG(tcp, INFO)
+          << "Disabling AF_INET6 sockets because socket() failed.";
     } else {
       sockaddr_in6 addr;
       memset(&addr, 0, sizeof(addr));
@@ -693,7 +695,8 @@ bool PosixSocketWrapper::IsIpv6LoopbackAvailable() {
       if (bind(fd, reinterpret_cast<sockaddr*>(&addr), sizeof(addr)) == 0) {
         loopback_available = true;
       } else {
-        LOG(INFO) << "Disabling AF_INET6 sockets because ::1 is not available.";
+        GRPC_TRACE_LOG(tcp, INFO)
+            << "Disabling AF_INET6 sockets because ::1 is not available.";
       }
       close(fd);
     }

src/core/lib/event_engine/windows/win_socket.cc

@@ -71,15 +71,17 @@ void WinSocket::Shutdown() {
                         &ioctl_num_bytes, NULL, NULL);
   if (status != 0) {
     char* utf8_message = gpr_format_message(WSAGetLastError());
-    LOG(INFO) << "Unable to retrieve DisconnectEx pointer : " << utf8_message;
+    GRPC_TRACE_LOG(event_engine_endpoint, INFO)
+        << "Unable to retrieve DisconnectEx pointer : " << utf8_message;
     gpr_free(utf8_message);
   } else if (DisconnectEx(socket_, NULL, 0, 0) == FALSE) {
     auto last_error = WSAGetLastError();
     // DisconnectEx may be called when the socket is not connected. Ignore that
     // error, and log all others.
     if (last_error != WSAENOTCONN) {
       char* utf8_message = gpr_format_message(last_error);
-      LOG(INFO) << "DisconnectEx failed: " << utf8_message;
+      GRPC_TRACE_LOG(event_engine_endpoint, INFO)
+          << "DisconnectEx failed: " << utf8_message;
       gpr_free(utf8_message);
     }
   }

src/core/lib/event_engine/windows/windows_endpoint.cc

@@ -42,8 +42,8 @@ constexpr int kMaxWSABUFCount = 16;
 void DumpSliceBuffer(SliceBuffer* buffer, absl::string_view context_string) {
   for (size_t i = 0; i < buffer->Count(); i++) {
     auto str = buffer->MutableSliceAt(i).as_string_view();
-    gpr_log(GPR_INFO, "%s: %.*s", context_string.data(), str.length(),
-            str.data());
+    GRPC_TRACE_LOG(event_engine_endpoint, INFO)
+        << context_string << ": " << str;
   }
 }
 
@@ -159,8 +159,9 @@ bool WindowsEndpoint::Write(absl::AnyInvocable<void(absl::Status)> on_writable,
   if (GRPC_TRACE_FLAG_ENABLED(event_engine_endpoint_data)) {
     for (size_t i = 0; i < data->Count(); i++) {
       auto str = data->RefSlice(i).as_string_view();
-      gpr_log(GPR_INFO, "WindowsEndpoint::%p WRITE (peer=%s): %.*s", this,
-              peer_address_string_.c_str(), str.length(), str.data());
+      GRPC_TRACE_LOG(event_engine_endpoint, INFO)
+          << "WindowsEndpoint::" << this
+          << " WRITE (peer=" << peer_address_string_ << "): " << str;
     }
   }
   CHECK(data->Count() <= UINT_MAX);

src/core/lib/iomgr/endpoint_pair_windows.cc

@@ -66,13 +66,13 @@ static void create_sockets(SOCKET sv[2]) {
   closesocket(lst_sock);
   grpc_error_handle error = grpc_tcp_prepare_socket(cli_sock);
   if (!error.ok()) {
-    LOG(INFO) << "Prepare cli_sock failed with error: "
-              << grpc_core::StatusToString(error);
+    VLOG(2) << "Prepare cli_sock failed with error: "
+            << grpc_core::StatusToString(error);
   }
   error = grpc_tcp_prepare_socket(svr_sock);
   if (!error.ok()) {
-    LOG(INFO) << "Prepare svr_sock failed with error: "
-              << grpc_core::StatusToString(error);
+    VLOG(2) << "Prepare svr_sock failed with error: "
+            << grpc_core::StatusToString(error);
   }
 
   sv[1] = cli_sock;

src/core/lib/iomgr/socket_windows.cc

@@ -132,7 +132,7 @@ void grpc_winsocket_shutdown(grpc_winsocket* winsocket) {
     DisconnectEx(winsocket->socket, NULL, 0, 0);
   } else {
     char* utf8_message = gpr_format_message(WSAGetLastError());
-    LOG(INFO) << "Unable to retrieve DisconnectEx pointer : " << utf8_message;
+    VLOG(2) << "Unable to retrieve DisconnectEx pointer : " << utf8_message;
     gpr_free(utf8_message);
   }
   // Calling closesocket triggers invocation of any pending I/O operations with
@@ -216,7 +216,7 @@ static void probe_ipv6_once(void) {
   SOCKET s = socket(AF_INET6, SOCK_STREAM, 0);
   g_ipv6_loopback_available = 0;
   if (s == INVALID_SOCKET) {
-    LOG(INFO) << "Disabling AF_INET6 sockets because socket() failed.";
+    VLOG(2) << "Disabling AF_INET6 sockets because socket() failed.";
   } else {
     grpc_sockaddr_in6 addr;
     memset(&addr, 0, sizeof(addr));
@@ -225,7 +225,7 @@ static void probe_ipv6_once(void) {
     if (bind(s, reinterpret_cast<grpc_sockaddr*>(&addr), sizeof(addr)) == 0) {
       g_ipv6_loopback_available = 1;
     } else {
-      LOG(INFO) << "Disabling AF_INET6 sockets because ::1 is not available.";
+      VLOG(2) << "Disabling AF_INET6 sockets because ::1 is not available.";
     }
     closesocket(s);
   }

src/core/lib/iomgr/tcp_posix.cc

@@ -210,7 +210,8 @@ class TcpZerocopySendCtx {
     if (send_records_ == nullptr || free_send_records_ == nullptr) {
       gpr_free(send_records_);
       gpr_free(free_send_records_);
-      LOG(INFO) << "Disabling TCP TX zerocopy due to memory pressure.\n";
+      GRPC_TRACE_LOG(tcp, INFO)
+          << "Disabling TCP TX zerocopy due to memory pressure.\n";
       memory_limited_ = true;
     } else {
       for (int idx = 0; idx < max_sends_; ++idx) {

src/core/lib/iomgr/tcp_server_posix.cc

@@ -424,10 +424,9 @@ static void on_read(void* arg, grpc_error_handle err) {
       int64_t dropped_connections_count =
           num_dropped_connections.fetch_add(1, std::memory_order_relaxed) + 1;
       if (dropped_connections_count % 1000 == 1) {
-        gpr_log(GPR_INFO,
-                "Dropped >= %" PRId64
-                " new connection attempts due to high memory pressure",
-                dropped_connections_count);
+        GRPC_TRACE_LOG(tcp, INFO)
+            << "Dropped >= " << dropped_connections_count
+            << " new connection attempts due to high memory pressure";
       }
       close(fd);
       continue;
@@ -549,16 +548,14 @@ static grpc_error_handle add_wildcard_addrs_to_server(grpc_tcp_server* s,
   }
   if (*out_port > 0) {
     if (!v6_err.ok()) {
-      gpr_log(GPR_INFO,
-              "Failed to add :: listener, "
-              "the environment may not support IPv6: %s",
-              grpc_core::StatusToString(v6_err).c_str());
+      GRPC_TRACE_LOG(tcp, INFO) << "Failed to add :: listener, "
+                                << "the environment may not support IPv6: "
+                                << grpc_core::StatusToString(v6_err);
     }
     if (!v4_err.ok()) {
-      gpr_log(GPR_INFO,
-              "Failed to add 0.0.0.0 listener, "
-              "the environment may not support IPv4: %s",
-              grpc_core::StatusToString(v4_err).c_str());
+      GRPC_TRACE_LOG(tcp, INFO) << "Failed to add 0.0.0.0 listener, "
+                                << "the environment may not support IPv4: "
+                                << grpc_core::StatusToString(v4_err);
     }
     return absl::OkStatus();
   } else {

src/core/lib/iomgr/tcp_server_windows.cc

@@ -386,8 +386,8 @@ static void on_accept(void* arg, grpc_error_handle error) {
   // this is necessary in the read/write case, it's useless for the accept
   // case. We only need to adjust the pending callback count
   if (!error.ok()) {
-    LOG(INFO) << "Skipping on_accept due to error: "
-              << grpc_core::StatusToString(error);
+    VLOG(2) << "Skipping on_accept due to error: "
+            << grpc_core::StatusToString(error);
 
     gpr_mu_unlock(&sp->server->mu);
     return;

src/core/lib/promise/party.cc

@@ -288,13 +288,13 @@ bool Party::RunOneParticipant(int i) {
   currently_polling_ = kNotPolling;
   if (done) {
     if (!name.empty()) {
-      gpr_log(GPR_INFO, "%s[%s] end poll and finish job %d", DebugTag().c_str(),
-              std::string(name).c_str(), i);
+      GRPC_TRACE_LOG(promise_primitives, INFO)
+          << DebugTag() << "[" << name << "] end poll and finish job " << i;
     }
     participants_[i].store(nullptr, std::memory_order_relaxed);
   } else if (!name.empty()) {
-    gpr_log(GPR_INFO, "%s[%s] end poll", DebugTag().c_str(),
-            std::string(name).c_str());
+    GRPC_TRACE_LOG(promise_primitives, INFO)
+        << DebugTag() << "[" << name << "] end poll";
   }
   return done;
 }

src/core/load_balancing/grpclb/grpclb.cc

@@ -489,10 +489,10 @@ class GrpcLb final : public LoadBalancingPolicy {
           new_state == GRPC_CHANNEL_TRANSIENT_FAILURE) {
         // In TRANSIENT_FAILURE.  Cancel the fallback timer and go into
         // fallback mode immediately.
-        gpr_log(GPR_INFO,
-                "[grpclb %p] balancer channel in state:TRANSIENT_FAILURE (%s); "
-                "entering fallback mode",
-                parent_.get(), status.ToString().c_str());
+        GRPC_TRACE_LOG(glb, INFO)
+            << "[grpclb " << parent_.get()
+            << "] balancer channel in state:TRANSIENT_FAILURE ("
+            << status.ToString() << "); entering fallback mode";
         parent_->fallback_at_startup_checks_pending_ = false;
         parent_->channel_control_helper()->GetEventEngine()->Cancel(
             *parent_->lb_fallback_timer_handle_);
@@ -670,11 +670,10 @@ class GrpcLb::Serverlist::AddressIterator final
       std::string lb_token(server.load_balance_token, lb_token_length);
       if (lb_token.empty()) {
         auto addr_uri = grpc_sockaddr_to_uri(&addr);
-        gpr_log(GPR_INFO,
-                "Missing LB token for backend address '%s'. The empty token "
-                "will be used instead",
-                addr_uri.ok() ? addr_uri->c_str()
-                              : addr_uri.status().ToString().c_str());
+        GRPC_TRACE_LOG(glb, INFO)
+            << "Missing LB token for backend address '"
+            << (addr_uri.ok() ? *addr_uri : addr_uri.status().ToString())
+            << "'. The empty token will be used instead";
       }
       // Return address with a channel arg containing LB token and stats object.
       callback(EndpointAddresses(
@@ -852,12 +851,12 @@ void GrpcLb::Helper::UpdateState(grpc_connectivity_state state,
     client_stats = parent()->lb_calld_->client_stats()->Ref();
   }
   if (GRPC_TRACE_FLAG_ENABLED(glb)) {
-    gpr_log(GPR_INFO,
-            "[grpclb %p helper %p] state=%s (%s) wrapping child "
-            "picker %p (serverlist=%p, client_stats=%p)",
-            parent(), this, ConnectivityStateName(state),
-            status.ToString().c_str(), picker.get(), serverlist.get(),
-            client_stats.get());
+    GRPC_TRACE_LOG(glb, INFO)
+        << "[grpclb " << parent() << " helper " << this
+        << "] state=" << ConnectivityStateName(state) << " ("
+        << status.ToString() << ") wrapping child picker " << picker.get()
+        << " (serverlist=" << serverlist.get()
+        << ", client_stats=" << client_stats.get() << ")";
   }
   parent()->channel_control_helper()->UpdateState(
       state, status,

src/core/util/subprocess_windows.cc

@@ -114,7 +114,7 @@ void gpr_subprocess_interrupt(gpr_subprocess* p) {
   DWORD dwExitCode;
   if (GetExitCodeProcess(p->pi.hProcess, &dwExitCode)) {
     if (dwExitCode == STILL_ACTIVE) {
-      gpr_log(GPR_INFO, "sending ctrl-break");
+      VLOG(2) << "sending ctrl-break";
       GenerateConsoleCtrlEvent(CTRL_BREAK_EVENT, p->pi.dwProcessId);
       p->joined = 1;
       p->interrupted = 1;