Tests get stuck. #261
Comments
|
I suggest kill -QUIT on the stuck test to get a backtrace |
|
|
|
you can kill by writing into the fuse control connection, eg. echo 1 > /sys/fs/fuse/connections/47/abort this should get it unstuck so you can kill the process and unmount |
|
Yes, this is how I was stopping it. Sorry I did not digged for more information on how/where it got stuck for now. |
For completeness - for some of the stuck processes, even after corresponding |
Even |
|
if you do a kill -QUIT and then abort FUSE through the /sys/fs you should be able to get a stacktrace. Can you figure out which test is the one causing the hang? |
|
Ok, here is what I get this way: (extracted with I cannot say I read the tracebacks well, but from what I could understand it stuck in |
|
I found a second time and also found the tests stuck in TestDeleteNotify: |
|
On Sun, Jun 16, 2019 at 07:39:12PM -0700, qiffang wrote:
Hi @navytux
I use the fuse to inject file system error, the code like this
```
go func(){
server.Serve()
}()
```
After all tests finished, I call server.Unmount(), it failed because of device or resource busy, even though i call unmount -f $mountpoint in the program, it also fail because of device or resource busy.
```
2019/04/22 02:59:29 Unimplemented opcode POLL
...
Umount failed mountpoint=/tmp/mountpoint873241772, err=device or resource busy
```
Can you give some suggestions?
Thanks
Offhand what I can say is that you need to debug your filesystem server
and see where things are stuck and holding the mount. Usually checking
FUSE debug log helps as well as checking which request handling
goroutine are stuck and where.
Hope this helps a bit,
Kirill
|
|
is this still an issue? |
|
Unfortunately yes - I've tried to run the tests in repeated mode (as described in #261 (comment)) and got it stuck on 6th cycle. This time the stuck test is newunionfs.test: |
|
|
In one of your traces, there is a call to sync.Pool.Get(), which triggers a GC. This call happens inside the critical section for obtaining a request to read out. This means that no further requests can be read. I don't understand why the GC is not making progress, but it seems like a no-brainer to not get new Pool elements under lock |
gerritforge-ltd
pushed a commit
that referenced
this issue
Jul 26, 2019
Pool.Get() can trigger a GC, and we see this GC being hung in stack traces for the TestDeleteNotify test case. See issue #261. Change-Id: I278a05fc3c6a59c701686aebd410511c5502d9d5
|
https://review.gerrithub.io/c/hanwen/go-fuse/+/463283 @navytux - can you check if this helps (i haven't been able to repro the hang.) |
|
@hanwen, thanks, I've tried and even though it took longer time, the tests got stuck again (though for that stuck I could not extract the traceback - in that particular case after Btw, about 33b2c2f - I suggest to move P.S. I also reran the test on Which led me to think that the stuck is related to timing race, not particularly and after trying several things I think I've found a way to reliably trigger the stuck. On master (v1.0.0-227-g2f29805) it is either: (I think TestCacheControl is not unique but at this test it reliably gets stuck) or leave GOMAXPROCS unmodified (o.r. e.g. set it to 4 which is the default on my computer) but apply the following patch which raises probability of GC triggered from under reqMu: --- a/fuse/server.go
+++ b/fuse/server.go
@@ -263,6 +263,8 @@ func (ms *Server) readRequest(exitIdle bool) (req *request, code Status) {
ms.reqMu.Unlock()
return nil, OK
}
+ //time.Sleep(1*time.Millisecond)
+ runtime.GC()
ms.reqReaders++
ms.reqMu.Unlock()and then e.g. For now I have not looked further as I need to finish other urgent stuff. Hope this helps a bit, P.S. as some bugs are only likely to trigger only when run on uniprocessor system, I suggest to add |
|
this is still going on as of today commit da0665e the problem is in the fuse/test/ package |
|
As of 2020-03-23 ( |
|
This is still the case as of today master ( |
|
Can repro. backtrace.txt |
|
Looking at the kernel stacks, we see that one thread is blocked on a page fault: This page fault is caused by this mmap read (verified by printf debugging): go-fuse/fuse/test/cachecontrol_test.go Line 225 in 0b6cbc5 I think this cannot work with GOMAXPROCS=1. The active thread is blocked in a page fault from the mmap. A blocking syscall would have created another thread, but not a blocking memory read! Handling that page fault requires handling a FUSE transaction, for which we have no free thread => deadlock. Maybe this can be fixed using lockOsThread() |
|
Fixed using Mlock() in https://review.gerrithub.io/c/hanwen/go-fuse/+/503708 . |
|
@rfjakob, thanks. Please see my feedback regarding your patch on gerrit. However after fixing (neo) (z-dev) (g.env) kirr@deco:~/src/neo/src/github.com/hanwen/go-fuse$ GOTRACEBACK=crash GOMAXPROCS=1 go1.14 test -v -count=1 -run TestDeleteNotify ./fuse/test
=== RUN TestDeleteNotify
18:16:01.232359 rx 2: INIT i0 {7.31 Ra 0x20000 FLOCK_LOCKS,WRITEBACK_CACHE,NO_OPEN_SUPPORT,POSIX_LOCKS,SPLICE_WRITE,AUTO_INVAL_DATA,NO_OPENDIR_SUPPORT,DONT_MASK,SPLICE_MOVE,SPLICE_READ,ASYNC_READ,ATOMIC_O_TRUNC,EXPORT_SUPPORT,BIG_WRITES,IOCTL_DIR,POSIX_ACL,HANDLE_KILLPRIV,CACHE_SYMLINKS,EXPLICIT_INVAL_DATA,MAX_PAGES,READDIRPLUS,READDIRPLUS_AUTO,ASYNC_DIO,PARALLEL_DIROPS,ABORT_ERROR}
18:16:01.232447 tx 2: OK, {7.28 Ra 0x20000 AUTO_INVAL_DATA,BIG_WRITES,ASYNC_READ,PARALLEL_DIROPS,READDIRPLUS,NO_OPEN_SUPPORT 0/0 Wr 0x10000 Tg 0x0}
18:16:01.232702 rx 4: LOOKUP i1 [".go-fuse-epoll-hack"] 20b
18:16:01.232724 tx 4: OK, {i18446744073709551615 g0 tE=0s tA=0s {M0100644 SZ=0 L=1 0:0 B0*0 i0:18446744073709551615 A 0.000000 M 0.000000 C 0.000000}}
18:16:01.232748 rx 6: OPEN i18446744073709551615 {O_RDONLY,0x8000}
18:16:01.232753 tx 6: OK, {Fh 18446744073709551615 }
18:16:01.232775 rx 8: POLL i18446744073709551615
18:16:01.232780 tx 8: 38=function not implemented
18:16:01.232795 rx 10: FLUSH i18446744073709551615 {Fh 18446744073709551615}
18:16:01.232799 tx 10: 34=numerical result out of range
18:16:01.232848 rx 12: RELEASE i18446744073709551615 {Fh 18446744073709551615 0x8000 L0}
18:16:01.232853 tx 12: 34=numerical result out of range
18:16:01.232863 rx 14: LOOKUP i1 ["testdir"] 8b
18:16:01.232874 tx 14: OK, {i3 g2 tE=0s tA=0s {M040755 SZ=0 L=0 0:0 B0*0 i0:3 A 1602083761.232808 M 1602083761.232808 C 1602083761.232808}}
18:16:01.232893 rx 16: LOOKUP i3 ["testfile"] 9b
18:16:01.232902 tx 16: 2=no such file or directory, {i0 g0 tE=0s tA=0s {M00 SZ=0 L=0 0:0 B0*0 i0:0 A 0.000000 M 0.000000 C 0.000000}}
18:16:01.232928 rx 18: CREATE i3 {0100644 [WRONLY,TRUNC,CREAT,0x8000] (022)} ["testfile"] 9b
18:16:01.232965 tx 18: OK, {i4 g3 {M0100644 SZ=0 L=1 0:0 B0*0 i0:4 A 1602083761.232932 M 1602083761.232932 C 1602083761.232932} &{2 0 0}}
18:16:01.233005 rx 20: GETXATTR i4 {sz 0} ["security.capability"] 20b
18:16:01.233010 tx 20: 61=no data available
18:16:01.233033 rx 22: WRITE i4 {Fh 2 [0 +1) L 0 WRONLY,NONBLOCK,0x8000} "*" 1b
18:16:01.233044 tx 22: OK
18:16:01.233060 rx 24: FLUSH i4 {Fh 2}
18:16:01.233076 tx 24: OK
18:16:01.233148 rx 26: RELEASE i4 {Fh 2 WRONLY,NONBLOCK,0x8000 L0}
18:16:01.233154 tx 26: OK
18:16:01.233164 rx 28: LOOKUP i1 ["testdir"] 8b
18:16:01.233174 tx 28: OK, {i3 g2 tE=0s tA=0s {M040755 SZ=0 L=0 0:0 B0*0 i0:3 A 1602083761.232808 M 1602083761.232808 C 1602083761.232808}}
18:16:01.233189 rx 30: GETATTR i3 {Fh 0}
18:16:01.233198 tx 30: OK, {tA=0s {M040755 SZ=0 L=1 0:0 B0*0 i0:3 A 1602083761.232808 M 1602083761.232808 C 1602083761.232808}}
# hang
^\SIGQUIT: quit
PC=0x4686ed m=2 sigcode=128
goroutine 0 [idle]:
runtime.usleep(0x1b9200002710, 0x0, 0x44be01, 0x271000000002, 0x1b76cf56e49a, 0x1b920b834b3f, 0x1b920b834b3f, 0x1c0282046c69, 0x7fc486b9ce30, 0x0, ...)
/home/kirr/src/tools/go/go1.14/src/runtime/sys_linux_amd64.s:146 +0x3d fp=0x7fc486b9cde0 sp=0x7fc486b9cdc0 pc=0x4686ed
runtime.sysmon()
/home/kirr/src/tools/go/go1.14/src/runtime/proc.go:4512 +0x8d fp=0x7fc486b9ce58 sp=0x7fc486b9cde0 pc=0x44220d
runtime.mstart1()
/home/kirr/src/tools/go/go1.14/src/runtime/proc.go:1112 +0xc3 fp=0x7fc486b9ce80 sp=0x7fc486b9ce58 pc=0x439ef3
runtime.mstart()
/home/kirr/src/tools/go/go1.14/src/runtime/proc.go:1077 +0x6e fp=0x7fc486b9cea8 sp=0x7fc486b9ce80 pc=0x439e0e
goroutine 1 [chan receive]:
runtime.gopark(0x628860, 0xc000020358, 0x4d170e, 0x2)
/home/kirr/src/tools/go/go1.14/src/runtime/proc.go:304 +0xe0 fp=0xc000045b88 sp=0xc000045b68 pc=0x437970
runtime.chanrecv(0xc000020300, 0xc000045c87, 0xc000000101, 0x4e23f2)
/home/kirr/src/tools/go/go1.14/src/runtime/chan.go:525 +0x2e7 fp=0xc000045c18 sp=0xc000045b88 pc=0x407817
runtime.chanrecv1(0xc000020300, 0xc000045c87)
/home/kirr/src/tools/go/go1.14/src/runtime/chan.go:407 +0x2b fp=0xc000045c48 sp=0xc000045c18 pc=0x40751b
testing.(*T).Run(0xc0000a8120, 0x61deac, 0x10, 0x628348, 0x483b01)
/home/kirr/src/tools/go/go1.14/src/testing/testing.go:1106 +0x399 fp=0xc000045ce0 sp=0xc000045c48 pc=0x4e2419
testing.runTests.func1(0xc0000a8000)
/home/kirr/src/tools/go/go1.14/src/testing/testing.go:1349 +0x78 fp=0xc000045d30 sp=0xc000045ce0 pc=0x4e6408
testing.tRunner(0xc0000a8000, 0xc000045e10)
/home/kirr/src/tools/go/go1.14/src/testing/testing.go:1054 +0xdc fp=0xc000045d80 sp=0xc000045d30 pc=0x4e200c
testing.runTests(0xc00000e140, 0x7c4e00, 0x3c, 0x3c, 0x0)
/home/kirr/src/tools/go/go1.14/src/testing/testing.go:1347 +0x2a7 fp=0xc000045e40 sp=0xc000045d80 pc=0x4e3a17
testing.(*M).Run(0xc000086100, 0x0)
/home/kirr/src/tools/go/go1.14/src/testing/testing.go:1264 +0x1b7 fp=0xc000045f20 sp=0xc000045e40 pc=0x4e28c7
main.main()
_testmain.go:162 +0x135 fp=0xc000045f88 sp=0xc000045f20 pc=0x5b0c45
runtime.main()
/home/kirr/src/tools/go/go1.14/src/runtime/proc.go:203 +0x1fa fp=0xc000045fe0 sp=0xc000045f88 pc=0x4375aa
runtime.goexit()
/home/kirr/src/tools/go/go1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000045fe8 sp=0xc000045fe0 pc=0x466b81
goroutine 2 [force gc (idle)]:
runtime.gopark(0x628a28, 0x7c8100, 0x1411, 0x1)
/home/kirr/src/tools/go/go1.14/src/runtime/proc.go:304 +0xe0 fp=0xc000032fb0 sp=0xc000032f90 pc=0x437970
runtime.goparkunlock(...)
/home/kirr/src/tools/go/go1.14/src/runtime/proc.go:310
runtime.forcegchelper()
/home/kirr/src/tools/go/go1.14/src/runtime/proc.go:253 +0xb7 fp=0xc000032fe0 sp=0xc000032fb0 pc=0x437827
runtime.goexit()
/home/kirr/src/tools/go/go1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000032fe8 sp=0xc000032fe0 pc=0x466b81
created by runtime.init.6
/home/kirr/src/tools/go/go1.14/src/runtime/proc.go:242 +0x35
goroutine 3 [GC sweep wait]:
runtime.gopark(0x628a28, 0x7c82a0, 0x140c, 0x1)
/home/kirr/src/tools/go/go1.14/src/runtime/proc.go:304 +0xe0 fp=0xc0000337a8 sp=0xc000033788 pc=0x437970
runtime.goparkunlock(...)
/home/kirr/src/tools/go/go1.14/src/runtime/proc.go:310
runtime.bgsweep(0xc000052000)
/home/kirr/src/tools/go/go1.14/src/runtime/mgcsweep.go:70 +0x9c fp=0xc0000337d8 sp=0xc0000337a8 pc=0x4238fc
runtime.goexit()
/home/kirr/src/tools/go/go1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0000337e0 sp=0xc0000337d8 pc=0x466b81
created by runtime.gcenable
/home/kirr/src/tools/go/go1.14/src/runtime/mgc.go:214 +0x5c
goroutine 4 [GC scavenge wait]:
runtime.gopark(0x628a28, 0x7c8260, 0x140d, 0x1)
/home/kirr/src/tools/go/go1.14/src/runtime/proc.go:304 +0xe0 fp=0xc000033f78 sp=0xc000033f58 pc=0x437970
runtime.goparkunlock(...)
/home/kirr/src/tools/go/go1.14/src/runtime/proc.go:310
runtime.bgscavenge(0xc000052000)
/home/kirr/src/tools/go/go1.14/src/runtime/mgcscavenge.go:237 +0xd0 fp=0xc000033fd8 sp=0xc000033f78 pc=0x421e60
runtime.goexit()
/home/kirr/src/tools/go/go1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000033fe0 sp=0xc000033fd8 pc=0x466b81
created by runtime.gcenable
/home/kirr/src/tools/go/go1.14/src/runtime/mgc.go:215 +0x7e
goroutine 5 [finalizer wait]:
runtime.gopark(0x628a28, 0x7f1ab8, 0x1410, 0x1)
/home/kirr/src/tools/go/go1.14/src/runtime/proc.go:304 +0xe0 fp=0xc000034758 sp=0xc000034738 pc=0x437970
runtime.goparkunlock(...)
/home/kirr/src/tools/go/go1.14/src/runtime/proc.go:310
runtime.runfinq()
/home/kirr/src/tools/go/go1.14/src/runtime/mfinal.go:175 +0xa3 fp=0xc0000347e0 sp=0xc000034758 pc=0x4194c3
runtime.goexit()
/home/kirr/src/tools/go/go1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0000347e8 sp=0xc0000347e0 pc=0x466b81
created by runtime.createfing
/home/kirr/src/tools/go/go1.14/src/runtime/mfinal.go:156 +0x61
goroutine 6 [running]:
goroutine running on other thread; stack unavailable
created by testing.(*T).Run
/home/kirr/src/tools/go/go1.14/src/testing/testing.go:1105 +0x372
goroutine 7 [runnable]:
syscall.Syscall(0x1, 0x9, 0xc0000c20f8, 0x78, 0x78, 0x78, 0x0)
/home/kirr/src/tools/go/go1.14/src/syscall/asm_linux_amd64.s:18 +0x5 fp=0xc0000e5c48 sp=0xc0000e5c40 pc=0x47cb75
syscall.write(0x9, 0xc0000c20f8, 0x78, 0xa0, 0xc0000e5d80, 0x523488, 0xc0000120f0)
/home/kirr/src/tools/go/go1.14/src/syscall/zsyscall_linux_amd64.go:914 +0x5a fp=0xc0000e5ca0 sp=0xc0000e5c48 pc=0x47b24a
syscall.Write(...)
/home/kirr/src/tools/go/go1.14/src/syscall/syscall_unix.go:214
github.com/hanwen/go-fuse/fuse.(*Server).systemWrite.func1(0x1a0, 0x84)
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server_linux.go:15 +0x4c fp=0xc0000e5ce8 sp=0xc0000e5ca0 pc=0x53e37c
github.com/hanwen/go-fuse/fuse.handleEINTR(0xc0000e5d58, 0x7c05a0, 0x60afe0)
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:255 +0x27 fp=0xc0000e5d08 sp=0xc0000e5ce8 pc=0x5397a7
github.com/hanwen/go-fuse/fuse.(*Server).systemWrite(0xc0000ba000, 0xc0000c2000, 0xc0000c20f8, 0x78, 0xa0, 0x52e1ad)
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server_linux.go:14 +0x3bb fp=0xc0000e5dd0 sp=0xc0000e5d08 pc=0x53cd3b
github.com/hanwen/go-fuse/fuse.(*Server).write(0xc0000ba000, 0xc0000c2000, 0x1)
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:528 +0xbf fp=0xc0000e5e38 sp=0xc0000e5dd0 pc=0x53b09f
github.com/hanwen/go-fuse/fuse.(*Server).handleRequest(0xc0000ba000, 0xc0000c2000, 0xc000000000)
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:475 +0x13d fp=0xc0000e5ed8 sp=0xc0000e5e38 pc=0x53aa9d
github.com/hanwen/go-fuse/fuse.(*Server).loop(0xc0000ba000, 0x0)
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:445 +0x18a fp=0xc0000e5f38 sp=0xc0000e5ed8 pc=0x53a93a
github.com/hanwen/go-fuse/fuse.(*Server).Serve(0xc0000ba000)
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:367 +0x45 fp=0xc0000e5fd8 sp=0xc0000e5f38 pc=0x53a4d5
runtime.goexit()
/home/kirr/src/tools/go/go1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0000e5fe0 sp=0xc0000e5fd8 pc=0x466b81
created by github.com/hanwen/go-fuse/fuse/test.TestDeleteNotify
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/test/delete_linux_test.go:54 +0x391
goroutine 8 [runnable]:
github.com/hanwen/go-fuse/fuse.(*Server).loop(0xc0000ba000, 0xc00000e201)
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:419 fp=0xc000034fd0 sp=0xc000034fc8 pc=0x53a7b0
runtime.goexit()
/home/kirr/src/tools/go/go1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000034fd8 sp=0xc000034fd0 pc=0x466b81
created by github.com/hanwen/go-fuse/fuse.(*Server).readRequest
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:312 +0x417
goroutine 9 [runnable]:
github.com/hanwen/go-fuse/fuse.(*Server).loop(0xc0000ba000, 0xc00000e201)
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:419 fp=0xc0000327d0 sp=0xc0000327c8 pc=0x53a7b0
runtime.goexit()
/home/kirr/src/tools/go/go1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0000327d8 sp=0xc0000327d0 pc=0x466b81
created by github.com/hanwen/go-fuse/fuse.(*Server).readRequest
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:312 +0x417
goroutine 10 [runnable]:
github.com/hanwen/go-fuse/fuse.(*Server).loop(0xc0000ba000, 0xc00000e301)
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:419 fp=0xc0000357d0 sp=0xc0000357c8 pc=0x53a7b0
runtime.goexit()
/home/kirr/src/tools/go/go1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0000357d8 sp=0xc0000357d0 pc=0x466b81
created by github.com/hanwen/go-fuse/fuse.(*Server).readRequest
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:312 +0x417
goroutine 11 [runnable]:
github.com/hanwen/go-fuse/fuse.(*Server).loop(0xc0000ba000, 0xc00000e301)
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:419 fp=0xc000035fd0 sp=0xc000035fc8 pc=0x53a7b0
runtime.goexit()
/home/kirr/src/tools/go/go1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000035fd8 sp=0xc000035fd0 pc=0x466b81
created by github.com/hanwen/go-fuse/fuse.(*Server).readRequest
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:312 +0x417
goroutine 12 [runnable]:
github.com/hanwen/go-fuse/fuse.(*Server).loop(0xc0000ba000, 0xc00000e301)
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:419 fp=0xc00002e7d0 sp=0xc00002e7c8 pc=0x53a7b0
runtime.goexit()
/home/kirr/src/tools/go/go1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc00002e7d8 sp=0xc00002e7d0 pc=0x466b81
created by github.com/hanwen/go-fuse/fuse.(*Server).readRequest
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:312 +0x417
goroutine 13 [runnable]:
github.com/hanwen/go-fuse/fuse.(*Server).loop(0xc0000ba000, 0xc00000e301)
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:419 fp=0xc00002efd0 sp=0xc00002efc8 pc=0x53a7b0
runtime.goexit()
/home/kirr/src/tools/go/go1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc00002efd8 sp=0xc00002efd0 pc=0x466b81
created by github.com/hanwen/go-fuse/fuse.(*Server).readRequest
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:312 +0x417
goroutine 14 [runnable]:
github.com/hanwen/go-fuse/fuse.(*Server).loop(0xc0000ba000, 0xc00000e401)
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:419 fp=0xc00002f7d0 sp=0xc00002f7c8 pc=0x53a7b0
runtime.goexit()
/home/kirr/src/tools/go/go1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc00002f7d8 sp=0xc00002f7d0 pc=0x466b81
created by github.com/hanwen/go-fuse/fuse.(*Server).readRequest
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:312 +0x417
goroutine 15 [runnable]:
github.com/hanwen/go-fuse/fuse.(*Server).loop(0xc0000ba000, 0xc00000e401)
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:419 fp=0xc00002ffd0 sp=0xc00002ffc8 pc=0x53a7b0
runtime.goexit()
/home/kirr/src/tools/go/go1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc00002ffd8 sp=0xc00002ffd0 pc=0x466b81
created by github.com/hanwen/go-fuse/fuse.(*Server).readRequest
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:312 +0x417
goroutine 16 [runnable]:
github.com/hanwen/go-fuse/fuse.(*Server).loop(0xc0000ba000, 0xc00000e501)
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:419 fp=0xc0000307d0 sp=0xc0000307c8 pc=0x53a7b0
runtime.goexit()
/home/kirr/src/tools/go/go1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0000307d8 sp=0xc0000307d0 pc=0x466b81
created by github.com/hanwen/go-fuse/fuse.(*Server).readRequest
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:312 +0x417
goroutine 18 [runnable]:
github.com/hanwen/go-fuse/fuse.(*Server).loop(0xc0000ba000, 0xc00000e501)
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:419 fp=0xc000030fd0 sp=0xc000030fc8 pc=0x53a7b0
runtime.goexit()
/home/kirr/src/tools/go/go1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000030fd8 sp=0xc000030fd0 pc=0x466b81
created by github.com/hanwen/go-fuse/fuse.(*Server).readRequest
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:312 +0x417
goroutine 19 [runnable]:
github.com/hanwen/go-fuse/fuse.(*Server).loop(0xc0000ba000, 0xc00000e601)
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:419 fp=0xc0000317d0 sp=0xc0000317c8 pc=0x53a7b0
runtime.goexit()
/home/kirr/src/tools/go/go1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0000317d8 sp=0xc0000317d0 pc=0x466b81
created by github.com/hanwen/go-fuse/fuse.(*Server).readRequest
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:312 +0x417
goroutine 20 [runnable]:
github.com/hanwen/go-fuse/fuse.(*Server).loop(0xc0000ba000, 0xc00000e701)
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:419 fp=0xc000031fd0 sp=0xc000031fc8 pc=0x53a7b0
runtime.goexit()
/home/kirr/src/tools/go/go1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000031fd8 sp=0xc000031fd0 pc=0x466b81
created by github.com/hanwen/go-fuse/fuse.(*Server).readRequest
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:312 +0x417
goroutine 21 [runnable]:
github.com/hanwen/go-fuse/fuse.(*Server).loop(0xc0000ba000, 0xc00000e701)
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:419 fp=0xc0000fa7d0 sp=0xc0000fa7c8 pc=0x53a7b0
runtime.goexit()
/home/kirr/src/tools/go/go1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0000fa7d8 sp=0xc0000fa7d0 pc=0x466b81
created by github.com/hanwen/go-fuse/fuse.(*Server).readRequest
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:312 +0x417
goroutine 22 [runnable]:
github.com/hanwen/go-fuse/fuse.(*Server).loop(0xc0000ba000, 0xc00000e701)
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:419 fp=0xc0000fafd0 sp=0xc0000fafc8 pc=0x53a7b0
runtime.goexit()
/home/kirr/src/tools/go/go1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0000fafd8 sp=0xc0000fafd0 pc=0x466b81
created by github.com/hanwen/go-fuse/fuse.(*Server).readRequest
/home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:312 +0x417
rax 0xfffffffffffffffc
rbx 0x4e20
rcx 0x4686ed
rdx 0x0
rdi 0x7fc486b9cdc0
rsi 0x0
rbp 0x7fc486b9cdd0
rsp 0x7fc486b9cdc0
r8 0x5
r9 0x7f1ae8
r10 0x0
r11 0x202
r12 0xf1
r13 0x0
r14 0x65610c
r15 0x0
rip 0x4686ed
rflags 0x202
cs 0x33
fs 0x0
gs 0x0
-----
SIGQUIT: quit
PC=0x468cf1 m=3 sigcode=0
goroutine 0 [idle]:
runtime.futex(0xc000036848, 0x80, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x7fc48639bcc0, 0x40c3ff, ...)
/home/kirr/src/tools/go/go1.14/src/runtime/sys_linux_amd64.s:567 +0x21 fp=0x7fc48639bc48 sp=0x7fc48639bc40 pc=0x468cf1
runtime.futexsleep(0xc000036848, 0x7ffc00000000, 0xffffffffffffffff)
/home/kirr/src/tools/go/go1.14/src/runtime/os_linux.go:45 +0x46 fp=0x7fc48639bc98 sp=0x7fc48639bc48 pc=0x4313a6
runtime.notesleep(0xc000036848)
/home/kirr/src/tools/go/go1.14/src/runtime/lock_futex.go:151 +0x9f fp=0x7fc48639bcd0 sp=0x7fc48639bc98 pc=0x40c3ff
runtime.stopm()
/home/kirr/src/tools/go/go1.14/src/runtime/proc.go:1852 +0xc0 fp=0x7fc48639bcf8 sp=0x7fc48639bcd0 pc=0x43b440
runtime.findrunnable(0xc000024000, 0x0)
/home/kirr/src/tools/go/go1.14/src/runtime/proc.go:2399 +0xa0d fp=0x7fc48639bde0 sp=0x7fc48639bcf8 pc=0x43ca8d
runtime.schedule()
/home/kirr/src/tools/go/go1.14/src/runtime/proc.go:2559 +0x2fc fp=0x7fc48639be48 sp=0x7fc48639bde0 pc=0x43d5cc
runtime.park_m(0xc000001500)
/home/kirr/src/tools/go/go1.14/src/runtime/proc.go:2729 +0x9d fp=0x7fc48639be78 sp=0x7fc48639be48 pc=0x43db4d
runtime.mcall(0x800000)
/home/kirr/src/tools/go/go1.14/src/runtime/asm_amd64.s:318 +0x5b fp=0x7fc48639be88 sp=0x7fc48639be78 pc=0x464a5b
rax 0xca
rbx 0xc000036700
rcx 0x468cf3
rdx 0x0
rdi 0xc000036848
rsi 0x80
rbp 0x7fc48639bc88
rsp 0x7fc48639bc40
r8 0x0
r9 0x0
r10 0x0
r11 0x286
r12 0x3
r13 0xc000001080
r14 0x655f88
r15 0x0
rip 0x468cf1
rflags 0x286
cs 0x33
fs 0x0
gs 0x0
-----
SIGQUIT: quit
PC=0x468cf1 m=4 sigcode=0
goroutine 0 [idle]:
runtime.futex(0x7f1cd8, 0x80, 0x0, 0x0, 0x0, 0x8000, 0x7fc485b9ae20, 0x44bc79, 0x7fc485b9ae28, 0x40c3ff, ...)
/home/kirr/src/tools/go/go1.14/src/runtime/sys_linux_amd64.s:567 +0x21 fp=0x7fc485b9adb0 sp=0x7fc485b9ada8 pc=0x468cf1
runtime.futexsleep(0x7f1cd8, 0x0, 0xffffffffffffffff)
/home/kirr/src/tools/go/go1.14/src/runtime/os_linux.go:45 +0x46 fp=0x7fc485b9ae00 sp=0x7fc485b9adb0 pc=0x4313a6
runtime.notesleep(0x7f1cd8)
/home/kirr/src/tools/go/go1.14/src/runtime/lock_futex.go:151 +0x9f fp=0x7fc485b9ae38 sp=0x7fc485b9ae00 pc=0x40c3ff
runtime.templateThread()
/home/kirr/src/tools/go/go1.14/src/runtime/proc.go:1830 +0xf2 fp=0x7fc485b9ae58 sp=0x7fc485b9ae38 pc=0x43b362
runtime.mstart1()
/home/kirr/src/tools/go/go1.14/src/runtime/proc.go:1112 +0xc3 fp=0x7fc485b9ae80 sp=0x7fc485b9ae58 pc=0x439ef3
runtime.mstart()
/home/kirr/src/tools/go/go1.14/src/runtime/proc.go:1077 +0x6e fp=0x7fc485b9aea8 sp=0x7fc485b9ae80 pc=0x439e0e
rax 0xca
rbx 0xc000036a80
rcx 0x468cf3
rdx 0x0
rdi 0x7f1cd8
rsi 0x80
rbp 0x7fc485b9adf0
rsp 0x7fc485b9ada8
r8 0x0
r9 0x0
r10 0x0
r11 0x286
r12 0xc000001380
r13 0x7ffc0d873acf
r14 0x7fc485b9afc0
r15 0x802000
rip 0x468cf1
rflags 0x286
cs 0x33
fs 0x0
gs 0x0
-----
SIGQUIT: quit
PC=0x468cf1 m=5 sigcode=0
goroutine 0 [idle]:
runtime.futex(0xc000089d48, 0x80, 0x0, 0x0, 0xc000000000, 0xc0000f0f00, 0x7fc485359e30, 0x43f9d0, 0x7fc485359e10, 0x40c3ff, ...)
/home/kirr/src/tools/go/go1.14/src/runtime/sys_linux_amd64.s:567 +0x21 fp=0x7fc485359d98 sp=0x7fc485359d90 pc=0x468cf1
runtime.futexsleep(0xc000089d48, 0x7fc400000000, 0xffffffffffffffff)
/home/kirr/src/tools/go/go1.14/src/runtime/os_linux.go:45 +0x46 fp=0x7fc485359de8 sp=0x7fc485359d98 pc=0x4313a6
runtime.notesleep(0xc000089d48)
/home/kirr/src/tools/go/go1.14/src/runtime/lock_futex.go:151 +0x9f fp=0x7fc485359e20 sp=0x7fc485359de8 pc=0x40c3ff
runtime.stopm()
/home/kirr/src/tools/go/go1.14/src/runtime/proc.go:1852 +0xc0 fp=0x7fc485359e48 sp=0x7fc485359e20 pc=0x43b440
runtime.exitsyscall0(0xc000001800)
/home/kirr/src/tools/go/go1.14/src/runtime/proc.go:3301 +0x111 fp=0x7fc485359e78 sp=0x7fc485359e48 pc=0x43f2e1
runtime.mcall(0x800000)
/home/kirr/src/tools/go/go1.14/src/runtime/asm_amd64.s:318 +0x5b fp=0x7fc485359e88 sp=0x7fc485359e78 pc=0x464a5b
rax 0xca
rbx 0xc000089c00
rcx 0x468cf3
rdx 0x0
rdi 0xc000089d48
rsi 0x80
rbp 0x7fc485359dd8
rsp 0x7fc485359d90
r8 0x0
r9 0x0
r10 0x0
r11 0x286
r12 0xffffffffffffffff
r13 0x14
r14 0x13
r15 0x40
rip 0x468cf1
rflags 0x286
cs 0x33
fs 0x0
gs 0x0
-----
FAIL github.com/hanwen/go-fuse/fuse/test 121.994s
FAIL |
|
Looks like the hang in chdir, |
hanwen
pushed a commit
that referenced
this issue
Oct 7, 2020
GOMAXPROCS=1 currently triggers tests hang: #261 Change-Id: I3dc98c8bbdaac7a4ce86639e405ba1a1cef4c295
hanwen
pushed a commit
that referenced
this issue
Oct 7, 2020
…RALLEL_DIROPS
If kernel internally serializes lookup requests for a directory, the
test will deadlock, becaue it tries to issue two such request and pause
lookup handlers, untill both requests come in.
For example here is how this test hangs on Ubuntu Xenial 16.04:
kirr@kubu:~/t/go-fuse$ go test -count=1 -v -run TestNodeParallelLookup ./fuse/test/
=== RUN TestNodeParallelLookup
18:24:38.494651 rx 1: INIT i0 {7.23 Ra 0x20000 POSIX_LOCKS,ATOMIC_O_TRUNC,EXPORT_SUPPORT,DONT_MASK,FLOCK_LOCKS,READDIRPLUS_AUTO,ASYNC_DIO,WRITEBACK_CACHE,SPLICE_WRITE,SPLICE_READ,IOCTL_DIR,AUTO_INVAL_DATA,READDIRPLUS,NO_OPEN_SUPPORT,ASYNC_READ,BIG_WRITES,SPLICE_MOVE}
18:24:38.494713 tx 1: OK, {7.23 Ra 0x20000 ASYNC_READ,BIG_WRITES,AUTO_INVAL_DATA,READDIRPLUS,NO_OPEN_SUPPORT 0/0 Wr 0x10000 Tg 0x0}
18:24:38.495351 rx 2: LOOKUP i1 [".go-fuse-epoll-hack"] 20b
18:24:38.495467 tx 2: OK, {i18446744073709551615 g0 tE=0s tA=0s {M0100644 SZ=0 L=1 0:0 B0*0 i0:18446744073709551615 A 0.000000 M 0.000000 C 0.000000}}
18:24:38.495530 rx 3: OPEN i18446744073709551615 {O_RDONLY,0x8000}
18:24:38.495575 tx 3: OK, {Fh 18446744073709551615 }
18:24:38.495624 rx 4: POLL i18446744073709551615
18:24:38.495659 tx 4: 38=function not implemented
18:24:38.495706 rx 5: FLUSH i18446744073709551615 {Fh 18446744073709551615}
18:24:38.495741 tx 5: 34=numerical result out of range
18:24:38.495812 rx 6: RELEASE i18446744073709551615 {Fh 18446744073709551615 0x8000 L0}
18:24:38.495849 tx 6: 34=numerical result out of range
18:24:38.495904 rx 7: LOOKUP i1 ["world"] 6b
18:24:38.495957 I: <- lookup "world"
< hang >
Amends: 17c0c40 (nodefs: Allow for several Lookup requests to be served simultaneously)
Updates: #261
Change-Id: I5d0a76d1190af805351326c378f69cf8ff781a37
hanwen
pushed a commit
that referenced
this issue
Jul 30, 2021
This GOMAXPROCS=1 go test -v -count=1 -run TestDeleteNotify ./fuse/test deadlocked reliably, apparently in the chdir() from cmd.Start(). We can do without the chdir() by using an absolte path. This avoids the issue. Fixes #261 Change-Id: Ia9c8f15819c125c5bf94b085fa4c5f2977a6789a
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
I was trying to run go-fuse testsuite in repeated mode and after some 10-20-30 iterations the tests get stuck:
inspecting the stuck process a bit:
i.e. single thread.
i.e. it is blocked in a syscall. Syscall details:
I had only a brief quick look and had not inspected further.
The text was updated successfully, but these errors were encountered: