tchannel: Only log system error failures when clients haven't timed out

This fixes a minor logging annoyance. Some users have reported large
amounts of `SendSystemError failed` and `responseWriter failed to
close` logs. This was introduced in #1561 to help improve
observability of TChannel system failures.

However, if a client times out, we'll still log the failures; these
logs are are uninformative/unactionable to users as they are expected.

With this diff, we only log TChannel system failures when the client
is still waiting for a response, ie has yet to time out.

Ref T5305225#107015299, supersedes #1814

CHANGELOG.md

@@ -20,6 +20,9 @@ and this project adheres to [Semantic Versioning](http://semver.org/spec/v2.0.0.
 - The `x/yarpcmeta` package is completely removed.
 - tchannel: dropped "handler failed" log. Context error override change makes
   this log redundant as richer information exists in observability logs.
+- tchannel: when callers time out, TChannel servers will not log
+  "SendSystemError failed" and "responseWriter failed to close" messages, since
+  they are unactionable.
 
 ## [1.45.0] - 2020-04-21
 ### Added

transport/tchannel/handler.go

@@ -123,9 +123,14 @@ func (h handler) handle(ctx context.Context, call inboundCall) {
 		call.Response().Blackhole()
 		return
 	}
+
+	clientTimedOut := ctx.Err() == context.DeadlineExceeded
+
 	if err != nil && !responseWriter.IsApplicationError() {
-		if err := call.Response().SendSystemError(getSystemError(err)); err != nil {
-			h.logger.Error("SendSystemError failed", zap.Error(err))
+		sendSysErr := call.Response().SendSystemError(getSystemError(err))
+		if sendSysErr != nil && !clientTimedOut {
+			// only log errors if client is still waiting for our response
+			h.logger.Error("SendSystemError failed", zap.Error(sendSysErr))
 		}
 		return
 	}
@@ -144,11 +149,14 @@ func (h handler) handle(ctx context.Context, call inboundCall) {
 			responseWriter.AddHeader(ErrorMessageHeaderKey, status.Message())
 		}
 	}
-	if err := responseWriter.Close(); err != nil {
-		if err := call.Response().SendSystemError(getSystemError(err)); err != nil {
-			h.logger.Error("SendSystemError failed", zap.Error(err))
+	if reswErr := responseWriter.Close(); reswErr != nil {
+		sendSysErr := call.Response().SendSystemError(getSystemError(reswErr))
+		if !clientTimedOut { // only log errors if client is still waiting for our response
+			if sendSysErr != nil {
+				h.logger.Error("SendSystemError failed", zap.Error(sendSysErr))
+			}
+			h.logger.Error("responseWriter failed to close", zap.Error(reswErr))
 		}
-		h.logger.Error("responseWriter failed to close", zap.Error(err))
 	}
 }
 

transport/tchannel/handler_test.go

@@ -26,6 +26,7 @@ import (
 	"errors"
 	"fmt"
 	"testing"
+	"time"
 
 	"github.com/golang/mock/gomock"
 	"github.com/stretchr/testify/assert"
@@ -659,3 +660,105 @@ func TestGetSystemError(t *testing.T) {
 		})
 	}
 }
+
+func TestHandlerSystemErrorLogs(t *testing.T) {
+	mockCtrl := gomock.NewController(t)
+	defer mockCtrl.Finish()
+
+	zapCore, observedLogs := observer.New(zapcore.ErrorLevel)
+	router := transporttest.NewMockRouter(mockCtrl)
+	transportHandler := &testUnaryHandler{}
+	spec := transport.NewUnaryHandlerSpec(transportHandler)
+
+	tchannelHandler := handler{
+		router:            router,
+		logger:            zap.New(zapCore),
+		newResponseWriter: newHandlerWriter,
+	}
+
+	router.EXPECT().Choose(gomock.Any(), gomock.Any()).Return(spec, nil).Times(4)
+
+	inboundCall := &fakeInboundCall{
+		service: "foo-service",
+		caller:  "foo-caller",
+		method:  "foo-method",
+		format:  tchannel.JSON,
+		arg2:    []byte{},
+		arg3:    []byte{},
+		resp:    newFaultyResponseRecorder(),
+	}
+
+	t.Run("client awaiting response", func(t *testing.T) {
+		t.Run("handler success", func(t *testing.T) {
+			transportHandler.reset()
+
+			ctx, cancel := context.WithTimeout(context.Background(), time.Second)
+			defer cancel()
+
+			tchannelHandler.handle(ctx, inboundCall)
+			logs := observedLogs.TakeAll()
+			require.Len(t, logs, 2, "unexpected number of logs")
+
+			assert.Equal(t, logs[0].Message, "SendSystemError failed", "unexpected log message")
+			assert.Equal(t, logs[1].Message, "responseWriter failed to close", "unexpected log message")
+		})
+
+		t.Run("handler error", func(t *testing.T) {
+			transportHandler.reset()
+			transportHandler.err = errors.New("handler error")
+
+			ctx, cancel := context.WithTimeout(context.Background(), time.Second)
+			defer cancel()
+
+			tchannelHandler.handle(ctx, inboundCall)
+			logs := observedLogs.TakeAll()
+			require.Len(t, logs, 1, "unexpected number of logs")
+
+			assert.Equal(t, logs[0].Message, "SendSystemError failed", "unexpected log message")
+		})
+	})
+
+	t.Run("client timed out", func(t *testing.T) {
+		t.Run("handler success", func(t *testing.T) {
+			transportHandler.reset()
+
+			ctx, cancel := context.WithTimeout(context.Background(), 100*time.Millisecond)
+			defer cancel()
+
+			transportHandler.fn = func() { <-ctx.Done() } // ensure client times out
+
+			tchannelHandler.handle(ctx, inboundCall)
+			require.Empty(t, observedLogs.TakeAll(), "expected no logs")
+		})
+
+		t.Run("handler err", func(t *testing.T) {
+			transportHandler.reset()
+			transportHandler.err = errors.New("handler error")
+
+			ctx, cancel := context.WithTimeout(context.Background(), 100*time.Millisecond)
+			defer cancel()
+
+			transportHandler.fn = func() { <-ctx.Done() } // ensure client times out
+
+			tchannelHandler.handle(ctx, inboundCall)
+			require.Empty(t, observedLogs.TakeAll(), "expected no logs")
+		})
+	})
+}
+
+type testUnaryHandler struct {
+	err error
+	fn  func()
+}
+
+func (h *testUnaryHandler) Handle(context.Context, *transport.Request, transport.ResponseWriter) error {
+	if h.fn != nil {
+		h.fn()
+	}
+	return h.err
+}
+
+func (h *testUnaryHandler) reset() {
+	h.err = nil
+	h.fn = nil
+}