zaptest: Add testing.TB compatible logger #518

abhinav · 2017-10-26T20:17:08Z

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 · 2017-10-26T20:53:15Z

Codecov Report

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

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

prashantv

Looks pretty good, just one suggestion for the API

prashantv · 2017-10-26T21:12:13Z

zaptest/tlogger/tlogger.go

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


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.

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.

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.

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

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

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.

prashantv

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

prashantv · 2017-10-26T21:35:52Z

zaptest/tlogger/tlogger.go

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


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 · 2017-10-28T00:06:00Z

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.

akshayjshah

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.

akshayjshah · 2017-10-28T00:25:34Z

zaptest/tlogger/tlogger.go

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


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

Yeah, we don't. Removing.

akshayjshah · 2017-10-31T23:24:00Z

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.

This reverts commit be2b5ea.

abhinav · 2017-11-01T16:38:10Z

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

kriskowal

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 · 2017-11-01T21:28:10Z

@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 · 2017-11-07T17:09:44Z

Friendly bump @akshayjshah

fgrosse · 2017-12-13T19:16:09Z

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:

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.

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 :)

akshayjshah

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 · 2018-02-16T21:35:21Z

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.

prashantv · 2018-02-17T00:09:56Z

zaptest/logger.go

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


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

prashantv · 2018-02-17T00:10:09Z

zaptest/logger.go

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


can this just be an option instead to NewLogger

prashantv · 2018-02-21T21:45:14Z

zaptest/logger.go

+	s := string(p)
+
+	// Strip trailing newline because t.Log always adds one.
+	if s[len(s)-1] == '\n' {


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

prashantv · 2018-02-21T22:49:34Z

zaptest/testingt.go

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


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?

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

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.

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 · 2018-03-19T23:18:14Z

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.

ash2k · 2018-03-19T23:19:34Z

zaptest/logger.go

+			testingWriter{t},
+			cfg.Level,
+		),
+	)


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.

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.

Excellent point. It should fail the test.

Done in #566

ash2k · 2018-03-19T23:20:39Z

zaptest/logger.go

