diff --git a/codegen/template_bundle/template_files.go b/codegen/template_bundle/template_files.go index 9b2c0b1a6..1437ec0a6 100644 --- a/codegen/template_bundle/template_files.go +++ b/codegen/template_bundle/template_files.go @@ -2512,7 +2512,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, @@ -2548,7 +2548,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"}} @@ -2558,7 +2558,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), @@ -2572,7 +2572,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, @@ -2668,7 +2668,7 @@ func tchannel_endpointTmpl() (*asset, error) { return nil, err } - info := bindataFileInfo{name: "tchannel_endpoint.tmpl", size: 8129, mode: os.FileMode(420), modTime: time.Unix(1, 0)} + info := bindataFileInfo{name: "tchannel_endpoint.tmpl", size: 8133, mode: os.FileMode(420), modTime: time.Unix(1, 0)} a := &asset{bytes: bytes, info: info} return a, nil } diff --git a/codegen/templates/tchannel_endpoint.tmpl b/codegen/templates/tchannel_endpoint.tmpl index cf50ae2d3..b70d0a0a9 100644 --- a/codegen/templates/tchannel_endpoint.tmpl +++ b/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, diff --git a/examples/example-gateway/build/endpoints/tchannel/baz/baz_simpleservice_method_call_tchannel.go b/examples/example-gateway/build/endpoints/tchannel/baz/baz_simpleservice_method_call_tchannel.go index aec739853..320af2c30 100644 --- a/examples/example-gateway/build/endpoints/tchannel/baz/baz_simpleservice_method_call_tchannel.go +++ b/examples/example-gateway/build/endpoints/tchannel/baz/baz_simpleservice_method_call_tchannel.go @@ -107,7 +107,7 @@ func (h *SimpleServiceCallHandler) Handle( var req endpointsTchannelBazBaz.SimpleService_Call_Args 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, @@ -133,7 +133,7 @@ func (h *SimpleServiceCallHandler) Handle( if err != nil { switch v := err.(type) { case *endpointsTchannelBazBaz.AuthErr: - h.Deps.Default.ContextLogger.Warn( + h.Deps.Default.ContextLogger.Error( ctx, "Handler returned non-nil error type *endpointsTchannelBazBaz.AuthErr but nil value", zap.Error(err), @@ -146,7 +146,7 @@ func (h *SimpleServiceCallHandler) Handle( } res.AuthErr = v 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, diff --git a/examples/example-gateway/build/endpoints/tchannel/baz/baz_simpleservice_method_echo_tchannel.go b/examples/example-gateway/build/endpoints/tchannel/baz/baz_simpleservice_method_echo_tchannel.go index a1e7a15d6..7807e6f64 100644 --- a/examples/example-gateway/build/endpoints/tchannel/baz/baz_simpleservice_method_echo_tchannel.go +++ b/examples/example-gateway/build/endpoints/tchannel/baz/baz_simpleservice_method_echo_tchannel.go @@ -93,7 +93,7 @@ func (h *SimpleServiceEchoHandler) Handle( var req endpointsTchannelBazBaz.SimpleService_Echo_Args 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, @@ -117,7 +117,7 @@ func (h *SimpleServiceEchoHandler) Handle( } 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 = &r diff --git a/examples/example-gateway/build/endpoints/tchannel/echo/echo_echo_method_echo_tchannel.go b/examples/example-gateway/build/endpoints/tchannel/echo/echo_echo_method_echo_tchannel.go index 789206c3d..d84305a49 100644 --- a/examples/example-gateway/build/endpoints/tchannel/echo/echo_echo_method_echo_tchannel.go +++ b/examples/example-gateway/build/endpoints/tchannel/echo/echo_echo_method_echo_tchannel.go @@ -93,7 +93,7 @@ func (h *EchoEchoHandler) Handle( var req endpointsTchannelEchoEcho.Echo_Echo_Args 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, @@ -117,7 +117,7 @@ func (h *EchoEchoHandler) Handle( } 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 = &r diff --git a/examples/example-gateway/build/endpoints/tchannel/panic/panic_simpleservice_method_anothercall_tchannel.go b/examples/example-gateway/build/endpoints/tchannel/panic/panic_simpleservice_method_anothercall_tchannel.go index 5c5d54277..ad782b502 100644 --- a/examples/example-gateway/build/endpoints/tchannel/panic/panic_simpleservice_method_anothercall_tchannel.go +++ b/examples/example-gateway/build/endpoints/tchannel/panic/panic_simpleservice_method_anothercall_tchannel.go @@ -100,7 +100,7 @@ func (h *SimpleServiceAnotherCallHandler) Handle( var req endpointsTchannelBazBaz.SimpleService_AnotherCall_Args 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, @@ -126,7 +126,7 @@ func (h *SimpleServiceAnotherCallHandler) Handle( if err != nil { switch v := err.(type) { case *endpointsTchannelBazBaz.AuthErr: - h.Deps.Default.ContextLogger.Warn( + h.Deps.Default.ContextLogger.Error( ctx, "Handler returned non-nil error type *endpointsTchannelBazBaz.AuthErr but nil value", zap.Error(err), @@ -139,7 +139,7 @@ func (h *SimpleServiceAnotherCallHandler) Handle( } res.AuthErr = v 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, diff --git a/examples/example-gateway/endpoints/tchannel/baz/baz_call.go b/examples/example-gateway/endpoints/tchannel/baz/baz_call.go index 2f5bdeb10..f25a3814a 100644 --- a/examples/example-gateway/endpoints/tchannel/baz/baz_call.go +++ b/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 } } diff --git a/runtime/tchannel_client.go b/runtime/tchannel_client.go index 48dee8ffd..389221fbd 100644 --- a/runtime/tchannel_client.go +++ b/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,7 +311,6 @@ 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, @@ -317,14 +318,12 @@ func (c *tchannelOutboundCall) writeReqHeaders(reqHeaders map[string]string) err } 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,7 +345,6 @@ 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, @@ -355,14 +352,12 @@ func (c *tchannelOutboundCall) writeReqBody(req RWTStruct) error { } 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,7 +384,6 @@ 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, @@ -398,14 +391,12 @@ func (c *tchannelOutboundCall) readResHeaders(response *tchannel.OutboundCallRes } 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,7 +412,6 @@ 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, @@ -429,7 +419,6 @@ func (c *tchannelOutboundCall) readResBody(response *tchannel.OutboundCallRespon } 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, @@ -437,14 +426,12 @@ func (c *tchannelOutboundCall) readResBody(response *tchannel.OutboundCallRespon } 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, diff --git a/runtime/tchannel_logger.go b/runtime/tchannel_logger.go index c44b8cea7..329b69db2 100644 --- a/runtime/tchannel_logger.go +++ b/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)) } } diff --git a/runtime/tchannel_server.go b/runtime/tchannel_server.go index 9e3ccaf16..b49617f8d 100644 --- a/runtime/tchannel_server.go +++ b/runtime/tchannel_server.go @@ -269,8 +269,11 @@ func (c *tchannelInboundCall) finish(err error) { c.endpoint.Metrics.Latency.Record(c.finishTime.Sub(c.startTime)) // write logs - LogErrorWarnTimeoutContext(c.ctx, c.endpoint.contextLogger, err, "Thrift server error") - c.endpoint.contextLogger.Info(c.ctx, "Finished an incoming server TChannel request", c.logFields()...) + if err == nil { + c.endpoint.contextLogger.Info(c.ctx, "Finished an incoming server TChannel request", c.logFields()...) + } else { + c.endpoint.contextLogger.Warn(c.ctx, "Failed to serve incoming TChannel request", zap.Error(err)) + } } func (c *tchannelInboundCall) logFields() []zapcore.Field { @@ -300,7 +303,6 @@ func (c *tchannelInboundCall) readReqHeaders(ctx context.Context) error { treader, err := c.call.Arg2Reader() if err != nil { - LogErrorWarnTimeoutContext(ctx, c.endpoint.contextLogger, err, "Could not create arg2reader for inbound request") return errors.Wrapf(err, "Could not create arg2reader for inbound %s.%s (%s) request", c.endpoint.EndpointID, c.endpoint.HandlerID, c.endpoint.Method, ) @@ -308,20 +310,17 @@ func (c *tchannelInboundCall) readReqHeaders(ctx context.Context) error { c.reqHeaders, err = ReadHeaders(treader) if err != nil { _ = treader.Close() - LogErrorWarnTimeoutContext(ctx, c.endpoint.contextLogger, err, "Could not read headers for inbound request") return errors.Wrapf(err, "Could not read headers for inbound %s.%s (%s) request", c.endpoint.EndpointID, c.endpoint.HandlerID, c.endpoint.Method, ) } if err := EnsureEmpty(treader, "reading request headers"); err != nil { _ = treader.Close() - LogErrorWarnTimeoutContext(ctx, c.endpoint.contextLogger, err, "Could not ensure arg2reader is empty for inbound request") return errors.Wrapf(err, "Could not ensure arg2reader is empty for inbound %s.%s (%s) request", c.endpoint.EndpointID, c.endpoint.HandlerID, c.endpoint.Method, ) } if err := treader.Close(); err != nil { - LogErrorWarnTimeoutContext(ctx, c.endpoint.contextLogger, err, "Could not close arg2reader for inbound request") return errors.Wrapf(err, "Could not close arg2reader for inbound %s.%s (%s) request", c.endpoint.EndpointID, c.endpoint.HandlerID, c.endpoint.Method, ) @@ -339,7 +338,6 @@ func (c *tchannelInboundCall) readReqBody(ctx context.Context) (wireValue wire.V treader, err := c.call.Arg3Reader() if err != nil { - LogErrorWarnTimeoutContext(ctx, c.endpoint.contextLogger, err, "Could not create arg3reader for inbound request") err = errors.Wrapf(err, "Could not create arg3reader for inbound %s.%s (%s) request", c.endpoint.EndpointID, c.endpoint.HandlerID, c.endpoint.Method, ) @@ -349,7 +347,6 @@ func (c *tchannelInboundCall) readReqBody(ctx context.Context) (wireValue wire.V defer PutBuffer(buf) if _, err = buf.ReadFrom(treader); err != nil { _ = treader.Close() - LogErrorWarnTimeoutContext(ctx, c.endpoint.contextLogger, err, "Could not read from arg3reader for inbound request") err = errors.Wrapf(err, "Could not read from arg3reader for inbound %s.%s (%s) request", c.endpoint.EndpointID, c.endpoint.HandlerID, c.endpoint.Method, ) @@ -365,14 +362,12 @@ func (c *tchannelInboundCall) readReqBody(ctx context.Context) (wireValue wire.V } if err = EnsureEmpty(treader, "reading request body"); err != nil { _ = treader.Close() - LogErrorWarnTimeoutContext(ctx, c.endpoint.contextLogger, err, "Could not ensure arg3reader is empty for inbound request") err = errors.Wrapf(err, "Could not ensure arg3reader is empty for inbound %s.%s (%s) request", c.endpoint.EndpointID, c.endpoint.HandlerID, c.endpoint.Method, ) return } if err = treader.Close(); err != nil { - LogErrorWarnTimeoutContext(ctx, c.endpoint.contextLogger, err, "Could not close arg3reader for inbound request") err = errors.Wrapf(err, "Could not close arg3reader for inbound %s.%s (%s) request", c.endpoint.EndpointID, c.endpoint.HandlerID, c.endpoint.Method, ) @@ -395,15 +390,15 @@ func (c *tchannelInboundCall) handle(ctx context.Context, wireValue *wire.Value) defer c.endpoint.callback(ctx, c.endpoint.Method, resp) } if err != nil { - LogErrorWarnTimeoutContext(c.ctx, c.endpoint.contextLogger, err, "Unexpected tchannel system error") + c.endpoint.contextLogger.Warn(c.ctx, "Unexpected tchannel system error", zap.Error(err)) if er := c.call.Response().SendSystemError(errors.New("Server Error")); er != nil { - LogErrorWarnTimeoutContext(c.ctx, c.endpoint.contextLogger, err, "Error sending server error response") + c.endpoint.contextLogger.Warn(c.ctx, "Error sending server error response", zap.Error(er)) } return } if !c.success { if err = c.call.Response().SetApplicationError(); err != nil { - LogErrorWarnTimeoutContext(ctx, c.endpoint.contextLogger, err, "Could not set application error for inbound response") + c.endpoint.contextLogger.Warn(c.ctx, "Could not set application error for inbound response", zap.Error(err)) return } } @@ -419,20 +414,17 @@ func (c *tchannelInboundCall) writeResHeaders(ctx context.Context) error { twriter, err := c.call.Response().Arg2Writer() if err != nil { - LogErrorWarnTimeoutContext(ctx, c.endpoint.contextLogger, err, "Could not create arg2writer for inbound response") return errors.Wrapf(err, "Could not create arg2writer for inbound %s.%s (%s) response", c.endpoint.EndpointID, c.endpoint.HandlerID, c.endpoint.Method, ) } if err = WriteHeaders(twriter, c.resHeaders); err != nil { _ = twriter.Close() - LogErrorWarnTimeoutContext(ctx, c.endpoint.contextLogger, err, "Could not write headers for inbound response") return errors.Wrapf(err, "Could not write headers for inbound %s.%s (%s) response", c.endpoint.EndpointID, c.endpoint.HandlerID, c.endpoint.Method, ) } if err = twriter.Close(); err != nil { - LogErrorWarnTimeoutContext(ctx, c.endpoint.contextLogger, err, "Could not close arg2writer for inbound response") return errors.Wrapf(err, "Could not close arg2writer for inbound %s.%s (%s) response", c.endpoint.EndpointID, c.endpoint.HandlerID, c.endpoint.Method, ) @@ -449,9 +441,9 @@ func (c *tchannelInboundCall) writeResBody(ctx context.Context, resp RWTStruct) structWireValue, err := resp.ToWire() if err != nil { - // If we could not write the body then we should do something else instead. - _ = c.call.Response().SendSystemError(errors.New("Server Error")) - LogErrorWarnTimeoutContext(ctx, c.endpoint.contextLogger, err, "Could not serialize arg3 for inbound response") + if er := c.call.Response().SendSystemError(errors.New("Server Error")); er != nil { + c.endpoint.contextLogger.Warn(c.ctx, "Error sending server error response", zap.Error(er)) + } return errors.Wrapf(err, "Could not serialize arg3 for inbound %s.%s (%s) response", c.endpoint.EndpointID, c.endpoint.HandlerID, c.endpoint.Method, ) @@ -459,7 +451,6 @@ func (c *tchannelInboundCall) writeResBody(ctx context.Context, resp RWTStruct) twriter, err := c.call.Response().Arg3Writer() if err != nil { - LogErrorWarnTimeoutContext(ctx, c.endpoint.contextLogger, err, "Could not create arg3writer for inbound response") return errors.Wrapf(err, "Could not create arg3writer for inbound %s.%s (%s) response", c.endpoint.EndpointID, c.endpoint.HandlerID, c.endpoint.Method, ) @@ -467,14 +458,12 @@ func (c *tchannelInboundCall) writeResBody(ctx context.Context, resp RWTStruct) err = protocol.Binary.Encode(structWireValue, twriter) if err != nil { _ = twriter.Close() - LogErrorWarnTimeoutContext(ctx, c.endpoint.contextLogger, err, "Could not write arg3 for inbound response") return errors.Wrapf(err, "Could not write arg3 for inbound %s.%s (%s) response", c.endpoint.EndpointID, c.endpoint.HandlerID, c.endpoint.Method, ) } c.responded = true if err = twriter.Close(); err != nil { - LogErrorWarnTimeoutContext(ctx, c.endpoint.contextLogger, err, "Could not close arg3writer for inbound response") return errors.Wrapf(err, "Could not close arg3writer for inbound %s.%s (%s) response", c.endpoint.EndpointID, c.endpoint.HandlerID, c.endpoint.Method, ) diff --git a/test/endpoints/baz/baz_simpleservice_method_ping_test.go b/test/endpoints/baz/baz_simpleservice_method_ping_test.go index 3f535be8c..54e26275a 100644 --- a/test/endpoints/baz/baz_simpleservice_method_ping_test.go +++ b/test/endpoints/baz/baz_simpleservice_method_ping_test.go @@ -163,10 +163,6 @@ func TestPingWithInvalidResponse(t *testing.T) { KnownTChannelBackends: []string{"baz"}, TestBinary: util.DefaultMainFile("example-gateway"), ConfigFiles: util.DefaultConfigFiles("example-gateway"), - LogWhitelist: map[string]bool{ - "Could not create arg2reader for outbound response": true, - "Could not make outbound request": true, - }, }) if !assert.NoError(t, err, "got bootstrap err") { return @@ -206,17 +202,13 @@ func TestPingWithInvalidResponse(t *testing.T) { assert.Equal(t, `{"error":"Unexpected server error"}`, string(bytes)) - allLogs := gateway.AllLogs() - - assert.Equal(t, 1, len(allLogs["Started ExampleGateway"])) - assert.Equal(t, 1, len(allLogs["Created new active connection."])) - assert.Equal(t, 1, len(allLogs["Could not create arg2reader for outbound response"])) - assert.Equal(t, 1, len(allLogs["Failed after non-retriable error."])) - assert.Equal(t, 1, len(allLogs["Could not make outbound request"])) - assert.Equal(t, 1, len(allLogs["TChannel client call returned error"])) - assert.Equal(t, 1, len(allLogs["Finished an incoming server HTTP request"])) - assert.Equal(t, 1, len(allLogs["Finished an outgoing client TChannel request"])) - assert.Equal(t, 1, len(allLogs["Could not make client request"])) + assert.Len(t, gateway.Logs("info", "Started ExampleGateway"), 1) + assert.Len(t, gateway.Logs("info", "Created new active connection."), 1) + assert.Len(t, gateway.Logs("info", "Failed after non-retriable error."), 1) + assert.Len(t, gateway.Logs("warn", "TChannel client call returned error"), 1) + assert.Len(t, gateway.Logs("info", "Finished an incoming server HTTP request"), 1) + assert.Len(t, gateway.Logs("warn", "Failed to send outgoing client TChannel request"), 1) + assert.Len(t, gateway.Logs("warn", "Could not make client request"), 1) logLines := gateway.Logs("warn", "Could not make client request") assert.Equal(t, 1, len(logLines)) diff --git a/test/endpoints/tchannel/baz/baz_simpleservice_method_call_test.go b/test/endpoints/tchannel/baz/baz_simpleservice_method_call_test.go index 34aaf7687..c6fe79d92 100644 --- a/test/endpoints/tchannel/baz/baz_simpleservice_method_call_test.go +++ b/test/endpoints/tchannel/baz/baz_simpleservice_method_call_test.go @@ -201,6 +201,9 @@ func TestCallTChannelTimeout(t *testing.T) { TChannelClientMethods: map[string]string{ "SimpleService::Call": "Call", }, + LogWhitelist: map[string]bool{ + "Handler returned error": true, + }, }) if !assert.NoError(t, err, "got bootstrap err") { return @@ -247,17 +250,21 @@ func TestCallTChannelTimeout(t *testing.T) { assert.False(t, success) allLogs := gateway.AllLogs() - assert.Len(t, allLogs, 12) + assert.Len(t, allLogs, 8) assert.Len(t, gateway.Logs("info", "Started ExampleGateway"), 1) assert.Len(t, gateway.Logs("info", "Created new active connection."), 2) - assert.Len(t, gateway.Logs("warn", "Thrift server error"), 1) - assert.Len(t, gateway.Logs("warn", "Could not make outbound request"), 1) - assert.Len(t, gateway.Logs("info", "Finished an outgoing client TChannel request"), 1) - assert.Len(t, gateway.Logs("warn", "baz.Call returned error"), 1) - assert.Len(t, gateway.Logs("warn", "Handler returned error"), 1) - assert.Len(t, gateway.Logs("warn", "Unexpected tchannel system error"), 1) - assert.Len(t, gateway.Logs("warn", "Could not create arg2reader for outbound response"), 1) + + // logged from tchannel client runtime assert.Len(t, gateway.Logs("info", "Failed after non-retriable error."), 1) - assert.Len(t, gateway.Logs("info", "Finished an incoming server TChannel request"), 1) + assert.Len(t, gateway.Logs("warn", "Failed to send outgoing client TChannel request"), 1) + + // logged from generated client assert.Len(t, gateway.Logs("warn", "TChannel client call returned error"), 1) + + // logged from generated endpoint + assert.Len(t, gateway.Logs("error", "Handler returned error"), 1) + + // logged from tchannel server runtime + assert.Len(t, gateway.Logs("warn", "Failed to serve incoming TChannel request"), 1) + assert.Len(t, gateway.Logs("warn", "Unexpected tchannel system error"), 1) }