search

GoogleCloudPlatform / gcsfuse

A user-space file system for interacting with Google Cloud Storage
https://cloud.google.com/storage/docs/gcs-fuse
Apache License 2.0
2.05k stars 429 forks source link

Error unlock of unlocked mutex #2630

Open lewandowskim1988 opened 1 week ago

lewandowskim1988 commented 1 week ago

I have an issue with one of my CI tests. All tests are mounting FUSE volume in same directory and do some operations but only one is failing with error message that I don't know how to manage.

Error message from Kubernetes events of failing pod:

Normal   Killing      12m                kubelet            Stopping container gke-gcsfuse-sidecar
Warning  FailedMount  12m (x3 over 12m)  kubelet            MountVolume.SetUp failed for volume "gcs-fuse-csi-pv" : rpc error: code = Internal desc = gcsfuse failed with error: fatal error: sync: unlock of unlocked mutex

goroutine 16040 [running]:
sync.fatal({0x172a50c?, 0xc0008158d8?})
  /usr/local/go/src/runtime/panic.go:1007 +0x18
sync.(*Mutex).unlockSlow(0xc000aa3a88, 0xffffffff)
  /usr/local/go/src/sync/mutex.go:229 +0x35
sync.(*Mutex).Unlock(0xc000a00a80?)
  /usr/local/go/src/sync/mutex.go:223 +0x25
github.com/googlecloudplatform/gcsfuse/v2/internal/fs.(*fileSystem).lookUpLocalFileInode.func1()
  /go/gcsfuse/internal/fs/fs.go:984 +0x46
panic({0x13989c0?, 0xc000c8cdc0?})
  /usr/local/go/src/runtime/panic.go:770 +0x132
github.com/googlecloudplatform/gcsfuse/v2/internal/fs/inode.NewFileName({{0x0, 0x0}, {0xc000120bd0, 0x22}}, {0x2897a50, 0x0})
  /go/gcsfuse/internal/fs/inode/name.go:58 +0x108
github.com/googlecloudplatform/gcsfuse/v2/internal/fs.(*fileSystem).lookUpLocalFileInode(0xc000469dc0, {0x7c8aadc39e40?, 0xc00088c390?}, {0x2897a50, 0x1?})
  /go/gcsfuse/internal/fs/fs.go:989 +0x150
github.com/googlecloudplatform/gcsfuse/v2/internal/fs.(*fileSystem).lookUpOrCreateChildInode(0xc000469dc0, {0x1c5e100, 0xc000c8b310}, {0x7c8aadc39e40, 0xc00088c390}, {0x2897a50, 0x1})
  /go/gcsfuse/internal/fs/fs.go:923 +0x66
github.com/googlecloudplatform/gcsfuse/v2/internal/fs.(*fileSystem).LookUpInode(0xc000469dc0, {0x1c5e0c8?, 0xc000ba59b0?}, 0xc0004e0e10)
  /go/gcsfuse/internal/fs/fs.go:1344 +0x146
github.com/googlecloudplatform/gcsfuse/v2/internal/fs/wrappers.(*errorMapping).LookUpInode(0xc000ab3f30, {0x1c5e0c8?, 0xc000ba59b0?}, 0x137b620?)
  /go/gcsfuse/internal/fs/wrappers/error_mapping.go:126 +0x69
github.com/googlecloudplatform/gcsfuse/v2/internal/fs/wrappers.(*monitoring).LookUpInode(0xc000ab3f40, {0x1c5e0c8, 0xc000ba59b0}, 0xc0004e0e10)
  /go/gcsfuse/internal/fs/wrappers/monitoring.go:156 +0x76
github.com/jacobsa/fuse/fuseutil.(*fileSystemServer).handleOp(0xc000ac8720, 0xc000d8a000, {0x1c5e0c8, 0xc000ba59b0}, {0x1361900?, 0xc0004e0e10})
  /tmp/build_gcsfuse_gopath3695249373/pkg/mod/github.com/jacobsa/fuse@v0.0.0-20240607092844-7285af0d05b0/fuseutil/file_system.go:144 +0x203
created by github.com/jacobsa/fuse/fuseutil.(*fileSystemServer).ServeOps in goroutine 56
  /tmp/build_gcsfuse_gopath3695249373/pkg/mod/github.com/jacobsa/fuse@v0.0.0-20240607092844-7285af0d05b0/fuseutil/file_system.go:123 +0x1be

goroutine 1 [select, 3 minutes]:
github.com/jacobsa/fuse.(*MountedFileSystem).Join(0xc000adecc0, {0x1c5de28, 0x29cdfe0})
  /tmp/build_gcsfuse_gopath3695249373/pkg/mod/github.com/jacobsa/fuse@v0.0.0-20240607092844-7285af0d05b0/mounted_file_system.go:46 +0x6f
