Repository: hashicorp/go-hclog
Pull request #39 (2019-04-23 22:26:34)

Don't panic if json logging fails
Handle cases where json logging fails to write:
* json serialization errors; log plain message with
metadata with a field indicating that args are omitted from logs
* io errors: ignore them, the same as non-json logging

Panicing in either case is somewhat unexpected and lead to unexpected
crashes, that can escalate  a minor bad untested logging into an process
crashes.

Fixes https://github.com/hashicorp/go-hclog/issues/38


Patch:
diff --git a/intlogger.go b/intlogger.go
index d32630c..6d2a87a 100644
--- a/intlogger.go
+++ b/intlogger.go
@@ -21,6 +21,9 @@ import (
 // contains millisecond precision
 const TimeFormat = "2006-01-02T15:04:05.000Z0700"
 
+// errJsonUnsupportedTypeMsg is included in log json entries, if an arg cannot be serialized to json
+const errJsonUnsupportedTypeMsg = "logging contained values that don't serialize to json"
+
 var (
 	_levelToBracket = map[Level]string{
 		Debug: "[DEBUG]",
@@ -296,39 +299,7 @@ func (l *intLogger) renderSlice(v reflect.Value) string {
 
 // JSON logging function
 func (l *intLogger) logJSON(t time.Time, level Level, msg string, args ...interface{}) {
-	vals := map[string]interface{}{
-		"@message":   msg,
-		"@timestamp": t.Format("2006-01-02T15:04:05.000000Z07:00"),
-	}
-
-	var levelStr string
-	switch level {
-	case Error:
-		levelStr = "error"
-	case Warn:
-		levelStr = "warn"
-	case Info:
-		levelStr = "info"
-	case Debug:
-		levelStr = "debug"
-	case Trace:
-		levelStr = "trace"
-	default:
-		levelStr = "all"
-	}
-
-	vals["@level"] = levelStr
-
-	if l.name != "" {
-		vals["@module"] = l.name
-	}
-
-	if l.caller {
-		if _, file, line, ok := runtime.Caller(3); ok {
-			vals["@caller"] = fmt.Sprintf("%s:%d", file, line)
-		}
-	}
-
+	vals := l.jsonMapEntry(t, level, msg)
 	args = append(l.implied, args...)
 
 	if args != nil && len(args) > 0 {
@@ -369,8 +340,49 @@ func (l *intLogger) logJSON(t time.Time, level Level, msg string, args ...interf
 
 	err := json.NewEncoder(l.writer).Encode(vals)
 	if err != nil {
-		panic(err)
+		if _, ok := err.(*json.UnsupportedTypeError); ok {
+			plainVal := l.jsonMapEntry(t, level, msg)
+			plainVal["@warn"] = errJsonUnsupportedTypeMsg
+
+			json.NewEncoder(l.writer).Encode(plainVal)
+		}
+	}
+}
+
+func (l intLogger) jsonMapEntry(t time.Time, level Level, msg string) map[string]interface{} {
+	vals := map[string]interface{}{
+		"@message":   msg,
+		"@timestamp": t.Format("2006-01-02T15:04:05.000000Z07:00"),
+	}
+
+	var levelStr string
+	switch level {
+	case Error:
+		levelStr = "error"
+	case Warn:
+		levelStr = "warn"
+	case Info:
+		levelStr = "info"
+	case Debug:
+		levelStr = "debug"
+	case Trace:
+		levelStr = "trace"
+	default:
+		levelStr = "all"
+	}
+
+	vals["@level"] = levelStr
+
+	if l.name != "" {
+		vals["@module"] = l.name
+	}
+
+	if l.caller {
+		if _, file, line, ok := runtime.Caller(4); ok {
+			vals["@caller"] = fmt.Sprintf("%s:%d", file, line)
+		}
 	}
+	return vals
 }
 
 // Emit the message and args at DEBUG level


Test patch:
diff --git a/logger_test.go b/logger_test.go
index 69dffed..c7064e9 100644
--- a/logger_test.go
+++ b/logger_test.go
@@ -6,6 +6,7 @@ import (
 	"errors"
 	"fmt"
 	"io"
+	"runtime"
 	"strconv"
 	"strings"
 	"testing"
@@ -149,7 +150,7 @@ func TestLogger(t *testing.T) {
 		rest := str[dataIdx+1:]
 
 		// This test will break if you move this around, it's line dependent, just fyi
-		assert.Equal(t, "[INFO]  go-hclog/logger_test.go:145: test: this is test: who=programmer why=\"testing is fun\"\n", rest)
+		assert.Equal(t, "[INFO]  go-hclog/logger_test.go:146: test: this is test: who=programmer why=\"testing is fun\"\n", rest)
 	})
 
 	t.Run("prefixes the name", func(t *testing.T) {
@@ -554,6 +555,55 @@ func TestLogger_JSON(t *testing.T) {
 		assert.Equal(t, "this is test", raw["@message"])
 		assert.Equal(t, "12 beans/day", raw["production"])
 	})
+
+	t.Run("includes the caller location", func(t *testing.T) {
+		var buf bytes.Buffer
+
+		logger := New(&LoggerOptions{
+			Name:            "test",
+			Output:          &buf,
+			JSONFormat:      true,
+			IncludeLocation: true,
+		})
+
+		logger.Info("this is test")
+		_, file, line, ok := runtime.Caller(0)
+		require.True(t, ok)
+
+		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, fmt.Sprintf("%v:%d", file, line-1), raw["@caller"])
+
+	})
+
+	t.Run("handles non-serializable entries", func(t *testing.T) {
+		var buf bytes.Buffer
+
+		logger := New(&LoggerOptions{
+			Name:       "test",
+			Output:     &buf,
+			JSONFormat: true,
+		})
+
+		myfunc := func() int { return 42 }
+		logger.Info("this is test", "production", myfunc)
+
+		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, errJsonUnsupportedTypeMsg, raw["@warn"])
+	})
 }
 
 type customErrJSON struct {