go icon indicating copy to clipboard operation
go copied to clipboard
Published 1 month ago • verified publisher icon golang

os: RemoveAll failures with EPERM on OpenBSD

Open mknyszek opened this issue 4 years ago • 6 comments 

#!watchflakes
post <- goos == "openbsd" && `unlinkat .*: operation not permitted`

Saw a trybot failure in TestMemProfileCheck: https://storage.googleapis.com/go-build-log/f46e4835/openbsd-amd64-68_61f03b52.log

Maybe not a real issue, and since it seems like the problem is when invoking the system ld, I'm inclined to believe this isn't our problem.

CC @thanm

mknyszek avatar Nov 23 '21 15:11 mknyszek

I looked at the testpoint in question -- it's not using the system "ld" as far as I can tell. Looks more like the test built a small Go program, ran it, and the resulting binary crashed (or did an early exit) without emitting any output. Tried greplogs:

greplogs -E TestMemProfileCheck -dashboard Output
2021-10-07T18:09:53-4607ebc/plan9-arm:
--- FAIL: TestMemProfileCheck (0.01s)
    --- FAIL: TestMemProfileCheck/with_memprofile_runtime_pprof (7.36s)
        ld_test.go:336: exit status: 'go 46650: 2'
FAIL
FAIL	cmd/link/internal/ld

2021-09-08T22:41:27-47f3e1e/freebsd-amd64-race:
--- FAIL: TestMemProfileCheck (0.00s)
--- FAIL: TestMemProfileCheck/no_memprofile (8.26s)
ld_test.go:326: signal: segmentation fault (core dumped)
FAIL
FAIL	cmd/link/internal/ld


2021-09-05T23:10:46-7619a45/freebsd-386-12_2:
--- FAIL: TestMemProfileCheck (0.00s)
--- FAIL: TestMemProfileCheck/with_memprofile (2.25s)
ld_test.go:326: signal: segmentation fault (core dumped)
FAIL
FAIL	cmd/link/internal/ld


2021-06-14T22:42:48-7841cb1/freebsd-386-12_2:
--- FAIL: TestMemProfileCheck (0.00s)
--- FAIL: TestMemProfileCheck/with_memprofile_indirect (0.09s)
ld_test.go:324: exit status 2
FAIL
FAIL	cmd/link/internal/ld


2021-04-21T20:44:00-122fca4/plan9-arm:
--- FAIL: TestMemProfileCheck (0.02s)
--- FAIL: TestMemProfileCheck/no_memprofile (4.28s)
ld_test.go:318: exit status: 'go 41673: 2'
FAIL
FAIL	cmd/link/internal/ld

Looks like this may be another one of those "bad things happen on freebsd/openbsd" problems.

thanm avatar Nov 24 '21 16:11 thanm

Looks like this may be another one of those "bad things happen on freebsd/openbsd" problems.

It does indeed seem to be specific to openbsd/386 these days, but now we have output from the failing command:

--- FAIL: TestMemProfileCheck (0.00s)
    --- FAIL: TestMemProfileCheck/with_memprofile (1.15s)
        ld_test.go:340: got "524288\ngo: failed to remove work dir: unlinkat /tmp/workdir/tmp/go-build3492844359/b001: operation not permitted"; want "524288"
FAIL
FAIL	cmd/link/internal/ld	15.002s

greplogs --dashboard -md -l -e 'FAIL: TestMemProfileCheck ' --since=2021-11-25

2022-02-07T18:09:07-fa04846/openbsd-386-70 2022-01-13T23:35:37-e550c30/openbsd-386-70 2021-12-22T18:43:55-0f3becf/openbsd-386-68

bcmills avatar Feb 08 '22 20:02 bcmills

Just looking for the unlinkat … operation not permitted error string gives some additional failures.

greplogs --dashboard -md -l -E 'unlinkat .*: operation not permitted' --since=2021-01-01

2022-02-07T18:09:07-fa04846/openbsd-386-70 2022-01-13T23:35:37-e550c30/openbsd-386-70 2021-12-22T18:43:55-0f3becf/openbsd-386-68 2021-12-10T18:20:08-c473ca0/openbsd-386-70 2021-11-25T04:02:39-45bae64/openbsd-amd64-70-n1 2021-11-24T20:59:14-67dd9ee/openbsd-amd64-70-n1 2021-11-23T21:59:51-1ac45e0/openbsd-amd64-68 2021-11-10T18:24:14-6406e09/openbsd-386-68 2021-11-09T19:01:06-81f37a7/openbsd-386-68 2021-11-08T21:28:37-ccea0b2/openbsd-386-68 2021-11-04T21:52:36-8ad0a7e/openbsd-386-68

From the variety of failures — and the fact that some are on openbsd-amd64-n1, which was not believed to be affected by the memory-corruption bug — this looks like a bug in os.RemoveAll on OpenBSD.

bcmills avatar Feb 08 '22 20:02 bcmills

(CC @4a6f656c)

bcmills avatar Feb 08 '22 21:02 bcmills

