GOSUMDB failing "410 Gone" for publicly-available tag

[bmhatfield]

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

go version go1.13 darwin/amd64

Does this issue reproduce with the latest release?

yes

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

go env Output

GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/bhatfield/Library/Caches/go-build"
GOENV="/Users/bhatfield/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/bhatfield/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/Cellar/go/1.13/libexec"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/Cellar/go/1.13/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD=""
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/w_/sj20ml6511v9vvzd4lzxhvlc0000gn/T/go-build931033925=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

In a private repository (which works fine with modules and 1.13), update a replace directive for a publicly-available fork:

diff --git a/go.mod b/go.mod
index ebfb0191..ae8706d6 100644
--- a/go.mod
+++ b/go.mod
@@ -80,4 +80,4 @@ require (
        gopkg.in/yaml.v2 v2.2.2
 )

-replace github.com/graph-gophers/graphql-go => github.com/digits/graphql-go v0.0.1
+replace github.com/graph-gophers/graphql-go => github.com/digits/graphql-go v0.0.2

What did you expect to see?

I expected go test ./... to succeed.

What did you see instead?

verifying github.com/digits/[email protected]/go.mod: github.com/digits/[email protected]/go.mod: reading https://sum.golang.org/lookup/github.com/digits/[email protected]: 410 Gone

However, running: export GOPRIVATE=github.com/digits/* allows this to succeed.

Confirmed that neither the proxy nor the sumdb are aware of this tag:

https://proxy.golang.org/github.com/digits/graphql-go/@v/v0.0.2.info

not found: unknown revision v0.0.2

https://sum.golang.org/lookup/github.com/digits/[email protected]

not found: unknown revision v0.0.2

The previous version works:

https://sum.golang.org/lookup/github.com/digits/[email protected]

244913
github.com/digits/graphql-go v0.0.1 h1:Xgu9jg7C95iTNBPQWwbH5d+4dJK2gxajAh6njHQrKLw=
github.com/digits/graphql-go v0.0.1/go.mod h1:uJhtPXrcJLqyi0H5IuMFh+fgW+8cMMakK3Txrbk/WJE=

go.sum database tree
247079
RC76d6sRqOwSsWp4dwujWYtHjPrkVdxOYACPkq3Z8As=

— sum.golang.org Az3grhOf345qDAkbBWZXMFGy4K0sxdkz+K6tTsBYKb8QbnZRNbnz66lwhGPX1c7BsnKM+nbH+En+L/oMvP7ezLKmuAw=

[FiloSottile]

Those URLs work for me now. Were you maybe hitting the cache that had not learned about the new version yet?

[toothrot]

@bmhatfield Interesting, I can't reproduce this.

$ curl https://proxy.golang.org/github.com/digits/graphql-go/@v/v0.0.2.info
{"Version":"v0.0.2","Time":"2019-09-18T14:52:33Z"}

It also appears in the sumdb for me.

/cc @katiehockman who should know more.

[bmhatfield]

Interesting. The proxy link still does not work for me, but the sum link now does. What is the delay on the proxy making a version available? It took me nearly an hour of troubleshooting and debugging to get to this point.

[heschi]

There are two levels of caching at work, and their expirations are not synchronized, so I think what happened is:

• Someone made a request for v0.0.2 before it existed. The nonexistance of that version was cached internally to proxy/sum.golang.org.
• v0.0.2 was tagged, but the cache of its nonexistance had not yet expired.
• As requests were made to various HTTP endpoints, HTTP caching kicked in, prolonging the problem.
• Eventually the HTTP cache expired, causing a new download attempt, and succeeded.

Without going into too much detail, because all of this is subject to change, the longest this could have lasted was an hour. So all of your links are working for me, and I think they'll probably work for you given the timeouts involved. Note that some of the caching is regional so it's not surprising that different people would see different results.

All of this is working as we expect, but there may be room for improvement, particularly in synchronizing the various cache expirations. I've only heard of one other example of this kind of problem, though.

For now, you might consider setting GONOPROXY on repositories that you control so that you don't accidentally fetch a tag that you're about to create.

Edit: the caches are now synchronized, see below.

[bmhatfield]

@heschik your explanation makes sense to me. Both links are now working.

For a little more detail, what happened here was I originally forgot the v in the tag name and pushed 0.0.2. After I got an error trying to build, I pushed the correct tag v0.0.2, and then hit this issue. It didn't originally occur to me that (of course) I had initiated one request for a non-existent tag.

One suggestion I have here is to dramatically reduce or eliminate the cache time on 4XX and 5XX responses from the upstream sources. While I understand there may be a need to cache 4XX errors to limit the number of requests making it upstream from proxy.golang.org, perhaps reducing that cache time would have avoided this confusion. I have had success with this strategy on very-highly used caches (500k+ RPS) in the past.

[heschi]

If failure responses were always due to user error, I think that would be good. Unfortunately package-to-module resolution is expected to yield errors. For example, go get golang.org/x/tools/cmd/goimports makes 5 proxy requests, all but one of which will fail. As of 1.13 those requests are made in parallel, but there's still a tradeoff to be made here. As we get more data we can re-evaluate that tradeoff, but so far cases like yours have been very rare.

I'm going to close this since I don't think there's anything to do right now, but if people have more trouble like this, please feel free to comment here or file a new issue referencing this one so that we can reconsider.

[MMulthaupt]

I am getting this problem with publicly tagged commits way older than 1 hour. (18 and 50 days)
Getting the problem with one of these in go.mod:
require github.com/shirou/gopsutil v2.19.8+incompatible (Released Sep 1)
require github.com/shirou/gopsutil v2.19.7+incompatible (Released Jul 31)
However, v2.19.6 does work:
require github.com/shirou/gopsutil v2.19.6+incompatible (Released Jun 27)
I'd like to request to reopen this issue.

EDIT: New issue as requested below: #34402

[FiloSottile]

@MMulthaupt Please open a new issue, it's likely to have a different cause, and we don't track closed issues. (I suggest you try without +incompatible, in case v2.19.7 added a go.mod and became compatible with modules.)

[katiehockman]

As an update, we've fixed some of the synchronization of our caching and expirations, so now the longest that this kind of problem could occur would be 30 minutes, rather than an hour.

We still strongly suggest that you Tag first, Fetch second. Then there should be no delay at all.

[mholt]

How do we reset the cache then? I have a public tag that can't be accessed that is blocking a new release: #36183

FWIW, my tag was created first and then the command was run thereafter.