diff --git a/common_test.go b/common_test.go new file mode 100644 index 000000000..2b80cec4a --- /dev/null +++ b/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() + } + }() + } +} diff --git a/logger.go b/logger.go index 6c968252e..288e99a06 100644 --- a/logger.go +++ b/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...) } } diff --git a/logger_test.go b/logger_test.go index c136399c1..e4a6fbad5 100644 --- a/logger_test.go +++ b/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() - } - }() - } -} diff --git a/options.go b/options.go index f16165558..3881e9eda 100644 --- a/options.go +++ b/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.