Add a ZapMapLogger and ZerologMapLogger for logging without duplicate…

… entries (#94)

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-zerolog/internal/logger.go

@@ -25,11 +25,24 @@ import (
 )
 
 type zeroLogEntry struct {
-	evt *zerolog.Event
-	wlog.MapValueEntries
+	evt             *zerolog.Event
+	keys            map[string]struct{}
+	stringMapValues map[string]map[string]string
+	anyMapValues    map[string]map[string]interface{}
+}
+
+func (e *zeroLogEntry) keyExists(key string) bool {
+	if _, exists := e.keys[key]; exists {
+		return true
+	}
+	e.keys[key] = struct{}{}
+	return false
 }
 
 func (e *zeroLogEntry) StringValue(key, value string) {
+	if e.keyExists(key) {
+		return
+	}
 	e.evt = e.evt.Str(key, value)
 }
 
@@ -41,25 +54,91 @@ 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)
 	}
 }
 
+//StringMapValue adds or merges the strings in values
+//Since wlog overrides duplicates with a preference for the last parameter
+//The parameters should not replace an existing key because parameters are passed to zerolog in reverse
+//This differs from the default wlog StringMapValue since parameters are not reversed
+func (e *zeroLogEntry) StringMapValue(key string, values map[string]string) {
+	if len(values) == 0 {
+		return
+	}
+	if e.stringMapValues == nil {
+		e.stringMapValues = make(map[string]map[string]string)
+	}
+	entryMapVals, ok := e.stringMapValues[key]
+	if !ok {
+		entryMapVals = make(map[string]string)
+		e.stringMapValues[key] = entryMapVals
+	}
+	for k, v := range values {
+		if _, exists := entryMapVals[k]; !exists {
+			entryMapVals[k] = v
+		}
+	}
+}
+
+//AnyMapValue adds or merges the values in values
+//Since wlog overrides duplicates with a preference for the last parameter
+//The parameters should not replace an existing key because parameters are passed to zerolog in reverse
+//This differs from the default wlog AnyMapValue since parameters are not reversed
+func (e *zeroLogEntry) AnyMapValue(key string, values map[string]interface{}) {
+	if len(values) == 0 {
+		return
+	}
+	if e.anyMapValues == nil {
+		e.anyMapValues = make(map[string]map[string]interface{})
+	}
+	entryMapVals, ok := e.anyMapValues[key]
+	if !ok {
+		entryMapVals = make(map[string]interface{})
+		e.anyMapValues[key] = entryMapVals
+	}
+	for k, v := range values {
+		if _, exists := entryMapVals[k]; !exists {
+			entryMapVals[k] = v
+		}
+	}
+}
+
+func (e *zeroLogEntry) StringMapValues() map[string]map[string]string {
+	return e.stringMapValues
+}
+
+func (e *zeroLogEntry) AnyMapValues() map[string]map[string]interface{} {
+	return e.anyMapValues
+}
+
 func (e *zeroLogEntry) Evt() *zerolog.Event {
 	evt := e.evt
 	for key, values := range e.StringMapValues() {
@@ -85,35 +164,66 @@ 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) {
+	for i, j := 0, len(params)-1; i < j; i, j = i+1, j-1 {
+		params[i], params[j] = params[j], params[i]
+	}
+}
+
 func logOutput(newEvt func() *zerolog.Event, msg, levelVal string, params []wlog.Param) {
 	entry := &zeroLogEntry{
-		evt: newEvt(),
+		evt:  newEvt(),
+		keys: make(map[string]struct{}),
 	}
 	if !entry.evt.Enabled() {
 		return
@@ -122,6 +232,7 @@ func logOutput(newEvt func() *zerolog.Event, msg, levelVal string, params []wlog
 	if levelVal != "" {
 		entry.evt = entry.evt.Str(svc1log.LevelKey, levelVal)
 	}
+	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)