267

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.

3
  • 1
    This could be possible for Go 1.14 (Q1 2010). See my answer below.
    – VonC
    Oct 22, 2019 at 21:47
  • @VonC s/b Q1 2020 Mar 18, 2020 at 13:58
  • @user2133814 Agreed, it should be 2020 indeed, not 2010. The answer below does mention 2020. I have edited said answer, with a reference to Dave Cheney's article on that new feature.
    – VonC
    Mar 18, 2020 at 14:12

8 Answers 8

274

The structs testing.T and testing.B both have a .Log and .Logf method that sound to be what you are looking for. .Log and .Logf are similar to fmt.Print and fmt.Printf respectively.

See more details here: http://golang.org/pkg/testing/#pkg-index

fmt.X print statements do work inside tests, but you will find their output is probably not on screen where you expect to find it and, hence, why you should use the logging methods in testing.

If, as in your case, you want to see the logs for tests that are not failing, you have to provide go test the -v flag (v for verbosity). More details on testing flags can be found here: https://golang.org/cmd/go/#hdr-Testing_flags

2
  • 32
    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 use fmt. See PeterSO's answer for using go test -v to show the output of fmt.Println when running tests. Oct 29, 2015 at 19:20
  • 15
    If anyone's running the tests from VSCode, just add "go.testFlags": ["-v"] in your settings.json (source: github.com/Microsoft/vscode-go/issues/1377)
    – gokul_uf
    Sep 24, 2021 at 21:50
221

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

Command go

Description of testing flags

-v
Verbose output: log all tests as they are run. Also print all
text from Log and Logf calls even if the test succeeds.

Package testing

func (*T) Log

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.

5
  • 42
    verbose is what I was looking for.
    – cevaris
    Dec 4, 2014 at 23:32
  • 2
    anwa to view log output in the moethod ou are testing itself Jul 23, 2016 at 16:40
  • I can't use fmt here because Visual Studio Code removes the import for fmt! Nov 3, 2020 at 13:50
  • It seems that verbose doesn't work in Example_xxx().
    – hyz
    Sep 22, 2021 at 7:09
  • It seems the v flags only take effect when the test success, how to log even test fail?
    – hongshuwei
    Mar 14, 2022 at 1:42
22

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 use fmt.

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 of TestFoo is done, then no output until all of TestBar is done, and again no more output until all of TestBaz 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.
    If TestFoo 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 and t.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   TestBaz
=== PAUSE TestBaz
=== CONT  TestFoo
=== CONT  TestBaz
    main_test.go:30: 0
=== CONT  TestFoo
    main_test.go:12: 0
=== CONT  TestBar
    main_test.go:21: 0
=== CONT  TestBaz
    main_test.go:30: 1
    main_test.go:30: 2
=== CONT  TestBar
    main_test.go:21: 1
=== CONT  TestFoo
    main_test.go:12: 1
=== CONT  TestBaz
    main_test.go:30: 3
    main_test.go:30: 4
=== CONT  TestBar
    main_test.go:21: 2
=== CONT  TestBaz
    main_test.go:30: 5
=== CONT  TestFoo
    main_test.go:12: 2
=== CONT  TestBar
    main_test.go:21: 3
=== CONT  TestBaz
    main_test.go:30: 6
    main_test.go:30: 7
=== CONT  TestBar
    main_test.go:21: 4
=== CONT  TestBaz
    main_test.go:30: 8
=== CONT  TestFoo
    main_test.go:12: 3
=== CONT  TestBaz
    main_test.go:30: 9
=== CONT  TestBar
    main_test.go:21: 5
=== CONT  TestBaz
    main_test.go:30: 10
    main_test.go:30: 11
=== CONT  TestFoo
    main_test.go:12: 4
=== CONT  TestBar
    main_test.go:21: 6
=== CONT  TestBaz
    main_test.go:30: 12
    main_test.go:30: 13
=== CONT  TestBar
    main_test.go:21: 7
=== CONT  TestBaz
    main_test.go:30: 14
=== CONT  TestFoo
    main_test.go:12: 5
--- PASS: TestBaz (15.01s)
=== CONT  TestBar
    main_test.go:21: 8
=== CONT  TestFoo
    main_test.go:12: 6
=== CONT  TestBar
    main_test.go:21: 9
    main_test.go:21: 10
=== CONT  TestFoo
    main_test.go:12: 7
=== CONT  TestBar
    main_test.go:21: 11
=== CONT  TestFoo
    main_test.go:12: 8
=== CONT  TestBar
    main_test.go:21: 12
    main_test.go:21: 13
=== CONT  TestFoo
    main_test.go:12: 9
=== CONT  TestBar
    main_test.go:21: 14
=== CONT  TestFoo
    main_test.go:12: 10
--- PASS: TestBar (30.01s)
=== CONT  TestFoo
    main_test.go:12: 11
    main_test.go:12: 12
    main_test.go:12: 13
    main_test.go:12: 14
--- PASS: TestFoo (45.02s)
PASS
ok      command-line-arguments  45.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 stream t.Log output as it happens, rather than hoarding it til the end of the test run.

Under Go 1.14 the fmt.Println and t.Log lines are interleaved, rather than waiting for the test to complete, demonstrating that test output is streamed when go 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.
Streaming t.Log output will help Gophers debug those test failures without having to wait until the entire test times out to receive their output.

3
  • Illuminating, thanks! :) Just one thing, test output doesn't match the tests in here.
    – bravmi
    Jan 2, 2022 at 7:47
  • @bravmi Good point. Can you edit the answer with the right updated output?
    – VonC
    Jan 2, 2022 at 7:54
  • My pleasure, once edit queue frees up! And let me take the opportunity to thank you so much for your answers. <3
    – bravmi
    Jan 2, 2022 at 8:01
11

For testing sometimes I do

fmt.Fprintln(os.Stdout, "hello")

Also, you can print to:

fmt.Fprintln(os.Stderr, "hello")
3
  • 1
    The first of those can just be fmt.Println("hello"). Sep 9, 2019 at 10:31
  • Visual Studio Code removes import fmt when I try to import and use it. :( Nov 3, 2020 at 13:51
  • @micahhoover that is the expected behavior, is an import is not used, the go tooling will remove it, because it won't compile, Add the fmt.Fprintln(os.Stderr, "hello) first Nov 4, 2020 at 18:14
4

WARNING: The answers here do not apply when testing multiple packages at once.

The answers from @VonC and @voidlogic are fantastic, but I wanted to bring the following thread to attention in case someone is running a permutation of go test -v ./...: https://github.com/golang/go/issues/46959

The issue lies in implementation nuances/difficulties related to running tests from multiple packages.

For example, running go test -v -count=1 -run TestOnlyOneInstanceOfThisTestExists ./multiple/packages/exist/below/... will only print logs after the test completes.

However, running go test -v -count=1 -run TestOnlyOneInstanceOfThisTestExists ./this/path/points/to/one/package/only/... will stream the output as expected.

3

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
0

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

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()
    }*/
}

Your Answer

Reminder: Answers generated by Artificial Intelligence tools are not allowed on Stack Overflow. Learn more

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge that you have read and understand our privacy policy and code of conduct.

Not the answer you're looking for? Browse other questions tagged or ask your own question.