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

proxy.golang.org: slow to update with latest version information #42449

Closed
myitcv opened this issue Nov 8, 2020 · 9 comments
Closed

proxy.golang.org: slow to update with latest version information #42449

myitcv opened this issue Nov 8, 2020 · 9 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.

Comments

@myitcv
Copy link
Member

myitcv commented Nov 8, 2020

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

$ go version
go version devel +3ef8562c9c Thu Nov 5 02:48:05 2020 +0000 linux/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
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/myitcv/.cache/go-build"
GOENV="/home/myitcv/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/myitcv/gostuff/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/myitcv/gostuff"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/myitcv/gos"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/myitcv/gos/pkg/tool/linux_amd64"
GOVCS=""
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/tmp/tmp.GJhX78qxmg/go.mod"
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 -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build655069535=/tmp/go-build -gno-record-gcc-switches"

What did you do?

$ go version
go version devel +3ef8562c9c Thu Nov 5 02:48:05 2020 +0000 linux/amd64
$ mkdir /home/gopher/proverb
$ cd /home/gopher/proverb
$ git init -q
$ git remote add origin https://example.com/proverb.git
$ go mod init example.com/proverb
go: creating new go.mod: module example.com/proverb
$ cat <<EOD > /home/gopher/proverb/proverb.go
package proverb

// Go returns a Go proverb
func Go() string {
	return "Don't communicate by sharing memory, shard memory by communicating."
}

EOD
$ git add -A
$ git commit -q -m "Initial commit"
$ git push -q origin main
remote: . Processing 1 references        
remote: Processed 1 references in total        
$ git tag v0.1.0
$ git push -q origin v0.1.0
remote: . Processing 1 references        
remote: Processed 1 references in total        
$ mkdir /home/gopher/gopher
$ cd /home/gopher/gopher
$ go mod init gopher
go: creating new go.mod: module gopher
$ cat <<EOD > /home/gopher/gopher/gopher.go
package main

import (
	"fmt"

	"example.com/proverb"
)

func main() {
	fmt.Println(proverb.Go())
}

EOD
$ go get example.com/proverb@v0.1.0
go: downloading example.com/proverb v0.1.0
$ go run .
Don't communicate by sharing memory, shard memory by communicating.
$ cd /home/gopher/proverb
$ cat <<EOD > /home/gopher/proverb/proverb.go
package proverb

// Go returns a Go proverb
func Go() string {
	return "Concurrency is parallelism."
}

EOD
$ git add -A
$ git commit -q -m "Switch Go proverb to something more famous"
$ git push -q origin main
remote: . Processing 1 references        
remote: Processed 1 references in total        
$ git tag v0.2.0
$ git push -q origin v0.2.0
remote: . Processing 1 references        
remote: Processed 1 references in total        
$ cd /home/gopher/gopher
$ go get example.com/proverb@v0.2.0
go: downloading example.com/proverb v0.2.0
$ go list -m -versions example.com/proverb
example.com/proverb v0.1.0

What did you expect to see?

The call to go list -m -versions reflect the version we have just pulled through the proxy

What did you see instead?

Only the previous version. Indeed I need to wait "some time" before the call to go list "updates".

