internal/transport: fix severity of log when receiving a GOAWAY with …

…error code ENHANCE_YOUR_CALM (#5935)
grpc · Feb 8, 2023 · 137a042 · 137a042
1 parent c8e621c
commit 137a042
Show file tree

Hide file tree

Showing 4 changed files with 18 additions and 4 deletions.
diff --git a/clientconn_test.go b/clientconn_test.go
@@ -38,6 +38,7 @@ import (
 	"google.golang.org/grpc/credentials/insecure"
 	internalbackoff "google.golang.org/grpc/internal/backoff"
 	"google.golang.org/grpc/internal/grpcsync"
+	"google.golang.org/grpc/internal/grpctest"
 	"google.golang.org/grpc/internal/transport"
 	"google.golang.org/grpc/keepalive"
 	"google.golang.org/grpc/resolver"
@@ -691,6 +692,8 @@ func (s) TestResolverEmptyUpdateNotPanic(t *testing.T) {
 }
 
 func (s) TestClientUpdatesParamsAfterGoAway(t *testing.T) {
+	grpctest.TLogger.ExpectError("Client received GoAway with error code ENHANCE_YOUR_CALM and debug data equal to ASCII \"too_many_pings\"")
+
 	lis, err := net.Listen("tcp", "localhost:0")
 	if err != nil {
 		t.Fatalf("Failed to listen. Err: %v", err)

diff --git a/internal/transport/http2_client.go b/internal/transport/http2_client.go
@@ -1264,10 +1264,12 @@ func (t *http2Client) handleGoAway(f *http2.GoAwayFrame) {
 		t.mu.Unlock()
 		return
 	}
-	if f.ErrCode == http2.ErrCodeEnhanceYourCalm {
-		if logger.V(logLevel) {
-			logger.Infof("Client received GoAway with http2.ErrCodeEnhanceYourCalm.")
-		}
+	if f.ErrCode == http2.ErrCodeEnhanceYourCalm && string(f.DebugData()) == "too_many_pings" {
+		// When a client receives a GOAWAY with error code ENHANCE_YOUR_CALM and debug
+		// data equal to ASCII "too_many_pings", it should log the occurrence at a log level that is
+		// enabled by default and double the configure KEEPALIVE_TIME used for new connections
+		// on that channel.
+		logger.Errorf("Client received GoAway with error code ENHANCE_YOUR_CALM and debug data equal to ASCII \"too_many_pings\".")
 	}
 	id := f.LastStreamID
 	if id > 0 && id%2 == 0 {

diff --git a/internal/transport/keepalive_test.go b/internal/transport/keepalive_test.go
@@ -32,6 +32,7 @@ import (
 
 	"golang.org/x/net/http2"
 	"google.golang.org/grpc/internal/channelz"
+	"google.golang.org/grpc/internal/grpctest"
 	"google.golang.org/grpc/internal/syscall"
 	"google.golang.org/grpc/keepalive"
 )
@@ -397,6 +398,8 @@ func (s) TestKeepaliveClientStaysHealthyWithResponsiveServer(t *testing.T) {
 // explicitly makes sure the fix works and the client sends a ping every [Time]
 // period.
 func (s) TestKeepaliveClientFrequency(t *testing.T) {
+	grpctest.TLogger.ExpectError("Client received GoAway with error code ENHANCE_YOUR_CALM and debug data equal to ASCII \"too_many_pings\"")
+
 	serverConfig := &ServerConfig{
 		KeepalivePolicy: keepalive.EnforcementPolicy{
 			MinTime:             1200 * time.Millisecond, // 1.2 seconds
@@ -443,6 +446,8 @@ func (s) TestKeepaliveClientFrequency(t *testing.T) {
 // (when there are no active streams), based on the configured
 // EnforcementPolicy.
 func (s) TestKeepaliveServerEnforcementWithAbusiveClientNoRPC(t *testing.T) {
+	grpctest.TLogger.ExpectError("Client received GoAway with error code ENHANCE_YOUR_CALM and debug data equal to ASCII \"too_many_pings\"")
+
 	serverConfig := &ServerConfig{
 		KeepalivePolicy: keepalive.EnforcementPolicy{
 			MinTime: 2 * time.Second,
@@ -488,6 +493,8 @@ func (s) TestKeepaliveServerEnforcementWithAbusiveClientNoRPC(t *testing.T) {
 // (even when there is an active stream), based on the configured
 // EnforcementPolicy.
 func (s) TestKeepaliveServerEnforcementWithAbusiveClientWithRPC(t *testing.T) {
+	grpctest.TLogger.ExpectError("Client received GoAway with error code ENHANCE_YOUR_CALM and debug data equal to ASCII \"too_many_pings\"")
+
 	serverConfig := &ServerConfig{
 		KeepalivePolicy: keepalive.EnforcementPolicy{
 			MinTime: 2 * time.Second,

diff --git a/test/goaway_test.go b/test/goaway_test.go
@@ -33,6 +33,7 @@ import (
 	"google.golang.org/grpc/credentials/insecure"
 	"google.golang.org/grpc/internal"
 	"google.golang.org/grpc/internal/grpcsync"
+	"google.golang.org/grpc/internal/grpctest"
 	"google.golang.org/grpc/internal/stubserver"
 	"google.golang.org/grpc/internal/testutils"
 	"google.golang.org/grpc/keepalive"
@@ -120,6 +121,7 @@ func (s) TestDetailedGoAwayErrorOnGracefulClosePropagatesToRPCError(t *testing.T
 }
 
 func (s) TestDetailedGoAwayErrorOnAbruptClosePropagatesToRPCError(t *testing.T) {
+	grpctest.TLogger.ExpectError("Client received GoAway with error code ENHANCE_YOUR_CALM and debug data equal to ASCII \"too_many_pings\"")
 	// set the min keepalive time very low so that this test can take
 	// a reasonable amount of time
 	prev := internal.KeepaliveMinPingTime