github.com/googlecloudplatform/gcsfuse/v2/cmd.runCLIApp(0xc0006bc160)
  /go/gcsfuse/cmd/legacy_main.go:468 +0x1825
github.com/googlecloudplatform/gcsfuse/v2/cmd.run.func1(0x1?)
  /go/gcsfuse/cmd/legacy_main.go:488 +0x1c
github.com/urfave/cli.HandleAction({0x139c4c0?, 0xc0004cc070?}, 0xc000880fc0?)
  /tmp/build_gcsfuse_gopath3695249373/pkg/mod/github.com/urfave/cli@v1.22.15/app.go:526 +0x75
github.com/urfave/cli.(*App).Run(0xc000880fc0, {0xc000140000, 0x11, 0x12})
  /tmp/build_gcsfuse_gopath3695249373/pkg/mod/github.com/urfave/cli@v1.22.15/app.go:286 +0x79b
github.com/googlecloudplatform/gcsfuse/v2/cmd.run()
  /go/gcsfuse/cmd/legacy_main.go:492 +0xbb
github.com/googlecloudplatform/gcsfuse/v2/cmd.ExecuteLegacyMain()
  /go/gcsfuse/cmd/legacy_main.go:507 +0x2b
main.main()
  /go/gcsfuse/main.go:83 +0x13e

goroutine 13 [select]:
go.opencensus.io/stats/view.(*worker).start(0xc0004b8880)
  /tmp/build_gcsfuse_gopath3695249373/pkg/mod/go.opencensus.io@v0.24.0/stats/view/worker.go:292 +0x9f
created by go.opencensus.io/stats/view.init.0 in goroutine 1
  /tmp/build_gcsfuse_gopath3695249373/pkg/mod/go.opencensus.io@v0.24.0/stats/view/worker.go:34 +0x8d

goroutine 37 [chan receive, 3 minutes]:
github.com/googlecloudplatform/gcsfuse/v2/internal/perf.HandleCPUProfileSignals()
  /go/gcsfuse/internal/perf/cpu.go:58 +0x85
created by github.com/googlecloudplatform/gcsfuse/v2/cmd.ExecuteLegacyMain in goroutine 1
  /go/gcsfuse/cmd/legacy_main.go:503 +0x1a

goroutine 38 [chan receive, 3 minutes]:
github.com/googlecloudplatform/gcsfuse/v2/internal/perf.HandleMemoryProfileSignals()
  /go/gcsfuse/internal/perf/memory.go:67 +0x98
created by github.com/googlecloudplatform/gcsfuse/v2/cmd.ExecuteLegacyMain in goroutine 1
  /go/gcsfuse/cmd/legacy_main.go:504 +0x26

goroutine 49 [syscall, 3 minutes]:
os/signal.signal_recv()
  /usr/local/go/src/runtime/sigqueue.go:152 +0x29
os/signal.loop()
  /usr/local/go/src/os/signal/signal_unix.go:23 +0x13
created by os/signal.Notify.func1.1 in goroutine 37
  /usr/local/go/src/os/signal/signal.go:151 +0x1f

goroutine 88 [select, 3 minutes]:
github.com/googlecloudplatform/gcsfuse/v2/internal/gcsx.garbageCollect({0x1c5e100, 0xc0006de9b0}, {0x170da5d, 0xd}, {0x1c676f8, 0xc000ac86e0})
  /go/gcsfuse/internal/gcsx/garbage_collect.go:108 +0x106
created by github.com/googlecloudplatform/gcsfuse/v2/internal/gcsx.(*bucketManager).SetUpBucket in goroutine 1
  /go/gcsfuse/internal/gcsx/bucket_manager.go:238 +0x745

goroutine 56 [syscall]:
syscall.Syscall(0x0, 0x3, 0xc001884000, 0x101000)
  /usr/local/go/src/syscall/syscall_linux.go:69 +0x25
syscall.read(0xc000d82060?, {0xc001884000?, 0x10?, 0x10?})
  /usr/local/go/src/syscall/zsyscall_linux_amd64.go:736 +0x38
syscall.Read(...)
  /usr/local/go/src/syscall/syscall_unix.go:181
internal/poll.ignoringEINTRIO(...)
  /usr/local/go/src/internal/poll/fd_unix.go:736
internal/poll.(*FD).Read(0xc000d82060, {0xc001884000, 0x101000, 0x101000})
  /usr/local/go/src/internal/poll/fd_unix.go:160 +0x2ae
