cmd/go: module chatter hides actual errors

jaloren commented 6 years ago

Please answer these questions before submitting your issue. Thanks!

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

go version go1.10.3 darwin/amd64 vgo:2018-02-20.1

Does this issue reproduce with the latest release?

yes i built from source today

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

GOARCH="amd64"
GOBIN="/Volumes/Repositories/go/bin"
GOCACHE="/Users/jlorenzini/Library/Caches/go-build"
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Volumes/Repositories/go"
GOPROXY=""
GORACE=""
GOROOT="/usr/local/go"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/8w/7ndx_j6s36x9hm9dns67j21s3hynqn/T/go-build299230517=/tmp/go-build -gno-record-gcc-switches -fno-common"
VGOMODROOT="/Users/jlorenzini/repos/operator"

What did you do?

vgo mod -vendor

What did you expect to see?

The vendor directory to be populated with the packages defined in my go.mod.

What did you see instead?

The vendor directory is empty after command seemed to download packages.

bcmills commented 6 years ago

In order to diagnose the problem, we need to be able to reproduce it. Please provide some more detail.

What were the contents of your go.mod before and after you ran vgo mod -vendor?
What is the output of vgo list -m for your module?
What are in your module source tree before and after vgo mod -vendor? (What is the output of find . in your module root?)

jaloren commented 6 years ago

What were the contents of your go.mod before and after you ran vgo mod -vendor?

No change.

module bb.dev.norvax.net/dep/operator

require (
    github.com/armon/go-radix v0.0.0-20170727155443-1fca145dffbc
    github.com/bgentry/speakeasy v0.1.0
    github.com/fatih/color v1.7.0
    github.com/fatih/structs v1.0.0
    github.com/golang/snappy v0.0.0-20180518054509-2e65f85255db
    github.com/hashicorp/errwrap v0.0.0-20141028054710-7554cd9344ce
    github.com/hashicorp/go-cleanhttp v0.0.0-20171218145408-d5fe4b57a186
    github.com/hashicorp/go-multierror v0.0.0-20171204182908-b7773ae21874
    github.com/hashicorp/go-rootcerts v0.0.0-20160503143440-6bb64b370b90
    github.com/hashicorp/hcl v0.0.0-20180404174102-ef8a98b0bbce
    github.com/hashicorp/vault v0.9.1
    github.com/mattn/go-colorable v0.0.9
    github.com/mattn/go-isatty v0.0.3
    github.com/mitchellh/cli v0.0.0-20180414170447-c48282d14eba
    github.com/mitchellh/go-homedir v0.0.0-20180523094522-3864e76763d9
    github.com/mitchellh/mapstructure v0.0.0-20180511142126-bb74f1db0675
    github.com/pkg/errors v0.8.0
    github.com/posener/complete v1.1.1
    github.com/sethgrid/pester v0.0.0-20180430140037-03e26c9abbbf
    golang.org/x/crypto v0.0.0-20180621125126-a49355c7e3f8
    golang.org/x/net v0.0.0-20180629035331-4cb1c02c05b0
    golang.org/x/sys v0.0.0-20180627142611-7138fd3d9dc8
    golang.org/x/text v0.3.0
    gopkg.in/yaml.v2 v2.2.1
)

What is the output of vgo list -m for your module?

jlorenzini@jlorenzini-mb operator$ vgo list -m
bb.dev.norvax.net/dep/operator

What are in your module source tree before and after vgo mod -vendor? (What is the output of find . in your module root?)

No change as far as i can tell.

./locksmith
./locksmith/README.md
./locksmith/build.yml
./locksmith/cli
./locksmith/cli/commands.go
./locksmith/cli/help.go
./locksmith/cli/main.go
./locksmith/client
./locksmith/client/client.go
./locksmith/command
./locksmith/command/export.go
./locksmith/command/import.go
./locksmith/command/migrations.go
./locksmith/command/migrations_apply.go
./locksmith/command/renew.go
./locksmith/command/secret.go
./locksmith/command/secret_add.go
./locksmith/command/secret_rm.go
./locksmith/command/status.go
./locksmith/data
./locksmith/data/sample.yml
./locksmith/expandvar
./locksmith/expandvar/expandvar.go
./locksmith/hooks
./locksmith/hooks/test.sh
./locksmith/main.go
./locksmith/migrations
./locksmith/migrations/audit_enable.go
./locksmith/migrations/auth_enable.go
./locksmith/migrations/delete.go
./locksmith/migrations/migrations.go
./locksmith/migrations/mount.go
./locksmith/migrations/mount_tune.go
./locksmith/migrations/policy_write.go
./locksmith/migrations/read.go
./locksmith/migrations/unmount.go
./locksmith/migrations/write.go
./locksmith/symmetric
./locksmith/symmetric/symmetric.go
./locksmith/symmetric/symmetric_test.go
./locksmith/tests
./locksmith/tests/Dockerfile

