cmd/go: go module fetching gives unexpected stderr output

[carlpett]

What version of Go are you using (go version)?

$ go version
go version go1.13.5 windows/amd64

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (go env)?

go env Output

$ go env
set GO111MODULE=
set GOARCH=amd64
set GOBIN=
set GOCACHE=C:\Users\username\AppData\Local\go-build
set GOENV=C:\Users\username\AppData\Roaming\go\env
set GOEXE=.exe
set GOFLAGS=
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GONOPROXY=
set GONOSUMDB=
set GOOS=windows
set GOPATH=C:\Users\username\dev
set GOPRIVATE=
set GOPROXY=https://proxy.golang.org,direct
set GOROOT=C:\Program Files\Go
set GOSUMDB=sum.golang.org
set GOTMPDIR=
set GOTOOLDIR=C:\Program Files\Go\pkg\tool\windows_amd64
set GCCGO=gccgo
set AR=ar
set CC=gcc
set CXX=g++
set CGO_ENABLED=0
set GOMOD=C:\Users\username\Dev\src\path\to\repo\go.mod
set CGO_CFLAGS=-g -O2
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-g -O2
set CGO_FFLAGS=-g -O2
set CGO_LDFLAGS=-g -O2
set PKG_CONFIG=pkg-config
set GOGCCFLAGS=-m64 -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=C:\Users\username\AppData\Local\Temp\go-build955724962=/tmp/go-build -gno-record-gcc-switches

What did you do?

go mod download

What did you expect to see?

As per the documentation of the command,

By default, download reports errors to standard error but is otherwise silent.

I expected no output on success.

What did you see instead?

A line to stderr for each module as it is cached:

go: finding golang.org/x/sys v0.0.0-20190507160741-ecd444e8653b

Discussion

This appears to come from here:

go/src/cmd/go/internal/modfetch/cache.go

Line 171 in dcd3b2c

fmt.Fprintf(os.Stderr, "go: finding %s %s\n", r.path, rev)

This is an issue since many many CI tools will fail the build on output to stderr. We could redirect to stdout, but then actual errors might be missed (although that probably triggers a fail based on exit code).

The smallest possible fix would be to update the documentation so that it mentions that caching will also write to stderr, but a "better" fix from my point of view would be to either move the caching logs to stdout, and/or hide them completely unless a verbose flag is passed?

[carlpett]

On closer inspection, this is not just on go mod download, but probably happens for any command which causes a fetch, including build?
Is there a good reason to write such diagnostic output to stderr? Should that not be reserved for actual errors?

[aofei]

... but a "better" fix from my point of view would be to either move the caching logs to stdout...

I'm afraid that changes like this will break more existing things because currently go takes stdout as the target of the output that needs to be processed, like this:

$ go mod download -json golang.org/x/text@v0.3.2                                                                                                                                                                       
go: finding golang.org/x/text v0.3.2
{
        "Path": "golang.org/x/text",
        "Version": "v0.3.2",
        "Info": "/Users/aofei/go/pkg/mod/cache/download/golang.org/x/text/@v/v0.3.2.info",
        "GoMod": "/Users/aofei/go/pkg/mod/cache/download/golang.org/x/text/@v/v0.3.2.mod",
        "Zip": "/Users/aofei/go/pkg/mod/cache/download/golang.org/x/text/@v/v0.3.2.zip",
        "Dir": "/Users/aofei/go/pkg/mod/golang.org/x/text@v0.3.2",
        "Sum": "h1:tW2bmiBqwgJj/UpqtC8EpXEZVYOwU0yG4iWbprSVAcs=",
        "GoModSum": "h1:bEr9sfX3Q8Zfm5fL9x+3itogRgK3+ptLWKqgva+5dAk="
}

Only the JSON part is what we're going to process as a successful output. If we also move go: finding golang.org/x/text v0.3.2 to stdout, then we will have to pay attention to splitting the output before processing it.

[RodionGork]

@carlpett sorry, but I dare to add that

On closer inspection, this is not just on go mod download

this is not only about go, many "defacto-standard" tools use stderr as output for secondary information, ranging from maven to curl. thus

many CI tools will fail the build on output to stderr.

I think this (your ci pipeline or tools) should be fixed instead. We usually set up CI so that it detects failure by non-zero return code, rather than by output to stderr. Though I do vaguely remember one or two tools who have such behavior as you describe by default.

I believe most of them have some setting about this at least. You can name some specific tool you want to have better integration with so we can look closer...

[carlpett]

Thanks for those perspectives @aofei and @RodionGork! As always, there are more nuances than initially expected :)
The specific case I ran into today was on AppVeyor, which runs Windows builds. To get Powershell to treat non-zero exit codes as errors, there is a setting ErrorActionPreference which needs to be set to Stop. However, this also makes any stderr output a stopping error.
In this case there seems to be no reasonable escape? I've resorted to running go mod download without the preference variable set (so any module download errors will be ignored), and then go build with it set, which will trigger a build failure if a module needs to be cached since the download failed. So it kinda works.

Anyway, the initial issue topic about mod download writing other things to stderr than what is explicitly documented (a quick look indicated most other commands don't document thier outputs at all) might be worth doing something about?

[RodionGork]

Anyway, the initial issue ... than what is explicitly documented ... might be worth doing something about?

Well, this may be worthwile, if there is some specific text in documentation which could be improved / extended...

Do you mean this line?
https://github.com/golang/go/blob/master/src/cmd/go/internal/modcmd/download.go#L33

Regretfully such comments easily become obsolete unless they have corresponding unit-test (which may show that empty stderr is desired and important). So I'm not sure, to which side this should be fixed (e.g. perhaps removing this line as it contradicts current behavior) :(

[cagedmantis]

/cc @bcmills @jayconrod

[jayconrod]

For go mod download, the documentation should be updated to match reality.

All module-related commands may print messages related to network operations to stderr.

[gopherbot]

Change https://golang.org/cl/213134 mentions this issue: cmd/go: clarify stderr behavior for 'go help mod download'