Simplify and correct the Logger

And some design pattern proposals added

Author: Lars Ekman

docs/logging.md

@@ -46,6 +46,16 @@ When executed this will produce (formatted with
 }
 ```
 
+Structured logs can be scanned with [jq](https://stedolan.github.io/jq/).
+
+```
+kubectl logs -n red meridio-load-balancer-6dbbb9556f-f5cc4 -c load-balancer \
+  | grep '^{' | jq 'select(.extra_data.class == "SimpleNetworkService")'
+kubectl logs -n red meridio-load-balancer-6dbbb9556f-f5cc4 -c load-balancer \
+  | grep '^{' | jq 'select(.extra_data.class == "SimpleNetworkService")|select(.message == "updateVips")'
+
+```
+
 ## Logger from context
 
 A logger should be created in `main()` and be used for logging
@@ -139,3 +149,53 @@ Example output;
   }
 }
 ```
+
+
+## Design patterns
+
+Patterns must evolve slowly to get really good so these are mere
+ideas. It is very easy to get carried away and impose some over
+structured logging that floods the logs with useless data.
+
+
+### Class logger
+
+A logger used in a type (Class) can be decorated with `class` and
+`instance` records;
+
+```go
+type someHandler struct {
+	ctx    context.Context
+	logger logr.Logger
+	Adr    *net.TCPAddr // Capitalized to make it visible!
+}
+
+func newHandler(ctx context.Context, addr string) *someHandler {
+	logger := log.FromContextOrGlobal(ctx).WithValues("class", "someHandler")
+	adr, err := net.ResolveTCPAddr("tcp", addr)
+	if err != nil {
+		log.Fatal(logger, "ResolveTCPAddr", "error", err)
+	}
+	h := &someHandler{
+		ctx:    ctx,
+		logger: logger.WithValues("instance", adr),
+		Adr:    adr,
+	}
+	h.logger.Info("Created")
+	return h
+}
+
+func (h *someHandler) connect() error {
+	logger := h.logger.WithValues("func", "connect")
+	logger.Info("Called")
+	return nil
+}
+```
+
+The `class` is the name of the type and `instance` can be anything
+that identifies an instance. Remember that the instance field must be
+visible (Capitalized).
+
+The example shows a `func` entry to identify a function. This should
+*not* be used as a common pattern but may be handy in some cases.
+

pkg/log/logger.go

@@ -24,7 +24,6 @@ import (
 	nsmlog "github.com/networkservicemesh/sdk/pkg/tools/log"
 )
 
-
 // Several different logr backends can be tested by remove/add comment
 // below.
 
@@ -142,7 +141,6 @@ import (
 
 	"github.com/go-logr/zapr"
 	"go.uber.org/zap"
-	"go.uber.org/zap/buffer"
 	"go.uber.org/zap/zapcore"
 )
 
