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

Conversation

abhinav
Copy link
Collaborator

@abhinav abhinav commented Oct 26, 2017

This adds zaptest.NewLogger and zaptest.NewLoggerAt which log messages to
testing.TBs. This allows us to use non-nop loggers from tests without
spamming the test output. These loggers will write output only if the test
failed or go test -v was used.

@codecov
Copy link

codecov bot commented Oct 26, 2017

Codecov Report

Merging #518 into master will increase coverage by 0.43%.
The diff coverage is 100%.

Impacted file tree graph

@@            Coverage Diff             @@
##           master     #518      +/-   ##
==========================================
+ Coverage   97.06%   97.49%   +0.43%     
==========================================
  Files          39       40       +1     
  Lines        2279     2035     -244     
==========================================
- Hits         2212     1984     -228     
+ Misses         59       43      -16     
  Partials        8        8
Impacted Files Coverage Δ
zaptest/logger.go 100% <100%> (ø)
zapcore/console_encoder.go 96.49% <0%> (-1.07%) ⬇️
zapcore/error.go 93.75% <0%> (-0.7%) ⬇️
stacktrace.go 97.87% <0%> (-0.44%) ⬇️
logger.go 94.49% <0%> (-0.36%) ⬇️
zapcore/memory_encoder.go 98.66% <0%> (-0.02%) ⬇️
zapgrpc/zapgrpc.go 100% <0%> (ø) ⬆️
zapcore/hook.go 100% <0%> (ø) ⬆️
zaptest/observer/observer.go 100% <0%> (ø) ⬆️
zapcore/tee.go 100% <0%> (ø) ⬆️
... and 21 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update f85c78b...d0af2be. Read the comment docs.

Copy link
Collaborator

@prashantv prashantv left a comment

Choose a reason for hiding this comment

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

Looks pretty good, just one suggestion for the API

