From 25797cf8062288a24fe300307f356dc9665776e8 Mon Sep 17 00:00:00 2001 From: Yash Tibrewal Date: Wed, 6 Feb 2019 18:45:06 -0800 Subject: [PATCH 1/2] Add logging around GOAWAYs and keepalives --- .../chttp2/transport/chttp2_transport.cc | 16 +++++++++++++--- 1 file changed, 13 insertions(+), 3 deletions(-) diff --git a/src/core/ext/transport/chttp2/transport/chttp2_transport.cc b/src/core/ext/transport/chttp2/transport/chttp2_transport.cc index c2b57ed2905..34477c93230 100644 --- a/src/core/ext/transport/chttp2/transport/chttp2_transport.cc +++ b/src/core/ext/transport/chttp2/transport/chttp2_transport.cc @@ -1119,9 +1119,6 @@ static void queue_setting_update(grpc_chttp2_transport* t, void grpc_chttp2_add_incoming_goaway(grpc_chttp2_transport* t, uint32_t goaway_error, grpc_slice goaway_text) { - // GRPC_CHTTP2_IF_TRACING( - // gpr_log(GPR_INFO, "got goaway [%d]: %s", goaway_error, msg)); - // Discard the error from a previous goaway frame (if any) if (t->goaway_error != GRPC_ERROR_NONE) { GRPC_ERROR_UNREF(t->goaway_error); @@ -1132,6 +1129,9 @@ void grpc_chttp2_add_incoming_goaway(grpc_chttp2_transport* t, GRPC_ERROR_INT_HTTP2_ERROR, static_cast(goaway_error)), GRPC_ERROR_STR_RAW_BYTES, goaway_text); + gpr_log(GPR_ERROR, "%s: Got goaway [%d] err=%s", t->peer_string, goaway_error, + grpc_error_string(t->goaway_error)); + /* When a client receives a GOAWAY with error code ENHANCE_YOUR_CALM and debug * data equal to "too_many_pings", it should log the occurrence at a log level * that is enabled by default and double the configured KEEPALIVE_TIME used @@ -1774,6 +1774,8 @@ void grpc_chttp2_ack_ping(grpc_chttp2_transport* t, uint64_t id) { } static void send_goaway(grpc_chttp2_transport* t, grpc_error* error) { + gpr_log(GPR_ERROR, "%s: Sending goaway err=%s", t->peer_string, + grpc_error_string(error)); t->sent_goaway_state = GRPC_CHTTP2_GOAWAY_SEND_SCHEDULED; grpc_http2_error_code http_error; grpc_slice slice; @@ -2723,6 +2725,9 @@ static void start_keepalive_ping_locked(void* arg, grpc_error* error) { if (t->channelz_socket != nullptr) { t->channelz_socket->RecordKeepaliveSent(); } + if (grpc_http_trace.enabled()) { + gpr_log(GPR_INFO, "%s: Start keepalive ping", t->peer_string); + } GRPC_CHTTP2_REF_TRANSPORT(t, "keepalive watchdog"); grpc_timer_init(&t->keepalive_watchdog_timer, grpc_core::ExecCtx::Get()->Now() + t->keepalive_timeout, @@ -2733,6 +2738,9 @@ static void finish_keepalive_ping_locked(void* arg, grpc_error* error) { grpc_chttp2_transport* t = static_cast(arg); if (t->keepalive_state == GRPC_CHTTP2_KEEPALIVE_STATE_PINGING) { if (error == GRPC_ERROR_NONE) { + if (grpc_http_trace.enabled()) { + gpr_log(GPR_INFO, "%s: Finish keepalive ping", t->peer_string); + } t->keepalive_state = GRPC_CHTTP2_KEEPALIVE_STATE_WAITING; grpc_timer_cancel(&t->keepalive_watchdog_timer); GRPC_CHTTP2_REF_TRANSPORT(t, "init keepalive ping"); @@ -2748,6 +2756,8 @@ static void keepalive_watchdog_fired_locked(void* arg, grpc_error* error) { grpc_chttp2_transport* t = static_cast(arg); if (t->keepalive_state == GRPC_CHTTP2_KEEPALIVE_STATE_PINGING) { if (error == GRPC_ERROR_NONE) { + gpr_log(GPR_ERROR, "%s: Keepalive watchdog fired. Closing transport.", + t->peer_string); t->keepalive_state = GRPC_CHTTP2_KEEPALIVE_STATE_DYING; close_transport_locked( t, grpc_error_set_int(GRPC_ERROR_CREATE_FROM_STATIC_STRING( From 3af64e8495c8cb62966273db5c48c95f5e4ab905 Mon Sep 17 00:00:00 2001 From: Yash Tibrewal Date: Wed, 6 Feb 2019 19:22:15 -0800 Subject: [PATCH 2/2] Reduce logging level to info from error for goaway --- src/core/ext/transport/chttp2/transport/chttp2_transport.cc | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/src/core/ext/transport/chttp2/transport/chttp2_transport.cc b/src/core/ext/transport/chttp2/transport/chttp2_transport.cc index 34477c93230..8e8c9b88493 100644 --- a/src/core/ext/transport/chttp2/transport/chttp2_transport.cc +++ b/src/core/ext/transport/chttp2/transport/chttp2_transport.cc @@ -1129,7 +1129,8 @@ void grpc_chttp2_add_incoming_goaway(grpc_chttp2_transport* t, GRPC_ERROR_INT_HTTP2_ERROR, static_cast(goaway_error)), GRPC_ERROR_STR_RAW_BYTES, goaway_text); - gpr_log(GPR_ERROR, "%s: Got goaway [%d] err=%s", t->peer_string, goaway_error, + /* We want to log this irrespective of whether http tracing is enabled */ + gpr_log(GPR_INFO, "%s: Got goaway [%d] err=%s", t->peer_string, goaway_error, grpc_error_string(t->goaway_error)); /* When a client receives a GOAWAY with error code ENHANCE_YOUR_CALM and debug @@ -1774,7 +1775,8 @@ void grpc_chttp2_ack_ping(grpc_chttp2_transport* t, uint64_t id) { } static void send_goaway(grpc_chttp2_transport* t, grpc_error* error) { - gpr_log(GPR_ERROR, "%s: Sending goaway err=%s", t->peer_string, + /* We want to log this irrespective of whether http tracing is enabled */ + gpr_log(GPR_INFO, "%s: Sending goaway err=%s", t->peer_string, grpc_error_string(error)); t->sent_goaway_state = GRPC_CHTTP2_GOAWAY_SEND_SCHEDULED; grpc_http2_error_code http_error;