os.(*File).read(...)
  /usr/local/go/src/os/file_posix.go:29
os.(*File).Read(0xc000d86000, {0xc001884000?, 0x7c7e10?, 0x7c8aadaa9ea8?})
  /usr/local/go/src/os/file.go:118 +0x52
github.com/jacobsa/fuse/internal/buffer.(*InMessage).Init(0xc0011d9840, {0x1c3d9c0?, 0xc000d86000?})
  /tmp/build_gcsfuse_gopath3695249373/pkg/mod/github.com/jacobsa/fuse@v0.0.0-20240607092844-7285af0d05b0/internal/buffer/in_message.go:85 +0x4c
github.com/jacobsa/fuse.(*Connection).readMessage(0xc000d8a000)
  /tmp/build_gcsfuse_gopath3695249373/pkg/mod/github.com/jacobsa/fuse@v0.0.0-20240607092844-7285af0d05b0/connection.go:346 +0x45
github.com/jacobsa/fuse.(*Connection).ReadOp(0xc000d8a000)
  /tmp/build_gcsfuse_gopath3695249373/pkg/mod/github.com/jacobsa/fuse@v0.0.0-20240607092844-7285af0d05b0/connection.go:405 +0x3c
github.com/jacobsa/fuse/fuseutil.(*fileSystemServer).ServeOps(0xc000ac8720, 0xc000d8a000)
  /tmp/build_gcsfuse_gopath3695249373/pkg/mod/github.com/jacobsa/fuse@v0.0.0-20240607092844-7285af0d05b0/fuseutil/file_system.go:106 +0x6b
github.com/jacobsa/fuse.Mount.func1()
  /tmp/build_gcsfuse_gopath3695249373/pkg/mod/github.com/jacobsa/fuse@v0.0.0-20240607092844-7285af0d05b0/mount.go:93 +0x32
created by github.com/jacobsa/fuse.Mount in goroutine 1
  /tmp/build_gcsfuse_gopath3695249373/pkg/mod/github.com/jacobsa/fuse@v0.0.0-20240607092844-7285af0d05b0/mount.go:92 +0x5b9

goroutine 57 [chan receive, 3 minutes]:
github.com/googlecloudplatform/gcsfuse/v2/cmd.registerSIGINTHandler.func1()
  /go/gcsfuse/cmd/legacy_main.go:66 +0x65
created by github.com/googlecloudplatform/gcsfuse/v2/cmd.registerSIGINTHandler in goroutine 1
  /go/gcsfuse/cmd/legacy_main.go:64 +0xbc

goroutine 1347 [IO wait]:
internal/poll.runtime_pollWait(0x7c8aaddc0c80, 0x72)
  /usr/local/go/src/runtime/netpoll.go:345 +0x85
internal/poll.(*pollDesc).wait(0xc000067080?, 0xc000552800?, 0x0)
  /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x27
internal/poll.(*pollDesc).waitRead(...)
  /usr/local/go/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc000067080, {0xc000552800, 0x4800, 0x4800})
  /usr/local/go/src/internal/poll/fd_unix.go:164 +0x27a
net.(*netFD).Read(0xc000067080, {0xc000552800?, 0x7c8aaddf5c98?, 0xc0000dbe48?})
  /usr/local/go/src/net/fd_posix.go:55 +0x25
net.(*conn).Read(0xc000d86360, {0xc000552800?, 0xc000472930?, 0x411d5b?})
  /usr/local/go/src/net/net.go:179 +0x45
crypto/tls.(*atLeastReader).Read(0xc0000dbe48, {0xc000552800?, 0x0?, 0xc0000dbe48?})
  /usr/local/go/src/crypto/tls/conn.go:806 +0x3b
bytes.(*Buffer).ReadFrom(0xc0001f1b30, {0x1c403a0, 0xc0000dbe48})
  /usr/local/go/src/bytes/buffer.go:211 +0x98
crypto/tls.(*Conn).readFromUntil(0xc0001f1888, {0x1c3e720, 0xc000d86360}, 0xc000472978?)
  /usr/local/go/src/crypto/tls/conn.go:828 +0xde
crypto/tls.(*Conn).readRecordOrCCS(0xc0001f1888, 0x0)
  /usr/local/go/src/crypto/tls/conn.go:626 +0x3cf
crypto/tls.(*Conn).readRecord(...)
  /usr/local/go/src/crypto/tls/conn.go:588
crypto/tls.(*Conn).Read(0xc0001f1888, {0xc000c72000, 0x1000, 0x8?})
  /usr/local/go/src/crypto/tls/conn.go:1370 +0x156
