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

[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 #37039

COPYBARA_INTEGRATE_REVIEW=https://github.com/grpc/grpc/pull/37039 from tanvi-jagtap:large_file_01 d7705c0bf6
PiperOrigin-RevId: 646417700
pull/37042/head
Tanvi Jagtap 8 months ago committed by Copybara-Service
parent 44053ea490
commit 7040266dc6
  1. 278
      src/core/ext/transport/chttp2/transport/chttp2_transport.cc

@ -53,7 +53,6 @@
#include <grpc/slice_buffer.h> #include <grpc/slice_buffer.h>
#include <grpc/status.h> #include <grpc/status.h>
#include <grpc/support/alloc.h> #include <grpc/support/alloc.h>
#include <grpc/support/log.h>
#include <grpc/support/port_platform.h> #include <grpc/support/port_platform.h>
#include <grpc/support/time.h> #include <grpc/support/time.h>
@ -419,9 +418,9 @@ static void read_channel_args(grpc_chttp2_transport* t,
channel_args.GetInt(GRPC_ARG_HTTP2_INITIAL_SEQUENCE_NUMBER).value_or(-1); channel_args.GetInt(GRPC_ARG_HTTP2_INITIAL_SEQUENCE_NUMBER).value_or(-1);
if (initial_sequence_number > 0) { if (initial_sequence_number > 0) {
if ((t->next_stream_id & 1) != (initial_sequence_number & 1)) { if ((t->next_stream_id & 1) != (initial_sequence_number & 1)) {
gpr_log(GPR_ERROR, "%s: low bit must be %d on %s", LOG(ERROR) << GRPC_ARG_HTTP2_INITIAL_SEQUENCE_NUMBER
GRPC_ARG_HTTP2_INITIAL_SEQUENCE_NUMBER, t->next_stream_id & 1, << ": low bit must be " << (t->next_stream_id & 1) << " on "
is_client ? "client" : "server"); << (is_client ? "client" : "server");
} else { } else {
t->next_stream_id = static_cast<uint32_t>(initial_sequence_number); t->next_stream_id = static_cast<uint32_t>(initial_sequence_number);
} }
@ -527,8 +526,8 @@ static void read_channel_args(grpc_chttp2_transport* t,
t->max_concurrent_streams_policy.SetTarget(value); t->max_concurrent_streams_policy.SetTarget(value);
} }
} else if (channel_args.Contains(GRPC_ARG_MAX_CONCURRENT_STREAMS)) { } else if (channel_args.Contains(GRPC_ARG_MAX_CONCURRENT_STREAMS)) {
gpr_log(GPR_DEBUG, "%s is not available on clients", VLOG(2) << GRPC_ARG_MAX_CONCURRENT_STREAMS
GRPC_ARG_MAX_CONCURRENT_STREAMS); << " is not available on clients";
} }
value = value =
channel_args.GetInt(GRPC_ARG_HTTP2_HPACK_TABLE_SIZE_DECODER).value_or(-1); channel_args.GetInt(GRPC_ARG_HTTP2_HPACK_TABLE_SIZE_DECODER).value_or(-1);
@ -926,11 +925,11 @@ static const char* write_state_name(grpc_chttp2_write_state st) {
static void set_write_state(grpc_chttp2_transport* t, static void set_write_state(grpc_chttp2_transport* t,
grpc_chttp2_write_state st, const char* reason) { grpc_chttp2_write_state st, const char* reason) {
GRPC_CHTTP2_IF_TRACING( GRPC_TRACE_LOG(http, INFO)
gpr_log(GPR_INFO, "W:%p %s [%s] state %s -> %s [%s]", t, << "W:" << t << " " << (t->is_client ? "CLIENT" : "SERVER") << " ["
t->is_client ? "CLIENT" : "SERVER", << t->peer_string.as_string_view() << "] state "
std::string(t->peer_string.as_string_view()).c_str(), << write_state_name(t->write_state) << " -> " << write_state_name(st)
write_state_name(t->write_state), write_state_name(st), reason)); << " [" << reason << "]";
t->write_state = st; t->write_state = st;
// If the state is being reset back to idle, it means a write was just // If the state is being reset back to idle, it means a write was just
// finished. Make sure all the run_after_write closures are scheduled. // finished. Make sure all the run_after_write closures are scheduled.
@ -1020,11 +1019,10 @@ static void write_action_begin_locked(
// We had paused reading, because we had many induced frames (SETTINGS // We had paused reading, because we had many induced frames (SETTINGS
// ACK, PINGS ACK and RST_STREAMS) pending in t->qbuf. Now that we have // ACK, PINGS ACK and RST_STREAMS) pending in t->qbuf. Now that we have
// been able to flush qbuf, we can resume reading. // been able to flush qbuf, we can resume reading.
GRPC_CHTTP2_IF_TRACING(gpr_log( GRPC_TRACE_LOG(http, INFO)
GPR_INFO, << "transport " << t.get()
"transport %p : Resuming reading after being paused due to too " << " : Resuming reading after being paused due to too many unwritten "
"many unwritten SETTINGS ACK, PINGS ACK and RST_STREAM frames", "SETTINGS ACK, PINGS ACK and RST_STREAM frames";
t.get()));
t->reading_paused_on_pending_induced_frames = false; t->reading_paused_on_pending_induced_frames = false;
continue_read_action_locked(std::move(t)); continue_read_action_locked(std::move(t));
} }
@ -1151,15 +1149,15 @@ void grpc_chttp2_add_incoming_goaway(grpc_chttp2_transport* t,
static_cast<intptr_t>(goaway_error)), static_cast<intptr_t>(goaway_error)),
grpc_core::StatusIntProperty::kRpcStatus, GRPC_STATUS_UNAVAILABLE); grpc_core::StatusIntProperty::kRpcStatus, GRPC_STATUS_UNAVAILABLE);
GRPC_CHTTP2_IF_TRACING( GRPC_TRACE_LOG(http, INFO)
gpr_log(GPR_INFO, "transport %p got goaway with last stream id %d", t, << "transport " << t << " got goaway with last stream id "
last_stream_id)); << last_stream_id;
// We want to log this irrespective of whether http tracing is enabled if we // We want to log this irrespective of whether http tracing is enabled if we
// received a GOAWAY with a non NO_ERROR code. // received a GOAWAY with a non NO_ERROR code.
if (goaway_error != GRPC_HTTP2_NO_ERROR) { if (goaway_error != GRPC_HTTP2_NO_ERROR) {
gpr_log(GPR_INFO, "%s: Got goaway [%d] err=%s", LOG(INFO) << t->peer_string.as_string_view() << ": Got goaway ["
std::string(t->peer_string.as_string_view()).c_str(), goaway_error, << goaway_error
grpc_core::StatusToString(t->goaway_error).c_str()); << "] err=" << grpc_core::StatusToString(t->goaway_error);
} }
if (t->is_client) { if (t->is_client) {
cancel_unstarted_streams(t, t->goaway_error, false); cancel_unstarted_streams(t, t->goaway_error, false);
@ -1185,12 +1183,11 @@ void grpc_chttp2_add_incoming_goaway(grpc_chttp2_transport* t,
if (GPR_UNLIKELY(t->is_client && if (GPR_UNLIKELY(t->is_client &&
goaway_error == GRPC_HTTP2_ENHANCE_YOUR_CALM && goaway_error == GRPC_HTTP2_ENHANCE_YOUR_CALM &&
goaway_text == "too_many_pings")) { goaway_text == "too_many_pings")) {
gpr_log(GPR_ERROR, LOG(ERROR) << t->peer_string.as_string_view()
"%s: Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug " << ": Received a GOAWAY with error code ENHANCE_YOUR_CALM and "
"data equal to \"too_many_pings\". Current keepalive time (before " "debug data equal to \"too_many_pings\". Current keepalive "
"throttling): %s", "time (before throttling): "
std::string(t->peer_string.as_string_view()).c_str(), << t->keepalive_time.ToString();
t->keepalive_time.ToString().c_str());
constexpr int max_keepalive_time_millis = constexpr int max_keepalive_time_millis =
INT_MAX / KEEPALIVE_TIME_BACKOFF_MULTIPLIER; INT_MAX / KEEPALIVE_TIME_BACKOFF_MULTIPLIER;
int64_t throttled_keepalive_time = int64_t throttled_keepalive_time =
@ -1222,10 +1219,10 @@ static void maybe_start_some_streams(grpc_chttp2_transport* t) {
t->stream_map.size() < t->settings.peer().max_concurrent_streams() && t->stream_map.size() < t->settings.peer().max_concurrent_streams() &&
grpc_chttp2_list_pop_waiting_for_concurrency(t, &s)) { grpc_chttp2_list_pop_waiting_for_concurrency(t, &s)) {
// safe since we can't (legally) be parsing this stream yet // safe since we can't (legally) be parsing this stream yet
GRPC_CHTTP2_IF_TRACING(gpr_log( GRPC_TRACE_LOG(http, INFO)
GPR_INFO, << "HTTP:" << (t->is_client ? "CLI" : "SVR") << ": Transport " << t
"HTTP:%s: Transport %p allocating new grpc_chttp2_stream %p to id %d", << " allocating new grpc_chttp2_stream " << s << " to id "
t->is_client ? "CLI" : "SVR", t, s, t->next_stream_id)); << t->next_stream_id;
CHECK_EQ(s->id, 0u); CHECK_EQ(s->id, 0u);
s->id = t->next_stream_id; s->id = t->next_stream_id;
@ -1288,17 +1285,13 @@ void grpc_chttp2_complete_closure_step(grpc_chttp2_transport* t,
} }
closure->next_data.scratch -= CLOSURE_BARRIER_FIRST_REF_BIT; closure->next_data.scratch -= CLOSURE_BARRIER_FIRST_REF_BIT;
if (GRPC_TRACE_FLAG_ENABLED(http)) { if (GRPC_TRACE_FLAG_ENABLED(http)) {
gpr_log( LOG(INFO) << "complete_closure_step: t=" << t << " " << closure << " refs="
GPR_INFO, << (closure->next_data.scratch / CLOSURE_BARRIER_FIRST_REF_BIT)
"complete_closure_step: t=%p %p refs=%d flags=0x%04x desc=%s err=%s " << " flags="
"write_state=%s whence=%s:%d", << (closure->next_data.scratch % CLOSURE_BARRIER_FIRST_REF_BIT)
t, closure, << " desc=" << desc << " err=" << grpc_core::StatusToString(error)
static_cast<int>(closure->next_data.scratch / << " write_state=" << write_state_name(t->write_state)
CLOSURE_BARRIER_FIRST_REF_BIT), << " whence=" << whence.file() << ":" << whence.line();
static_cast<int>(closure->next_data.scratch %
CLOSURE_BARRIER_FIRST_REF_BIT),
desc, grpc_core::StatusToString(error).c_str(),
write_state_name(t->write_state), whence.file(), whence.line());
} }
if (!error.ok()) { if (!error.ok()) {
@ -1341,7 +1334,7 @@ static void log_metadata(const grpc_metadata_batch* md_batch, uint32_t id,
const std::string prefix = absl::StrCat( const std::string prefix = absl::StrCat(
"HTTP:", id, is_initial ? ":HDR" : ":TRL", is_client ? ":CLI:" : ":SVR:"); "HTTP:", id, is_initial ? ":HDR" : ":TRL", is_client ? ":CLI:" : ":SVR:");
md_batch->Log([&prefix](absl::string_view key, absl::string_view value) { md_batch->Log([&prefix](absl::string_view key, absl::string_view value) {
VLOG(2) << absl::StrCat(prefix, key, ": ", value); VLOG(2) << prefix << key << ": " << value;
}); });
} }
@ -1358,10 +1351,9 @@ static void perform_stream_op_locked(void* stream_op,
s->call_tracer = CallTracerIfSampled(s); s->call_tracer = CallTracerIfSampled(s);
s->tcp_tracer = TcpTracerIfSampled(s); s->tcp_tracer = TcpTracerIfSampled(s);
if (GRPC_TRACE_FLAG_ENABLED(http)) { if (GRPC_TRACE_FLAG_ENABLED(http)) {
gpr_log(GPR_INFO, LOG(INFO) << "perform_stream_op_locked[s=" << s << "; op=" << op
"perform_stream_op_locked[s=%p; op=%p]: %s; on_complete = %p", s, << "]: " << grpc_transport_stream_op_batch_string(op, false)
op, grpc_transport_stream_op_batch_string(op, false).c_str(), << "; on_complete = " << op->on_complete;
op->on_complete);
if (op->send_initial_metadata) { if (op->send_initial_metadata) {
log_metadata(op_payload->send_initial_metadata.send_initial_metadata, log_metadata(op_payload->send_initial_metadata.send_initial_metadata,
s->id, t->is_client, true); s->id, t->is_client, true);
@ -1625,8 +1617,8 @@ void grpc_chttp2_transport::PerformStreamOp(
} }
if (GRPC_TRACE_FLAG_ENABLED(http)) { if (GRPC_TRACE_FLAG_ENABLED(http)) {
gpr_log(GPR_INFO, "perform_stream_op[s=%p; op=%p]: %s", s, op, LOG(INFO) << "perform_stream_op[s=" << s << "; op=" << op
grpc_transport_stream_op_batch_string(op, false).c_str()); << "]: " << grpc_transport_stream_op_batch_string(op, false);
} }
GRPC_CHTTP2_STREAM_REF(s, "perform_stream_op"); GRPC_CHTTP2_STREAM_REF(s, "perform_stream_op");
@ -1637,8 +1629,8 @@ void grpc_chttp2_transport::PerformStreamOp(
} }
static void cancel_pings(grpc_chttp2_transport* t, grpc_error_handle error) { static void cancel_pings(grpc_chttp2_transport* t, grpc_error_handle error) {
GRPC_CHTTP2_IF_TRACING(gpr_log(GPR_INFO, "%p CANCEL PINGS: %s", t, GRPC_TRACE_LOG(http, INFO)
grpc_core::StatusToString(error).c_str())); << t << " CANCEL PINGS: " << grpc_core::StatusToString(error);
// callback remaining pings: they're not allowed to call into the transport, // callback remaining pings: they're not allowed to call into the transport,
// and maybe they hold resources that need to be freed // and maybe they hold resources that need to be freed
t->ping_callbacks.CancelAll(t->event_engine.get()); t->ping_callbacks.CancelAll(t->event_engine.get());
@ -1721,8 +1713,8 @@ static void retry_initiate_ping_locked(
void grpc_chttp2_ack_ping(grpc_chttp2_transport* t, uint64_t id) { void grpc_chttp2_ack_ping(grpc_chttp2_transport* t, uint64_t id) {
if (!t->ping_callbacks.AckPing(id, t->event_engine.get())) { if (!t->ping_callbacks.AckPing(id, t->event_engine.get())) {
gpr_log(GPR_DEBUG, "Unknown ping response from %s: %" PRIx64, VLOG(2) << "Unknown ping response from " << t->peer_string.as_string_view()
std::string(t->peer_string.as_string_view()).c_str(), id); << ": " << id;
return; return;
} }
if (t->ping_callbacks.ping_requested()) { if (t->ping_callbacks.ping_requested()) {
@ -1732,19 +1724,18 @@ void grpc_chttp2_ack_ping(grpc_chttp2_transport* t, uint64_t id) {
void grpc_chttp2_keepalive_timeout( void grpc_chttp2_keepalive_timeout(
grpc_core::RefCountedPtr<grpc_chttp2_transport> t) { grpc_core::RefCountedPtr<grpc_chttp2_transport> t) {
t->combiner->Run( t->combiner->Run(grpc_core::NewClosure([t](grpc_error_handle) {
grpc_core::NewClosure([t](grpc_error_handle) { LOG(INFO) << t->peer_string.as_string_view()
gpr_log(GPR_INFO, "%s: Keepalive timeout. Closing transport.", << ": Keepalive timeout. Closing transport.";
std::string(t->peer_string.as_string_view()).c_str()); send_goaway(t.get(),
send_goaway( grpc_error_set_int(
t.get(), GRPC_ERROR_CREATE("keepalive_timeout"),
grpc_error_set_int(GRPC_ERROR_CREATE("keepalive_timeout"),
grpc_core::StatusIntProperty::kHttp2Error, grpc_core::StatusIntProperty::kHttp2Error,
GRPC_HTTP2_ENHANCE_YOUR_CALM), GRPC_HTTP2_ENHANCE_YOUR_CALM),
/*immediate_disconnect_hint=*/true); /*immediate_disconnect_hint=*/true);
close_transport_locked( close_transport_locked(
t.get(), t.get(), grpc_error_set_int(
grpc_error_set_int(GRPC_ERROR_CREATE("keepalive timeout"), GRPC_ERROR_CREATE("keepalive timeout"),
grpc_core::StatusIntProperty::kRpcStatus, grpc_core::StatusIntProperty::kRpcStatus,
GRPC_STATUS_UNAVAILABLE)); GRPC_STATUS_UNAVAILABLE));
}), }),
@ -1753,19 +1744,18 @@ void grpc_chttp2_keepalive_timeout(
void grpc_chttp2_ping_timeout( void grpc_chttp2_ping_timeout(
grpc_core::RefCountedPtr<grpc_chttp2_transport> t) { grpc_core::RefCountedPtr<grpc_chttp2_transport> t) {
t->combiner->Run( t->combiner->Run(grpc_core::NewClosure([t](grpc_error_handle) {
grpc_core::NewClosure([t](grpc_error_handle) { LOG(INFO) << t->peer_string.as_string_view()
gpr_log(GPR_INFO, "%s: Ping timeout. Closing transport.", << ": Ping timeout. Closing transport.";
std::string(t->peer_string.as_string_view()).c_str()); send_goaway(t.get(),
send_goaway( grpc_error_set_int(
t.get(), GRPC_ERROR_CREATE("ping_timeout"),
grpc_error_set_int(GRPC_ERROR_CREATE("ping_timeout"),
grpc_core::StatusIntProperty::kHttp2Error, grpc_core::StatusIntProperty::kHttp2Error,
GRPC_HTTP2_ENHANCE_YOUR_CALM), GRPC_HTTP2_ENHANCE_YOUR_CALM),
/*immediate_disconnect_hint=*/true); /*immediate_disconnect_hint=*/true);
close_transport_locked( close_transport_locked(
t.get(), t.get(), grpc_error_set_int(
grpc_error_set_int(GRPC_ERROR_CREATE("ping timeout"), GRPC_ERROR_CREATE("ping timeout"),
grpc_core::StatusIntProperty::kRpcStatus, grpc_core::StatusIntProperty::kRpcStatus,
GRPC_STATUS_UNAVAILABLE)); GRPC_STATUS_UNAVAILABLE));
}), }),
@ -1774,19 +1764,18 @@ void grpc_chttp2_ping_timeout(
void grpc_chttp2_settings_timeout( void grpc_chttp2_settings_timeout(
grpc_core::RefCountedPtr<grpc_chttp2_transport> t) { grpc_core::RefCountedPtr<grpc_chttp2_transport> t) {
t->combiner->Run( t->combiner->Run(grpc_core::NewClosure([t](grpc_error_handle) {
grpc_core::NewClosure([t](grpc_error_handle) { LOG(INFO) << t->peer_string.as_string_view()
gpr_log(GPR_INFO, "%s: Settings timeout. Closing transport.", << ": Settings timeout. Closing transport.";
std::string(t->peer_string.as_string_view()).c_str()); send_goaway(t.get(),
send_goaway( grpc_error_set_int(
t.get(), GRPC_ERROR_CREATE("settings_timeout"),
grpc_error_set_int(GRPC_ERROR_CREATE("settings_timeout"),
grpc_core::StatusIntProperty::kHttp2Error, grpc_core::StatusIntProperty::kHttp2Error,
GRPC_HTTP2_SETTINGS_TIMEOUT), GRPC_HTTP2_SETTINGS_TIMEOUT),
/*immediate_disconnect_hint=*/true); /*immediate_disconnect_hint=*/true);
close_transport_locked( close_transport_locked(
t.get(), t.get(), grpc_error_set_int(
grpc_error_set_int(GRPC_ERROR_CREATE("settings timeout"), GRPC_ERROR_CREATE("settings timeout"),
grpc_core::StatusIntProperty::kRpcStatus, grpc_core::StatusIntProperty::kRpcStatus,
GRPC_STATUS_UNAVAILABLE)); GRPC_STATUS_UNAVAILABLE));
}), }),
@ -1827,22 +1816,21 @@ class GracefulGoaway : public grpc_core::RefCounted<GracefulGoaway> {
return; return;
} }
if (t_->destroying || !t_->closed_with_error.ok()) { if (t_->destroying || !t_->closed_with_error.ok()) {
GRPC_CHTTP2_IF_TRACING( GRPC_TRACE_LOG(http, INFO) << "transport:" << t_.get() << " "
gpr_log(GPR_INFO, << (t_->is_client ? "CLIENT" : "SERVER")
"transport:%p %s peer:%s Transport already shutting down. " << " peer:" << t_->peer_string.as_string_view()
"Graceful GOAWAY abandoned.", << " Transport already shutting down. "
t_.get(), t_->is_client ? "CLIENT" : "SERVER", "Graceful GOAWAY abandoned.";
std::string(t_->peer_string.as_string_view()).c_str()));
return; return;
} }
// Ping completed. Send final goaway. // Ping completed. Send final goaway.
GRPC_CHTTP2_IF_TRACING( GRPC_TRACE_LOG(http, INFO)
gpr_log(GPR_INFO, << "transport:" << t_.get() << " "
"transport:%p %s peer:%s Graceful shutdown: Ping received. " << (t_->is_client ? "CLIENT" : "SERVER")
"Sending final GOAWAY with stream_id:%d", << " peer:" << std::string(t_->peer_string.as_string_view())
t_.get(), t_->is_client ? "CLIENT" : "SERVER", << " Graceful shutdown: Ping received. "
std::string(t_->peer_string.as_string_view()).c_str(), "Sending final GOAWAY with stream_id:"
t_->last_new_stream_id)); << t_->last_new_stream_id;
t_->sent_goaway_state = GRPC_CHTTP2_FINAL_GOAWAY_SEND_SCHEDULED; t_->sent_goaway_state = GRPC_CHTTP2_FINAL_GOAWAY_SEND_SCHEDULED;
grpc_chttp2_goaway_append(t_->last_new_stream_id, 0, grpc_empty_slice(), grpc_chttp2_goaway_append(t_->last_new_stream_id, 0, grpc_empty_slice(),
&t_->qbuf); &t_->qbuf);
@ -1886,10 +1874,10 @@ static void send_goaway(grpc_chttp2_transport* t, grpc_error_handle error,
} else if (t->sent_goaway_state == GRPC_CHTTP2_NO_GOAWAY_SEND || } else if (t->sent_goaway_state == GRPC_CHTTP2_NO_GOAWAY_SEND ||
t->sent_goaway_state == GRPC_CHTTP2_GRACEFUL_GOAWAY) { t->sent_goaway_state == GRPC_CHTTP2_GRACEFUL_GOAWAY) {
// We want to log this irrespective of whether http tracing is enabled // We want to log this irrespective of whether http tracing is enabled
gpr_log(GPR_DEBUG, "%s %s: Sending goaway last_new_stream_id=%d err=%s", VLOG(2) << t->peer_string.as_string_view() << " "
std::string(t->peer_string.as_string_view()).c_str(), << (t->is_client ? "CLIENT" : "SERVER")
t->is_client ? "CLIENT" : "SERVER", t->last_new_stream_id, << ": Sending goaway last_new_stream_id=" << t->last_new_stream_id
grpc_core::StatusToString(error).c_str()); << " err=" << grpc_core::StatusToString(error);
t->sent_goaway_state = GRPC_CHTTP2_FINAL_GOAWAY_SEND_SCHEDULED; t->sent_goaway_state = GRPC_CHTTP2_FINAL_GOAWAY_SEND_SCHEDULED;
grpc_chttp2_goaway_append( grpc_chttp2_goaway_append(
t->last_new_stream_id, static_cast<uint32_t>(http_error), t->last_new_stream_id, static_cast<uint32_t>(http_error),
@ -1973,8 +1961,8 @@ static void perform_transport_op_locked(void* stream_op,
void grpc_chttp2_transport::PerformOp(grpc_transport_op* op) { void grpc_chttp2_transport::PerformOp(grpc_transport_op* op) {
if (GRPC_TRACE_FLAG_ENABLED(http)) { if (GRPC_TRACE_FLAG_ENABLED(http)) {
gpr_log(GPR_INFO, "perform_transport_op[t=%p]: %s", this, LOG(INFO) << "perform_transport_op[t=" << this
grpc_transport_op_string(op).c_str()); << "]: " << grpc_transport_op_string(op);
} }
op->handler_private.extra_arg = this; op->handler_private.extra_arg = this;
Ref().release()->combiner->Run( Ref().release()->combiner->Run(
@ -2026,10 +2014,9 @@ void grpc_chttp2_maybe_complete_recv_message(grpc_chttp2_transport* t,
// exited out of at any point by returning. // exited out of at any point by returning.
[&]() { [&]() {
if (GRPC_TRACE_FLAG_ENABLED(http)) { if (GRPC_TRACE_FLAG_ENABLED(http)) {
gpr_log(GPR_DEBUG, VLOG(2) << "maybe_complete_recv_message " << s
"maybe_complete_recv_message %p final_metadata_requested=%d " << " final_metadata_requested=" << s->final_metadata_requested
"seen_error=%d", << " seen_error=" << s->seen_error;
s, s->final_metadata_requested, s->seen_error);
} }
if (s->final_metadata_requested && s->seen_error) { if (s->final_metadata_requested && s->seen_error) {
grpc_slice_buffer_reset_and_unref(&s->frame_storage); grpc_slice_buffer_reset_and_unref(&s->frame_storage);
@ -2042,10 +2029,9 @@ void grpc_chttp2_maybe_complete_recv_message(grpc_chttp2_transport* t,
auto r = grpc_deframe_unprocessed_incoming_frames( auto r = grpc_deframe_unprocessed_incoming_frames(
s, &min_progress_size, &**s->recv_message, s->recv_message_flags); s, &min_progress_size, &**s->recv_message, s->recv_message_flags);
if (GRPC_TRACE_FLAG_ENABLED(http)) { if (GRPC_TRACE_FLAG_ENABLED(http)) {
gpr_log(GPR_DEBUG, "Deframe data frame: %s", VLOG(2) << "Deframe data frame: "
grpc_core::PollToString(r, [](absl::Status r) { << grpc_core::PollToString(
return r.ToString(); r, [](absl::Status r) { return r.ToString(); });
}).c_str());
} }
if (r.pending()) { if (r.pending()) {
if (s->read_closed) { if (s->read_closed) {
@ -2098,12 +2084,11 @@ void grpc_chttp2_maybe_complete_recv_trailing_metadata(grpc_chttp2_transport* t,
grpc_chttp2_stream* s) { grpc_chttp2_stream* s) {
grpc_chttp2_maybe_complete_recv_message(t, s); grpc_chttp2_maybe_complete_recv_message(t, s);
if (GRPC_TRACE_FLAG_ENABLED(http)) { if (GRPC_TRACE_FLAG_ENABLED(http)) {
gpr_log(GPR_DEBUG, VLOG(2) << "maybe_complete_recv_trailing_metadata cli=" << t->is_client
"maybe_complete_recv_trailing_metadata cli=%d s=%p closure=%p " << " s=" << s << " closure=" << s->recv_trailing_metadata_finished
"read_closed=%d " << " read_closed=" << s->read_closed
"write_closed=%d %" PRIdPTR, << " write_closed=" << s->write_closed << " "
t->is_client, s, s->recv_trailing_metadata_finished, s->read_closed, << s->frame_storage.length;
s->write_closed, s->frame_storage.length);
} }
if (s->recv_trailing_metadata_finished != nullptr && s->read_closed && if (s->recv_trailing_metadata_finished != nullptr && s->read_closed &&
s->write_closed) { s->write_closed) {
@ -2309,12 +2294,13 @@ grpc_chttp2_transport::RemovedStreamHandle grpc_chttp2_mark_stream_closed(
int close_writes, grpc_error_handle error) { int close_writes, grpc_error_handle error) {
grpc_chttp2_transport::RemovedStreamHandle rsh; grpc_chttp2_transport::RemovedStreamHandle rsh;
if (GRPC_TRACE_FLAG_ENABLED(http)) { if (GRPC_TRACE_FLAG_ENABLED(http)) {
gpr_log( VLOG(2) << "MARK_STREAM_CLOSED: t=" << t << " s=" << s << "(id=" << s->id
GPR_DEBUG, "MARK_STREAM_CLOSED: t=%p s=%p(id=%d) %s [%s]", t, s, s->id, << ") "
(close_reads && close_writes) << ((close_reads && close_writes)
? "read+write" ? "read+write"
: (close_reads ? "read" : (close_writes ? "write" : "nothing??")), : (close_reads ? "read"
grpc_core::StatusToString(error).c_str()); : (close_writes ? "write" : "nothing??")))
<< " [" << grpc_core::StatusToString(error) << "]";
} }
if (s->read_closed && s->write_closed) { if (s->read_closed && s->write_closed) {
// already closed, but we should still fake the status if needed. // already closed, but we should still fake the status if needed.
@ -2722,11 +2708,10 @@ static void read_action_parse_loop_locked(
if (keep_reading) { if (keep_reading) {
if (t->num_pending_induced_frames >= DEFAULT_MAX_PENDING_INDUCED_FRAMES) { if (t->num_pending_induced_frames >= DEFAULT_MAX_PENDING_INDUCED_FRAMES) {
t->reading_paused_on_pending_induced_frames = true; t->reading_paused_on_pending_induced_frames = true;
GRPC_CHTTP2_IF_TRACING( GRPC_TRACE_LOG(http, INFO)
gpr_log(GPR_INFO, << "transport " << t.get()
"transport %p : Pausing reading due to too " << " : Pausing reading due to too many unwritten "
"many unwritten SETTINGS ACK and RST_STREAM frames", "SETTINGS ACK and RST_STREAM frames";
t.get()));
} else { } else {
continue_read_action_locked(std::move(t)); continue_read_action_locked(std::move(t));
} }
@ -2741,9 +2726,8 @@ static void read_action_locked(
if (t->keepalive_ping_timeout_handle != TaskHandle::kInvalid) { if (t->keepalive_ping_timeout_handle != TaskHandle::kInvalid) {
if (GRPC_TRACE_FLAG_ENABLED(http2_ping) || if (GRPC_TRACE_FLAG_ENABLED(http2_ping) ||
GRPC_TRACE_FLAG_ENABLED(http_keepalive)) { GRPC_TRACE_FLAG_ENABLED(http_keepalive)) {
gpr_log(GPR_INFO, LOG(INFO) << (t->is_client ? "CLIENT" : "SERVER") << "[" << t.get()
"%s[%p]: Clear keepalive timer because data was received", << "]: Clear keepalive timer because data was received";
t->is_client ? "CLIENT" : "SERVER", t.get());
} }
t->event_engine->Cancel( t->event_engine->Cancel(
std::exchange(t->keepalive_ping_timeout_handle, TaskHandle::kInvalid)); std::exchange(t->keepalive_ping_timeout_handle, TaskHandle::kInvalid));
@ -2794,9 +2778,8 @@ static void start_bdp_ping_locked(
grpc_core::RefCountedPtr<grpc_chttp2_transport> t, grpc_core::RefCountedPtr<grpc_chttp2_transport> t,
grpc_error_handle error) { grpc_error_handle error) {
if (GRPC_TRACE_FLAG_ENABLED(http)) { if (GRPC_TRACE_FLAG_ENABLED(http)) {
gpr_log(GPR_INFO, "%s: Start BDP ping err=%s", LOG(INFO) << t->peer_string.as_string_view()
std::string(t->peer_string.as_string_view()).c_str(), << ": Start BDP ping err=" << grpc_core::StatusToString(error);
grpc_core::StatusToString(error).c_str());
} }
if (!error.ok() || !t->closed_with_error.ok()) { if (!error.ok() || !t->closed_with_error.ok()) {
return; return;
@ -2821,9 +2804,8 @@ static void finish_bdp_ping_locked(
grpc_core::RefCountedPtr<grpc_chttp2_transport> t, grpc_core::RefCountedPtr<grpc_chttp2_transport> t,
grpc_error_handle error) { grpc_error_handle error) {
if (GRPC_TRACE_FLAG_ENABLED(http)) { if (GRPC_TRACE_FLAG_ENABLED(http)) {
gpr_log(GPR_INFO, "%s: Complete BDP ping err=%s", LOG(INFO) << t->peer_string.as_string_view()
std::string(t->peer_string.as_string_view()).c_str(), << ": Complete BDP ping err=" << grpc_core::StatusToString(error);
grpc_core::StatusToString(error).c_str());
} }
if (!error.ok() || !t->closed_with_error.ok()) { if (!error.ok() || !t->closed_with_error.ok()) {
return; return;
@ -2966,8 +2948,8 @@ static void finish_keepalive_ping_locked(
if (error.ok()) { if (error.ok()) {
if (GRPC_TRACE_FLAG_ENABLED(http) || if (GRPC_TRACE_FLAG_ENABLED(http) ||
GRPC_TRACE_FLAG_ENABLED(http_keepalive)) { GRPC_TRACE_FLAG_ENABLED(http_keepalive)) {
gpr_log(GPR_INFO, "%s: Finish keepalive ping", LOG(INFO) << t->peer_string.as_string_view()
std::string(t->peer_string.as_string_view()).c_str()); << ": Finish keepalive ping";
} }
t->keepalive_state = GRPC_CHTTP2_KEEPALIVE_STATE_WAITING; t->keepalive_state = GRPC_CHTTP2_KEEPALIVE_STATE_WAITING;
CHECK(t->keepalive_ping_timer_handle == TaskHandle::kInvalid); CHECK(t->keepalive_ping_timer_handle == TaskHandle::kInvalid);
@ -2988,8 +2970,8 @@ static void maybe_reset_keepalive_ping_timer_locked(grpc_chttp2_transport* t) {
// need to Ref or Unref here since we still hold the Ref. // need to Ref or Unref here since we still hold the Ref.
if (GRPC_TRACE_FLAG_ENABLED(http) || if (GRPC_TRACE_FLAG_ENABLED(http) ||
GRPC_TRACE_FLAG_ENABLED(http_keepalive)) { GRPC_TRACE_FLAG_ENABLED(http_keepalive)) {
gpr_log(GPR_INFO, "%s: Keepalive ping cancelled. Resetting timer.", LOG(INFO) << t->peer_string.as_string_view()
std::string(t->peer_string.as_string_view()).c_str()); << ": Keepalive ping cancelled. Resetting timer.";
} }
t->keepalive_ping_timer_handle = t->keepalive_ping_timer_handle =
t->event_engine->RunAfter(t->keepalive_time, [t = t->Ref()]() mutable { t->event_engine->RunAfter(t->keepalive_time, [t = t->Ref()]() mutable {
@ -3008,9 +2990,9 @@ static void connectivity_state_set(grpc_chttp2_transport* t,
grpc_connectivity_state state, grpc_connectivity_state state,
const absl::Status& status, const absl::Status& status,
const char* reason) { const char* reason) {
GRPC_CHTTP2_IF_TRACING(gpr_log( GRPC_TRACE_LOG(http, INFO)
GPR_INFO, "transport %p set connectivity_state=%d; status=%s; reason=%s", << "transport " << t << " set connectivity_state=" << state
t, state, status.ToString().c_str(), reason)); << "; status=" << status.ToString() << "; reason=" << reason;
t->state_tracker.SetState(state, status, reason); t->state_tracker.SetState(state, status, reason);
} }
@ -3087,8 +3069,8 @@ static void benign_reclaimer_locked(
// Channel with no active streams: send a goaway to try and make it // Channel with no active streams: send a goaway to try and make it
// disconnect cleanly // disconnect cleanly
if (GRPC_TRACE_FLAG_ENABLED(resource_quota)) { if (GRPC_TRACE_FLAG_ENABLED(resource_quota)) {
gpr_log(GPR_INFO, "HTTP2: %s - send goaway to free memory", LOG(INFO) << "HTTP2: " << t->peer_string.as_string_view()
std::string(t->peer_string.as_string_view()).c_str()); << " - send goaway to free memory";
} }
send_goaway(t.get(), send_goaway(t.get(),
grpc_error_set_int(GRPC_ERROR_CREATE("Buffers full"), grpc_error_set_int(GRPC_ERROR_CREATE("Buffers full"),
@ -3096,11 +3078,9 @@ static void benign_reclaimer_locked(
GRPC_HTTP2_ENHANCE_YOUR_CALM), GRPC_HTTP2_ENHANCE_YOUR_CALM),
/*immediate_disconnect_hint=*/true); /*immediate_disconnect_hint=*/true);
} else if (error.ok() && GRPC_TRACE_FLAG_ENABLED(resource_quota)) { } else if (error.ok() && GRPC_TRACE_FLAG_ENABLED(resource_quota)) {
gpr_log(GPR_INFO, LOG(INFO) << "HTTP2: " << t->peer_string.as_string_view()
"HTTP2: %s - skip benign reclamation, there are still %" PRIdPTR << " - skip benign reclamation, there are still "
" streams", << t->stream_map.size() << " streams";
std::string(t->peer_string.as_string_view()).c_str(),
t->stream_map.size());
} }
t->benign_reclaimer_registered = false; t->benign_reclaimer_registered = false;
if (error != absl::CancelledError()) { if (error != absl::CancelledError()) {
@ -3116,8 +3096,8 @@ static void destructive_reclaimer_locked(
// As stream_map is a hash map, this selects effectively a random stream. // As stream_map is a hash map, this selects effectively a random stream.
grpc_chttp2_stream* s = t->stream_map.begin()->second; grpc_chttp2_stream* s = t->stream_map.begin()->second;
if (GRPC_TRACE_FLAG_ENABLED(resource_quota)) { if (GRPC_TRACE_FLAG_ENABLED(resource_quota)) {
gpr_log(GPR_INFO, "HTTP2: %s - abandon stream id %d", LOG(INFO) << "HTTP2: " << t->peer_string.as_string_view()
std::string(t->peer_string.as_string_view()).c_str(), s->id); << " - abandon stream id " << s->id;
} }
grpc_chttp2_cancel_stream( grpc_chttp2_cancel_stream(
t.get(), s, t.get(), s,

Loading…
Cancel
Save