greplogs -l -E 'unlinkat .*: operation not permitted' --since=2022-02-08 2022-09-01T03:24:42-49ab44d-86e9e0e/openbsd-amd64-70 2022-08-30T19:01:26-248c34b-3c6a5cd/openbsd-386-70

(attn @golang/openbsd)

bcmills avatar Sep 06 '22 20:09 bcmills

Found new matching dashboard test flakes for:

#!watchflakes
post <- goos == "openbsd" && `unlinkat .*: operation not permitted`
2022-08-29 18:21 openbsd-386-70 tools@248c34b8 go@3c6a5cdb x/tools/go/packages.TestNewPackagesInOverlay (log) 
--- FAIL: TestNewPackagesInOverlay (0.00s)
    --- FAIL: TestNewPackagesInOverlay/Modules (20.55s)
        --- FAIL: TestNewPackagesInOverlay/Modules/main_overlay (5.05s)
            invoke.go:230: 1.112629782s for GOROOT= GOPATH=/tmp/workdir/tmp/TestNewPackagesInOverlay_Modules2319073194/modcache GO111MODULE=on GOPROXY=file:///tmp/workdir/tmp/TestNewPackagesInOverlay_Modules2319073194/modproxy PWD=/tmp/workdir/tmp/TestNewPackagesInOverlay_Modules2319073194/fake go list -f "{{context.GOARCH}} {{context.Compiler}}" -- unsafe
            invoke.go:230: 1.498030519s for GOROOT= GOPATH=/tmp/workdir/tmp/TestNewPackagesInOverlay_Modules2319073194/modcache GO111MODULE=off GOPROXY=file:///tmp/workdir/tmp/TestNewPackagesInOverlay_Modules2319073194/modproxy PWD=/tmp/workdir/tmp/TestNewPackagesInOverlay_Modules2319073194/fake go list -e -f {{context.ReleaseTags}} -- unsafe
            invoke.go:230: 3.510514706s for GOROOT= GOPATH=/tmp/workdir/tmp/TestNewPackagesInOverlay_Modules2319073194/modcache GO111MODULE=on GOPROXY=file:///tmp/workdir/tmp/TestNewPackagesInOverlay_Modules2319073194/modproxy PWD=/tmp/workdir/tmp/TestNewPackagesInOverlay_Modules2319073194/fake go list -overlay=/tmp/workdir/tmp/gopackages-3466373920/overlay.json -e -json=Name,ImportPath,Error,Dir,GoFiles,IgnoredGoFiles,IgnoredOtherFiles,CFiles,CgoFiles,CXXFiles,MFiles,HFiles,FFiles,SFiles,SwigFiles,SwigCXXFiles,SysoFiles,TestGoFiles,XTestGoFiles,CompiledGoFiles,Export,DepOnly,Imports,ImportMap,TestImports,XTestImports -compiled=true -test=true -export=false -deps=true -find=false -- /tmp/workdir/tmp/TestNewPackagesInOverlay_Modules2319073194/fake/e
            overlay_test.go:452: err: exit status 1: stderr: go: unlinkat /tmp/workdir/tmp/go-build3458287667: operation not permitted
2022-09-01 03:24 openbsd-amd64-70 tools@49ab44de go@86e9e0ea x/tools/gopls/internal/regtest/watch.TestCreateDependency (log) 
goroutine profile: total 3
1 @ 0x430fd6 0x466325 0x5bf855 0x5bf66d 0x5bc5cb 0xce157d 0xce11e7 0x51cbeb 0x46cb41
#	0x466324	runtime/pprof.runtime_goroutineProfileWithLabels+0x24			/tmp/workdir/go/src/runtime/mprof.go:846
#	0x5bf854	runtime/pprof.writeRuntimeProfile+0xb4					/tmp/workdir/go/src/runtime/pprof/pprof.go:723
#	0x5bf66c	runtime/pprof.writeGoroutine+0x4c					/tmp/workdir/go/src/runtime/pprof/pprof.go:683
#	0x5bc5ca	runtime/pprof.(*Profile).WriteTo+0x14a					/tmp/workdir/go/src/runtime/pprof/pprof.go:330
#	0xce157c	golang.org/x/tools/internal/lsp/regtest.(*Runner).Run.func1.1+0x7c	/tmp/workdir/gopath/src/golang.org/x/tools/internal/lsp/regtest/runner.go:308
#	0xce11e6	golang.org/x/tools/internal/lsp/regtest.(*Runner).Run.func1+0xca6	/tmp/workdir/gopath/src/golang.org/x/tools/internal/lsp/regtest/runner.go:355
#	0x51cbea	testing.tRunner+0x10a							/tmp/workdir/go/src/testing/testing.go:1446