net/http.(*persistConn).Read(0xc000141440, {0xc000c72000?, 0xc000c461e0?, 0xc000472d38?})
  /usr/local/go/src/net/http/transport.go:1977 +0x4a
bufio.(*Reader).fill(0xc0006eb9e0)
  /usr/local/go/src/bufio/bufio.go:110 +0x103
bufio.(*Reader).Peek(0xc0006eb9e0, 0x1)
  /usr/local/go/src/bufio/bufio.go:148 +0x53
net/http.(*persistConn).readLoop(0xc000141440)
  /usr/local/go/src/net/http/transport.go:2141 +0x1b9
created by net/http.(*Transport).dialConn in goroutine 1271
  /usr/local/go/src/net/http/transport.go:1799 +0x152f

goroutine 1436 [IO wait]:
internal/poll.runtime_pollWait(0x7c8aaddc0a90, 0x72)
  /usr/local/go/src/runtime/netpoll.go:345 +0x85
internal/poll.(*pollDesc).wait(0xc000504f00?, 0xc000c4f300?, 0x0)
  /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x27
internal/poll.(*pollDesc).waitRead(...)
  /usr/local/go/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc000504f00, {0xc000c4f300, 0x1300, 0x1300})
  /usr/local/go/src/internal/poll/fd_unix.go:164 +0x27a
net.(*netFD).Read(0xc000504f00, {0xc000c4f300?, 0x7c8aadbf3c58?, 0xc001e864c8?})
  /usr/local/go/src/net/fd_posix.go:55 +0x25
net.(*conn).Read(0xc000d87110, {0xc000c4f300?, 0xc000027930?, 0x411d5b?})
  /usr/local/go/src/net/net.go:179 +0x45
crypto/tls.(*atLeastReader).Read(0xc001e864c8, {0xc000c4f300?, 0x0?, 0xc001e864c8?})
  /usr/local/go/src/crypto/tls/conn.go:806 +0x3b
bytes.(*Buffer).ReadFrom(0xc000926630, {0x1c403a0, 0xc001e864c8})
  /usr/local/go/src/bytes/buffer.go:211 +0x98
crypto/tls.(*Conn).readFromUntil(0xc000926388, {0x1c3e720, 0xc000d87110}, 0xc000027978?)
  /usr/local/go/src/crypto/tls/conn.go:828 +0xde
crypto/tls.(*Conn).readRecordOrCCS(0xc000926388, 0x0)
  /usr/local/go/src/crypto/tls/conn.go:626 +0x3cf
crypto/tls.(*Conn).readRecord(...)
  /usr/local/go/src/crypto/tls/conn.go:588
crypto/tls.(*Conn).Read(0xc000926388, {0xc000e76000, 0x1000, 0x8?})
  /usr/local/go/src/crypto/tls/conn.go:1370 +0x156
net/http.(*persistConn).Read(0xc0009a5e60, {0xc000e76000?, 0xc000c467e0?, 0xc000027d38?})
  /usr/local/go/src/net/http/transport.go:1977 +0x4a
bufio.(*Reader).fill(0xc000297c20)
  /usr/local/go/src/bufio/bufio.go:110 +0x103
bufio.(*Reader).Peek(0xc000297c20, 0x1)
  /usr/local/go/src/bufio/bufio.go:148 +0x53
net/http.(*persistConn).readLoop(0xc0009a5e60)
  /usr/local/go/src/net/http/transport.go:2141 +0x1b9
created by net/http.(*Transport).dialConn in goroutine 1307
  /usr/local/go/src/net/http/transport.go:1799 +0x152f

goroutine 1348 [select]:
net/http.(*persistConn).writeLoop(0xc000141440)
  /usr/local/go/src/net/http/transport.go:2444 +0xf0
created by net/http.(*Transport).dialConn in goroutine 1271
  /usr/local/go/src/net/http/transport.go:1800 +0x1585

goroutine 1437 [select]:
net/http.(*persistConn).writeLoop(0xc0009a5e60)
  /usr/local/go/src/net/http/transport.go:2444 +0xf0
created by net/http.(*Transport).dialConn in goroutine 1307
  /usr/local/go/src/net/http/transport.go:1800 +0x1585
gcsfuse exited with error: exit status 2

My setup is as follows

Dose anybody have some idea how I can debug it further?

kislaykishore commented 1 week ago

Could you double check the GCSFuse and GKE versions? The line numbers in your error message align more with v2.4.0 than with 2.5.0.

Tulsishah commented 1 week ago

Hey @lewandowskim1988 ,

Can you please provide the steps to reproduce the issue?

Thanks, Tulsi Shah