@@ -190,7 +188,6 @@ func newLogger(level string) logr.Logger {
 	//zc.EncoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder (almost works)
 	zc.EncoderConfig.EncodeTime = timeEncoder
 	zc.EncoderConfig.EncodeLevel = adpLevelEncoder
-	zc.Encoding = "ADP"
 	z, err := zc.Build()
 	if err != nil {
 		zc.Encoding = "json"
@@ -199,122 +196,11 @@ func newLogger(level string) logr.Logger {
 			panic(fmt.Sprintf("Can't create a zap logger (%v)?", err))
 		}
 	}
-	return zapr.NewLogger(z.With(zap.String("version", "1.1.0")))
-}
-
-// We just want to add "extra_data: { ... }" for additional fields
-// but I found no other way than to define an own zapcore.Encoder.
-// Everything except the EncodeEntry() is passed to the JSONEncoder.
-type adpEncoder struct {
-	jsonEncoder zapcore.Encoder
-}
-
-func (e *adpEncoder) Clone() zapcore.Encoder {
-	return &adpEncoder{jsonEncoder: e.jsonEncoder.Clone()}
-}
-
-// https://stackoverflow.com/questions/53737435/how-to-prepend-int-to-slice
-func prependField(x []zapcore.Field, y zapcore.Field) []zapcore.Field {
-	x = append(x, zapcore.Field{})
-	copy(x[1:], x)
-	x[0] = y
-	return x
-}
-func (e *adpEncoder) EncodeEntry(
-	entry zapcore.Entry, f []zapcore.Field) (*buffer.Buffer, error) {
-	if len(f) == 0 {
-		return e.jsonEncoder.EncodeEntry(entry, f)
-	}
-	ns := zapcore.Field{
-		Key:  "extra_data",
-		Type: zapcore.NamespaceType,
-	}
-	return e.jsonEncoder.EncodeEntry(entry, prependField(f, ns))
-}
-func (e *adpEncoder) AddArray(key string, marshaler zapcore.ArrayMarshaler) error {
-	return e.jsonEncoder.AddArray(key, marshaler)
-}
-func (e *adpEncoder) AddObject(key string, marshaler zapcore.ObjectMarshaler) error {
-	return e.jsonEncoder.AddObject(key, marshaler)
-}
-func (e *adpEncoder) AddBinary(key string, value []byte) {
-	e.jsonEncoder.AddBinary(key, value)
-}
-func (e *adpEncoder) AddByteString(key string, value []byte) {
-	e.jsonEncoder.AddByteString(key, value)
-}
-func (e *adpEncoder) AddBool(key string, value bool) {
-	e.jsonEncoder.AddBool(key, value)
-}
-func (e *adpEncoder) AddComplex128(key string, value complex128) {
-	e.jsonEncoder.AddComplex128(key, value)
-}
-func (e *adpEncoder) AddComplex64(key string, value complex64) {
-	e.jsonEncoder.AddComplex64(key, value)
-}
-func (e *adpEncoder) AddDuration(key string, value time.Duration) {
-	e.jsonEncoder.AddDuration(key, value)
-}
-func (e *adpEncoder) AddFloat64(key string, value float64) {
-	e.jsonEncoder.AddFloat64(key, value)
-}
-func (e *adpEncoder) AddFloat32(key string, value float32) {
-	e.jsonEncoder.AddFloat32(key, value)
-}
-func (e *adpEncoder) AddInt(key string, value int) {
-	e.jsonEncoder.AddInt(key, value)
-}
-func (e *adpEncoder) AddInt64(key string, value int64) {
-	e.jsonEncoder.AddInt64(key, value)
-}
-func (e *adpEncoder) AddInt32(key string, value int32) {
-	e.jsonEncoder.AddInt32(key, value)
-}
-func (e *adpEncoder) AddInt16(key string, value int16) {
-	e.jsonEncoder.AddInt16(key, value)
-}
-func (e *adpEncoder) AddInt8(key string, value int8) {
-	e.jsonEncoder.AddInt8(key, value)
-}
-func (e *adpEncoder) AddString(key, value string) {
-	e.jsonEncoder.AddString(key, value)
-}
-func (e *adpEncoder) AddTime(key string, value time.Time) {
-	e.jsonEncoder.AddTime(key, value)
-}
-func (e *adpEncoder) AddUint(key string, value uint) {
-	e.jsonEncoder.AddUint(key, value)
-}
-func (e *adpEncoder) AddUint64(key string, value uint64) {
-	e.jsonEncoder.AddUint64(key, value)
-}
-func (e *adpEncoder) AddUint32(key string, value uint32) {
-	e.jsonEncoder.AddUint32(key, value)
-}
-func (e *adpEncoder) AddUint16(key string, value uint16) {
-	e.jsonEncoder.AddUint16(key, value)
-}
-func (e *adpEncoder) AddUint8(key string, value uint8) {
-	e.jsonEncoder.AddUint8(key, value)
-}
-func (e *adpEncoder) AddUintptr(key string, value uintptr) {
-	e.jsonEncoder.AddUintptr(key, value)
-}
-func (e *adpEncoder) AddReflected(key string, value interface{}) error {
-	return e.jsonEncoder.AddReflected(key, value)
-}
-func (e *adpEncoder) OpenNamespace(key string) {
-	e.jsonEncoder.OpenNamespace(key)
+	return zapr.NewLogger(z.With(
+		zap.String("version", "1.0.0"), zap.Namespace("extra_data")))
 }
 
 func init() {
-	_ = zap.RegisterEncoder(
-		"ADP", func(cfg zapcore.EncoderConfig) (zapcore.Encoder, error) {
-			//return zapcore.NewJSONEncoder(cfg), nil
-			return &adpEncoder{
-				jsonEncoder: zapcore.NewJSONEncoder(cfg),
-			}, nil
-		})
 	Logger = newLogger("").WithName("Meridio")
 }
 