...
1 @ 0x43b336 0x40853b 0x408038 0x51d9da 0xce0445 0xce5b65 0xce5b35 0x51cbeb 0x46cb41
#	0x51d9d9	testing.(*T).Run+0x379								/tmp/workdir/go/src/testing/testing.go:1494
#	0xce0444	golang.org/x/tools/internal/lsp/regtest.(*Runner).Run+0x3e4			/tmp/workdir/gopath/src/golang.org/x/tools/internal/lsp/regtest/runner.go:268
#	0xce5b64	golang.org/x/tools/internal/lsp/regtest.Run+0x44				/tmp/workdir/gopath/src/golang.org/x/tools/internal/lsp/regtest/regtest.go:54
#	0xce5b34	golang.org/x/tools/gopls/internal/regtest/watch.TestCreateDependency+0x14	/tmp/workdir/gopath/src/golang.org/x/tools/gopls/internal/regtest/watch/watch_test.go:201
#	0x51cbea	testing.tRunner+0x10a								/tmp/workdir/go/src/testing/testing.go:1446

--- FAIL: TestCreateDependency (2.09s)
    --- FAIL: TestCreateDependency/default (2.09s)
        runner.go:309: closing the sandbox: error(s) cleaning sandbox: cleaning modcache: <nil>; removing files: unlinkat /tmp/workdir/tmp/gopls-regtest-2881688214/TestCreateDependency/default/work/b: operation not permitted

— watchflakes

gopherbot avatar Sep 20 '22 19:09 gopherbot

Found new dashboard test flakes for:

#!watchflakes
post <- goos == "openbsd" && `unlinkat .*: operation not permitted`
2023-06-16 16:38 openbsd-amd64-72 tools@a4ed05f1 go@606a5a60 x/tools/gopls/internal/regtest/modfile.TestModFileModification (log) 
goroutine profile: total 6
1 @ 0x430f36 0x466765 0x5c1fd5 0x5c1ded 0x5bed4b 0xd8c95d 0xd8c5b0 0x51ebcb 0x46cf81
#	0x466764	runtime/pprof.runtime_goroutineProfileWithLabels+0x24				/tmp/workdir/go/src/runtime/mprof.go:846
#	0x5c1fd4	runtime/pprof.writeRuntimeProfile+0xb4						/tmp/workdir/go/src/runtime/pprof/pprof.go:723
#	0x5c1dec	runtime/pprof.writeGoroutine+0x4c						/tmp/workdir/go/src/runtime/pprof/pprof.go:683
#	0x5bed4a	runtime/pprof.(*Profile).WriteTo+0x14a						/tmp/workdir/go/src/runtime/pprof/pprof.go:330
#	0xd8c95c	golang.org/x/tools/gopls/internal/lsp/regtest.(*Runner).Run.func1.1+0x7c	/tmp/workdir/gopath/src/golang.org/x/tools/gopls/internal/lsp/regtest/runner.go:209
#	0xd8c5af	golang.org/x/tools/gopls/internal/lsp/regtest.(*Runner).Run.func1+0xc8f		/tmp/workdir/gopath/src/golang.org/x/tools/gopls/internal/lsp/regtest/runner.go:257
#	0x51ebca	testing.tRunner+0x10a								/tmp/workdir/go/src/testing/testing.go:1446

...

1 @ 0x43b2d6 0x4697a5 0xc388fd 0x46cf81
#	0x4697a4	time.Sleep+0x124						/tmp/workdir/go/src/runtime/time.go:195
#	0xc388fc	golang.org/x/tools/gopls/internal/lsp/filecache.gc+0x27c	/tmp/workdir/gopath/src/golang.org/x/tools/gopls/internal/lsp/filecache/filecache.go:492

--- FAIL: TestModFileModification (10.46s)
    --- FAIL: TestModFileModification/basic (4.79s)
        --- FAIL: TestModFileModification/basic/nested (2.16s)
            --- FAIL: TestModFileModification/basic/nested/default (2.16s)
                runner.go:210: closing the sandbox: error(s) cleaning sandbox: cleaning modcache: <nil>; removing files: unlinkat /tmp/workdir/tmp/gopls-regtest-2389196202/TestModFileModification/basic/nested/default/proxy/random.org: operation not permitted

— watchflakes

gopherbot avatar Jun 19 '23 16:06 gopherbot

Found new dashboard test flakes for:

#!watchflakes
post <- goos == "openbsd" && `unlinkat .*: operation not permitted`
2023-06-21 11:18 openbsd-386-72 mod@baa5c2d0 go@c4590af1 x/mod/zip.TestCreateFromDir (log) 
--- FAIL: TestCreateFromDir (0.00s)
    --- FAIL: TestCreateFromDir/exclude_submodule (0.01s)
        testing.go:1097: TempDir RemoveAll cleanup: unlinkat /tmp/workdir/tmp/TestCreateFromDirexclude_submodule4163264695: operation not permitted

— watchflakes

gopherbot avatar Jul 06 '23 00:07 gopherbot

Commit c4590af1 is on release-branch.go1.19, and so are commit 606a5a60 and commit 86e9e0ea.

That leaves commit 3c6a5cdb as the most recent failure on the main branch, and that was almost a year ago. I suspect this may be fixed at head.

bcmills avatar Aug 21 '23 14:08 bcmills

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.)

gopherbot avatar Sep 21 '23 14:09 gopherbot