Suggestion to improve tracing in nats-server through wrapping errors

Signed-off-by: Matthias Hanel <mh@synadia.com>

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)

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()
+}

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")
+	}
+}

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{}) {

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
 		}
 	}
 

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")
 	}
 }

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)