rsc commented 6 years ago

At the risk of asking two dumb questions:

If that's the output of "find ." in your module root, why is there no line for ./go.mod?
Do the files in locksmith import packages from modules from your go.mod file?
What happens to go.mod if you run vgo mod -sync?

jaloren commented 6 years ago

@rsc not dumb questions of all especially since when I went to answer questions, I realized I omitted some important information that actually helps isolate the problem. So I originally used dep, which defines a dependency on go-yaml like this (note its not using the versioning or gopkg.in)

[[projects]]
  name = "github.com/go-yaml/yaml"
  packages = ["."]
  revision = "5420a8b6744d3b0345ab293f6fcba19c978f1183"
  version = "v2.2.1"

Before i ran vgo build for the first time, I dropped this go.mod in the root directory.

module "bb.dev.norvax.net/dep/operator"

Then when I do the vgo build, for the first time this is what is outputted.

vgo: copying requirements from /Users/jlorenzini/repos/operator/Gopkg.lock
vgo: downloaded "github.com/go-yaml/yaml" and got module "gopkg.in/yaml.v2"

And here's what's in go.mod file (due to automatic conversation of the dep lock file):

module bb.dev.norvax.net/dep/operator

require (
    github.com/agext/levenshtein v1.2.1
    github.com/apparentlymart/go-cidr v0.0.0-20170616213631-2bd8b58cf427
    github.com/apparentlymart/go-textseg v0.0.0-20170531203952-b836f5c4d331
    github.com/armon/go-radix v0.0.0-20170727155443-1fca145dffbc
    github.com/aws/aws-sdk-go v1.13.54
    github.com/beorn7/perks v0.0.0-20180321164747-3a771d992973
    github.com/bgentry/go-netrc v0.0.0-20140422174119-9fd32a8b3d3d
    github.com/bgentry/speakeasy v0.1.0
    github.com/blang/semver v0.0.0-20170727064818-2ee87856327b
    github.com/cenkalti/backoff v0.0.0-20171224164212-2ea60e5f0944
    github.com/coreos/go-systemd v0.0.0-20180202092358-40e2722dffea
    github.com/davecgh/go-spew v1.1.0
    github.com/docker/distribution v0.0.0-20180522175653-f0cc92778478
    github.com/docker/docker v1.12.6
    github.com/docker/engine-api v0.4.0
    github.com/docker/libtrust v0.0.0-20160708172513-aabc10ec26b7
    github.com/dsnet/compress v0.0.0-20171208185109-cc9eb1d7ad76
    github.com/f5devcentral/go-bigip v0.0.0-20180523221152-f965982c0fc1
    github.com/fatih/color v1.7.0
    github.com/fatih/structs v0.0.0-20170103081050-a720dfa8df58
    github.com/fsouza/go-dockerclient v0.0.0-20160427172547-1d4f4ae73768
    github.com/go-ini/ini v1.36.0
    github.com/go-yaml/yaml v0.0.0-20180328195020-5420a8b6744d
    github.com/golang/protobuf v1.1.0
    github.com/golang/snappy v0.0.0-20180518054509-2e65f85255db
    github.com/hashicorp/consul v1.1.0
    github.com/hashicorp/errwrap v0.0.0-20141028054710-7554cd9344ce
    github.com/hashicorp/go-cleanhttp v0.0.0-20171218145408-d5fe4b57a186
    github.com/hashicorp/go-getter v0.0.0-20180425224130-3f60ec5cfbb2
    github.com/hashicorp/go-multierror v0.0.0-20171204182908-b7773ae21874
    github.com/hashicorp/go-rootcerts v0.0.0-20160503143440-6bb64b370b90
    github.com/hashicorp/go-safetemp v0.0.0-20180326211150-b1a1dbde6fdc
    github.com/hashicorp/go-uuid v0.0.0-20180228145832-27454136f036
    github.com/hashicorp/go-version v0.0.0-20180322230233-23480c066577
    github.com/hashicorp/hcl v0.0.0-20180404174102-ef8a98b0bbce
    github.com/hashicorp/hcl2 v0.0.0-20180523235629-81d22773002d
    github.com/hashicorp/hil v0.0.0-20170627220502-fa9f258a9250
    github.com/hashicorp/serf v0.8.1
    github.com/hashicorp/terraform v0.11.7
    github.com/hashicorp/vault v0.9.1
    github.com/heroku/docker-registry-client v0.0.0-20171019183014-fd2fe8034968
    github.com/inconshreveable/mousetrap v0.0.0-20141017200713-76626ae9c91c
    github.com/jmespath/go-jmespath v0.0.0-20160202185014-0b12d6b521d8
    github.com/mattn/go-colorable v0.0.9
    github.com/mattn/go-isatty v0.0.3
    github.com/matttproud/golang_protobuf_extensions v1.0.0
    github.com/mholt/archiver v0.0.0-20180417220235-e4ef56d48eb0
    github.com/mitchellh/cli v0.0.0-20180414170447-c48282d14eba
    github.com/mitchellh/copystructure v0.0.0-20170525013902-d23ffcb85de3
    github.com/mitchellh/go-homedir v0.0.0-20180523094522-3864e76763d9
    github.com/mitchellh/go-testing-interface v0.0.0-20171004221916-a61a99592b77
    github.com/mitchellh/go-wordwrap v0.0.0-20150314170334-ad45545899c7
    github.com/mitchellh/hashstructure v0.0.0-20170609045927-2bca23e0e452
    github.com/mitchellh/mapstructure v0.0.0-20180511142126-bb74f1db0675
    github.com/mitchellh/reflectwalk v0.0.0-20170726202117-63d60e9d0dbc
    github.com/nwaples/rardecode v0.0.0-20171029023500-e06696f847ae
    github.com/opencontainers/go-digest v1.0.0-rc1
    github.com/opencontainers/runc v0.1.1
    github.com/pierrec/lz4 v0.0.0-20171218195038-2fcda4cb7018
    github.com/pierrec/xxHash v0.1.1
    github.com/pkg/errors v0.8.0
    github.com/pmezard/go-difflib v1.0.0
    github.com/posener/complete v1.1.1
    github.com/prometheus/client_golang v0.8.0
    github.com/prometheus/client_model v0.0.0-20171117100541-99fa1f4be8e5
    github.com/prometheus/common v0.0.0-20180518154759-7600349dcfe1
    github.com/prometheus/procfs v0.0.0-20180408092902-8b1c2da0d56d
    github.com/sergi/go-diff v1.0.0
    github.com/sethgrid/pester v0.0.0-20180430140037-03e26c9abbbf
    github.com/sirupsen/logrus v1.0.5
    github.com/spf13/cobra v0.0.3
    github.com/spf13/pflag v1.0.1
    github.com/stretchr/testify v1.2.1
    github.com/ulikunitz/xz v0.5.4
    github.com/zclconf/go-cty v0.0.0-20180524003106-ba988ce11d99
    golang.org/x/crypto v0.0.0-20180524125353-159ae71589f3
    golang.org/x/net v0.0.0-20180522190444-9ef9f5bb98a1
    golang.org/x/sys v0.0.0-20180524135853-04b83988a018
    golang.org/x/text v0.3.0
    gopkg.in/natefinch/lumberjack.v2 v2.0.0-20170531160350-a96e63847dc3
    gopkg.in/yaml.v2 v2.2.1
)

