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

cmd/go: 'go test' output-hiding behavior is under-documented #21461

Closed
cespare opened this issue Aug 15, 2017 · 11 comments
Closed

cmd/go: 'go test' output-hiding behavior is under-documented #21461

cespare opened this issue Aug 15, 2017 · 11 comments

Comments

@cespare
Copy link
Contributor

cespare commented Aug 15, 2017

Using 1.9rc1 / amd64, but it's not particular to any version.

The fact that go test hides output from passing tests if you give it a package selector argument is surprising and is not properly documented.

$ cat x_test.go
package main

import (
        "fmt"
        "testing"
)

func TestFoo(t *testing.T) {
        fmt.Println("hello")
}
$ go1.9rc1 test
hello
PASS
ok      _/home/caleb/test/p     0.001s
$ go1.9rc1 test .
ok      _/home/caleb/test/p     0.001s

The closest I can find to documentation of this difference is at the beginning of go help test:

usage: go test [build/test flags] [packages] [build/test flags & test binary flags]

'Go test' automates testing the packages named by the import paths.
It prints a summary of the test results in the format:

        ok   archive/tar   0.011s
        FAIL archive/zip   0.022s
        ok   compress/gzip 0.033s
        ...

followed by detailed output for each failed package.

In particular, "detailed output for each failed package" hints that there might be a difference between the way output for failed and passed packages are handled, but the documentation should be explicit about when output is hidden from the user.


At a philosophical level, I think it's harmful to hide the output at all. Best practice seems to be writing tests that don't print stuff on success, so the hiding behavior just makes it take longer to discover and fix these bad tests.

I have also observed the behavior of sometimes hiding the output and sometimes not -- depending on how the test was invoked -- to be a source of confusion for go test users.

@cespare cespare added this to the Go1.10 milestone Aug 15, 2017
@ianlancetaylor
Copy link
Contributor

I agree we need better documentation.

I want to support the current behavior, in that it makes it easy to casually add t.Log calls to your tests. They won't be printed if the test passes, but they will be if the test fails. So it makes it simpler to, as you, don't print stuff on success.

@cespare
Copy link
Contributor Author

cespare commented Aug 15, 2017

@ianlancetaylor no, t.Log calls are hidden unless -v is used, regardless of the package selector argument.

$ cat x_test.go
package main

import (
        "testing"
)

func TestFoo(t *testing.T) {
        t.Log("t.Log")
}
$ go1.9rc1 test
PASS
ok      _/home/caleb/test/p     0.002s
$ go1.9rc1 test .
ok      _/home/caleb/test/p     0.001s
$ go1.9rc1 test -v
=== RUN   TestFoo
--- PASS: TestFoo (0.00s)
        x_test.go:8: t.Log
PASS
ok      _/home/caleb/test/p     0.001s
$ go1.9rc1 test -v .
=== RUN   TestFoo
--- PASS: TestFoo (0.00s)
        x_test.go:8: t.Log
PASS
ok      _/home/caleb/test/p     0.002s

@cespare
Copy link
Contributor Author

cespare commented Aug 15, 2017

@ianlancetaylor I guess my response doesn't correspond to

They won't be printed if the test passes, but they will be if the test fails.

In my original post, what I intended to suggest is that it would be less confusing if go test <someargument> didn't hide output for passing tests (so it would behave the same way as go test). This change wouldn't affect what t.Log does, since that only prints with -v or on failure.

@ianlancetaylor
Copy link
Contributor

Sorry, I was supporting hiding the output of passing tests. I agree that it should be consistent.

@cespare
Copy link
Contributor Author

cespare commented Aug 15, 2017

@ianlancetaylor to be precise, are you suggesting that fmt.Println("hello") in a passing test should be hidden when you run go test?

@ianlancetaylor
Copy link
Contributor

Yes. (I can see a counter-argument, but that is my vote.)

@rsc
Copy link
Contributor

rsc commented Dec 1, 2017

New output for go help test, added since this bug was filed:

r$ go help test
...
Go test runs in two different modes: local directory mode when invoked with
no package arguments (for example, 'go test'), and package list mode when
invoked with package arguments (for example 'go test math', 'go test ./...',
and even 'go test .').

