Add finer grained caller annotation support (#227)

* Add AddCallerSkip option
* Improve and expand caller skip test
* Fix logger Check v Level-log skipping
* logger: drop old Log method; not actually part of the interface since #201

common_test.go

@@ -0,0 +1,84 @@
+// Copyright (c) 2016 Uber Technologies, Inc.
+//
+// Permission is hereby granted, free of charge, to any person obtaining a copy
+// of this software and associated documentation files (the "Software"), to deal
+// in the Software without restriction, including without limitation the rights
+// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+// copies of the Software, and to permit persons to whom the Software is
+// furnished to do so, subject to the following conditions:
+//
+// The above copyright notice and this permission notice shall be included in
+// all copies or substantial portions of the Software.
+//
+// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
+// THE SOFTWARE.
+
+package zap
+
+import (
+	"os"
+	"sync"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+)
+
+func opts(opts ...Option) []Option {
+	return opts
+}
+
+type stubbedExit struct {
+	Status *int
+}
+
+func (se *stubbedExit) Unstub() {
+	_exit = os.Exit
+}
+
+func (se *stubbedExit) AssertNoExit(t testing.TB) {
+	assert.Nil(t, se.Status, "Unexpected exit.")
+}
+
+func (se *stubbedExit) AssertStatus(t testing.TB, expected int) {
+	if assert.NotNil(t, se.Status, "Expected to exit.") {
+		assert.Equal(t, expected, *se.Status, "Unexpected exit code.")
+	}
+}
+
+func stubExit() *stubbedExit {
+	stub := &stubbedExit{}
+	_exit = func(s int) { stub.Status = &s }
+	return stub
+}
+
+func withJSONLogger(t testing.TB, enab LevelEnabler, opts []Option, f func(Logger, *testBuffer)) {
+	sink := &testBuffer{}
+	errSink := &testBuffer{}
+
+	allOpts := make([]Option, 0, 2+len(opts))
+	allOpts = append(allOpts, ErrorOutput(errSink))
+	allOpts = append(allOpts, opts...)
+	logger := New(
+		WriterFacility(newJSONEncoder(NoTime()), sink, enab),
+		allOpts...)
+
+	f(logger, sink)
+	assert.Empty(t, errSink.String(), "Expected error sink to be empty.")
+}
+
+func runConcurrently(goroutines, iterations int, wg *sync.WaitGroup, f func()) {
+	wg.Add(goroutines)
+	for g := 0; g < goroutines; g++ {
+		go func() {
+			defer wg.Done()
+			for i := 0; i < iterations; i++ {
+				f()
+			}
+		}()
+	}
+}

logger.go

@@ -27,10 +27,7 @@ import (
 	"time"
 )
 
-var (
-	_exit              = os.Exit // for tests
-	_defaultCallerSkip = 3       // for logger.callerSkip
-)
+var _exit = os.Exit // for tests
 
 // A Logger enables leveled, structured logging. All methods are safe for
 // concurrent use.
@@ -49,9 +46,7 @@ type Logger interface {
 	// accumulated on the logger, as well as any fields added at the log site.
 	//
 	// Calling Panic should panic() and calling Fatal should terminate the
-	// process, but calling Log(PanicLevel, ...) or Log(FatalLevel, ...) should
-	// not. It may not be possible for compatibility wrappers to comply with
-	// this last part (e.g. the bark wrapper).
+	// process.
 	Debug(string, ...Field)
 	Info(string, ...Field)
 	Warn(string, ...Field)
@@ -88,7 +83,6 @@ func New(fac Facility, options ...Option) Logger {
 		fac:         fac,
 		errorOutput: newLockedWriteSyncer(os.Stderr),
 		addStack:    maxLevel, // TODO: better an `always false` level enabler
-		callerSkip:  _defaultCallerSkip,
 	}
 	for _, opt := range options {
 		opt.apply(log)
@@ -111,6 +105,14 @@ func (log *logger) With(fields ...Field) Logger {
 }
 
 func (log *logger) Check(lvl Level, msg string) *CheckedEntry {
+	return log.check(lvl, msg)
+}
+
+func (log *logger) check(lvl Level, msg string) *CheckedEntry {
+	// check must always be called directly by another `logger` entry function
+	// (e.g. Check, Log, Info, etc)
+	const callerSkipOffset = 2
+
 	// Create basic checked entry thru the facility; this will be non-nil if
 	// the log message will actually be written somewhere.
 	ent := Entry{
@@ -144,7 +146,7 @@ func (log *logger) Check(lvl Level, msg string) *CheckedEntry {
 	ce.ErrorOutput = log.errorOutput
 
 	if log.addCaller {
-		ce.Entry.Caller = MakeEntryCaller(runtime.Caller(log.callerSkip))
+		ce.Entry.Caller = MakeEntryCaller(runtime.Caller(log.callerSkip + callerSkipOffset))
 		if !ce.Entry.Caller.Defined {
 			fmt.Fprintf(log.errorOutput, "%v addCaller error: failed to get caller\n", time.Now().UTC())
 			log.errorOutput.Sync()
@@ -159,16 +161,44 @@ func (log *logger) Check(lvl Level, msg string) *CheckedEntry {
 	return ce
 }
 
-func (log *logger) Debug(msg string, fields ...Field)  { log.Log(DebugLevel, msg, fields...) }
-func (log *logger) Info(msg string, fields ...Field)   { log.Log(InfoLevel, msg, fields...) }
-func (log *logger) Warn(msg string, fields ...Field)   { log.Log(WarnLevel, msg, fields...) }
-func (log *logger) Error(msg string, fields ...Field)  { log.Log(ErrorLevel, msg, fields...) }
-func (log *logger) DPanic(msg string, fields ...Field) { log.Log(DPanicLevel, msg, fields...) }
-func (log *logger) Panic(msg string, fields ...Field)  { log.Log(PanicLevel, msg, fields...) }
-func (log *logger) Fatal(msg string, fields ...Field)  { log.Log(FatalLevel, msg, fields...) }
+func (log *logger) Debug(msg string, fields ...Field) {
+	if ce := log.check(DebugLevel, msg); ce != nil {
+		ce.Write(fields...)
+	}
+}
+
+func (log *logger) Info(msg string, fields ...Field) {
+	if ce := log.check(InfoLevel, msg); ce != nil {
+		ce.Write(fields...)
+	}
+}
+
+func (log *logger) Warn(msg string, fields ...Field) {
+	if ce := log.check(WarnLevel, msg); ce != nil {
+		ce.Write(fields...)
+	}
+}
+
+func (log *logger) Error(msg string, fields ...Field) {
+	if ce := log.check(ErrorLevel, msg); ce != nil {
+		ce.Write(fields...)
+	}
+}
+
+func (log *logger) DPanic(msg string, fields ...Field) {
+	if ce := log.check(DPanicLevel, msg); ce != nil {
+		ce.Write(fields...)
+	}
+}
+
+func (log *logger) Panic(msg string, fields ...Field) {
+	if ce := log.check(PanicLevel, msg); ce != nil {
+		ce.Write(fields...)
+	}
+}
 
-func (log *logger) Log(lvl Level, msg string, fields ...Field) {
-	if ce := log.Check(lvl, msg); ce != nil {
+func (log *logger) Fatal(msg string, fields ...Field) {
+	if ce := log.check(FatalLevel, msg); ce != nil {
 		ce.Write(fields...)
 	}
 }

logger_test.go

@@ -23,7 +23,6 @@ package zap
 import (
 	"fmt"
 	"io/ioutil"
-	"os"
 	"strings"
 	"sync"
 	"testing"
@@ -34,49 +33,6 @@ import (
 	"github.com/stretchr/testify/require"
 )
 
-func opts(opts ...Option) []Option {
-	return opts
-}
-
-type stubbedExit struct {
-	Status *int
-}
-
-func (se *stubbedExit) Unstub() {
-	_exit = os.Exit
-}
-
-func (se *stubbedExit) AssertNoExit(t testing.TB) {
-	assert.Nil(t, se.Status, "Unexpected exit.")
-}
-
-func (se *stubbedExit) AssertStatus(t testing.TB, expected int) {
-	if assert.NotNil(t, se.Status, "Expected to exit.") {
-		assert.Equal(t, expected, *se.Status, "Unexpected exit code.")
-	}
-}
-
-func stubExit() *stubbedExit {
-	stub := &stubbedExit{}
-	_exit = func(s int) { stub.Status = &s }
-	return stub
-}
-
-func withJSONLogger(t testing.TB, enab LevelEnabler, opts []Option, f func(Logger, *testBuffer)) {
-	sink := &testBuffer{}
-	errSink := &testBuffer{}
-
-	allOpts := make([]Option, 0, 2+len(opts))
-	allOpts = append(allOpts, ErrorOutput(errSink))
-	allOpts = append(allOpts, opts...)
-	logger := New(
-		WriterFacility(newJSONEncoder(NoTime()), sink, enab),
-		allOpts...)
-
-	f(logger, sink)
-	assert.Empty(t, errSink.String(), "Expected error sink to be empty.")
-}
-
 func TestDynamicLevel(t *testing.T) {
 	lvl := DynamicLevel()
 	assert.Equal(t, InfoLevel, lvl.Level(), "Unexpected initial level.")
@@ -371,12 +327,61 @@ func TestJSONLoggerSyncsOutput(t *testing.T) {
 }
 
 func TestLoggerAddCaller(t *testing.T) {
-	withJSONLogger(t, DebugLevel, opts(AddCaller()), func(logger Logger, buf *testBuffer) {
-		logger.Info("Callers.")
-		assert.Regexp(t,
-			`"caller":"[^"]+/logger_test.go:[\d]+","msg":"Callers\."`,
-			buf.Stripped(), "Expected to find package name and file name in output.")
-	})
+	for i, testCase := range []struct {
+		makeLogger    func(sink, errSink *testBuffer) Logger
+		expectedLines []struct{ pat, name string }
+	}{
+		{
+			makeLogger: func(sink, errSink *testBuffer) Logger {
+				return New(
+					WriterFacility(newJSONEncoder(NoTime()), sink, DebugLevel),
+					ErrorOutput(errSink), AddCaller(),
+				)
+			},
+			expectedLines: []struct{ pat, name string }{
+				{`"caller":"[^"]+/logger_test.go:\d+","msg":"mess","i":0`, "log1.Info"},
+				{`"caller":"[^"]+/logger_test.go:\d+","msg":"mess","i":1`, "log1.Check(Info)"},
+			},
+		},
+		{
+			makeLogger: func(sink, errSink *testBuffer) Logger {
+				return New(
+					WriterFacility(newJSONEncoder(NoTime()), sink, DebugLevel),
+					ErrorOutput(errSink), AddCaller(), AddCallerSkip(1),
+				)
+			},
+			expectedLines: []struct{ pat, name string }{
+				{`"caller":"[^"]+/testing.go:\d+","msg":"mess","i":2`, "log2.Info"},
+				{`"caller":"[^"]+/testing.go:\d+","msg":"mess","i":3`, "log2.Check(Info)"},
+			},
+		},
+		{
+			makeLogger: func(sink, errSink *testBuffer) Logger {
+				return New(
+					WriterFacility(newJSONEncoder(NoTime()), sink, DebugLevel),
+					ErrorOutput(errSink), AddCaller(), AddCallerSkip(1), AddCallerSkip(1),
+				)
+			},
+			expectedLines: []struct{ pat, name string }{
+				{`"caller":"[^"]+/src/runtime/.*:\d+","msg":"mess","i":4`, "log3.Info"},
+				{`"caller":"[^"]+/src/runtime/.*:\d+","msg":"mess","i":5`, "log3.Check(Info)"},
+			},
+		},
+		// TODO: wrap(logger) family to be tested by upcoming sugared logger
+	} {
+		sink := &testBuffer{}
+		errSink := &testBuffer{}
+		logger := testCase.makeLogger(sink, errSink)
+		logger.Info("mess", Int("i", 2*i))
+		logger.Check(InfoLevel, "mess").Write(Int("i", 2*i+1))
+		lines := sink.Lines()
+		for i, expectedLine := range testCase.expectedLines {
+			assert.Regexp(t,
+				expectedLine.pat, lines[i],
+				"Expected to find package name and file name in %s output.", expectedLine.name)
+		}
+		assert.Empty(t, errSink.String(), "Expected error sink to be empty.")
+	}
 }
 
 func TestLoggerAddCallerFail(t *testing.T) {
@@ -434,15 +439,3 @@ func TestLoggerConcurrent(t *testing.T) {
 		assert.Equal(t, strings.Repeat(expected, 100), buf.String())
 	})
 }
-
-func runConcurrently(goroutines, iterations int, wg *sync.WaitGroup, f func()) {
-	wg.Add(goroutines)
-	for g := 0; g < goroutines; g++ {
-		go func() {
-			defer wg.Done()
-			for i := 0; i < iterations; i++ {
-				f()
-			}
-		}()
-	}
-}

options.go

@@ -64,6 +64,14 @@ func AddCaller() Option {
 	})
 }
 
+// AddCallerSkip increases the number of callers skipped by caller annotation
+// (as enabled by the AddCaller option).
+func AddCallerSkip(skip int) Option {
+	return optionFunc(func(log *logger) {
+		log.callerSkip += skip
+	})
+}
+
 // AddStacks configures the Logger to record a stack trace for all messages at
 // or above a given level. Keep in mind that this is (relatively speaking)
 // quite expensive.