Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

zaptest: Add testing.TB compatible logger #518

Merged
merged 17 commits into from
Apr 12, 2018
Merged
Show file tree
Hide file tree
Changes from 9 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
93 changes: 93 additions & 0 deletions zaptest/logger.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,93 @@
// Copyright (c) 2017 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 zaptest

import (
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
)

// LoggerOption configures the test logger built by NewLogger.
type LoggerOption interface {
applyLoggerOption(*loggerOptions)
}

type loggerOptions struct {
Level zapcore.LevelEnabler
}

type loggerOptionFunc func(*loggerOptions)

func (f loggerOptionFunc) applyLoggerOption(opts *loggerOptions) {
f(opts)
}

// Level controls which messages are logged by a test Logger built by
// NewLogger.
func Level(enab zapcore.LevelEnabler) LoggerOption {
return loggerOptionFunc(func(opts *loggerOptions) {
opts.Level = enab
})
}

// NewLogger builds a new Logger that logs all messages to the given
// testing.TB.
//
// logger := zaptest.NewLogger(t, zaptest.Level(zap.WarnLevel))
//
// Use this with a *testing.T or *testing.B to get logs which get printed only
// if a test fails or if you ran go test -v.
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it's worth mentioning that the default log level is DebugLevel.

func NewLogger(t TestingT, opts ...LoggerOption) *zap.Logger {
cfg := loggerOptions{
Level: zapcore.DebugLevel,
}
for _, o := range opts {
o.applyLoggerOption(&cfg)
}

return zap.New(
zapcore.NewCore(
zapcore.NewConsoleEncoder(zap.NewDevelopmentEncoderConfig()),
testingWriter{t},
cfg.Level,
),
)
Copy link
Contributor

@ash2k ash2k Mar 19, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

zap.New() sets the error output to stderr which should be overridden here. Otherwise there is no way to override it because testingWriter is not exported. And also I think it makes sense to do it.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Makes sense, although if you end up writing to ErrorOutput, we should probably fail the test as well since that implies a serious Zap-internal error has occurred. I'll create a separate follow-up diff for that.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Excellent point. It should fail the test.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done in #566

}

// testingWriter is a WriteSyncer that writes to the given testing.TB.
type testingWriter struct{ t TestingT }

func (w testingWriter) Write(p []byte) (n int, err error) {
s := string(p)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Would be more efficient to do it after the ending newline character has been stripped. Extra string allocation for each Write() call is avoided that way.

Edit: There is no need to convert to string explicitly at all. Just pass []byte to the Logf() and it will do the conversion (lazily?). It may be even more efficient, maybe. See https://play.golang.org/p/vTko3i3X4qD

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good call. Thanks!


// Strip trailing newline because t.Log always adds one.
if s[len(s)-1] == '\n' {
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

optionally: you can use bytes.TrimRight(s, "\n"):
https://golang.org/pkg/bytes/#TrimRight

s = s[:len(s)-1]
}

// Note: t.Log is safe for concurrent use.
w.t.Logf("%s", s)
return len(p), nil
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This introduces a bug now - it should be returning length of the original p, not the one with trimmed \n. Otherwise it is a partial write which should not happen unless there is an error.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oh, good catch!

}

func (w testingWriter) Sync() error {
return nil
}
99 changes: 99 additions & 0 deletions zaptest/logger_test.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,99 @@
// Copyright (c) 2017 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 zaptest

import (
"errors"
"fmt"
"strings"
"sync"
"testing"

"go.uber.org/zap"

"github.com/stretchr/testify/assert"
)

func TestTestLoggerIncludesDebug(t *testing.T) {
ts := newTestLogSpy(t)
log := NewLogger(ts)
log.Debug("calculating")
log.Info("finished calculating", zap.Int("answer", 42))

ts.AssertMessages(
"DEBUG calculating",
`INFO finished calculating {"answer": 42}`,
)
}

func TestTestLoggerAt(t *testing.T) {
ts := newTestLogSpy(t)
log := NewLogger(ts, Level(zap.WarnLevel))

log.Info("received work order")
log.Debug("starting work")
log.Warn("work may fail")
log.Error("work failed", zap.Error(errors.New("great sadness")))

assert.Panics(t, func() {
log.Panic("failed to do work")
}, "log.Panic should panic")

ts.AssertMessages(
"WARN work may fail",
`ERROR work failed {"error": "great sadness"}`,
"PANIC failed to do work",
)
}

// testLogSpy is a testing.TB that captures logged messages.
type testLogSpy struct {
testing.TB

mu sync.Mutex
Messages []string
}

func newTestLogSpy(t testing.TB) *testLogSpy {
return &testLogSpy{TB: t}
}

func (t *testLogSpy) Logf(format string, args ...interface{}) {
// Log messages are in the format,
//
// 2017-10-27T13:03:01.000-0700 DEBUG your message here {data here}
//
// We strip the first part of these messages because we can't really test
// for the timestamp from these tests.
m := fmt.Sprintf(format, args...)
m = m[strings.IndexByte(m, '\t')+1:]

// t.Log should be thread-safe.
t.mu.Lock()
t.Messages = append(t.Messages, m)
t.mu.Unlock()

t.TB.Log(args...)
}

func (t *testLogSpy) AssertMessages(msgs ...string) {
assert.Equal(t, msgs, t.Messages)
}
38 changes: 38 additions & 0 deletions zaptest/testingt.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,38 @@
// Copyright (c) 2017 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 zaptest

// TestingT is a subset of the API provided by all *testing.T and *testing.B
// objects.
type TestingT interface {
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

we'll be locked into this interface when we release it, so we might want to include methods that could be useful in future.

e.g., if we have an option to keep logs quiet unless the test fails, and we add a Close method that the user calls using defer, we'll want to check if the test has failed, so we might want to add the Failed() bool method now.

not sure if we need anything else (Name() string seems nice but don't have a concrete use case for it).

We could just take a testing.TB instead as well?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Happy to take a testing.TB in the public API.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This interface is a subset of testing.TB. We can't add custom methods
to it.

I'm happy to switch this to a different subset. FWIW, just Errorf and
FailNow have been enough in the past for testify. I added Logf
because we need it for this feature.

Depending directly on testing.TB here means that importing zaptest
always imports testing, which will always register extra flags on
your executable. I would like to avoid that if possible, but I don't
feel too strongly about it.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I would also like to avoid importing the testing package due to the side effects.
If you are concerned about restricting zaptest to the smaller interface we could instead copy the entire testing.TB here rather than using a narrow subset. This should work nicely since the authors of the testing package are already "locked in" to this interface themselves and cannot change it easily as well.

The only minor downside I see is that such a wide interface with unused functions isn't exactly idiomatic.

// Logs the given message without failing the test.
Logf(string, ...interface{})

// Logs the given message and marks the test as failed.
Errorf(string, ...interface{})

// Marks the test as failed and stops execution of that test.
FailNow()
}

// Note: We currently only rely on Logf. We are including Errorf and FailNow
// in the interface in anticipation of future need since we can't extend the
// interface without a breaking change.
29 changes: 29 additions & 0 deletions zaptest/testingt_test.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,29 @@
// Copyright (c) 2017 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 zaptest

import "testing"

// Just a compile-time test to ensure that TestingT matches the testing.TB
// interface. We could do this in testingt.go but that would put a dependency
// on the "testing" package from zaptest.

var _ TestingT = (testing.TB)(nil)