In local directory mode, go test compiles and tests the package sources
found in the current directory and then runs the resulting test binary.
In this mode, caching (discussed below) is disabled. After the package test
finishes, go test prints a summary line showing the test status ('ok' or 'FAIL'),
package name, and elapsed time.

In package list mode, go test compiles and tests each of the packages
listed on the command line. If a package test passes, go test prints only
the final 'ok' summary line. If a package test fails, go test prints the
full test output. If invoked with the -bench or -v flag, go test prints
the full output even for passing package tests, in order to display the
requested benchmark results or verbose logging.

I think this is now documented.

@rsc rsc closed this as completed Dec 1, 2017
@valentin-krasontovitsch

I stumbled upon this issue while using flags passed to the go test command to control behaviour during tests (setup). I seem to be experiencing a difference in output:

When running

go test ./...

I get a list of all packages, with OK, ?, or fail indication, and no other output, neither from log calls, nor from t.Log calls.

But when running

go test -compile ./...

I get output from all log calls (not from t.Log though - I guess you need -v for that).

I'm using the flag for flow control, in particular to control whether something gets comtpiled, or not - i don't really want to affect the verbosity of the output, yet I get flooded with output...

A minimal working example to reproduce the described behavior consists of the following to files, in an otherwise empty directory:

main.go:

package main

import (
  "log"
)

func main() {
}

func hello() {
  log.Println("hi")
}

test_main.go:

package main

import (
  "flag"
  "testing"
)

var (
  polite = flag.Bool("polite", false, "")
)

func TestFoo(t *testing.T) {
  hello()
}

results in outputs:

$ go test ./...
ok      _/test_playground/go_test     0.004s

and

$ go test -polite ./...
2018/01/28 12:38:23 hi
PASS
ok      _/Users/valkra/code/test_playground/go_test     0.005s

Is this expected behavior? Personally, I think it should not be ; )

It might be a good idea to add something about this in the docs either way.

@ianlancetaylor
Copy link
Contributor

@valentin-krasontovitsch This issue is closed, and, we believe, fixed. The Go project does not use the issue tracker for discussion; please ask your question on a forum: https://golang.org/wiki/Questions . Thanks.

@valentin-krasontovitsch
Copy link

valentin-krasontovitsch commented Jan 29, 2018

Well, in my humble opinion the issue persists: the behavior I'm describing is (as far as I can see) undocumented. That I formulate this as a question and not a claim is simply due to the fact that I don't want to claim knowledge of all of the documentation, and cannot exclude to have overlooked something ...

Please advise -

  1. do I have to reformulate and make it clearer that I would like to report an issue / bug?
  2. do I have to open a new issue?

Let me try to make a clear statement, as my comment indeed seems to be missing this:

The (difference in) logging behavior of running go test with a list of packages while using custom flags (as opposed to not using custom flags) is undocumented.

Of course, if you have a link at hand pointing me to the right spot of the documentation, I would really appreciate it...

@ianlancetaylor
Copy link
Contributor

I can only repeat what I said above: this issue is closed and, we believe, fixed. This is not the place for further discussion. Please open a new issue or discuss this on a forum. Thanks.

I'm not even sure what you expect from go test -compile. There is no such option.

raghavendra-talur added a commit to raghavendra-talur/heketi that referenced this issue Feb 17, 2018
Some tests were disabling logs and some were not. Based on the
discussion in heketi#792, changing everywhere to default logging.

As per golang/go#21461, the logs won't
pollute the output if all tests pass.

If a test fails then all logs from the package are shown. This is
something which can be fixed later. It would be useful to limit logs of
that particular test instead of package.

Signed-off-by: Raghavendra Talur <rtalur@redhat.com>
phlogistonjohn pushed a commit to heketi/heketi that referenced this issue Feb 17, 2018
Some tests were disabling logs and some were not. Based on the
discussion in #792, changing everywhere to default logging.

As per golang/go#21461, the logs won't
pollute the output if all tests pass.

If a test fails then all logs from the package are shown. This is
something which can be fixed later. It would be useful to limit logs of
that particular test instead of package.

Signed-off-by: Raghavendra Talur <rtalur@redhat.com>
@golang golang locked and limited conversation to collaborators Jan 29, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

5 participants