From d1d34d2638ecaa7aa89b1a6af1c6a1ef9786b032 Mon Sep 17 00:00:00 2001 From: Matthias Hanel Date: Mon, 24 Feb 2020 15:43:40 -0500 Subject: [PATCH] Suggestion to improve tracing in nats-server through wrapping errors Signed-off-by: Matthias Hanel --- server/client.go | 5 ++- server/errors.go | 38 ++++++++++++++++++++++ server/errors_test.go | 75 +++++++++++++++++++++++++++++++++++++++++++ server/log.go | 19 +++++++++++ server/parser.go | 6 ++-- server/parser_test.go | 3 +- server/reload.go | 2 +- 7 files changed, 143 insertions(+), 5 deletions(-) create mode 100644 server/errors_test.go diff --git a/server/client.go b/server/client.go index 02b6058a..65265d55 100644 --- a/server/client.go +++ b/server/client.go @@ -900,7 +900,7 @@ func (c *client) readLoop() { c.flushClients(0) // handled inline if err != ErrMaxPayload && err != ErrAuthentication { - c.Errorf("%s", err.Error()) + c.Error(err) c.closeConnection(ProtocolViolation) } return @@ -3786,6 +3786,9 @@ func (c *client) isClosed() bool { } // Logging functionality scoped to a client or route. +func (c *client) Error(err error) { + c.srv.Errorc(c, err) +} func (c *client) Errorf(format string, v ...interface{}) { format = fmt.Sprintf("%s - %s", c, format) diff --git a/server/errors.go b/server/errors.go index cf5f2549..29794321 100644 --- a/server/errors.go +++ b/server/errors.go @@ -208,3 +208,41 @@ func (e *processConfigErr) Warnings() []error { func (e *processConfigErr) Errors() []error { return e.errors } + +// errCtx wraps an error and stores additional ctx information for tracing. +// Does not print or return it unless explicitly requested. +type errCtx struct { + error + ctx string +} + +func NewErrorCtx(err error, format string, args ...interface{}) error { + return &errCtx{err, fmt.Sprintf(format, args...)} +} + +// implement to work with errors.Is and errors.As +func (e *errCtx) Unwrap() error { + if e == nil { + return nil + } + return e.error +} + +// Context for error +func (e *errCtx) Context() string { + if e == nil { + return "" + } + return e.ctx +} + +// Return Error or, if type is right error and context +func UnpackIfErrorCtx(err error) string { + if e, ok := err.(*errCtx); ok { + if _, ok := e.error.(*errCtx); ok { + return fmt.Sprint(UnpackIfErrorCtx(e.error), ": ", e.Context()) + } + return fmt.Sprint(e.Error(), ": ", e.Context()) + } + return err.Error() +} diff --git a/server/errors_test.go b/server/errors_test.go new file mode 100644 index 00000000..232d2708 --- /dev/null +++ b/server/errors_test.go @@ -0,0 +1,75 @@ +// Copyright 2012-2021 The NATS Authors +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package server + +import ( + "errors" + "strings" + "testing" +) + +func TestErrCtx(t *testing.T) { + ctx := "Extra context information" + e := NewErrorCtx(ErrWrongGateway, ctx) + + if e.Error() != ErrWrongGateway.Error() { + t.Fatalf("%v and %v are supposed to be identical", e, ErrWrongGateway) + } + if e == ErrWrongGateway { + t.Fatalf("%v and %v can't be compared this way", e, ErrWrongGateway) + } + if !errors.Is(e, ErrWrongGateway) { + t.Fatalf("%s and %s ", e, ErrWrongGateway) + } + if UnpackIfErrorCtx(ErrWrongGateway) != ErrWrongGateway.Error() { + t.Fatalf("Error of different type should be processed unchanged") + } + trace := UnpackIfErrorCtx(e) + if !strings.HasPrefix(trace, ErrWrongGateway.Error()) { + t.Fatalf("original error needs to remain") + } + if !strings.HasSuffix(trace, ctx) { + t.Fatalf("ctx nneds to be added") + } +} + +func TestErrCtxWrapped(t *testing.T) { + ctxO := "Original Ctx" + eO := NewErrorCtx(ErrWrongGateway, ctxO) + ctx := "Extra context information" + e := NewErrorCtx(eO, ctx) + + if e.Error() != ErrWrongGateway.Error() { + t.Fatalf("%v and %v are supposed to be identical", e, ErrWrongGateway) + } + if e == ErrWrongGateway { + t.Fatalf("%v and %v can't be compared this way", e, ErrWrongGateway) + } + if !errors.Is(e, ErrWrongGateway) { + t.Fatalf("%s and %s ", e, ErrWrongGateway) + } + if UnpackIfErrorCtx(ErrWrongGateway) != ErrWrongGateway.Error() { + t.Fatalf("Error of different type should be processed unchanged") + } + trace := UnpackIfErrorCtx(e) + if !strings.HasPrefix(trace, ErrWrongGateway.Error()) { + t.Fatalf("original error needs to remain") + } + if !strings.HasSuffix(trace, ctx) { + t.Fatalf("ctx nneds to be added") + } + if !strings.Contains(trace, ctxO) { + t.Fatalf("Needs to contain every context") + } +} diff --git a/server/log.go b/server/log.go index 762cce95..149b8268 100644 --- a/server/log.go +++ b/server/log.go @@ -156,6 +156,25 @@ func (s *Server) Errorf(format string, v ...interface{}) { }, format, v...) } +// Error logs an error with a scope +func (s *Server) Errors(scope interface{}, e error) { + s.executeLogCall(func(logger Logger, format string, v ...interface{}) { + logger.Errorf(format, v...) + }, "%s - %s", scope, UnpackIfErrorCtx(e)) +} + +func (s *Server) Errorc(ctx interface{}, e error) { + s.executeLogCall(func(logger Logger, format string, v ...interface{}) { + logger.Errorf(format, v...) + }, "%s: %s", ctx, UnpackIfErrorCtx(e)) +} + +func (s *Server) Errorsc(scope interface{}, ctx interface{}, e error) { + s.executeLogCall(func(logger Logger, format string, v ...interface{}) { + logger.Errorf(format, v...) + }, "%s - %s: %s", scope, ctx, UnpackIfErrorCtx(e)) +} + // Warnf logs a warning error func (s *Server) Warnf(format string, v ...interface{}) { s.executeLogCall(func(logger Logger, format string, v ...interface{}) { diff --git a/server/parser.go b/server/parser.go index d4d71755..99c8e9a5 100644 --- a/server/parser.go +++ b/server/parser.go @@ -855,9 +855,11 @@ func (c *client) parse(buf []byte) error { // exact at all but the performance hit is too great to be precise, and // catching here should prevent memory exhaustion attacks. if len(c.argBuf) > int(mcl) { - c.sendErr(ErrMaxControlLine.Error()) + err := NewErrorCtx(ErrMaxControlLine, "State %d, max_control_line %d, Buffer len %d", + c.state, int(mcl), len(c.argBuf)) + c.sendErr(err.Error()) c.closeConnection(MaxControlLineExceeded) - return ErrMaxControlLine + return err } } diff --git a/server/parser_test.go b/server/parser_test.go index caf930ab..dfe185de 100644 --- a/server/parser_test.go +++ b/server/parser_test.go @@ -15,6 +15,7 @@ package server import ( "bytes" + "errors" "testing" ) @@ -582,7 +583,7 @@ func TestMaxControlLine(t *testing.T) { pub := []byte("PUB foo.bar 11\r") err := c.parse(pub) - if err != ErrMaxControlLine { + if !errors.Is(err, ErrMaxControlLine) { t.Fatalf("Expected an error parsing longer than expected control line") } } diff --git a/server/reload.go b/server/reload.go index 89553be6..59e4aaba 100644 --- a/server/reload.go +++ b/server/reload.go @@ -643,7 +643,7 @@ func (s *Server) reloadOptions(curOpts, newOpts *Options) error { if err != nil { return err } - // Create a context that is used to pass special info that we may need + // Create a ctx that is used to pass special info that we may need // while applying the new options. ctx := reloadContext{oldClusterPerms: curOpts.Cluster.Permissions} s.setOpts(newOpts)