Repository: hashicorp/go-hclog
Pull request #17 (2018-04-01 21:43:42)

With() fixes
During the Vault migration to hclog log we ran into a data race error. This was traced back to a couple of slice aliasing instances in hclog. Tests were written (first commit) demonstrating the coupling between separate loggers. These operations in goroutines will trigger race detector errors (as well as incorrect output).

It was also discovered that the bound `With()` parameters were not being output if the format is set to JSON.

Both of these issues are addressed in this PR.


Patch:
diff --git a/int.go b/int.go
index 8b13493..340cfdf 100644
--- a/int.go
+++ b/int.go
@@ -274,6 +274,8 @@ func (z *intLogger) logJson(t time.Time, level Level, msg string, args ...interf
 		}
 	}
 
+	args = append(z.implied, args...)
+
 	if args != nil && len(args) > 0 {
 		if len(args)%2 != 0 {
 			cs, ok := args[len(args)-1].(CapturedStacktrace)
@@ -368,6 +370,8 @@ func (z *intLogger) IsError() bool {
 func (z *intLogger) With(args ...interface{}) Logger {
 	var nz intLogger = *z
 
+	nz.implied = make([]interface{}, 0, len(z.implied)+len(args))
+	nz.implied = append(nz.implied, z.implied...)
 	nz.implied = append(nz.implied, args...)
 
 	return &nz


Test patch:
diff --git a/logger_test.go b/logger_test.go
index 5249c52..bb233e9 100644
--- a/logger_test.go
+++ b/logger_test.go
@@ -152,17 +152,98 @@ func TestLogger(t *testing.T) {
 
 		assert.Equal(t, str[:dataIdx], time.Now().Format(time.Kitchen))
 	})
+
+	t.Run("use with", func(t *testing.T) {
+		var buf bytes.Buffer
+
+		rootLogger := New(&LoggerOptions{
+			Name:   "with_test",
+			Output: &buf,
+		})
+
+		// 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 two new loggers which should be completely independent
+		derived1 := rootLogger.With("cat", 30)
+		derived2 := rootLogger.With("dog", 40)
+
+		derived1.Info("test1")
+		output := buf.String()
+		dataIdx := strings.IndexByte(output, ' ')
+		assert.Equal(t, "[INFO ] with_test: test1: a=1 b=2 c=3 cat=30\n", output[dataIdx+1:])
+
+		buf.Reset()
+
+		derived2.Info("test2")
+		output = buf.String()
+		dataIdx = strings.IndexByte(output, ' ')
+		assert.Equal(t, "[INFO ] with_test: test2: a=1 b=2 c=3 dog=40\n", output[dataIdx+1:])
+	})
+
+	t.Run("use with and log", func(t *testing.T) {
+		var buf bytes.Buffer
+
+		rootLogger := New(&LoggerOptions{
+			Name:   "with_test",
+			Output: &buf,
+		})
+
+		// 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()
+		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:])
+	})
 }
 
 func TestLogger_JSON(t *testing.T) {
 	t.Run("json formatting", func(t *testing.T) {
 		var buf bytes.Buffer
+		logger := New(&LoggerOptions{
+			Name:       "test",
+			Output:     &buf,
+			JSONFormat: true,
+		})
+
+		logger.Info("this is test", "who", "programmer", "why", "testing is fun")
+
+		b := buf.Bytes()
+
+		var raw map[string]interface{}
+		if err := json.Unmarshal(b, &raw); err != nil {
+			t.Fatal(err)
+		}
 
+		assert.Equal(t, "this is test", raw["@message"])
+		assert.Equal(t, "programmer", raw["who"])
+		assert.Equal(t, "testing is fun", raw["why"])
+	})
+
+	t.Run("json formatting with", func(t *testing.T) {
+		var buf bytes.Buffer
 		logger := New(&LoggerOptions{
 			Name:       "test",
 			Output:     &buf,
 			JSONFormat: true,
 		})
+		logger = logger.With("cat", "in the hat", "dog", 42)
 
 		logger.Info("this is test", "who", "programmer", "why", "testing is fun")
 
@@ -176,7 +257,10 @@ func TestLogger_JSON(t *testing.T) {
 		assert.Equal(t, "this is test", raw["@message"])
 		assert.Equal(t, "programmer", raw["who"])
 		assert.Equal(t, "testing is fun", raw["why"])
+		assert.Equal(t, "in the hat", raw["cat"])
+		assert.Equal(t, float64(42), raw["dog"])
 	})
+
 	t.Run("json formatting error type", func(t *testing.T) {
 		var buf bytes.Buffer