@@ -341,17 +227,19 @@ func Fatal(logger logr.Logger, msg string, keysAndValues ...interface{}) {
 // NSMLogger return a logger to use for NSM logging.
 func NSMLogger(logger logr.Logger) nsmlog.Logger {
 	// Get the zap logger
-	if underlier, ok := logger.GetSink().(zapr.Underlier); ok {
-		z := underlier.GetUnderlying()
-		return &nsmLogger{ z: z, s: z.Sugar() }
-	} else {
+	z := ZapLogger(logger)
+	if z == nil {
 		panic("NSMLogger: Can't get the Zap logger")
 	}
+	nsmz := z.With(zap.String("subsystem", "NSM"))
+	return &nsmLogger{z: nsmz, s: nsmz.Sugar()}
 }
+
 type nsmLogger struct {
 	z *zap.Logger
 	s *zap.SugaredLogger
 }
+
 func (l *nsmLogger) Info(v ...interface{}) {
 	l.s.Info(v...)
 }
@@ -393,15 +281,14 @@ func (l *nsmLogger) Tracef(format string, v ...interface{}) {
 	}
 }
 func (l *nsmLogger) Object(k, v interface{}) {
-	l.s.Info(k, v)
+	l.z.Info("Object", zap.Any(fmt.Sprintf("%v", k), v))
 }
 func (l *nsmLogger) WithField(key, value interface{}) nsmlog.Logger {
 	return &nsmLogger{
 		z: l.z.With(zap.Any(fmt.Sprintf("%v", key), value)),
 	}
 }
 
-
 // Logger The global logger
 var Logger logr.Logger
 
@@ -419,8 +306,8 @@ func FromContextOrGlobal(ctx context.Context) logr.Logger {
 // the global Logger is set.
 func New(name, level string) logr.Logger {
 	logger := newLogger(level).WithName(name)
-	once.Do(func () {Logger = logger})
+	once.Do(func() { Logger = logger })
 	return logger
 }
-var once sync.Once
 
+var once sync.Once

pkg/log/logger_test.go

@@ -1,11 +1,14 @@
 package log_test
 
 import (
+	"context"
 	"fmt"
+	"net"
 	"os"
 	"testing"
 	"time"
 
+	"github.com/go-logr/logr"
 	"github.com/nordix/meridio/pkg/log"
 )
 
@@ -18,7 +21,7 @@ func TestLogger(t *testing.T) {
 	log.Logger.Info("From the default logger before New")
 	logger := log.New("Meridio-test-global", os.Getenv("FOO"))
 	log.Logger.Info("From the default logger AFTER New")
-	
+
 	logger.Info("Started", "at", time.Now())
 	log.Logger.Info("Printed by the global logger")
 	logger.Error(fmt.Errorf("THIS IS THE ERROR OBJ"), "An error!", "a number", 44)
@@ -46,10 +49,48 @@ func TestLogger(t *testing.T) {
 	log.Logger.V(2).Info("INVISIBLE TRACE message")
 
 	//log.Fatal(logger, "Can't read crucial data", "error", fmt.Errorf("Not found"))
+}
 
+func TestNSMLogger(t *testing.T) {
 	nsmlogger := log.NSMLogger(log.New("NSMLogger-info", ""))
-	if nsmlogger != nil {
-		nsmlogger.Info("one", "two", "three")
-		nsmlogger.Infof("%v, %v, %v", "one", "two", "three")
+	if nsmlogger == nil {
+		return
+	}
+	nsmlogger.Info("one", "two", "three")
+	nsmlogger.Infof("%v, %v, %v", "one", "two", "three")
+	nsmlogger.Object(44, "Key is an int")
+}
+
+type someHandler struct {
+	ctx    context.Context
+	logger logr.Logger
+	Adr    *net.TCPAddr // Capitalized to make it visible!
+}
+
+func newHandler(ctx context.Context, addr string) *someHandler {
+	logger := log.FromContextOrGlobal(ctx).WithValues("class", "someHandler")
+	adr, err := net.ResolveTCPAddr("tcp", addr)
+	if err != nil {
+		log.Fatal(logger, "ResolveTCPAddr", "error", err)
+	}
+	h := &someHandler{
+		ctx:    ctx,
+		logger: logger.WithValues("instance", adr),
+		Adr:    adr,
 	}
+	h.logger.Info("Created")
+	return h
+}
+
+func (h *someHandler) connect() error {
+	logger := h.logger.WithValues("func", "connect")
+	logger.Info("Called")
+	return nil
+}
+
+func TestPatterns(t *testing.T) {
+	logger := log.New("HandlerApp", "")
+	ctx := logr.NewContext(context.TODO(), logger)
+	h := newHandler(ctx, "[1000::]:80")
+	_ = h.connect()
 }