Discovered whilst trying out module retraction in tip (although I don't believe it is anything to do with module retraction)

The discontinuity between the fact that I can go get that version but can't go list it, makes for harder explanation to the user.

cc @katiehockman @heschik

@myitcv myitcv added NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. GoCommand cmd/go and removed GoCommand cmd/go labels Nov 8, 2020
@myitcv
Copy link
Member Author

myitcv commented Nov 8, 2020

The main issue I see arising from the aforementioned discontinuity is that despite the proxy being "aware" of a later version, if it doesn't report that latest version via the versions endpoint, then module retraction will appear not to work as expected, until the versions endpoint does update.

cc @jayconrod

@myitcv
Copy link
Member Author

myitcv commented Nov 8, 2020

Indeed this is most evident when a later version issues a retraction that includes that later version (the scenario here is when you want to retract an accidental v1.0.0). Pulling that version through the proxy via go get does not cause the go: warning: $mod@$version is retracted message to be printed. That message is only printed when the versions endpoint updates to include the latest version.

@hyangah
Copy link
Contributor

hyangah commented Nov 9, 2020

@myitcv how much is the delay ("some time") you observed?

@myitcv
Copy link
Member Author

myitcv commented Nov 9, 2020

I would say anywhere between 15-40 seconds. But as you can see from the following log, it takes some time for that to become a consistent answer, and in the intervening time the answer can "revert" to the previous state. And this is, I think, the behaviour I have observed in #42451.

The scenario leading up to the following log is that v0.1.0, v0.2.0 and v0.3.0 have been published (v0.3.0 retracts v0.2.0 if that is important). The proxy knows about all three versions because I've pulled them through with go get.

The log below is the output from repeated calls to go list -x -m -retracted -versions gopher.live/ub8cdaaf9d101/proverb. Each request is followed by a 1 second delay. The requests stop once 10 consecutive requests return the target state, i.e. v0.1.0 v0.2.0 v0.3.0.

# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.108s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.108s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.105s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.114s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.120s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.164s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0 v0.2.0 v0.3.0
gopher.live/ub8cdaaf9d101/proverb v0.1.0 v0.2.0 v0.3.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.101s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.100s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.100s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.109s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.108s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.106s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.106s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.110s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0 v0.2.0 v0.3.0
gopher.live/ub8cdaaf9d101/proverb v0.1.0 v0.2.0 v0.3.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.099s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.116s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0 v0.2.0 v0.3.0
gopher.live/ub8cdaaf9d101/proverb v0.1.0 v0.2.0 v0.3.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.099s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.107s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.099s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0 v0.2.0 v0.3.0
gopher.live/ub8cdaaf9d101/proverb v0.1.0 v0.2.0 v0.3.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.096s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.100s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.106s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.106s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.117s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.104s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.111s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0 v0.2.0 v0.3.0
gopher.live/ub8cdaaf9d101/proverb v0.1.0 v0.2.0 v0.3.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.097s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.104s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.103s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.108s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.106s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.110s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.119s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.105s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.113s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0 v0.2.0 v0.3.0
gopher.live/ub8cdaaf9d101/proverb v0.1.0 v0.2.0 v0.3.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.114s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0 v0.2.0 v0.3.0
gopher.live/ub8cdaaf9d101/proverb v0.1.0 v0.2.0 v0.3.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.132s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0 v0.2.0 v0.3.0
gopher.live/ub8cdaaf9d101/proverb v0.1.0 v0.2.0 v0.3.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.108s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0 v0.2.0 v0.3.0
gopher.live/ub8cdaaf9d101/proverb v0.1.0 v0.2.0 v0.3.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.103s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0 v0.2.0 v0.3.0
gopher.live/ub8cdaaf9d101/proverb v0.1.0 v0.2.0 v0.3.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.107s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0 v0.2.0 v0.3.0
gopher.live/ub8cdaaf9d101/proverb v0.1.0 v0.2.0 v0.3.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.101s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0 v0.2.0 v0.3.0
gopher.live/ub8cdaaf9d101/proverb v0.1.0 v0.2.0 v0.3.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.113s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0 v0.2.0 v0.3.0
gopher.live/ub8cdaaf9d101/proverb v0.1.0 v0.2.0 v0.3.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.105s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0 v0.2.0 v0.3.0
gopher.live/ub8cdaaf9d101/proverb v0.1.0 v0.2.0 v0.3.0
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list
# get https://proxy.golang.org/gopher.live/ub8cdaaf9d101/proverb/@v/list: 200 OK (0.114s)
gopher.live/ub8cdaaf9d101/proverb v0.1.0 v0.2.0 v0.3.0
gopher.live/ub8cdaaf9d101/proverb v0.1.0 v0.2.0 v0.3.0

@hyangah
Copy link
Contributor

hyangah commented Nov 9, 2020

The list query response from proxy.golang.org uses ~1min TTL for HTTP caching purpose (+ a small delay to reflect the change in our distributed database). I thought this HTTP caching effect was discussed previously.

cc @katiehockman @heschik

@heschi
Copy link
Contributor

heschi commented Nov 9, 2020

From proxy.golang.org:

I committed a new change (or released a new version) to a repository, why isn't it showing up when I run go get -u or go list -m --versions?
In order to improve our services' caching and serving latencies, new versions may not show up right away. If you want new code to be immediately available in the mirror, then first make sure there is a semantically versioned tag for this revision in the underlying source repository. Then explicitly request that version via go get module@version. After one minute for caches to expire, the go command will see that tagged version. If this doesn't work for you, please file an issue.

@myitcv
Copy link
Member Author

myitcv commented Nov 9, 2020

Thanks for reconfirming.

I thought this HTTP caching effect was discussed previously.

Yes indeed it has been, and is clearly documented on the proxy.golang.org website.

The confusing aspect of this issue and #42451 (to me at least) has been the inconsistent results during that ~1 minute+ that follows a go get. I had (incorrectly) assumed that results after the first "updated" response would be consistent.

From a documentation perspective, should I therefore say "now wait 2 minutes for proxy.golang.org to update"?

@jayconrod
Copy link
Contributor

@heschik told me that cache coherency is not guaranteed. I think you're seeing different requests hitting different instances.

The go command itself caches those requests in memory, so you won't see inconsistent results within a single invocation.

@myitcv
Copy link
Member Author

myitcv commented Nov 9, 2020

Thanks everyone for your responses. I'm going to close this issue on the basis things are working as expected and documented. My confusion was indeed an incorrect expectation of cache coherency.

@myitcv myitcv closed this as completed Nov 9, 2020
@golang golang locked and limited conversation to collaborators Nov 9, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Development

No branches or pull requests

5 participants