I'm running a test in Go with a statement to print something (i.e. for debugging of tests) but it's not printing anything.
func TestPrintSomething(t *testing.T) {
fmt.Println("Say hi")
}
When I run go test on this file, this is the output:
ok command-line-arguments 0.004s
The only way to really get it to print, as far as I know, is to print it via t.Error(), like so:
func TestPrintSomethingAgain(t *testing.T) {
t.Error("Say hi")
}
Which outputs this:
Say hi
--- FAIL: TestPrintSomethingAgain (0.00 seconds)
foo_test.go:35: Say hi
FAIL
FAIL command-line-arguments 0.003s
gom: exit status 1
I've Googled and looked through the manual but didn't find anything.
t.Log
and t.Logf
do print out in your test but can often be missed as it prints on the same line as your test. What I do is Log them in a way that makes them stand out, ie
t.Run("FindIntercomUserAndReturnID should find an intercom user", func(t *testing.T) {
id, err := ic.FindIntercomUserAndReturnID("[email protected]")
assert.Nil(t, err)
assert.NotNil(t, id)
t.Logf("\n\nid: %v\n\n", *id)
})
which prints it to the terminal as,
=== RUN TestIntercom
=== RUN TestIntercom/FindIntercomUserAndReturnID_should_find_an_intercom_user
TestIntercom/FindIntercomUserAndReturnID_should_find_an_intercom_user: intercom_test.go:34:
id: 5ea8caed05a4862c0d712008
--- PASS: TestIntercom (1.45s)
--- PASS: TestIntercom/FindIntercomUserAndReturnID_should_find_an_intercom_user (1.45s)
PASS
ok github.com/RuNpiXelruN/third-party-delete-service 1.470s
For testing sometimes I do
fmt.Fprintln(os.Stdout, "hello")
Also, you can print to:
fmt.Fprintln(os.Stderr, "hello)
In case your using testing.M
and associated setup/teardown; -v
is valid here as well.
package g
import (
"os"
"fmt"
"testing"
)
func TestSomething(t *testing.T) {
t.Skip("later")
}
func setup() {
fmt.Println("setting up")
}
func teardown() {
fmt.Println("tearing down")
}
func TestMain(m *testing.M) {
setup()
result := m.Run()
teardown()
os.Exit(result)
}
$ go test -v g_test.go
setting up
=== RUN TestSomething
g_test.go:10: later
--- SKIP: TestSomething (0.00s)
PASS
tearing down
ok command-line-arguments 0.002s
t.Log()
will not show up until after the test is complete, so if you're trying to debug a test that is hanging or performing badly it seems you need to usefmt
.
Yes: that was the case up to Go 1.13 (August 2019) included.
And that was followed in golang.org
issue 24929
Consider the following (silly) automated tests:
func TestFoo(t *testing.T) { t.Parallel() for i := 0; i < 15; i++ { t.Logf("%d", i) time.Sleep(3 * time.Second) } } func TestBar(t *testing.T) { t.Parallel() for i := 0; i < 15; i++ { t.Logf("%d", i) time.Sleep(2 * time.Second) } } func TestBaz(t *testing.T) { t.Parallel() for i := 0; i < 15; i++ { t.Logf("%d", i) time.Sleep(1 * time.Second) } }
If I run
go test -v
, I get no log output until all ofTestFoo
is done, then no output until all ofTestBar
is done, and again no more output until all ofTestBaz
is done.
This is fine if the tests are working, but if there is some sort of bug, there are a few cases where buffering log output is problematic:
- When iterating locally, I want to be able to make a change, run my tests, see what's happening in the logs immediately to understand what's going on, hit CTRL+C to shut the test down early if necessary, make another change, re-run the tests, and so on.
IfTestFoo
is slow (e.g., it's an integration test), I get no log output until the very end of the test. This significantly slows down iteration.- If
TestFoo
has a bug that causes it to hang and never complete, I'd get no log output whatsoever. In these cases,t.Log
andt.Logf
are of no use at all.
This makes debugging very difficult.- Moreover, not only do I get no log output, but if the test hangs too long, either the Go test timeout kills the test after 10 minutes, or if I increase that timeout, many CI servers will also kill off tests if there is no log output after a certain amount of time (e.g., 10 minutes in CircleCI).
So now my tests are killed and I have nothing in the logs to tell me what happened.
But for (possibly) Go 1.14 (Q1 2020): CL 127120
testing: stream log output in verbose mode
The output now is:
=== RUN TestFoo
=== PAUSE TestFoo
=== RUN TestBar
=== PAUSE TestBar
=== RUN TestGaz
=== PAUSE TestGaz
=== CONT TestFoo
TestFoo: main_test.go:14: hello from foo
=== CONT TestGaz
=== CONT TestBar
TestGaz: main_test.go:38: hello from gaz
TestBar: main_test.go:26: hello from bar
TestFoo: main_test.go:14: hello from foo
TestBar: main_test.go:26: hello from bar
TestGaz: main_test.go:38: hello from gaz
TestFoo: main_test.go:14: hello from foo
TestGaz: main_test.go:38: hello from gaz
TestBar: main_test.go:26: hello from bar
TestFoo: main_test.go:14: hello from foo
TestGaz: main_test.go:38: hello from gaz
TestBar: main_test.go:26: hello from bar
TestGaz: main_test.go:38: hello from gaz
TestFoo: main_test.go:14: hello from foo
TestBar: main_test.go:26: hello from bar
--- PASS: TestFoo (1.00s)
--- PASS: TestGaz (1.00s)
--- PASS: TestBar (1.00s)
PASS
ok dummy/streaming-test 1.022s
It is indeed in Go 1.14, as Dave Cheney attests in "go test -v
streaming output":
In Go 1.14,
go test -v
will streamt.Log
output as it happens, rather than hoarding it til the end of the test run.Under Go 1.14 the
fmt.Println
andt.Log
lines are interleaved, rather than waiting for the test to complete, demonstrating that test output is streamed whengo test -v
is used.
Advantage, according to Dave:
This is a great quality of life improvement for integration style tests that often retry for long periods when the test is failing.
Streamingt.Log
output will help Gophers debug those test failures without having to wait until the entire test times out to receive their output.
For example,
package verbose
import (
"fmt"
"testing"
)
func TestPrintSomething(t *testing.T) {
fmt.Println("Say hi")
t.Log("Say bye")
}
go test -v
=== RUN TestPrintSomething
Say hi
--- PASS: TestPrintSomething (0.00 seconds)
v_test.go:10: Say bye
PASS
ok so/v 0.002s
-v Verbose output: log all tests as they are run. Also print all text from Log and Logf calls even if the test succeeds.
func (c *T) Log(args ...interface{})
Log formats its arguments using default formatting, analogous to Println, and records the text in the error log. For tests, the text will be printed only if the test fails or the -test.v flag is set. For benchmarks, the text is always printed to avoid having performance depend on the value of the -test.v flag.
The *_test.go
file is a Go source like the others, you can initialize a new logger every time if you need to dump complex data structure, here an example:
// initZapLog is delegated to initialize a new 'log manager'
func initZapLog() *zap.Logger {
config := zap.NewDevelopmentConfig()
config.EncoderConfig.EncodeLevel = zapcore.CapitalColorLevelEncoder
config.EncoderConfig.TimeKey = "timestamp"
config.EncoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder
logger, _ := config.Build()
return logger
}
Then, every time, in every test:
func TestCreateDB(t *testing.T) {
loggerMgr := initZapLog()
// Make logger avaible everywhere
zap.ReplaceGlobals(loggerMgr)
defer loggerMgr.Sync() // flushes buffer, if any
logger := loggerMgr.Sugar()
logger.Debug("START")
conf := initConf()
/* Your test here
if false {
t.Fail()
}*/
}
Source: Stackoverflow.com