cmd/go: GOCACHEPROG asks to overwrite existing output ID with open file

[klauspost]

Go version

go version go1.24rc1 windows/amd64

Output of go env in your module/workspace:

set AR=ar
set CC=gcc
set CGO_CFLAGS=-O2 -g
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-O2 -g
set CGO_ENABLED=1
set CGO_FFLAGS=-O2 -g
set CGO_LDFLAGS=-O2 -g
set CXX=g++
set GCCGO=gccgo
set GO111MODULE=
set GOAMD64=v1
set GOARCH=amd64
set GOAUTH=netrc
set GOBIN=
set GOCACHE=e:\temp\gocache
set GODEBUG=
set GOENV=C:\Users\klaus\AppData\Roaming\go\env
set GOEXE=.exe
set GOEXPERIMENT=
set GOFIPS140=off
set GOFLAGS=
set GOGCCFLAGS=-m64 -mthreads -Wl,--no-gc-sections -fmessage-length=0 -ffile-prefix-map=e:\temp\wintemp\go-build3327516323=/tmp/go-build -gno-record-gcc-switches
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOINSECURE=
set GOMOD=e:\gopath\src\github.com\minio\minio\go.mod
set GOMODCACHE=e:\gopath\pkg\mod
set GONOPROXY=
set GONOSUMDB=
set GOOS=windows
set GOPATH=e:\gopath
set GOPRIVATE=
set GOPROXY=https://goproxy.io,https://proxy.golang.org,direct
set GOROOT=C:\go
set GOSUMDB=sum.golang.org
set GOTELEMETRY=local
set GOTELEMETRYDIR=C:\Users\klaus\AppData\Roaming\go\telemetry
set GOTMPDIR=
set GOTOOLCHAIN=auto
set GOTOOLDIR=C:\go\pkg\tool\windows_amd64
set GOVCS=
set GOVERSION=go1.24rc1
set GOWORK=
set PKG_CONFIG=pkg-config

Also set GOCACHEPROG=go-cacher --verbose (seems to be missing from go.env)

What did you do?

λ go build -v . with above cache enabled.

What did you see happen?

It seems like the go builder keeps the output file open in some cases while asking the cache to update it... This is a problem on Windows, since it is unable to write to an open file.

Request 1, asks for an output id {"ID":1,"Command":"get","ActionID":"pBAlwHUzJSDNnEKHSTg/axJSDSKXGl8g+SZj8jK6m58="}

We respond with the output id: {"ID":1,"OutputID":"/Rw93YonOb5fieSCtjYgTXP1E/KTrUN78aVuoX9f++A=","Size":283,"Time":"2024-12-29T15:19:59.2800213+01:00","DiskPath":"C:\\Users\\klaus\\AppData\\Local\\go-cacher\\o-fd1c3ddd8a2739be5f89e482b636204d73f513f293ad437bf1a56ea17f5ffbe0"}

go file then opens this file (grabbed through process monitor)

16.13.53,1788842	go.exe	8448	CreateFile	C:\Users\klaus\AppData\Local\go-cacher\o-fd1c3ddd8a2739be5f89e482b636204d73f513f293ad437bf1a56ea17f5ffbe0	SUCCESS	Desired Access: Generic Read, Disposition: Open, Options: Synchronous IO Non-Alert, Attributes: R, ShareMode: Read, Write, AllocationSize: n/a, OpenResult: Opened
16.13.53,1789196	go.exe	8448	QueryInformationVolume	C:\Users\klaus\AppData\Local\go-cacher\o-fd1c3ddd8a2739be5f89e482b636204d73f513f293ad437bf1a56ea17f5ffbe0	SUCCESS	VolumeCreationTime: 19/07/2019 03.28.03, VolumeSerialNumber: 1897-A658, SupportsObjects: True, VolumeLabel: 
16.13.53,1789285	go.exe	8448	QueryAllInformationFile	C:\Users\klaus\AppData\Local\go-cacher\o-fd1c3ddd8a2739be5f89e482b636204d73f513f293ad437bf1a56ea17f5ffbe0	BUFFER OVERFLOW	CreationTime: 29/12/2024 14.59.58, LastAccessTime: 29/12/2024 16.12.12, LastWriteTime: 29/12/2024 15.19.59, ChangeTime: 29/12/2024 15.19.59, FileAttributes: A, AllocationSize: 288, EndOfFile: 283, NumberOfLinks: 1, DeletePending: False, Directory: False, IndexNumber: 0x1f0000000c8656, EaSize: 0, Access: Generic Read, Position: 0, Mode: Synchronous IO Non-Alert, AlignmentRequirement: Long
16.13.53,1789446	go.exe	8448	CreateFileMapping	C:\Users\klaus\AppData\Local\go-cacher\o-fd1c3ddd8a2739be5f89e482b636204d73f513f293ad437bf1a56ea17f5ffbe0	FILE LOCKED WITH ONLY READERS	SyncType: SyncTypeCreateSection, PageProtection: |PAGE_NOCACHE
16.13.53,1789542	go.exe	8448	QueryStandardInformationFile	C:\Users\klaus\AppData\Local\go-cacher\o-fd1c3ddd8a2739be5f89e482b636204d73f513f293ad437bf1a56ea17f5ffbe0	SUCCESS	AllocationSize: 288, EndOfFile: 283, NumberOfLinks: 1, DeletePending: False, Directory: False
16.13.53,1789704	go.exe	8448	CreateFileMapping	C:\Users\klaus\AppData\Local\go-cacher\o-fd1c3ddd8a2739be5f89e482b636204d73f513f293ad437bf1a56ea17f5ffbe0	SUCCESS	SyncType: SyncTypeOther