Note that the conversion took the dep from github.com/go-yaml/yaml to gopkg.in/yaml.v2. However, in my package the import is github.com/go-yaml/yaml. Because it didn't output an error message, I had not realized that vgo build and vgo install were actually failing at the point this message is printed out:

vgo: downloaded "github.com/go-yaml/yaml" and got module "gopkg.in/yaml.v2"

So vgo vendor wasn't just failing, but vgo build was failing as well. Since I always do a vgo install and a previous version of the binary was already in GOBIN, I thought the build was succeeding when it was failing. If I change the import in the go package to gopkg.in/yaml.v2, then vgo mod -vendor and vgo build start working again.

jaloren commented 6 years ago

@rsc updated the title to more accurately describe the problem. I don't know if this ticket is the appropriate place, but some UX feedback here would be that if vgo operation fails it would be really helpful if vgo printed a message like "ERROR - operation X failed because of Y" to stderr.

rsc commented 6 years ago

@jaloren, thanks that's very helpful. One thing I need to do before the release is make the commands far less chatty, so that real errors aren't lost in the noise. If you still have a copy of the full output hiding the error, can you post it? I'll make sure to take care of the non-error prints in the transcript. Thanks.

jaloren commented 6 years ago

@rsc here's the output. The last line is the error.

vgo build bb.dev.norvax.net/dep/operator/locksmith 
vgo: copying requirements from /Users/jlorenzini/repos/operator/Gopkg.lock
vgo: finding github.com/apparentlymart/go-textseg v0.0.0-20170531203952-b836f5c4d331
vgo: finding github.com/beorn7/perks v0.0.0-20180321164747-3a771d992973
vgo: finding github.com/docker/libtrust v0.0.0-20160708172513-aabc10ec26b7
vgo: finding github.com/coreos/go-systemd v0.0.0-20180202092358-40e2722dffea
vgo: finding github.com/docker/engine-api v0.4.0
vgo: finding github.com/docker/docker v1.12.6
vgo: finding github.com/blang/semver v0.0.0-20170727064818-2ee87856327b
vgo: finding github.com/mitchellh/cli v0.0.0-20180414170447-c48282d14eba
vgo: finding github.com/pkg/errors v0.8.0
vgo: finding github.com/apparentlymart/go-cidr v0.0.0-20170616213631-2bd8b58cf427
vgo: finding github.com/mitchellh/go-testing-interface v0.0.0-20171004221916-a61a99592b77
vgo: finding github.com/nwaples/rardecode v0.0.0-20171029023500-e06696f847ae
vgo: finding github.com/hashicorp/go-getter v0.0.0-20180425224130-3f60ec5cfbb2
vgo: finding github.com/armon/go-radix v0.0.0-20170727155443-1fca145dffbc
vgo: finding github.com/hashicorp/errwrap v0.0.0-20141028054710-7554cd9344ce
vgo: finding github.com/hashicorp/go-cleanhttp v0.0.0-20171218145408-d5fe4b57a186
vgo: finding github.com/spf13/cobra v0.0.3
vgo: finding github.com/opencontainers/go-digest v1.0.0-rc1
vgo: finding github.com/bgentry/speakeasy v0.1.0
vgo: finding github.com/mitchellh/reflectwalk v0.0.0-20170726202117-63d60e9d0dbc
vgo: finding github.com/golang/snappy v0.0.0-20180518054509-2e65f85255db
vgo: finding github.com/hashicorp/hcl v0.0.0-20180404174102-ef8a98b0bbce
vgo: finding golang.org/x/sys v0.0.0-20180524135853-04b83988a018
vgo: finding github.com/f5devcentral/go-bigip v0.0.0-20180523221152-f965982c0fc1
vgo: finding github.com/aws/aws-sdk-go v1.13.54
vgo: finding github.com/hashicorp/hil v0.0.0-20170627220502-fa9f258a9250
vgo: finding github.com/hashicorp/hcl2 v0.0.0-20180523235629-81d22773002d
vgo: finding github.com/pierrec/lz4 v0.0.0-20171218195038-2fcda4cb7018
vgo: finding github.com/hashicorp/vault v0.9.1
vgo: finding github.com/sergi/go-diff v1.0.0
vgo: finding github.com/sirupsen/logrus v1.0.5
vgo: finding github.com/cenkalti/backoff v0.0.0-20171224164212-2ea60e5f0944
vgo: finding github.com/heroku/docker-registry-client v0.0.0-20171019183014-fd2fe8034968
vgo: finding github.com/mitchellh/hashstructure v0.0.0-20170609045927-2bca23e0e452
vgo: finding github.com/mitchellh/copystructure v0.0.0-20170525013902-d23ffcb85de3
vgo: finding github.com/mitchellh/go-homedir v0.0.0-20180523094522-3864e76763d9
vgo: finding github.com/inconshreveable/mousetrap v0.0.0-20141017200713-76626ae9c91c
vgo: finding github.com/jmespath/go-jmespath v0.0.0-20160202185014-0b12d6b521d8
vgo: finding github.com/mholt/archiver v0.0.0-20180417220235-e4ef56d48eb0
vgo: finding golang.org/x/crypto v0.0.0-20180524125353-159ae71589f3
vgo: finding github.com/fsouza/go-dockerclient v0.0.0-20160427172547-1d4f4ae73768
vgo: finding github.com/hashicorp/go-multierror v0.0.0-20171204182908-b7773ae21874
vgo: finding github.com/fatih/color v1.7.0
vgo: finding github.com/hashicorp/serf v0.8.1
vgo: finding github.com/go-ini/ini v1.36.0
vgo: finding github.com/mattn/go-colorable v0.0.9
vgo: finding github.com/hashicorp/consul v1.1.0
vgo: finding github.com/hashicorp/go-rootcerts v0.0.0-20160503143440-6bb64b370b90
vgo: finding github.com/hashicorp/go-uuid v0.0.0-20180228145832-27454136f036
vgo: finding github.com/stretchr/testify v1.2.1
vgo: finding golang.org/x/net v0.0.0-20180522190444-9ef9f5bb98a1
vgo: finding github.com/fatih/structs v0.0.0-20170103081050-a720dfa8df58
vgo: finding github.com/matttproud/golang_protobuf_extensions v1.0.0
vgo: finding github.com/sethgrid/pester v0.0.0-20180430140037-03e26c9abbbf
vgo: finding github.com/go-yaml/yaml v0.0.0-20180328195020-5420a8b6744d
vgo: finding github.com/hashicorp/go-safetemp v0.0.0-20180326211150-b1a1dbde6fdc
vgo: finding github.com/dsnet/compress v0.0.0-20171208185109-cc9eb1d7ad76
vgo: finding github.com/ulikunitz/xz v0.5.4
vgo: finding github.com/prometheus/common v0.0.0-20180518154759-7600349dcfe1
vgo: finding github.com/pmezard/go-difflib v1.0.0
vgo: finding golang.org/x/text v0.3.0
vgo: finding github.com/mattn/go-isatty v0.0.3
vgo: finding github.com/davecgh/go-spew v1.1.0
vgo: finding github.com/zclconf/go-cty v0.0.0-20180524003106-ba988ce11d99
vgo: finding github.com/prometheus/client_golang v0.8.0
vgo: finding github.com/spf13/pflag v1.0.1
vgo: finding github.com/hashicorp/terraform v0.11.7
vgo: finding github.com/prometheus/procfs v0.0.0-20180408092902-8b1c2da0d56d
vgo: finding github.com/posener/complete v1.1.1
vgo: finding github.com/prometheus/client_model v0.0.0-20171117100541-99fa1f4be8e5
vgo: finding github.com/golang/protobuf v1.1.0
vgo: finding github.com/opencontainers/runc v0.1.1
vgo: finding github.com/docker/distribution v0.0.0-20180522175653-f0cc92778478
vgo: finding github.com/mitchellh/go-wordwrap v0.0.0-20150314170334-ad45545899c7
vgo: finding github.com/agext/levenshtein v1.2.1
vgo: finding github.com/hashicorp/go-version v0.0.0-20180322230233-23480c066577
vgo: finding github.com/mitchellh/mapstructure v0.0.0-20180511142126-bb74f1db0675
vgo: finding github.com/pierrec/xxHash v0.1.1
vgo: finding github.com/bgentry/go-netrc v0.0.0-20140422174119-9fd32a8b3d3d
vgo: finding gopkg.in/yaml.v2 v2.2.1
vgo: finding gopkg.in/natefinch/lumberjack.v2 v2.0.0-20170531160350-a96e63847dc3
vgo: downloaded "github.com/go-yaml/yaml" and got module "gopkg.in/yaml.v2"

