Athens: HTTP 500 when getting info on orphaned commit (?)

Created on 9 Nov 2018 · 14Comments · Source: gomods/athens

Thanks for creating this proxy, we use it here at Sourcegraph!

Our builds started failing with an error message like this:

go: honnef.co/go/[email protected]: unexpected status (http://athens-athens-proxy/honnef.co/go/tools/@v/v0.0.0-20180910201051-f1b53a58b022.info): 500 Internal Server Error

I can confirm that this commit does exist on GitHub (https://github.com/dominikh/go-tools/commit/f1b53a58b022) but it appears to no longer be on a branch (I suspect that it was in the past though and some history got force pushed).

I can confirm that Athens 500s when I hit it directly

# wget http://athens-athens-proxy/honnef.co/go/tools/@v/v0.0.0-20180910201051-f1b53a58b022.info
--2018-11-09 06:37:18--  http://athens-athens-proxy/honnef.co/go/tools/@v/v0.0.0-20180910201051-f1b53a58b022.info
Resolving athens-athens-proxy (athens-athens-proxy)... 10.3.254.50
Connecting to athens-athens-proxy (athens-athens-proxy)|10.3.254.50|:80... connected.
HTTP request sent, awaiting response... 500 Internal Server Error
2018-11-09 06:37:19 ERROR 500: Internal Server Error.

I found the "same" commit with a different hash on the next branch (https://github.com/dominikh/go-tools/commit/6b04966a29ff3758eb1f9d92aa1b31205263589d) and Athen's seems to be able to fetch that fine:

# wget http://athens-athens-proxy/honnef.co/go/tools/@v/v0.0.0-20180910201051-6b04966a29ff3758eb1f9d92aa1b31205263589d.info
--2018-11-09 06:37:45--  http://athens-athens-proxy/honnef.co/go/tools/@v/v0.0.0-20180910201051-6b04966a29ff3758eb1f9d92aa1b31205263589d.info
Resolving athens-athens-proxy (athens-athens-proxy)... 10.3.254.50
Connecting to athens-athens-proxy (athens-athens-proxy)|10.3.254.50|:80... connected.
HTTP request sent, awaiting response... 200 OK
Length: 106 [text/plain]
Saving to: 'v0.0.0-20180910201051-6b04966a29ff3758eb1f9d92aa1b31205263589d.info'

v0.0.0-20180910201051-6b04966a29ff3758eb1f9d 100%[============================================================================================>]     106  --.-KB/s    in 0s

2018-11-09 06:37:47 (18.0 MB/s) - 'v0.0.0-20180910201051-6b04966a29ff3758eb1f9d92aa1b31205263589d.info' saved [106/106]

I don't think Athens should 500 in this case.

bug

Source

nicksnyder

Most helpful comment

My assumption is that the pod restarted and our ephemeral storage was cleared, which surfaced the issue, but I don't know for sure.

If you are interested in attempting to reproduce (to verify Athens behavior), then all you need to do is create a toy go dependency, load it into the proxy, force push over that commit you are depending on, and then see if Athens behaves correctly (using the cached one).

nicksnyder on 17 Nov 2018

👍3

All 14 comments

Hey @nicksnyder thanks for raising an issue. Sourcegraph is awesome!

We'll look into it 👍

chriscoffee on 9 Nov 2018

@nicksnyder What kind of storge are you using with athens? Could you check if honnef.co/go/tools/@v/v0.0.0-20180910201051-f1b53a58b022(.info/.mod/.zip) files are stored there?

marpio on 15 Nov 2018

We use ephemeral disk storage. It has been cleared away and we no longer attempt to fetch that version via athens. The directory and files are not present.

So I just manually fetched the info URL described above, and the file was still not present:

# wget http://localhost:3000/honnef.co/go/tools/@v/v0.0.0-20180910201051-f1b53a58b022.info
--2018-11-15 10:05:54--  http://localhost:3000/honnef.co/go/tools/@v/v0.0.0-20180910201051-f1b53a58b022.info
Resolving localhost (localhost)... ::1, 127.0.0.1
Connecting to localhost (localhost)|::1|:3000... connected.
HTTP request sent, awaiting response... 500 Internal Server Error
2018-11-15 10:05:55 ERROR 500: Internal Server Error.

# find /var/lib/athens/honnef.co -type f
/var/lib/athens/honnef.co/go/tools/v0.0.0-20180920030910-6b04966a29ff/v0.0.0-20180920030910-6b04966a29ff.info
/var/lib/athens/honnef.co/go/tools/v0.0.0-20180920030910-6b04966a29ff/source.zip
/var/lib/athens/honnef.co/go/tools/v0.0.0-20180920030910-6b04966a29ff/go.mod
/var/lib/athens/honnef.co/go/tools/v0.0.0-20181108184350-ae8f1f9103cc/source.zip
/var/lib/athens/honnef.co/go/tools/v0.0.0-20181108184350-ae8f1f9103cc/v0.0.0-20181108184350-ae8f1f9103cc.info
/var/lib/athens/honnef.co/go/tools/v0.0.0-20181108184350-ae8f1f9103cc/go.mod
/var/lib/athens/honnef.co/go/tools/v0.0.0-20180728063816-88497007e858/v0.0.0-20180728063816-88497007e858.info
/var/lib/athens/honnef.co/go/tools/v0.0.0-20180728063816-88497007e858/source.zip
/var/lib/athens/honnef.co/go/tools/v0.0.0-20180728063816-88497007e858/go.mod
/var/lib/athens/honnef.co/go/tools/v0.0.0-20180920025451-e3ad64cb4ed3/source.zip
/var/lib/athens/honnef.co/go/tools/v0.0.0-20180920025451-e3ad64cb4ed3/go.mod
/var/lib/athens/honnef.co/go/tools/v0.0.0-20180920025451-e3ad64cb4ed3/v0.0.0-20180920025451-e3ad64cb4ed3.info

Here is the relevant line from the athens log:

time="2018-11-15T10:05:55Z" level=error msg="v0.0.0-20180910201051-f1b53a58b022.mod not found in /tmp/athens739178965/pkg/mod/cache/download/honnef.co/go/tools/@v" http-method=GET http-path=/honnef.co/go/tools/@v/v0.0.0-20180910201051-f1b53a58b022.info http-url=/honnef.co/go/tools/@v/v0.0.0-20180910201051-f1b53a58b022.info kind="Internal Server Error" module=honnef.co/go/tools operation=download.versionInfoHandler ops="[download.versionInfoHandler protocol.Info protocol.fillCache goget.Version goGetFetcher.Fetch module.getSources module.checkFiles]" version=v0.0.0-20180910201051-f1b53a58b022
handler: GET /honnef.co/go/tools/@v/v0.0.0-20180910201051-f1b53a58b022.info [500]

keegancsmith on 15 Nov 2018

Just upgraded to v0.2.0 and same problem. Here is the log message now

time="2018-11-15T10:49:37Z" level=error msg="unknown revision f1b53a58b022" http-method=GET http-path=/honnef.co/go/tools/@v/v0.0.0-20180910201051-f1b53a58b022.info http-url=/honnef.co/go/tools/@v/v0.0.0-20180910201051-f1b53a58b022.info kind="Internal Server Error" module=honnef.co/go/tools operation=download.VersionInfoHandler ops="[download.VersionInfoHandler pool.Info protocol.Info stash.Pool stasher.Stash stasher.fetchModule goGetFetcher.Fetch module.downloadModule]" version=v0.0.0-20180910201051-f1b53a58b022

keegancsmith on 15 Nov 2018

@keegancsmith Could you try go get this version without the proxy? Does it work then?

marpio on 15 Nov 2018

Yes it works, but it might be locally cached. So I sudo rm -rf $GOPATH/pkg $(go env GOCACHE) in case there is an old clone of the repo which works. It then failed:

go: honnef.co/go/[email protected]: unknown revision f1b53a58b022

I think this issue is more about the proxy returning a 500 responses, when maybe a 404 response would be more appropriate?

keegancsmith on 15 Nov 2018

👍 for some 4xx status. The problem is, go doesn't return error codes so we have to parse text unfortunately.
Ref: #916

marpio on 15 Nov 2018

Can you confirm that Athens doesn’t even attempt to fetch from the network if it finds a matching entry on the disk cache? I want to rule out the possibility that we started seeing the 500 before our ephemeral storage was cleared (e.g. by a pod restart)

nicksnyder on 15 Nov 2018

yes the logic is that once module is not stored it is fetched, stored and then served from store

michalpristas on 15 Nov 2018

@nicksnyder it would be awesome if you could confirm that the storage has been cleared before your build started to fail. If that wasn't the case we have to investigate this.

marpio on 17 Nov 2018

My assumption is that the pod restarted and our ephemeral storage was cleared, which surfaced the issue, but I don't know for sure.

nicksnyder on 17 Nov 2018

👍3

I would like to reproduce this and see what can we do about this one.

manugupt1 on 23 Nov 2018

@manugupt1 i was thinking, we could create a e2e test that checks this (repo/commit removed) since it's one of the biggest advantages of using Athens. I will create an issue for that.

marpio on 23 Nov 2018

👍2

@nicksnyder Go only accepts 200 status from Athens (or any GOPROXY) so whether we return 500 or 4xx, the build fails anyway and there's no programmable way to make Go act differently based on this (as of now). Go also does not show any response message coming from Athens back to the user who ran go build. So we can't really tell the user what went wrong. Go does show the status message so maybe we can give a very slight hint through the status code?

Furthermore, If the storage was not cleared, things should have worked fine. And would be great if you can double check that in your own world :)

I'm closing the issue for now, since there's no bug here but anyone feel free to continue discussing and reopen if there's something to be fixed here.

Thanks!