+type testingWriter struct{ t TestingT }
+
+func (w testingWriter) Write(p []byte) (n int, err error) {
+	s := string(p)


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

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.

ash2k · 2018-03-26T22:20:41Z

zaptest/logger.go

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


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.

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 · 2018-04-09T18:17:53Z

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

akshayjshah

Two small suggestions, but LGTM.

akshayjshah · 2018-04-11T21:14:55Z

zaptest/logger.go

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


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

akshayjshah · 2018-04-11T21:17:42Z

zaptest/logger.go

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


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.

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 · 2018-04-12T05:50:20Z

Fair point.

On Wed, Apr 11, 2018 at 5:58 PM Mikhail Mazurskiy ***@***.***> wrote: ***@***.**** commented on this pull request. ------------------------------ In zaptest/logger.go <#518 (comment)>: > +// the provided value. +func (w testingWriter) WithMarkFailed(v bool) testingWriter { + w.markFailed = v + return w +} + +func (w testingWriter) Write(p []byte) (n int, err error) { + n = len(p) + + // Strip trailing newline because t.Log always adds one. + p = bytes.TrimRight(p, "\n") + + // Note: t.Log is safe for concurrent use. + w.t.Logf("%s", p) + if w.markFailed { + w.t.Fail() 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 <golang/go#24678> — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#518 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AA7X9t8sMBnaFUNs2g9-sgO7FReJQvnbks5tnqbSgaJpZM4QIJ4i> .

-- Akshay Shah Software Engineer, RPC shah@uber.com

This documents that loggers built with zaptest.NewLogger default to debug level logging.

abhinav requested review from akshayjshah and prashantv October 26, 2017 20:17

abhinav force-pushed the abg/test-logger branch from 4938cc6 to 6636ecf Compare October 26, 2017 20:18

prashantv reviewed Oct 26, 2017

View reviewed changes

prashantv approved these changes Oct 26, 2017

View reviewed changes

akshayjshah reviewed Oct 28, 2017

View reviewed changes

This was referenced Oct 30, 2017

This is great! fgrosse/zaptest#1

Closed

Break dependency between zap and zaptest #523

Merged

abhinav added 6 commits October 31, 2017 16:52

Rename to zaptest/tlogger

be2b5ea

Remove backticks

a73cb3f

Revert "Remove backticks"

e78537e

This reverts commit a73cb3f.

Revert "Rename to zaptest/tlogger"

9c4600e

This reverts commit be2b5ea.

NewTestLogger => NewLogger; return *zap.Logger

316a110

abhinav force-pushed the abg/test-logger branch from dc5f66b to 316a110 Compare October 31, 2017 23:58

abhinav added 2 commits November 1, 2017 11:59

Rely on subset of testing.TB interface

ca6ac7d

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.

no need to duplicate NewDevelopmentEncoderConfig

660acc6

kriskowal approved these changes Nov 1, 2017

View reviewed changes

akshayjshah suggested changes Feb 16, 2018

View reviewed changes

prashantv reviewed Feb 17, 2018

View reviewed changes

Drop NewLoggerAt in favor of options

4de70e3

prashantv approved these changes Feb 21, 2018

View reviewed changes

ash2k reviewed Mar 19, 2018

View reviewed changes

abhinav added 3 commits March 26, 2018 14:58

Use bytes.TrimRight instead of manual trimming

959d416

Also, no explicit string conversion

test: All levels for happy case

063f7a1

This tests all log levels for the happy case.

testLogSpy: Logf should log the message

8dd84b6

testLogSpy was logging the `args`, not the actual string.

ash2k suggested changes Mar 26, 2018

View reviewed changes

abhinav mentioned this pull request Mar 26, 2018

zaptest: Expand TestingT interface #565

Merged

abhinav added 4 commits March 26, 2018 15:54

testingWriter: Return original length

3ebc5fc

testingWriter should return the length of the original slice, not the trimmed slice.

zaptest: testLogSpy doesn't have to be thread-safe

d7b6a16

This simplifies the implementation of testLogSpy by removing all thread-safety from it. It's only used from these specific tests and never concurrently.

prashantv approved these changes Apr 9, 2018

View reviewed changes

akshayjshah approved these changes Apr 11, 2018

View reviewed changes

zaptest/NewLogger: Clarify default log level

d0af2be

This documents that loggers built with zaptest.NewLogger default to debug level logging.

akshayjshah merged commit 031c049 into master Apr 12, 2018

akshayjshah deleted the abg/test-logger branch April 24, 2018 22:24

JeanMertz mentioned this pull request Nov 2, 2018

Deprecate test logger in favour of new Zap test logger blendle/go-streamprocessor#104

Merged

github-actions bot mentioned this pull request Apr 10, 2022

Link Checker Report scylladb/scylla-manager#3102

Closed

github-actions bot mentioned this pull request Apr 17, 2022

Link Checker Report scylladb/scylla-manager#3121

Closed

zaptest: Add testing.TB compatible logger #518

zaptest: Add testing.TB compatible logger #518

Conversation

abhinav commented Oct 26, 2017 • edited Loading

codecov bot commented Oct 26, 2017 • edited Loading

Codecov Report

prashantv left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

prashantv left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

akshayjshah commented Oct 28, 2017

akshayjshah left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

akshayjshah commented Oct 31, 2017 • edited Loading

abhinav commented Nov 1, 2017

kriskowal left a comment

Choose a reason for hiding this comment

abhinav commented Nov 1, 2017

abhinav commented Nov 7, 2017

fgrosse commented Dec 13, 2017

akshayjshah left a comment

Choose a reason for hiding this comment

akshayjshah commented Feb 16, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ash2k commented Mar 19, 2018 • edited Loading

ash2k Mar 19, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

abhinav commented Apr 9, 2018

akshayjshah left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

akshayjshah commented Apr 12, 2018 via email

abhinav commented Oct 26, 2017 •

edited

Loading

codecov bot commented Oct 26, 2017 •

edited

Loading

akshayjshah commented Oct 31, 2017 •

edited

Loading

ash2k commented Mar 19, 2018 •

edited

Loading

ash2k Mar 19, 2018 •

edited

Loading