It then sends a request to update the same output id:

{"ID":2,"Command":"put","ActionID":"pBAlwHUzJSDNnEKHSTg/axJSDSKXGl8g+SZj8jK6m58=","OutputID":"/Rw93YonOb5fieSCtjYgTXP1E/KTrUN78aVuoX9f++A=","BodySize":283}

With deterministic files, this fails since go.exe never closed the handle on the file:

16.13.53,1803634	go-cacher.exe	10208	SetRenameInformationFile	C:\Users\klaus\AppData\Local\go-cacher\o-fd1c3ddd8a2739be5f89e482b636204d73f513f293ad437bf1a56ea17f5ffbe0.2969869016	ACCESS DENIED	ReplaceIfExists: True, FileName: C:\Users\klaus\AppData\Local\go-cacher\o-fd1c3ddd8a2739be5f89e482b636204d73f513f293ad437bf1a56ea17f5ffbe0

We return an error:

{"ID":2,"Err":"rename C:\\Users\\klaus\\AppData\\Local\\go-cacher\\o-fd1c3ddd8a2739be5f89e482b636204d73f513f293ad437bf1a56ea17f5ffbe0.3796057084 C:\\Users\\klaus\\AppData\\Local\\go-cacher\\o-fd1c3ddd8a2739be5f89e482b636204d73f513f293ad437bf1a56ea17f5ffbe0: Access is denied."}

... and go.exe now closes the file:

16.13.53,1842822	go.exe	8448	CloseFile	C:\Users\klaus\AppData\Local\go-cacher\o-fd1c3ddd8a2739be5f89e482b636204d73f513f293ad437bf1a56ea17f5ffbe0	SUCCESS	

It seems to only happen on non-clean setup. Building from scratch doesn't trigger the issue.

What did you expect to see?

Go closes the file before it asks cache to update it.

[gabyhelp]

Related Issues

• cmd/go: GOCACHE=off doesn't work if the compiled binary is already there #25929 (closed)
• cmd/go: deadlock occurs if `GOCACHEPROG` program exits after receiving "close" command without sending response back #70848
• open C:\Users\YANGPA~1\AppData\Local\Temp\go-build213642030\b001\exe\a.out.exe: The process cannot access the file because it is being used by another process. #46919 (closed)
• cmd/go: go build error. open C:\Users...\a.out.exe: The process cannot access the file because it is being used by another process. #29093 (closed)
• cmd/go 'go mod download <package name>' fetches all modules if module cache is empty/missing #40245 (closed)
• cmd/go: GOOS=js GOARCH=wasm go build -o [non-empty parent dir] ./... fails on Windows host #37472 (closed)
• cmd/go: test reported as cached, but not actually cached #41593
• cmd/go: go build -mod=readonly still updates a go.work.sum file #70272 (closed)
• cmd/go: go build fails with permission error inside a temporary directory on Windows #42224 (closed)

Related Discussions

• 'go build' over writing source code.

_{(Emoji vote if this was helpful or unhelpful; more detailed feedback welcome in this discussion.)}

[klauspost]

It seems like cache.GetMmap doesn't return the file handle, so it is effectively leaked, AFAICT.

Furthermore, it seems like mmap.Mmap leaks the file handle if an error occurs. It is calling mmapFile, which doesn't close the file, so the file remains open. The handle isn't returned on any error path, so callers cannot do the cleanup either.

[klauspost]

FWIW replacing both cache.GetMmap with cache.GetBytes seems to fix it. So if you are looking at a quick fix disabling mmap on Windows seems to be it.

[dmitshur]

Thanks for the report. Marking as a release blocker since this feature is new(ly promoted out of experimental phase) in Go 1.24, so this needs to be understood and either fixed or explicitly decided to handle it another way.

CC @bradfitz, @matloob, @samthanawalla.

[matloob]

There seem to be a couple of problems here. The unfortunate part is that affects opening module index files on Windows, even when not using a GOCACHEPROG. We'd (pretty much) always fail to open the module index file using GetMmap, and then silently fail to write a new file.

We should not be trying to write a new file unless the error we get from GetMmap is a IsNotExist error. If there was a problem mmapping the file (or there was another problem but the file exists on disk), we should just give up then.

But the bigger problem, and why things were broken on Windows is the check in GetMmap that the size of the slice returned by mmap is the same as the expected size of the file. Currently on Windows, the size that the Mmap function that GetMmap uses is actually the size of the mapping, which seems to be a multiple of the page size. If I understand this correctly, I think the solution here is to change the Mmap function we use to re-slice the slice we use for the mapping on Windowsto the size of the file before we do the check. Alternatively, we could avoid the size check when we return from the mmap function.

[gopherbot]

Change https://go.dev/cl/640155 mentions this issue: cmd/go/internal/mmap: truncate returned slice to file size on Windows

[klauspost]

I can confirm this also fixes the issue. Tried to see if modifying the on-disk content would bring it back in this state, but it just seems to break the build.

I personally think this takes it off the "release blocker" status, but seems like some hardening could be a good idea.

[matloob]

I agree. I'm trying to figure out where that should be done. We need to distinguish the error case where the file isn't cached (in which case we haven't opened the file) vs. the case where the file is the wrong size (in which case we have opened the file, and we won't be able to open it to write the replacement).

[gopherbot]

Change https://go.dev/cl/640577 mentions this issue: cmd/go/internal/modindex: don't write index entry if file open

[gopherbot]

Change https://go.dev/cl/640755 mentions this issue: cmd/go/internal/env: add GOCACHEPROG to go env output

[gopherbot]

Change https://go.dev/cl/641375 mentions this issue: cmd/go/testdata/script: fix TestScript/env_gocacheprog on Windows