Repository: hashicorp/go-hclog
Pull request #22 (2018-07-05 13:41:51)

Fix With appending multiple keys with different values
See #21

jefferai: Added a few leads as reviewers just to get visibility on the change.

Patch:
diff --git a/int.go b/int.go
index 0166c3d..7d17d81 100644
--- a/int.go
+++ b/int.go
@@ -8,9 +8,11 @@ import (
 	"log"
 	"os"
 	"runtime"
+	"sort"
 	"strconv"
 	"strings"
 	"sync"
+	"sync/atomic"
 	"time"
 )
 
@@ -52,11 +54,12 @@ func New(opts *LoggerOptions) Logger {
 		name:       opts.Name,
 		timeFormat: TimeFormat,
 		w:          bufio.NewWriter(output),
-		level:      level,
+		level:      new(int32),
 	}
 	if opts.TimeFormat != "" {
 		ret.timeFormat = opts.TimeFormat
 	}
+	atomic.StoreInt32(ret.level, int32(level))
 	return ret
 }
 
@@ -72,7 +75,7 @@ type intLogger struct {
 	// those derived loggers share the bufio.Writer as well.
 	m     *sync.Mutex
 	w     *bufio.Writer
-	level Level
+	level *int32
 
 	implied []interface{}
 }
@@ -87,7 +90,7 @@ const TimeFormat = "2006-01-02T15:04:05.000Z0700"
 // Log a message and a set of key/value pairs if the given level is at
 // or more severe that the threshold configured in the Logger.
 func (z *intLogger) Log(level Level, msg string, args ...interface{}) {
-	if level < z.level {
+	if level < Level(atomic.LoadInt32(z.level)) {
 		return
 	}
 
@@ -347,38 +350,66 @@ func (z *intLogger) Error(msg string, args ...interface{}) {
 
 // Indicate that the logger would emit TRACE level logs
 func (z *intLogger) IsTrace() bool {
-	return z.level == Trace
+	return Level(atomic.LoadInt32(z.level)) == Trace
 }
 
 // Indicate that the logger would emit DEBUG level logs
 func (z *intLogger) IsDebug() bool {
-	return z.level <= Debug
+	return Level(atomic.LoadInt32(z.level)) <= Debug
 }
 
 // Indicate that the logger would emit INFO level logs
 func (z *intLogger) IsInfo() bool {
-	return z.level <= Info
+	return Level(atomic.LoadInt32(z.level)) <= Info
 }
 
 // Indicate that the logger would emit WARN level logs
 func (z *intLogger) IsWarn() bool {
-	return z.level <= Warn
+	return Level(atomic.LoadInt32(z.level)) <= Warn
 }
 
 // Indicate that the logger would emit ERROR level logs
 func (z *intLogger) IsError() bool {
-	return z.level <= Error
+	return Level(atomic.LoadInt32(z.level)) <= Error
 }
 
 // Return a sub-Logger for which every emitted log message will contain
 // the given key/value pairs. This is used to create a context specific
 // Logger.
 func (z *intLogger) With(args ...interface{}) Logger {
+	if len(args)%2 != 0 {
+		panic("With() call requires paired arguments")
+	}
+
 	var nz intLogger = *z
 
+	result := make(map[string]interface{}, len(z.implied)+len(args))
+	keys := make([]string, 0, len(z.implied)+len(args))
+
+	// Read existing args, store map and key for consistent sorting
+	for i := 0; i < len(z.implied); i += 2 {
+		key := z.implied[i].(string)
+		keys = append(keys, key)
+		result[key] = z.implied[i+1]
+	}
+	// Read new args, store map and key for consistent sorting
+	for i := 0; i < len(args); i += 2 {
+		key := args[i].(string)
+		_, exists := result[key]
+		if !exists {
+			keys = append(keys, key)
+		}
+		result[key] = args[i+1]
+	}
+
+	// Sort keys to be consistent
+	sort.Strings(keys)
+
 	nz.implied = make([]interface{}, 0, len(z.implied)+len(args))
-	nz.implied = append(nz.implied, z.implied...)
-	nz.implied = append(nz.implied, args...)
+	for _, k := range keys {
+		nz.implied = append(nz.implied, k)
+		nz.implied = append(nz.implied, result[k])
+	}
 
 	return &nz
 }
@@ -408,6 +439,12 @@ func (z *intLogger) ResetNamed(name string) Logger {
 	return &nz
 }
 
+// Update the logging level on-the-fly. This will affect all subloggers as
+// well.
+func (z *intLogger) SetLevel(level Level) {
+	atomic.StoreInt32(z.level, int32(level))
+}
+
 // Create a *log.Logger that will send it's data through this Logger. This
 // allows packages that expect to be using the standard library log to actually
 // use this logger.
diff --git a/log.go b/log.go
index 3629248..894e846 100644
--- a/log.go
+++ b/log.go
@@ -13,7 +13,7 @@ var (
 	DefaultLevel  = Info
 )
 
-type Level int
+type Level int32
 
 const (
 	// This is a special level used to indicate that no level has been
@@ -121,6 +121,10 @@ type Logger interface {
 	// the current name as well.
 	ResetNamed(name string) Logger
 
+	// Updates the level. This should affect all sub-loggers as well. If an
+	// implementation cannot update the level on the fly, it should no-op.
+	SetLevel(level Level)
+
 	// Return a value that conforms to the stdlib log.Logger interface
 	StandardLogger(opts *StandardLoggerOptions) *log.Logger
 }
diff --git a/nulllogger.go b/nulllogger.go
index c10ce6e..0942361 100644
--- a/nulllogger.go
+++ b/nulllogger.go
@@ -1,8 +1,8 @@
 package hclog
 
 import (
-	"log"
 	"io/ioutil"
+	"log"
 )
 
 // NewNullLogger instantiates a Logger for which all calls
@@ -40,6 +40,8 @@ func (l *nullLogger) Named(name string) Logger { return l }
 
 func (l *nullLogger) ResetNamed(name string) Logger { return l }
 
+func (l *nullLogger) SetLevel(level Level) {}
+
 func (l *nullLogger) StandardLogger(opts *StandardLoggerOptions) *log.Logger {
 	return log.New(ioutil.Discard, "", log.LstdFlags)
-}
\ No newline at end of file
+}


Test patch:
diff --git a/logger_test.go b/logger_test.go
index d8c143f..b82ed12 100644
--- a/logger_test.go
+++ b/logger_test.go
@@ -183,6 +183,23 @@ func TestLogger(t *testing.T) {
 		assert.Equal(t, "[INFO ] with_test: test2: a=1 b=2 c=3 dog=40\n", output[dataIdx+1:])
 	})
 
+	t.Run("unpaired with", func(t *testing.T) {
+		defer func() {
+			if r := recover(); r == nil {
+				t.Fatal("expected panic")
+			}
+		}()
+
+		var buf bytes.Buffer
+
+		rootLogger := New(&LoggerOptions{
+			Name:   "with_test",
+			Output: &buf,
+		})
+
+		rootLogger = rootLogger.With("a")
+	})
+
 	t.Run("use with and log", func(t *testing.T) {
 		var buf bytes.Buffer
 
@@ -194,6 +211,9 @@ func TestLogger(t *testing.T) {
 		// Build the root logger in two steps, which triggers a slice capacity increase
 		// and is part of the test for inadvertant slice aliasing.
 		rootLogger = rootLogger.With("a", 1, "b", 2)
+		// This line is here to test that when calling With with the same key,
+		// only the last value remains (see issue #21)
+		rootLogger = rootLogger.With("c", 4)
 		rootLogger = rootLogger.With("c", 3)
 
 		// Derive another logger which should be completely independent of rootLogger
@@ -212,6 +232,52 @@ func TestLogger(t *testing.T) {
 		assert.Equal(t, "[INFO ] with_test: derived_test: a=1 b=2 c=3 cat=30\n", output[dataIdx+1:])
 	})
 
+	t.Run("use with and log and change levels", func(t *testing.T) {
+		var buf bytes.Buffer
+
+		rootLogger := New(&LoggerOptions{
+			Name:   "with_test",
+			Output: &buf,
+			Level:  Warn,
+		})
+
+		// Build the root logger in two steps, which triggers a slice capacity increase
+		// and is part of the test for inadvertant slice aliasing.
+		rootLogger = rootLogger.With("a", 1, "b", 2)
+		rootLogger = rootLogger.With("c", 3)
+
+		// Derive another logger which should be completely independent of rootLogger
+		derived := rootLogger.With("cat", 30)
+
+		rootLogger.Info("root_test", "bird", 10)
+		output := buf.String()
+		if output != "" {
+			t.Fatalf("unexpected output: %s", output)
+		}
+
+		buf.Reset()
+
+		derived.Info("derived_test")
+		output = buf.String()
+		if output != "" {
+			t.Fatalf("unexpected output: %s", output)
+		}
+
+		derived.SetLevel(Info)
+
+		rootLogger.Info("root_test", "bird", 10)
+		output = buf.String()
+		dataIdx := strings.IndexByte(output, ' ')
+		assert.Equal(t, "[INFO ] with_test: root_test: a=1 b=2 c=3 bird=10\n", output[dataIdx+1:])
+
+		buf.Reset()
+
+		derived.Info("derived_test")
+		output = buf.String()
+		dataIdx = strings.IndexByte(output, ' ')
+		assert.Equal(t, "[INFO ] with_test: derived_test: a=1 b=2 c=3 cat=30\n", output[dataIdx+1:])
+	})
+
 	t.Run("supports Printf style expansions when requested", func(t *testing.T) {
 		var buf bytes.Buffer