Clean up tchannel client/endpoint/server logs

codegen/templates/tchannel_endpoint.tmpl

@@ -116,7 +116,7 @@ func (h *{{$handlerName}}) Handle(
 	{{if ne .RequestType "" -}}
 	var req {{unref .RequestType}}
 	if err := req.FromWire(*wireValue); err != nil {
-		h.Deps.Default.ContextLogger.Warn(ctx, "Error converting request from wire", zap.Error(err))
+		h.Deps.Default.ContextLogger.Error(ctx, "Error converting request from wire", zap.Error(err))
 		return false, nil, nil, errors.Wrapf(
 			err, "Error converting %s.%s (%s) request from wire",
 			h.endpoint.EndpointID, h.endpoint.HandlerID, h.endpoint.Method,
@@ -152,7 +152,7 @@ func (h *{{$handlerName}}) Handle(
 
 	{{if eq (len .Exceptions) 0 -}}
 		if err != nil {
-			h.Deps.Default.ContextLogger.Warn(ctx, "Handler returned error", zap.Error(err))
+			h.Deps.Default.ContextLogger.Error(ctx, "Handler returned error", zap.Error(err))
 			return false, nil, resHeaders, err
 		}
 		res.Success = {{.RefResponse "r"}}
@@ -162,7 +162,7 @@ func (h *{{$handlerName}}) Handle(
 			{{$method := .Name -}}
 			{{range .Exceptions -}}
 				case *{{.Type}}:
-					h.Deps.Default.ContextLogger.Warn(
+					h.Deps.Default.ContextLogger.Error(
 						ctx,
 						"Handler returned non-nil error type *{{.Type}} but nil value",
 						zap.Error(err),
@@ -176,7 +176,7 @@ func (h *{{$handlerName}}) Handle(
 					res.{{title .Name}} = v
 			{{end -}}
 				default:
-					h.Deps.Default.ContextLogger.Warn(ctx, "Handler returned error", zap.Error(err))
+					h.Deps.Default.ContextLogger.Error(ctx, "Handler returned error", zap.Error(err))
 					return false, nil, resHeaders, errors.Wrapf(
 						err, "%s.%s (%s) handler returned error",
 						h.endpoint.EndpointID, h.endpoint.HandlerID, h.endpoint.Method,

examples/example-gateway/endpoints/tchannel/baz/baz_call.go

@@ -75,10 +75,6 @@ func (w Workflow) Handle(
 		case *clientBaz.AuthErr:
 			return respHeaders, (*endpointBaz.AuthErr)(v)
 		default:
-			zanzibar.LogErrorWarnTimeoutContext(
-				ctx, w.contextLogger, err,
-				"baz.Call returned error",
-			)
 			return respHeaders, err
 		}
 	}

runtime/tchannel_client.go

@@ -216,7 +216,6 @@ func (c *TChannelClient) call(
 			RequestState: rs,
 		})
 		if cerr != nil {
-			LogErrorWarnTimeout(call.logger, err, "Could not begin outbound request")
 			return errors.Wrapf(
 				err, "Could not begin outbound %s.%s (%s %s) request",
 				call.client.ClientID, call.methodName, call.client.serviceName, call.serviceMethod,
@@ -245,7 +244,6 @@ func (c *TChannelClient) call(
 	})
 
 	if err != nil {
-		LogErrorWarnTimeout(call.logger, err, "Could not make outbound request")
 		// Do not wrap system errors.
 		if _, ok := err.(tchannel.SystemError); ok {
 			return call.success, nil, err
@@ -277,7 +275,11 @@ func (c *tchannelOutboundCall) finish(err error) {
 	c.metrics.Latency.Record(c.finishTime.Sub(c.startTime))
 
 	// write logs
-	c.logger.Info("Finished an outgoing client TChannel request", c.logFields()...)
+	if err == nil {
+		c.logger.Info("Finished an outgoing client TChannel request", c.logFields()...)
+	} else {
+		c.logger.Warn("Failed to send outgoing client TChannel request", zap.Error(err))
+	}
 }
 
 func (c *tchannelOutboundCall) logFields() []zapcore.Field {
@@ -309,22 +311,19 @@ func (c *tchannelOutboundCall) writeReqHeaders(reqHeaders map[string]string) err
 
 	twriter, err := c.call.Arg2Writer()
 	if err != nil {
-		LogErrorWarnTimeout(c.logger, err, "Could not create arg2writer for outbound request")
 		return errors.Wrapf(
 			err, "Could not create arg2writer for outbound %s.%s (%s %s) request",
 			c.client.ClientID, c.methodName, c.client.serviceName, c.serviceMethod,
 		)
 	}
 	if err := WriteHeaders(twriter, reqHeaders); err != nil {
 		_ = twriter.Close()
-		LogErrorWarnTimeout(c.logger, err, "Could not write headers for outbound request")
 		return errors.Wrapf(
 			err, "Could not write headers for outbound %s.%s (%s %s) request",
 			c.client.ClientID, c.methodName, c.client.serviceName, c.serviceMethod,
 		)
 	}
 	if err := twriter.Close(); err != nil {
-		LogErrorWarnTimeout(c.logger, err, "Could not close arg2writer for outbound request")
 		return errors.Wrapf(
 			err, "Could not close arg2writer for outbound %s.%s (%s %s) request",
 			c.client.ClientID, c.methodName, c.client.serviceName, c.serviceMethod,
@@ -338,7 +337,6 @@ func (c *tchannelOutboundCall) writeReqHeaders(reqHeaders map[string]string) err
 func (c *tchannelOutboundCall) writeReqBody(req RWTStruct) error {
 	structWireValue, err := req.ToWire()
 	if err != nil {
-		LogErrorWarnTimeout(c.logger, err, "Could not write request for outbound request")
 		return errors.Wrapf(
 			err, "Could not write request for outbound %s.%s (%s %s) request",
 			c.client.ClientID, c.methodName, c.client.serviceName, c.serviceMethod,
@@ -347,22 +345,19 @@ func (c *tchannelOutboundCall) writeReqBody(req RWTStruct) error {
 
 	twriter, err := c.call.Arg3Writer()
 	if err != nil {
-		LogErrorWarnTimeout(c.logger, err, "Could not create arg3writer for outbound request")
 		return errors.Wrapf(
 			err, "Could not create arg3writer for outbound %s.%s (%s %s) request",
 			c.client.ClientID, c.methodName, c.client.serviceName, c.serviceMethod,
 		)
 	}
 	if err := protocol.Binary.Encode(structWireValue, twriter); err != nil {
 		_ = twriter.Close()
-		LogErrorWarnTimeout(c.logger, err, "Could not write request for outbound request")
 		return errors.Wrapf(
 			err, "Could not write request for outbound %s.%s (%s %s) request",
 			c.client.ClientID, c.methodName, c.client.serviceName, c.serviceMethod,
 		)
 	}
 	if err := twriter.Close(); err != nil {
-		LogErrorWarnTimeout(c.logger, err, "Could not close arg3writer for outbound request")
 		return errors.Wrapf(
 			err, "Could not close arg3writer for outbound %s.%s (%s %s) request",
 			c.client.ClientID, c.methodName, c.client.serviceName, c.serviceMethod,
@@ -378,7 +373,6 @@ func (c *tchannelOutboundCall) writeReqBody(req RWTStruct) error {
 func (c *tchannelOutboundCall) readResHeaders(response *tchannel.OutboundCallResponse) error {
 	treader, err := response.Arg2Reader()
 	if err != nil {
-		LogErrorWarnTimeout(c.logger, err, "Could not create arg2reader for outbound response")
 		// Do not wrap system errors.
 		if _, ok := err.(tchannel.SystemError); ok {
 			return err
@@ -390,22 +384,19 @@ func (c *tchannelOutboundCall) readResHeaders(response *tchannel.OutboundCallRes
 	}
 	if c.resHeaders, err = ReadHeaders(treader); err != nil {
 		_ = treader.Close()
-		LogErrorWarnTimeout(c.logger, err, "Could not read headers for outbound response")
 		return errors.Wrapf(
 			err, "Could not read headers for outbound %s.%s (%s %s) response",
 			c.client.ClientID, c.methodName, c.client.serviceName, c.serviceMethod,
 		)
 	}
 	if err := EnsureEmpty(treader, "reading response headers"); err != nil {
 		_ = treader.Close()
-		LogErrorWarnTimeout(c.logger, err, "Could not ensure arg2reader is empty for outbound response")
 		return errors.Wrapf(
 			err, "Could not ensure arg2reader is empty for outbound %s.%s (%s %s) response",
 			c.client.ClientID, c.methodName, c.client.serviceName, c.serviceMethod,
 		)
 	}
 	if err := treader.Close(); err != nil {
-		LogErrorWarnTimeout(c.logger, err, "Could not close arg2reader for outbound response")
 		return errors.Wrapf(
 			err, "Could not close arg2reader for outbound %s.%s (%s %s) response",
 			c.client.ClientID, c.methodName, c.client.serviceName, c.serviceMethod,
@@ -421,30 +412,26 @@ func (c *tchannelOutboundCall) readResHeaders(response *tchannel.OutboundCallRes
 func (c *tchannelOutboundCall) readResBody(response *tchannel.OutboundCallResponse, resp RWTStruct) error {
 	treader, err := response.Arg3Reader()
 	if err != nil {
-		LogErrorWarnTimeout(c.logger, err, "Could not create arg3Reader for outbound response")
 		return errors.Wrapf(
 			err, "Could not create arg3Reader for outbound %s.%s (%s %s) response",
 			c.client.ClientID, c.methodName, c.client.serviceName, c.serviceMethod,
 		)
 	}
 	if err := ReadStruct(treader, resp); err != nil {
 		_ = treader.Close()
-		LogErrorWarnTimeout(c.logger, err, "Could not read outbound response")
 		return errors.Wrapf(
 			err, "Could not read outbound %s.%s (%s %s) response",
 			c.client.ClientID, c.methodName, c.client.serviceName, c.serviceMethod,
 		)
 	}
 	if err := EnsureEmpty(treader, "reading response body"); err != nil {
 		_ = treader.Close()
-		LogErrorWarnTimeout(c.logger, err, "Could not ensure arg3reader is empty for outbound response")
 		return errors.Wrapf(
 			err, "Could not ensure arg3reader is empty for outbound %s.%s (%s %s) response",
 			c.client.ClientID, c.methodName, c.client.serviceName, c.serviceMethod,
 		)
 	}
 	if err := treader.Close(); err != nil {
-		LogErrorWarnTimeout(c.logger, err, "Could not close arg3reader for outbound response")
 		return errors.Wrapf(
 			err, "Could not close arg3reader outbound %s.%s (%s %s) response",
 			c.client.ClientID, c.methodName, c.client.serviceName, c.serviceMethod,

runtime/tchannel_logger.go

@@ -126,27 +126,12 @@ func (l TChannelLogger) WithFields(fields ...tchannel.LogField) tchannel.Logger
 // TODO: We want to improve the classification of errors, similar to:
 // https://github.com/uber/tchannel-node/blob/master/errors.js#L907-L930
 //
-// Deprecated: Use LogErrorWarnTimeoutContext instead.
+// Deprecated: use proper level to log instead
 func LogErrorWarnTimeout(logger *zap.Logger, err error, msg string) {
-	if err != nil {
-		if isTimeout(err) {
-			logger.Warn(msg, zap.Error(err))
-		} else {
-			logger.Error(msg, zap.Error(err))
-		}
-	}
-}
-
-// LogErrorWarnTimeoutContext logs warnings for timeout errors, otherwise logs errors
-// TODO: We want to improve the classification of errors, similar to:
-// https://github.com/uber/tchannel-node/blob/master/errors.js#L907-L930
-func LogErrorWarnTimeoutContext(ctx context.Context, logger ContextLogger, err error, msg string) {
-	if err != nil {
-		if isTimeout(err) {
-			logger.Warn(ctx, msg, zap.Error(err))
-		} else {
-			logger.Error(ctx, msg, zap.Error(err))
-		}
+	if isTimeout(err) {
+		logger.Warn(msg, zap.Error(err))
+	} else {
+		logger.Error(msg, zap.Error(err))
 	}
 }