Repository: hashicorp/go-hclog
Pull request #77 (2020-10-19 18:41:12)

Reduce intercept logger and fix a bug with json format and caller location
Builds on #76

This PR reduces the implementation of all the Logger methods in `interceptLogger` to call a single helper method.

It also makes two improvements to the `IncludeLocation` option:

1. remove the need to call `runtime.Caller` twice. This call is relatively expensive, and we were calling it twice for every log line. Instead of guessing at the offset we pass the offset along. The logger itself knows what offset to use.
2. fix a bug when `IncludeLocation` was used with `JSONFormat` and `InterceptLogger`. We were also using a fixed offset of 4, but that would be wrong when called from an InterceptLogger or an `intLogger` used as a sink.


Patch:
diff --git a/interceptlogger.go b/interceptlogger.go
index d8e2e76..631baf2 100644
--- a/interceptlogger.go
+++ b/interceptlogger.go
@@ -18,8 +18,13 @@ type interceptLogger struct {
 }
 
 func NewInterceptLogger(opts *LoggerOptions) InterceptLogger {
+	l := newLogger(opts)
+	if l.callerOffset > 0 {
+		// extra frames for interceptLogger.{Warn,Info,Log,etc...}, and interceptLogger.log
+		l.callerOffset += 2
+	}
 	intercept := &interceptLogger{
-		Logger:    New(opts),
+		Logger:    l,
 		mu:        new(sync.Mutex),
 		sinkCount: new(int32),
 		Sinks:     make(map[SinkAdapter]struct{}),
@@ -31,6 +36,14 @@ func NewInterceptLogger(opts *LoggerOptions) InterceptLogger {
 }
 
 func (i *interceptLogger) Log(level Level, msg string, args ...interface{}) {
+	i.log(level, msg, args...)
+}
+
+// log is used to make the caller stack frame lookup consistent. If Warn,Info,etc
+// all called Log then direct calls to Log would have a different stack frame
+// depth. By having all the methods call the same helper we ensure the stack
+// frame depth is the same.
+func (i *interceptLogger) log(level Level, msg string, args ...interface{}) {
 	i.Logger.Log(level, msg, args...)
 	if atomic.LoadInt32(i.sinkCount) == 0 {
 		return
@@ -45,72 +58,27 @@ func (i *interceptLogger) Log(level Level, msg string, args ...interface{}) {
 
 // Emit the message and args at TRACE level to log and sinks
 func (i *interceptLogger) Trace(msg string, args ...interface{}) {
-	i.Logger.Trace(msg, args...)
-	if atomic.LoadInt32(i.sinkCount) == 0 {
-		return
-	}
-
-	i.mu.Lock()
-	defer i.mu.Unlock()
-	for s := range i.Sinks {
-		s.Accept(i.Name(), Trace, msg, i.retrieveImplied(args...)...)
-	}
+	i.log(Trace, msg, args...)
 }
 
 // Emit the message and args at DEBUG level to log and sinks
 func (i *interceptLogger) Debug(msg string, args ...interface{}) {
-	i.Logger.Debug(msg, args...)
-	if atomic.LoadInt32(i.sinkCount) == 0 {
-		return
-	}
-
-	i.mu.Lock()
-	defer i.mu.Unlock()
-	for s := range i.Sinks {
-		s.Accept(i.Name(), Debug, msg, i.retrieveImplied(args...)...)
-	}
+	i.log(Debug, msg, args...)
 }
 
 // Emit the message and args at INFO level to log and sinks
 func (i *interceptLogger) Info(msg string, args ...interface{}) {
-	i.Logger.Info(msg, args...)
-	if atomic.LoadInt32(i.sinkCount) == 0 {
-		return
-	}
-
-	i.mu.Lock()
-	defer i.mu.Unlock()
-	for s := range i.Sinks {
-		s.Accept(i.Name(), Info, msg, i.retrieveImplied(args...)...)
-	}
+	i.log(Info, msg, args...)
 }
 
 // Emit the message and args at WARN level to log and sinks
 func (i *interceptLogger) Warn(msg string, args ...interface{}) {
-	i.Logger.Warn(msg, args...)
-	if atomic.LoadInt32(i.sinkCount) == 0 {
-		return
-	}
-
-	i.mu.Lock()
-	defer i.mu.Unlock()
-	for s := range i.Sinks {
-		s.Accept(i.Name(), Warn, msg, i.retrieveImplied(args...)...)
-	}
+	i.log(Warn, msg, args...)
 }
 
 // Emit the message and args at ERROR level to log and sinks
 func (i *interceptLogger) Error(msg string, args ...interface{}) {
-	i.Logger.Error(msg, args...)
-	if atomic.LoadInt32(i.sinkCount) == 0 {
-		return
-	}
-
-	i.mu.Lock()
-	defer i.mu.Unlock()
-	for s := range i.Sinks {
-		s.Accept(i.Name(), Error, msg, i.retrieveImplied(args...)...)
-	}
+	i.log(Error, msg, args...)
 }
 
 func (i *interceptLogger) retrieveImplied(args ...interface{}) []interface{} {
@@ -123,7 +91,7 @@ func (i *interceptLogger) retrieveImplied(args ...interface{}) []interface{} {
 	return cp
 }
 
-// Create a new sub-Logger that a name decending from the current name.
+// Create a new sub-Logger that a name descending from the current name.
 // This is used to create a subsystem specific Logger.
 // Registered sinks will subscribe to these messages as well.
 func (i *interceptLogger) Named(name string) Logger {
diff --git a/intlogger.go b/intlogger.go
index f961ed9..3e575db 100644
--- a/intlogger.go
+++ b/intlogger.go
@@ -52,10 +52,10 @@ var _ Logger = &intLogger{}
 // intLogger is an internal logger implementation. Internal in that it is
 // defined entirely by this package.
 type intLogger struct {
-	json       bool
-	caller     bool
-	name       string
-	timeFormat string
+	json         bool
+	callerOffset int
+	name         string
+	timeFormat   string
 
 	// This is an interface so that it's shared by any derived loggers, since
 	// those derived loggers share the bufio.Writer as well.
@@ -79,7 +79,12 @@ func New(opts *LoggerOptions) Logger {
 // NewSinkAdapter returns a SinkAdapter with configured settings
 // defined by LoggerOptions
 func NewSinkAdapter(opts *LoggerOptions) SinkAdapter {
-	return newLogger(opts)
+	l := newLogger(opts)
+	if l.callerOffset > 0 {
+		// extra frames for interceptLogger.{Warn,Info,Log,etc...}, and SinkAdapter.Accept
+		l.callerOffset += 2
+	}
+	return l
 }
 
 func newLogger(opts *LoggerOptions) *intLogger {
@@ -104,7 +109,6 @@ func newLogger(opts *LoggerOptions) *intLogger {
 
 	l := &intLogger{
 		json:              opts.JSONFormat,
-		caller:            opts.IncludeLocation,
 		name:              opts.Name,
 		timeFormat:        TimeFormat,
 		mutex:             mutex,
@@ -113,6 +117,9 @@ func newLogger(opts *LoggerOptions) *intLogger {
 		exclude:           opts.Exclude,
 		independentLevels: opts.IndependentLevels,
 	}
+	if opts.IncludeLocation {
+		l.callerOffset = offsetIntLogger
+	}
 
 	l.setColorization(opts)
 
@@ -127,6 +134,10 @@ func newLogger(opts *LoggerOptions) *intLogger {
 	return l
 }
 
+// offsetIntLogger is the stack frame offset in the call stack for the caller to
+// one of the Warn,Info,Log,etc methods.
+const offsetIntLogger = 3
+
 // 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 (l *intLogger) log(name string, level Level, msg string, args ...interface{}) {
@@ -195,17 +206,8 @@ func (l *intLogger) logPlain(t time.Time, name string, level Level, msg string,
 		l.writer.WriteString("[?????]")
 	}
 
-	offset := 3
-	if l.caller {
-		// Check if the caller is inside our package and inside
-		// a logger implementation file
-		if _, file, _, ok := runtime.Caller(3); ok {
-			if strings.HasSuffix(file, "intlogger.go") || strings.HasSuffix(file, "interceptlogger.go") {
-				offset = 4
-			}
-		}
-
-		if _, file, line, ok := runtime.Caller(offset); ok {
+	if l.callerOffset > 0 {
+		if _, file, line, ok := runtime.Caller(l.callerOffset); ok {
 			l.writer.WriteByte(' ')
 			l.writer.WriteString(trimCallerPath(file))
 			l.writer.WriteByte(':')
@@ -442,8 +444,8 @@ func (l intLogger) jsonMapEntry(t time.Time, name string, level Level, msg strin
 		vals["@module"] = name
 	}
 
-	if l.caller {
-		if _, file, line, ok := runtime.Caller(4); ok {
+	if l.callerOffset > 0 {
+		if _, file, line, ok := runtime.Caller(l.callerOffset + 1); ok {
 			vals["@caller"] = fmt.Sprintf("%s:%d", file, line)
 		}
 	}


Test patch:
diff --git a/interceptlogger_test.go b/interceptlogger_test.go
index be8a2ed..7b5a86d 100644
--- a/interceptlogger_test.go
+++ b/interceptlogger_test.go
@@ -3,10 +3,13 @@ package hclog
 import (
 	"bytes"
 	"encoding/json"
+	"fmt"
+	"runtime"
 	"strings"
 	"testing"
 
 	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
 )
 
 func TestInterceptLogger(t *testing.T) {
@@ -167,25 +170,31 @@ func TestInterceptLogger(t *testing.T) {
 		var sbuf bytes.Buffer
 
 		intercept := NewInterceptLogger(&LoggerOptions{
-			Level:  Info,
-			Output: &buf,
+			Level:           Info,
+			Output:          &buf,
+			IncludeLocation: true,
 		})
 
 		sink := NewSinkAdapter(&LoggerOptions{
-			Level:      Debug,
-			Output:     &sbuf,
-			JSONFormat: true,
+			Level:           Debug,
+			Output:          &sbuf,
+			JSONFormat:      true,
+			IncludeLocation: true,
 		})
 
 		intercept.RegisterSink(sink)
 		defer intercept.DeregisterSink(sink)
 
 		intercept.Info("this is a test", "who", "caller")
+		_, file, line, ok := runtime.Caller(0)
+		require.True(t, ok)
+
 		output := buf.String()
 		dataIdx := strings.IndexByte(output, ' ')
 		rest := output[dataIdx+1:]
 
-		assert.Equal(t, "[INFO]  this is a test: who=caller\n", rest)
+		expected := fmt.Sprintf("[INFO]  go-hclog/interceptlogger_test.go:%d: this is a test: who=caller\n", line-1)
+		assert.Equal(t, expected, rest)
 
 		b := sbuf.Bytes()
 
@@ -196,6 +205,7 @@ func TestInterceptLogger(t *testing.T) {
 
 		assert.Equal(t, "this is a test", raw["@message"])
 		assert.Equal(t, "caller", raw["who"])
+		assert.Equal(t, fmt.Sprintf("%v:%d", file, line-1), raw["@caller"])
 	})
 
 	t.Run("handles parent with arguments and log level args", func(t *testing.T) {
@@ -278,18 +288,20 @@ func TestInterceptLogger(t *testing.T) {
 		defer logger.DeregisterSink(sink)
 
 		logger.Info("this is test", "who", "programmer", "why", "testing is fun")
+		_, _, line, ok := runtime.Caller(0)
+		require.True(t, ok)
 
 		str := buf.String()
 		dataIdx := strings.IndexByte(str, ' ')
 		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/interceptlogger_test.go:280: test: this is test: who=programmer why=\"testing is fun\"\n", rest)
+		expected := fmt.Sprintf("[INFO]  go-hclog/interceptlogger_test.go:%d: test: this is test: who=programmer why=\"testing is fun\"\n", line-1)
+		assert.Equal(t, expected, rest)
 
 		str = sbuf.String()
 		dataIdx = strings.IndexByte(str, ' ')
 		rest = str[dataIdx+1:]
-		assert.Equal(t, "[INFO]  go-hclog/interceptlogger_test.go:280: test: this is test: who=programmer why=\"testing is fun\"\n", rest)
+		assert.Equal(t, expected, rest)
 	})
 
 	t.Run("supports resetting the output", func(t *testing.T) {
diff --git a/logger_test.go b/logger_test.go
index aac7233..e80041c 100644
--- a/logger_test.go
+++ b/logger_test.go
@@ -715,7 +715,6 @@ func TestLogger_JSON(t *testing.T) {
 
 		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) {
diff --git a/stdlog_test.go b/stdlog_test.go
index 7cf6bfa..446fa56 100644
--- a/stdlog_test.go
+++ b/stdlog_test.go
@@ -2,15 +2,18 @@ package hclog
 
 import (
 	"bytes"
+	"fmt"
 	"log"
-	"regexp"
+	"path/filepath"
+	"runtime"
 	"strings"
 	"testing"
 
 	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
 )
 
-func TestStdlogAdapter(t *testing.T) {
+func TestStdlogAdapter_PickLevel(t *testing.T) {
 	t.Run("picks debug level", func(t *testing.T) {
 		var s stdlogAdapter
 
@@ -155,18 +158,26 @@ func TestStdlogAdapter_ForceLevel(t *testing.T) {
 	}
 }
 
-func TestFromLogger(t *testing.T) {
+func TestFromStandardLogger(t *testing.T) {
 	var buf bytes.Buffer
 
 	sl := log.New(&buf, "test-stdlib-log ", log.Ltime)
 
 	hl := FromStandardLogger(sl, &LoggerOptions{
-		Name: "hclog-inner",
+		Name:            "hclog-inner",
+		IncludeLocation: true,
 	})
 
 	hl.Info("this is a test", "name", "tester", "count", 1)
+	_, file, line, ok := runtime.Caller(0)
+	require.True(t, ok)
 
-	re := regexp.MustCompile(`test-stdlib-log [\d:]+ \[INFO\]  hclog-inner: this is a test: name=tester count=1`)
+	actual := buf.String()
+	suffix := fmt.Sprintf(
+		"[INFO]  go-hclog/%s:%d: hclog-inner: this is a test: name=tester count=1\n",
+		filepath.Base(file), line-1)
+	require.Equal(t, suffix, actual[25:])
 
-	assert.True(t, re.Match(buf.Bytes()))
+	prefix := "test-stdlib-log "
+	require.Equal(t, prefix, actual[:16])
 }