Add a ZapMapLogger for logging without duplicate entries

changelog/@unreleased/pr-94.v2.yml

@@ -0,0 +1,5 @@
+type: improvement
+improvement:
+  description: modify wlog-zap and wlog-zerolog to avoid printing duplicate fields in the base object. Duplicate fields results in ambiguous behavior when unmarshalling and can break certain json unmarshaler implementations
+  links:
+  - https://github.com/palantir/witchcraft-go-logging/pull/94

wlog-zap/internal/logger.go

@@ -27,12 +27,19 @@ import (
 )
 
 type zapLogEntry struct {
-	fields []zapcore.Field
+	fields map[string]*zapcore.Field
 	wlog.MapValueEntries
 }
 
+func newZapLogEntry() *zapLogEntry {
+	return &zapLogEntry{
+		fields: make(map[string]*zapcore.Field),
+	}
+}
+
 func (e *zapLogEntry) StringValue(key, value string) {
-	e.fields = append(e.fields, zap.String(key, value))
+	s := zap.String(key, value)
+	e.fields[key] = &s
 }
 
 func (e *zapLogEntry) OptionalStringValue(key, value string) {
@@ -43,29 +50,38 @@ func (e *zapLogEntry) OptionalStringValue(key, value string) {
 
 func (e *zapLogEntry) StringListValue(k string, v []string) {
 	if len(v) > 0 {
-		e.fields = append(e.fields, zap.Strings(k, v))
+		s := zap.Strings(k, v)
+		e.fields[k] = &s
 	}
 }
 
 func (e *zapLogEntry) SafeLongValue(key string, value int64) {
-	e.fields = append(e.fields, zap.Int64(key, value))
+	s := zap.Int64(key, value)
+	e.fields[key] = &s
 }
 
 func (e *zapLogEntry) IntValue(key string, value int32) {
-	e.fields = append(e.fields, zap.Int32(key, value))
+	s := zap.Int32(key, value)
+	e.fields[key] = &s
 }
 
 func (e *zapLogEntry) ObjectValue(k string, v interface{}, marshalerType reflect.Type) {
 	if field, ok := marshalers.FieldForType(marshalerType, k, v); ok {
-		e.fields = append(e.fields, field)
+		e.fields[k] = &field
 	} else {
-		e.fields = append(e.fields, zap.Reflect(k, v))
+		s := zap.Reflect(k, v)
+		e.fields[k] = &s
 	}
 }
 
 func (e *zapLogEntry) Fields() []zapcore.Field {
-	fields := e.fields
-	for key, values := range e.StringMapValues() {
+	stringMapValues := e.StringMapValues()
+	anyMapValues := e.AnyMapValues()
+	fields := make([]zapcore.Field, 0, len(e.fields)+len(stringMapValues)+len(anyMapValues))
+	for _, field := range e.fields {
+		fields = append(fields, *field)
+	}
+	for key, values := range stringMapValues {
 		key := key
 		values := values
 		fields = append(fields, zap.Object(key, zapcore.ObjectMarshalerFunc(func(enc zapcore.ObjectEncoder) error {
@@ -80,7 +96,7 @@ func (e *zapLogEntry) Fields() []zapcore.Field {
 			return nil
 		})))
 	}
-	for key, values := range e.AnyMapValues() {
+	for key, values := range anyMapValues {
 		key := key
 		values := values
 		fields = append(fields, zap.Object(key, zapcore.ObjectMarshalerFunc(func(enc zapcore.ObjectEncoder) error {
@@ -130,7 +146,7 @@ func (l *zapLogger) SetLevel(level wlog.LogLevel) {
 }
 
 func logOutput(logFn func(string, ...zap.Field), msg string, params []wlog.Param) {
-	entry := &zapLogEntry{}
+	entry := newZapLogEntry()
 	wlog.ApplyParams(entry, params)
 	logFn(msg, entry.Fields()...)
 }

wlog-zap/logger_test.go

@@ -47,6 +47,18 @@ func TestSvc1Log(t *testing.T) {
 	})
 }
 
+func BenchmarkSvc1Log(b *testing.B) {
+	b.ReportAllocs()
+	svc1logtests.JSONBenchmarkSuite(b, func(w io.Writer, level wlog.LogLevel, origin string) svc1log.Logger {
+		return svc1log.NewFromCreator(
+			w,
+			level,
+			zapimpl.LoggerProvider().NewLeveledLogger,
+			svc1log.Origin(origin),
+		)
+	})
+}
+
 func TestReq2Log(t *testing.T) {
 	req2logtests.JSONTestSuite(t, func(w io.Writer, params ...req2log.LoggerCreatorParam) req2log.Logger {
 		allParams := append([]req2log.LoggerCreatorParam{

wlog-zerolog/internal/logger.go

@@ -25,11 +25,24 @@ import (
 )
 
 type zeroLogEntry struct {
-	evt *zerolog.Event
+	evt  *zerolog.Event
+	keys map[string]int
 	wlog.MapValueEntries
 }
 
+func (e *zeroLogEntry) keyExists(key string) bool {
+	if i, exists := e.keys[key]; exists {
+		e.keys[key] = i + 1
+		return true
+	}
+	e.keys[key] = 1
+	return false
+}
+
 func (e *zeroLogEntry) StringValue(key, value string) {
+	if e.keyExists(key) {
+		return
+	}
 	e.evt = e.evt.Str(key, value)
 }
 
@@ -41,19 +54,31 @@ func (e *zeroLogEntry) OptionalStringValue(key, value string) {
 
 func (e *zeroLogEntry) StringListValue(k string, v []string) {
 	if len(v) > 0 {
+		if e.keyExists(k) {
+			return
+		}
 		e.evt.Strs(k, v)
 	}
 }
 
 func (e *zeroLogEntry) SafeLongValue(key string, value int64) {
+	if e.keyExists(key) {
+		return
+	}
 	e.evt = e.evt.Int64(key, value)
 }
 
 func (e *zeroLogEntry) IntValue(key string, value int32) {
+	if e.keyExists(key) {
+		return
+	}
 	e.evt = e.evt.Int32(key, value)
 }
 
 func (e *zeroLogEntry) ObjectValue(k string, v interface{}, marshalerType reflect.Type) {
+	if e.keyExists(k) {
+		return
+	}
 	ok := marshalers.EncodeType(e.evt, marshalerType, k, v)
 	if !ok {
 		e.evt.Interface(k, v)
@@ -85,35 +110,67 @@ func (e *zeroLogEntry) Evt() *zerolog.Event {
 
 type zeroLogger struct {
 	logger zerolog.Logger
+	level  zerolog.Level
+}
+
+func (l *zeroLogger) should(level zerolog.Level) bool {
+	if level < l.level {
+		return false
+	}
+	return true
 }
 
 func (l *zeroLogger) Log(params ...wlog.Param) {
+	if !l.should(zerolog.NoLevel) {
+		return
+	}
 	logOutput(l.logger.Log, "", "", params)
 }
 
 func (l *zeroLogger) Debug(msg string, params ...wlog.Param) {
-	logOutput(l.logger.Debug, msg, svc1log.LevelDebugValue, params)
+	if !l.should(zerolog.DebugLevel) {
+		return
+	}
+	logOutput(l.logger.Log, msg, svc1log.LevelDebugValue, params)
 }
 
 func (l *zeroLogger) Info(msg string, params ...wlog.Param) {
-	logOutput(l.logger.Info, msg, svc1log.LevelInfoValue, params)
+	if !l.should(zerolog.InfoLevel) {
+		return
+	}
+	logOutput(l.logger.Log, msg, svc1log.LevelInfoValue, params)
 }
 
 func (l *zeroLogger) Warn(msg string, params ...wlog.Param) {
-	logOutput(l.logger.Warn, msg, svc1log.LevelWarnValue, params)
+	if !l.should(zerolog.WarnLevel) {
+		return
+	}
+	logOutput(l.logger.Log, msg, svc1log.LevelWarnValue, params)
 }
 
 func (l *zeroLogger) Error(msg string, params ...wlog.Param) {
-	logOutput(l.logger.Error, msg, svc1log.LevelErrorValue, params)
+	if !l.should(zerolog.ErrorLevel) {
+		return
+	}
+	logOutput(l.logger.Log, msg, svc1log.LevelErrorValue, params)
 }
 
 func (l *zeroLogger) SetLevel(level wlog.LogLevel) {
+	l.level = toZeroLevel(level)
 	l.logger = l.logger.Level(toZeroLevel(level))
 }
 
+func reverseParams(params []wlog.Param) []wlog.Param {
+	for i, j := 0, len(params)-1; i < j; i, j = i+1, j-1 {
+		params[i], params[j] = params[j], params[i]
+	}
+	return params
+}
+
 func logOutput(newEvt func() *zerolog.Event, msg, levelVal string, params []wlog.Param) {
 	entry := &zeroLogEntry{
-		evt: newEvt(),
+		evt:  newEvt(),
+		keys: make(map[string]int),
 	}
 	if !entry.evt.Enabled() {
 		return
@@ -122,6 +179,7 @@ func logOutput(newEvt func() *zerolog.Event, msg, levelVal string, params []wlog
 	if levelVal != "" {
 		entry.evt = entry.evt.Str(svc1log.LevelKey, levelVal)
 	}
+	params = reverseParams(params)
 	wlog.ApplyParams(entry, params)
 	entry.Evt().Msg(msg)
 }

wlog-zerolog/internal/provider.go

@@ -37,6 +37,7 @@ func (lp *loggerProvider) NewLogger(w io.Writer) wlog.Logger {
 func (lp *loggerProvider) NewLeveledLogger(w io.Writer, level wlog.LogLevel) wlog.LeveledLogger {
 	return &zeroLogger{
 		logger: newZeroLogger(w, level),
+		level:  toZeroLevel(level),
 	}
 }
 

wlog/context_default_test.go

@@ -173,7 +173,7 @@ func testFromContextFromEmptyContextForSingleLogger(t *testing.T, tmpDir string,
 				logOutput := string(bytes)
 
 				firstPortionRegexp := regexp.MustCompile(
-					regexp.QuoteMeta(`[WARNING] github.com/palantir/witchcraft-go-logging/wlog_test.TestOutputFromContextEmptyContext`) + ".+" + regexp.QuoteMeta(`/github.com/palantir/witchcraft-go-logging/wlog/context_default_test.go:`) + "[0-9]+" + regexp.QuoteMeta(`]: usage of `+loggerTestCaseInfo.loggerPkg+`.Logger from FromContext that did not have that logger set: `))
+					regexp.QuoteMeta(`[WARNING]`) + ".*" + regexp.QuoteMeta(`github.com/`) + ".+" + regexp.QuoteMeta(`/witchcraft-go-logging/wlog_test.TestOutputFromContextEmptyContext`) + ".+" + regexp.QuoteMeta(`/github.com/`) + ".+" + regexp.QuoteMeta(`/witchcraft-go-logging/wlog/context_default_test.go:`) + "[0-9]+" + regexp.QuoteMeta(`]: usage of `+loggerTestCaseInfo.loggerPkg+`.Logger from FromContext that did not have that logger set: `))
 				loc := firstPortionRegexp.FindStringIndex(logOutput)
 				require.NotNil(t, loc, "Unexpected log output: %s", logOutput)
 
@@ -196,7 +196,7 @@ func testFromContextFromEmptyContextForSingleLogger(t *testing.T, tmpDir string,
 				logOutput := string(bytes)
 
 				firstPortionRegexp := regexp.MustCompile(
-					regexp.QuoteMeta(`[WARNING] github.com/palantir/witchcraft-go-logging/wlog_test.TestOutputFromContextEmptyContext`) + ".+" + regexp.QuoteMeta(`/github.com/palantir/witchcraft-go-logging/wlog/context_default_test.go:`) + "[0-9]+" + regexp.QuoteMeta(`]: usage of `+loggerTestCaseInfo.loggerPkg+`.Logger from FromContext that did not have that logger set: `))
+					regexp.QuoteMeta(`[WARNING]`) + ".*" + regexp.QuoteMeta(`github.com/`) + ".+" + regexp.QuoteMeta(`/witchcraft-go-logging/wlog_test.TestOutputFromContextEmptyContext`) + ".+" + regexp.QuoteMeta(`/github.com/`) + ".+" + regexp.QuoteMeta(`/witchcraft-go-logging/wlog/context_default_test.go:`) + "[0-9]+" + regexp.QuoteMeta(`]: usage of `+loggerTestCaseInfo.loggerPkg+`.Logger from FromContext that did not have that logger set: `))
 				loc := firstPortionRegexp.FindStringIndex(logOutput)
 				require.NotNil(t, loc, "Unexpected log output: %s", logOutput)
 

wlog/svclog/svc1log/svc1logtests/tests.go

@@ -19,6 +19,7 @@ import (
 	"encoding/json"
 	"fmt"
 	"io"
+	"strings"
 	"testing"
 
 	"github.com/palantir/pkg/objmatcher"
@@ -310,7 +311,61 @@ something/something:123`,
 				}),
 			}),
 		},
+		{
+			Name:    "duplicate origin",
+			Message: "this is a test",
+			LogParams: []svc1log.Param{
+				svc1log.Origin("origin.0"),
+				svc1log.Origin("origin.1"),
+				svc1log.UID("user-1"),
+				svc1log.SID("session-1"),
+				svc1log.TraceID("X-Y-Z"),
+				svc1log.SafeParams(map[string]interface{}{
+					"key": "value",
+					"int": 10,
+				}),
+				svc1log.UnsafeParams(map[string]interface{}{
+					"Password": "HelloWorld!",
+				}),
+				svc1log.Tags(map[string]string{
+					"key1": "value1",
+					"key2": "value2",
+				}),
+			},
+			JSONMatcher: objmatcher.MapMatcher(map[string]objmatcher.Matcher{
+				"origin":  objmatcher.NewEqualsMatcher("origin.1"),
+				"level":   objmatcher.NewEqualsMatcher("INFO"),
+				"time":    objmatcher.NewRegExpMatcher(".+"),
+				"type":    objmatcher.NewEqualsMatcher("service.1"),
+				"message": objmatcher.NewEqualsMatcher("this is a test"),
+				"params": objmatcher.MapMatcher(map[string]objmatcher.Matcher{
+					"key": objmatcher.NewEqualsMatcher("value"),
+					"int": objmatcher.NewEqualsMatcher(json.Number("10")),
+				}),
+				"uid":     objmatcher.NewEqualsMatcher("user-1"),
+				"sid":     objmatcher.NewEqualsMatcher("session-1"),
+				"traceId": objmatcher.NewEqualsMatcher("X-Y-Z"),
+				"unsafeParams": objmatcher.MapMatcher(map[string]objmatcher.Matcher{
+					"Password": objmatcher.NewEqualsMatcher("HelloWorld!"),
+				}),
+				"tags": objmatcher.MapMatcher(map[string]objmatcher.Matcher{
+					"key1": objmatcher.NewEqualsMatcher("value1"),
+					"key2": objmatcher.NewEqualsMatcher("value2"),
+				}),
+			}),
+		},
+	}
+}
+
+func BenchmarkCases() []TestCase {
+	testCases := TestCases()
+	benchmarkCases := make([]TestCase, 0, len(testCases))
+	for _, testCase := range testCases {
+		if testCase.Name != "duplicate origin" && testCase.Name != "parameter that is set manually overrides base value" {
+			benchmarkCases = append(benchmarkCases, testCase)
+		}
 	}
+	return benchmarkCases
 }
 
 func JSONTestSuite(t *testing.T, loggerProvider func(w io.Writer, level wlog.LogLevel, origin string) svc1log.Logger) {
@@ -362,6 +417,9 @@ func jsonOutputTests(t *testing.T, loggerProvider func(w io.Writer, level wlog.L
 			logEntry := buf.Bytes()
 			err := safejson.Unmarshal(logEntry, &gotServiceLog)
 			require.NoError(t, err, "Case %d: %s\nService log line is not a valid map: %v", i, tc.Name, string(logEntry))
+			logEntryRewrite, err := safejson.Marshal(gotServiceLog)
+			require.NoError(t, err, "Not able to marshal log line")
+			assert.Equal(t, len(strings.TrimRight(string(logEntry), "\n")), len(string(logEntryRewrite)), "log line is not stable. Differing length on remarshal")
 
 			assert.NoError(t, tc.JSONMatcher.Matches(gotServiceLog), "Case %d: %s", i, tc.Name)
 		})
@@ -447,6 +505,25 @@ func extraParamsDoNotAppearTest(t *testing.T, loggerProvider func(w io.Writer, l
 	})
 }
 
+func JSONBenchmarkSuite(b *testing.B, loggerProvider func(w io.Writer, level wlog.LogLevel, origin string) svc1log.Logger) {
+	jsonOutputBenchmarks(b, loggerProvider)
+}
+
+func jsonOutputBenchmarks(b *testing.B, loggerProvider func(w io.Writer, level wlog.LogLevel, origin string) svc1log.Logger) {
+	buf := bytes.Buffer{}
+	for _, tc := range BenchmarkCases() {
+		b.Run(tc.Name, func(b *testing.B) {
+			logger := loggerProvider(&buf, wlog.DebugLevel, tc.Origin)
+			b.ResetTimer()
+			for i := 0; i < b.N; i++ {
+				buf.Reset()
+				logger.Info(tc.Message, tc.LogParams...)
+				assert.Greater(b, buf.Len(), 0)
+			}
+		})
+	}
+}
+
 // panics when marshaled as JSON
 type jsonMarshalPanicType struct{}