// if a test fails or if you ran go test -v.
//
// logger := zap.New(tlogger.New(t))
func New(t testing.TB) zapcore.Core {
Copy link
Collaborator

Choose a reason for hiding this comment

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

could this just take ...zap.Option:
https://godoc.org/go.uber.org/zap#Option

that way, users could pass a level since it implements option, but they can also pass other options to add callers, stacktraces, etc.

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

Couple reasons it's like this:

  • zap.Option doesn't let you override the level.
  • zaptest/observer.New returns a zapcore.Core too.
  • Instead of New always accepting a level, I wanted a "just works" version which is why we have both New and NewAt.

Copy link
Collaborator

Choose a reason for hiding this comment

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

Fair enough. I wonder if a zap.Logger is more useful than a core most of the time (and you can still get the core using logger.Core
https://godoc.org/go.uber.org/zap#Logger.Core

I thought levels were options, but if not, NewAt definitely makes sense.

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

I don't feel strongly about Logger vs Core. @akshayjshah what do you think?

Copy link
Contributor

Choose a reason for hiding this comment

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

I don't feel super-strongly about it either; I suggested returning a Core here to match the observer.New API.

Copy link
Collaborator

Choose a reason for hiding this comment

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

I think we should deprecate the observer package, and as part of #520, introduce a set of options that can be used with either the verifying logger, or to filter a set of observed logs.

As part of this, we can introduce a more ergonomic API which is probably to return a Logger (every test here, and 99% of use cases where we use the observer want to use it as a *Logger). Since it's pretty easy to get a core out of a logger, it doesn't limit functionality.

Copy link
Collaborator

@prashantv prashantv left a comment

Choose a reason for hiding this comment

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

I think returning a *Logger might be more convenient, but otherwise lgtm.

// if a test fails or if you ran go test -v.
//
// logger := zap.New(tlogger.New(t))
func New(t testing.TB) zapcore.Core {
Copy link
Collaborator

Choose a reason for hiding this comment

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

Fair enough. I wonder if a zap.Logger is more useful than a core most of the time (and you can still get the core using logger.Core
https://godoc.org/go.uber.org/zap#Logger.Core

I thought levels were options, but if not, NewAt definitely makes sense.

@akshayjshah
Copy link
Contributor

Levels stopped being logger-level options when we introduced the ability to tee log output to multiple cores - that basically means that the logger no longer has a single level. They're now an attribute of an individual core.

Copy link
Contributor

@akshayjshah akshayjshah left a comment

Choose a reason for hiding this comment

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

Code looks good, apart from the question about backticks in comments.

Please hold off on merging this over the weekend - I'd like to consider whether we absolutely need a new package for this. If possible, I'd prefer to integrate this into zaptest.

// Package tlogger provides a zapcore.Core that is capable of writing log
// messages to a *testing.T and *testing.B. It may be used from Go tests or
// benchmarks to have log messages printed only if a test failed, or if the
// `-v` flag was passed to `go test`.
Copy link
Contributor

Choose a reason for hiding this comment

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

Do we typically do backticks in GoDoc? I haven't seen this in the standard lib - seems like a Markdown-ism.

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

Yeah, we don't. Removing.

@akshayjshah
Copy link
Contributor

akshayjshah commented Oct 31, 2017

Let's move this into zaptest now that #523 has landed. What do you think of zaptest.NewLogger and zaptest.NewLoggerAt?

If we're planning to deprecate the observer package, now's probably the right time to see if we can unify that functionality. We could use something like the observing core here, and also tee results to the testing.T.

This adds `zaptest.NewTestLogger(testing.TB) *zap.Logger` and a
level-override variant of it. This will enable us to use non-nop loggers
from tests without spamming the output.

These loggers will not print any output unless the test failed or
`go test -v` was used.
This reverts commit a73cb3f.
@abhinav
Copy link
Collaborator Author

abhinav commented Nov 1, 2017

@akshayjshah As discussed offline, we still want to create a subset of the
testing.TB interface for these methods.

Although we only need Log(...interface{}) for this feature, I want our
subset to include Logf, Errorf, and FailNow in anticipation of future
testing-related functionality since we can't change the interface afterwards.

Thoughts?

This declares a TestingT interface which is a subset of the
functionality provided by testing.TB, and changes zaptest to rely on
that.

This also means that zaptest no longer imports the "testing" package.
Copy link

@kriskowal kriskowal left a comment

Choose a reason for hiding this comment

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

Neat. Of course, @akshayjshah for final stamp. I’m thrilled about how this’ll improve testing for components that log. Would it make sense to export a spy so we can defer spy.AssertNoErrors() as a best-practice?

@abhinav
Copy link
Collaborator Author

abhinav commented Nov 1, 2017

@kriskowal you can do that today with the zaptest/observer APIs but there are plans to iterate on a nicer spy API in the zaptest package in the future.

@abhinav
Copy link
Collaborator Author

abhinav commented Nov 7, 2017

Friendly bump @akshayjshah

@fgrosse
Copy link

fgrosse commented Dec 13, 2017

Hey Uber people!

This pull request was brought to my attention by @akshayjshah via fgrosse/zaptest#1 and I would love to see this functionality becoming part of zap itself.

I do have some small suggestions that may be of interest in this discussion:

  1. in fgrosse/zaptest I decided to exclude the timestamp fields from the logged messages.
    The reason for this is that the log output of a testing.T would also not include this.
    I think in unit tests actual microsecond timestamps are normally not actually that interesting so
    this will most of the time just clutter the message when you want some clear output.

I implemented this by setting the EncodeTime of the zapcore.EncoderConfig to a noop implementation.
Moreover this default configuration is exported as a package level variable so people can actually change
the log encoder config if they really need to. However I realize this increases the package surface and
there is a trade-off - maybe even without an actually existing use case.

  1. One thing that was especially important for me was to be able to use my zaptest package in other
    (testing) frameworks as well. For instance fgrosse/zaptest supports Ginkgo out of the box just by
    exposing the following function:
// LoggerWriter creates a new zap.Logger that writes all messages to the given
// io.Writer.
func LoggerWriter(w io.Writer) *zap.Logger { … }

You can find an example of how this integrates with Ginkgo in my tests.

I hope this was useful :)

Copy link
Contributor

@akshayjshah akshayjshah left a comment

Choose a reason for hiding this comment

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

Okay - after letting this marinate for longer than I'd originally intended, let's try to ship it.

Before merging, I'd really like to open up some space for predictable future functionality (e.g., fail test if we see error-level or warn-level logs, capture log output in an un-serialized form, etc.). Can we unify NewLogger and NewLoggerAt into a NewLogger that takes variadic functional options?

@akshayjshah
Copy link
Contributor

Thanks for the input, @fgrosse! We can definitely accommodate your first suggestion with an option. I'm a bit reluctant to introduce a testing-specific logger constructor that only takes an io.Writer, specifically because it doesn't provide a way to hook into test success/failure. Ginkgo is one of the few frameworks I've seen that hides the standard library's testing.TB interface so thoroughly, and I'd prefer to accommodate it via a third-party zapginkgo package.

//
// 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.
func NewLogger(t TestingT) *zap.Logger {
Copy link
Collaborator

Choose a reason for hiding this comment

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

let's add support for options, so in future, we can add options for whether to log only on failure, or on failure + test.v.

in our repos, we'd like a logger that only logs on failure, and is quiet otherwise, even with -v, as we run our tests on Jenkins with -v and we don't need spammy lines

//
// 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.
func NewLoggerAt(t TestingT, enab zapcore.LevelEnabler) *zap.Logger {
Copy link
Collaborator

Choose a reason for hiding this comment

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

can this just be an option instead to NewLogger

s := string(p)

// 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


// 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.

@ash2k
Copy link
Contributor

ash2k commented Mar 19, 2018

Would be awesome to get this merged! I've implemented the same functionality (atlassian/smith#261) myself and then wanted to send a PR but it is here already.

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

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!

Also, no explicit string conversion
This tests all log levels for the happy case.
testLogSpy was logging the `args`, not the actual string.

// Note: t.Log is safe for concurrent use.
w.t.Logf("%s", p)
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!

testingWriter should return the length of the original slice, not the
trimmed slice.
This expands the TestingT interface to a much larger subset of
`testing.TB`.

The following were left out:

- `Error` and `Log` were left out in favor of `Errorf` and `Logf`
- `Fatal*` methods were left out in favor of `Errorf` followed by
  `FailNow`
- `Skip*` methods were left out because our test logger shouldn't be
  skipping tests
- `Helper` was left out because not all supported verisons of Go have
  that
Zap's errorOutput is used exclusively to log internal errors. If this
ever gets used in a test, something catastrophic happened and we should
fail the test.

This changes the logger returned by zaptest.NewLogger to implement this
behavior by passing a `WriteSyncer` to `zap.ErrorOutput` that marks the
test as failed upon being used.

To test this, we set up a test logger and replace its core with one that
will always fail to write.
This simplifies the implementation of testLogSpy by removing all
thread-safety from it. It's only used from these specific tests and
never concurrently.
@abhinav
Copy link
Collaborator Author

abhinav commented Apr 9, 2018

Merged #565, #566, and #567 into this PR.

Copy link
Contributor

@akshayjshah akshayjshah left a comment

Choose a reason for hiding this comment

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

Two small suggestions, but LGTM.

// 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.

// Note: t.Log is safe for concurrent use.
w.t.Logf("%s", p)
if w.markFailed {
w.t.Fail()
Copy link
Contributor

Choose a reason for hiding this comment

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

Should we instead FailNow? If there's a bunch of debug output, it seems like it'll be hard to identify the offending log line unless it's the last one.

Copy link
Contributor

Choose a reason for hiding this comment

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

FailNow() should only be used from the test goroutine but the logger may have been invoked by some other goroutine that the test goroutine has started. So calling FailNow() can be an invalid thing to do. Related: golang/go#24678

@akshayjshah
Copy link
Contributor

akshayjshah commented Apr 12, 2018 via email

This documents that loggers built with zaptest.NewLogger default to
debug level logging.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Development

Successfully merging this pull request may close these issues.

6 participants