cmd/go: go get of nested module picks version from outer module

[twmb]

What is the URL of the page with the issue?

https://pkg.go.dev/github.com/twmb/franz-go/pkg/kadm@v1.6.0

Screenshot

What did you do?

I have a repo, github.com/twmb/franz-go with a module at the top-level repo root and other modules at subdirectories. Whenever I release the repo root (push a tag), I can go get -u the new version of the project within seconds. When I release a sub-module, it takes more time -- and if I release the main module quickly followed by a submodule, it takes tens of minutes (I'm not sure when / if the cache will purge).

Repo structure:

github.com/twmb/franz-go/go.mod
github.com/twmb/franz-go/pkg/kadm/go.mod
...

I've managed tags like this for over a year now, and the wait for submodules has never been this long.

What did you expect to see?

go get github.com/twmb/franz-go/pkg/kadm@v1.6.0 to not fail for 30 minutes.

What did you see instead?

$ go get -u github.com/twmb/franz-go/pkg/kadm@v1.6.0
go: module github.com/twmb/franz-go@v1.6.0 found, but does not contain package github.com/twmb/franz-go/pkg/kadm

for 30 minutes

[seankhliao]

What does "quickly followed" mean?
I see your root module depends on the nested module.
Is that pushed with the new requirement and built/go get'd before you push the nested module's updated tag?

[twmb]

Yes, the nested module was pushed immediately before. The screenshot above is a small indication of the timing -- I pushed franz-go@v1.10.1, waited about 30s, and then in then in franz-go/pkg/kadm, go get github.com/twmb/franz-go@v1.10.1 to update kadm's deps. Three minutes after I pushed franz-go@v1.10.1, I tagged franz-go/pkg/kadm@v1.6.0.

I just tried again and was still unable to go get ...kadm@v1.6.0 after 9 hours. However, after a few repeated commands, something seemed to have fixed it:

[07:42:58]
@m4x3r:~/testing
$ go get -u github.com/twmb/franz-go/pkg/kadm@v1.6.0
go: module github.com/twmb/franz-go@v1.6.0 found, but does not contain package github.com/twmb/franz-go/pkg/kadm

[07:43:09]
@m4x3r:~/testing
$ go get -u github.com/twmb/franz-go
go: downloading github.com/twmb/franz-go v1.10.1
go: added github.com/twmb/franz-go v1.10.1

[07:43:20]
@m4x3r:~/testing
$ go get -u github.com/twmb/franz-go/pkg/kadm@v1.6.0
go: module github.com/twmb/franz-go@v1.6.0 found, but does not contain package github.com/twmb/franz-go/pkg/kadm

[07:43:55]
@m4x3r:~/testing
$ go get -u github.com/twmb/franz-go/pkg/kadm@v1.6.1
go: github.com/twmb/franz-go/pkg/kadm@v1.6.1: invalid version: unknown revision pkg/kadm/v1.6.1

[07:44:00]
@m4x3r:~/testing
$ go get -u github.com/twmb/franz-go/pkg/kadm@v1.6.0
go: module github.com/twmb/franz-go@v1.6.0 found, but does not contain package github.com/twmb/franz-go/pkg/kadm

[07:44:02]
@m4x3r:~/testing
$ go get -u github.com/twmb/franz-go/pkg/kadm@v1.5.0
go: downloading github.com/twmb/franz-go v1.5.0
go: downloading github.com/twmb/franz-go/pkg/kadm v1.5.0
go: downloading golang.org/x/crypto v0.3.0
go: upgraded github.com/klauspost/compress v1.15.9 => v1.15.12
go: upgraded github.com/pierrec/lz4/v4 v4.1.15 => v4.1.17
go: added github.com/twmb/franz-go/pkg/kadm v1.5.0
go: upgraded golang.org/x/crypto v0.0.0-20220817201139-bc19a97f63c8 => v0.3.0

[07:44:19]
@m4x3r:~/testing
$ go get -u github.com/twmb/franz-go/pkg/kadm@v1.6.0
go: downloading github.com/twmb/franz-go/pkg/kadm v1.6.0
go: upgraded github.com/twmb/franz-go/pkg/kadm v1.5.0 => v1.6.0

Screenshot attached showing this was still problematic after 9 hours:

---

Since things are now "fixed" locally, I don't know what extra debugging I'll be able to do (until the next release...). Let me know if there's anything more I can look into / provide that can help.

[twmb]

Update: actually I was able to do one more bit of investigating. The same thing was happening on my other laptop. I was able to resolve this locally by running:

go clean -modcache

My completely uninformed guess is that if go detects everything located locally (pkg/kadm being a directory in franz-go), then it does not refresh the cache. Anything that triggers go get to reach out remotely refreshes the cache.

[seankhliao]

You could run go get with -x to see which requests it's making.

cc @bcmills @matloob

[bcmills]

Without the output from go env, it's hard to say what might have been going on — that really depends a lot on what settings you were using for GOPRIVATE, GOPROXY, etc.

With the default proxy settings, this may be a duplicate of #38065.

[twmb]

GO111MODULE=""
GOARCH="arm64"
GOBIN=""
GOCACHE="/Users/travisbischel/Library/Caches/go-build"
GOENV="/Users/travisbischel/Library/Application Support/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="arm64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/travisbischel/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/travisbischel/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_arm64"
GOVCS=""
GOVERSION="go1.19"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/dev/null"
GOWORK=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -Wl,--no-gc-sections -fmessage-length=0 -fdebug-prefix-map=/var/folders/vn/34y9tqdx6998z47x1dwbg_f40000gn/T/go-build2691703604=/tmp/go-build -gno-record-gcc-switches -fno-common"

(other laptop is Linux [Ubuntu] but has similar defaults)

[twmb]

I think it's slightly different -- I don't think go even reached out to the proxy. I think go looked at ~/go/mod, saw github.com/twmb/franz-go@v1.6.0, and didn't consider checking github.com/twmb/franz-go/pkg/kadm@v1.6.0.

[bcmills]

I don't think go even reached out to the proxy. I think go looked at ~/go/mod, saw github.com/twmb/franz-go@v1.6.0, and didn't consider checking github.com/twmb/franz-go/pkg/kadm@v1.6.0.

If this happens again, you could check that by adding the -x flag to the go command line to print the subcommands that are executed (including HTTP requests).

Barring that, I don't think we have enough information to investigate further.

[gopherbot]

Timed out in state WaitingForInfo. Closing.

(I am just a bot, though. Please speak up if this is a mistake or you have the requested information.)

[twmb]

This is happening on v1.20.5.

I released a new module, github.com/twmb/franz-go/pkg/kmsg@v1.6.0.

$ go get -x github.com/twmb/franz-go/pkg/kmsg@v1.6.0
go: module github.com/twmb/franz-go@v1.6.0 found, but does not contain package github.com/twmb/franz-go/pkg/kmsg

The Go command does not issue any http requests. I suspect it's because I have old franz-go versions in my mod cache:

@m4x3r:~/go/pkg/mod/github.com/twmb
$ ll | grep franz
drwxr-xr-x travisbischel staff 128B Fri Mar 24 11:57:20 2023 franz-go/
dr-xr-xr-x travisbischel staff 480B Fri Mar 24 11:57:20 2023 franz-go@v1.11.5/
dr-xr-xr-x travisbischel staff 480B Sat Mar 25 10:23:19 2023 franz-go@v1.12.0/
dr-xr-xr-x travisbischel staff 480B Thu Apr 13 15:06:39 2023 franz-go@v1.12.1/
dr-xr-xr-x travisbischel staff 512B Fri Mar 24 12:27:20 2023 franz-go@v1.13.0/
dr-xr-xr-x travisbischel staff 512B Fri Mar 24 12:27:05 2023 franz-go@v1.13.1/
dr-xr-xr-x travisbischel staff 512B Fri Apr 14 13:21:41 2023 franz-go@v1.13.2/
dr-xr-xr-x travisbischel staff 512B Tue May  9 12:35:53 2023 franz-go@v1.13.3/
dr-xr-xr-x travisbischel staff 512B Tue May 30 11:32:44 2023 franz-go@v1.13.4/
dr-xr-xr-x travisbischel staff 512B Fri Jun  2 11:47:55 2023 franz-go@v1.13.5/
dr-xr-xr-x travisbischel staff 512B Wed Jul  5 23:57:52 2023 franz-go@v1.13.6/
dr-xr-xr-x travisbischel staff 480B Mon Apr 10 11:26:22 2023 franz-go@v1.2.3/
dr-xr-xr-x travisbischel staff 512B Mon Apr  3 21:59:03 2023 franz-go@v1.6.0/
dr-xr-xr-x travisbischel staff 512B Wed Apr  5 10:58:13 2023 franz-go@v1.7.1-0.20220901194750-0ca6478600c6/

So go sees franz-go@v1.6.0 exists, but because kmsg is a separate module, the pkg is not in that top-level module:

@m4x3r:~/go/pkg/mod/github.com/twmb/franz-go@v1.6.0/pkg
$ ll
dr-xr-xr-x travisbischel staff 128B Mon Apr  3 21:59:03 2023 kbin/
dr-xr-xr-x travisbischel staff  96B Mon Apr  3 21:59:03 2023 kerr/
dr-xr-xr-x travisbischel staff 1.1K Mon Apr  3 21:59:03 2023 kgo/
dr-xr-xr-x travisbischel staff 128B Mon Apr  3 21:59:03 2023 kversion/
dr-xr-xr-x travisbischel staff 224B Mon Apr  3 21:59:03 2023 sasl/