rsc commented 6 years ago

I can see how that didn't look like an error! Thanks.

gopherbot commented 5 years ago

Change https://golang.org/cl/172598 mentions this issue: cmd/go/internal/modfetch: remove noisy logging

mvdan commented 5 years ago

Perhaps relatedly, I wish I could use -v without seeing all the module download logs, because I'm mainly interested in the verbose build output. This was possible before, by doing go get -d ... and then go install -v .... I can still do that sometimes, but not always; for example, imagine a global install with @latest.

bcmills commented 5 years ago

My tentative plan for this for 1.14 is as follows.

Print:

A finding line per unresolved package path.
A downloading line for each module whose source code (zipfile) is newly downloaded to the module cache.
An added line for each module path that has been newly added to the build graph (#33284).
An updated line for each module path for which the MVS-selected version has changed (#33284).
An error message for each module whose version or go.mod file was required but could not be located.

Do not print:

Any line for a module whose go.mod file is fetched from a proxy without error.
Any line for a module that was already present in both the build list and the module cache.
More than one finding line in the course of successfully locating a module.

bcmills commented 4 years ago

A finding line per unresolved package path.

This turns out to be really redundant with the added line. Consolidating to a single found $pkg in $module $version line seems clearer.

gopherbot commented 4 years ago

Change https://golang.org/cl/204777 mentions this issue: cmd/go: adjust module-related logging

gopherbot commented 4 years ago

Change https://golang.org/cl/213679 mentions this issue: cmd/go: make "finding" logging deterministic

gopherbot commented 4 years ago

Change https://golang.org/cl/219437 mentions this issue: cmd/go: print a "found" line for each package found instead of each module added

golang / go