[log] Reducing log spam (#37253)

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)`

Closes #37253

COPYBARA_INTEGRATE_REVIEW=https://github.com/grpc/grpc/pull/37253 from yashykt:LoggingLevelFix 50d332e17a
PiperOrigin-RevId: 655248697
pull/37296/head^2
Yash Tibrewal 6 months ago committed by Copybara-Service
parent 15b6697ea4
commit 24683f1285
  1. 99
      src/core/ext/transport/chttp2/transport/chttp2_transport.cc
  2. 15
      src/core/handshaker/http_connect/http_proxy_mapper.cc
  3. 6
      src/core/lib/compression/message_compress.cc
  4. 6
      src/core/lib/event_engine/posix_engine/posix_endpoint.cc
  5. 2
      src/core/lib/event_engine/posix_engine/posix_endpoint.h
  6. 12
      src/core/lib/event_engine/posix_engine/posix_engine_listener_utils.cc
  7. 11
      src/core/lib/event_engine/posix_engine/tcp_socket_utils.cc
  8. 6
      src/core/lib/event_engine/windows/win_socket.cc
  9. 8
      src/core/lib/event_engine/windows/windows_endpoint.cc
  10. 8
      src/core/lib/iomgr/endpoint_pair_windows.cc
  11. 6
      src/core/lib/iomgr/socket_windows.cc
  12. 3
      src/core/lib/iomgr/tcp_posix.cc
  13. 17
      src/core/lib/iomgr/tcp_server_posix.cc
  14. 4
      src/core/lib/iomgr/tcp_server_windows.cc
  15. 7
      src/core/lib/promise/party.cc
  16. 25
      src/core/load_balancing/grpclb/grpclb.cc
  17. 2
      src/core/util/subprocess_windows.cc
  18. 12
      src/cpp/server/server_builder.cc

@ -1760,62 +1760,65 @@ void grpc_chttp2_ack_ping(grpc_chttp2_transport* t, uint64_t id) {
void grpc_chttp2_keepalive_timeout(
grpc_core::RefCountedPtr<grpc_chttp2_transport> t) {
t->combiner->Run(grpc_core::NewClosure([t](grpc_error_handle) {
LOG(INFO) << t->peer_string.as_string_view()
<< ": Keepalive timeout. Closing transport.";
send_goaway(t.get(),
grpc_error_set_int(
GRPC_ERROR_CREATE("keepalive_timeout"),
grpc_core::StatusIntProperty::kHttp2Error,
GRPC_HTTP2_ENHANCE_YOUR_CALM),
/*immediate_disconnect_hint=*/true);
close_transport_locked(
t.get(), grpc_error_set_int(
GRPC_ERROR_CREATE("keepalive timeout"),
grpc_core::StatusIntProperty::kRpcStatus,
GRPC_STATUS_UNAVAILABLE));
}),
absl::OkStatus());
t->combiner->Run(
grpc_core::NewClosure([t](grpc_error_handle) {
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"),
grpc_core::StatusIntProperty::kHttp2Error,
GRPC_HTTP2_ENHANCE_YOUR_CALM),
/*immediate_disconnect_hint=*/true);
close_transport_locked(
t.get(),
grpc_error_set_int(GRPC_ERROR_CREATE("keepalive timeout"),
grpc_core::StatusIntProperty::kRpcStatus,
GRPC_STATUS_UNAVAILABLE));
}),
absl::OkStatus());
}
void grpc_chttp2_ping_timeout(
grpc_core::RefCountedPtr<grpc_chttp2_transport> t) {
t->combiner->Run(grpc_core::NewClosure([t](grpc_error_handle) {
LOG(INFO) << t->peer_string.as_string_view()
<< ": Ping timeout. Closing transport.";
send_goaway(t.get(),
grpc_error_set_int(
GRPC_ERROR_CREATE("ping_timeout"),
grpc_core::StatusIntProperty::kHttp2Error,
GRPC_HTTP2_ENHANCE_YOUR_CALM),
/*immediate_disconnect_hint=*/true);
close_transport_locked(
t.get(), grpc_error_set_int(
GRPC_ERROR_CREATE("ping timeout"),
grpc_core::StatusIntProperty::kRpcStatus,
GRPC_STATUS_UNAVAILABLE));
}),
absl::OkStatus());
t->combiner->Run(
grpc_core::NewClosure([t](grpc_error_handle) {
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"),
grpc_core::StatusIntProperty::kHttp2Error,
GRPC_HTTP2_ENHANCE_YOUR_CALM),
/*immediate_disconnect_hint=*/true);
close_transport_locked(
t.get(),
grpc_error_set_int(GRPC_ERROR_CREATE("ping timeout"),
grpc_core::StatusIntProperty::kRpcStatus,
GRPC_STATUS_UNAVAILABLE));
}),
absl::OkStatus());
}
void grpc_chttp2_settings_timeout(
grpc_core::RefCountedPtr<grpc_chttp2_transport> t) {
t->combiner->Run(grpc_core::NewClosure([t](grpc_error_handle) {
LOG(INFO) << t->peer_string.as_string_view()
<< ": Settings timeout. Closing transport.";
send_goaway(t.get(),
grpc_error_set_int(
GRPC_ERROR_CREATE("settings_timeout"),
grpc_core::StatusIntProperty::kHttp2Error,
GRPC_HTTP2_SETTINGS_TIMEOUT),
/*immediate_disconnect_hint=*/true);
close_transport_locked(
t.get(), grpc_error_set_int(
GRPC_ERROR_CREATE("settings timeout"),
grpc_core::StatusIntProperty::kRpcStatus,
GRPC_STATUS_UNAVAILABLE));
}),
absl::OkStatus());
t->combiner->Run(
grpc_core::NewClosure([t](grpc_error_handle) {
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"),
grpc_core::StatusIntProperty::kHttp2Error,
GRPC_HTTP2_SETTINGS_TIMEOUT),
/*immediate_disconnect_hint=*/true);
close_transport_locked(
t.get(),
grpc_error_set_int(GRPC_ERROR_CREATE("settings timeout"),
grpc_core::StatusIntProperty::kRpcStatus,
GRPC_STATUS_UNAVAILABLE));
}),
absl::OkStatus());
}
namespace {

@ -217,12 +217,11 @@ absl::optional<std::string> HttpProxyMapper::MapName(
return absl::nullopt;
}
if (uri->scheme() == "unix") {
LOG(INFO) << "not using proxy for Unix domain socket '" << server_uri
<< "'";
VLOG(2) << "not using proxy for Unix domain socket '" << server_uri << "'";
return absl::nullopt;
}
if (uri->scheme() == "vsock") {
LOG(INFO) << "not using proxy for VSock '" << server_uri << "'";
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.
@ -235,17 +234,17 @@ absl::optional<std::string> HttpProxyMapper::MapName(
std::string server_port;
if (!SplitHostPort(absl::StripPrefix(uri->path(), "/"), &server_host,
&server_port)) {
LOG(INFO) << "unable to split host and port, not checking no_proxy list "
"for host '"
<< server_uri << "'";
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)) {
LOG(INFO) << "not using proxy for host in no_proxy list '" << server_uri
<< "'";
VLOG(2) << "not using proxy for host in no_proxy list '" << server_uri
<< "'";
return absl::nullopt;
}
}

@ -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;
}

@ -1297,9 +1297,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

@ -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 {

@ -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 {

@ -636,8 +636,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)
@ -691,7 +692,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));
@ -700,7 +702,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);
}

@ -71,7 +71,8 @@ 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();
@ -79,7 +80,8 @@ void WinSocket::Shutdown() {
// 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);
}
}

@ -42,7 +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();
LOG(INFO) << context_string << ": " << str;
GRPC_TRACE_LOG(event_engine_endpoint, INFO)
<< context_string << ": " << str;
}
}
@ -160,8 +161,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();
LOG(INFO) << "WindowsEndpoint::" << this
<< " WRITE (peer=" << peer_address_string_ << "): " << str;
GRPC_TRACE_LOG(event_engine_endpoint, INFO)
<< "WindowsEndpoint::" << this
<< " WRITE (peer=" << peer_address_string_ << "): " << str;
}
}
CHECK(data->Count() <= UINT_MAX);

@ -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;

@ -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);
}

@ -209,7 +209,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) {

@ -421,8 +421,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) {
LOG(INFO) << "Dropped >= " << dropped_connections_count
<< " new connection attempts due to high memory pressure";
GRPC_TRACE_LOG(tcp, INFO)
<< "Dropped >= " << dropped_connections_count
<< " new connection attempts due to high memory pressure";
}
close(fd);
continue;
@ -540,14 +541,14 @@ static grpc_error_handle add_wildcard_addrs_to_server(grpc_tcp_server* s,
}
if (*out_port > 0) {
if (!v6_err.ok()) {
LOG(INFO) << "Failed to add :: listener, "
<< "the environment may not support IPv6: "
<< grpc_core::StatusToString(v6_err);
GRPC_TRACE_LOG(tcp, INFO) << "Failed to add :: listener, "
<< "the environment may not support IPv6: "
<< grpc_core::StatusToString(v6_err);
}
if (!v4_err.ok()) {
LOG(INFO) << "Failed to add 0.0.0.0 listener, "
<< "the environment may not support IPv4: "
<< grpc_core::StatusToString(v4_err);
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 {

@ -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;

@ -302,12 +302,13 @@ bool Party::RunOneParticipant(int i) {
currently_polling_ = kNotPolling;
if (done) {
if (!name.empty()) {
LOG(INFO) << DebugTag() << "[" << name << "] end poll and finish job "
<< 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()) {
LOG(INFO) << DebugTag() << "[" << name << "] end poll";
GRPC_TRACE_LOG(promise_primitives, INFO)
<< DebugTag() << "[" << name << "] end poll";
}
return done;
}

@ -496,9 +496,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.
LOG(INFO) << "[grpclb " << parent_.get()
<< "] balancer channel in state:TRANSIENT_FAILURE ("
<< status.ToString() << "); entering fallback mode";
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_);
@ -673,9 +674,10 @@ class GrpcLb::Serverlist::AddressIterator final
server.load_balance_token, lb_token_length);
if (lb_token.empty()) {
auto addr_uri = grpc_sockaddr_to_uri(&addr);
LOG(INFO) << "Missing LB token for backend address '"
<< (addr_uri.ok() ? *addr_uri : addr_uri.status().ToString())
<< "'. The empty token will be used instead";
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(
@ -850,11 +852,12 @@ void GrpcLb::Helper::UpdateState(grpc_connectivity_state state,
client_stats = parent()->lb_calld_->client_stats()->Ref();
}
if (GRPC_TRACE_FLAG_ENABLED(glb)) {
LOG(INFO) << "[grpclb " << parent() << " helper " << this
<< "] state=" << ConnectivityStateName(state) << " ("
<< status.ToString() << ") wrapping child picker " << picker.get()
<< " (serverlist=" << serverlist.get()
<< ", client_stats=" << 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,

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

@ -389,16 +389,14 @@ std::unique_ptr<grpc::Server> ServerBuilder::BuildAndStart() {
if (has_sync_methods) {
// This is a Sync server
LOG(INFO) << "Synchronous server. Num CQs: "
<< sync_server_settings_.num_cqs
<< ", Min pollers: " << sync_server_settings_.min_pollers
<< ", Max Pollers: " << sync_server_settings_.max_pollers
<< ", CQ timeout (msec): "
<< sync_server_settings_.cq_timeout_msec;
VLOG(2) << "Synchronous server. Num CQs: " << sync_server_settings_.num_cqs
<< ", Min pollers: " << sync_server_settings_.min_pollers
<< ", Max Pollers: " << sync_server_settings_.max_pollers
<< ", CQ timeout (msec): " << sync_server_settings_.cq_timeout_msec;
}
if (has_callback_methods) {
LOG(INFO) << "Callback server.";
VLOG(2) << "Callback server.";
}
std::unique_ptr<grpc::Server> server(new grpc::Server(

Loading…
Cancel
Save