ovh / svfs

The Swift Virtual File System
Other
375 stars 54 forks source link

Crash on map write (race condition) #74

Closed speed47 closed 8 years ago

speed47 commented 8 years ago

Context

  1. mount
  2. rsync data to hubic (-rtW --inplace)
  3. after some time, svfs crashes

    Results you expected :

no crash

Results you observed :

crash

Debug log :

This is a golang trace. You seem to miss a mutex when writing to some map. The problem may have existed since a long time, as runtime data race detection has been added to golang in v1.6.

fatal error: concurrent map writes

goroutine 191452 [running]:
runtime.throw(0x999b80, 0x15)
        /home/admin/.gvm/gos/go1.6.2/src/runtime/panic.go:547 +0x90 fp=0xc82ab3b160 sp=0xc82ab3b148
runtime.mapdelete(0x7cea20, 0xc82001b6b0, 0xc82ab3b1f8)
        /home/admin/.gvm/gos/go1.6.2/src/runtime/hashmap.go:559 +0x5a fp=0xc82ab3b1c0 sp=0xc82ab3b160
github.com/ovh/svfs/svfs.(*SimpleCache).Remove(0xc82002a058, 0x7ffd94a14406, 0x7, 0xc82aa85200, 0x55)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/cache.go:191 +0x84 fp=0xc82ab3b210 sp=0xc82ab3b1c0
github.com/ovh/svfs/svfs.(*ObjectHandle).Release(0xc8205a86c0, 0x7f93c5c6a1f0, 0xc823383980, 0xc82ad150e0, 0x0, 0x0)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/handle.go:56 +0x1c9 fp=0xc82ab3b278 sp=0xc82ab3b210
github.com/ovh/svfs/vendor/bazil.org/fuse/fs.(*Server).handleRequest(0xc82113ef00, 0x7f93c5c6a1f0, 0xc823383980, 0x7f93c5c6fce0, 0xc82a9a2de0, 0xc82a9998c0, 0x7f93c5c6a458, 0xc82ad150e0, 0xc82ab3bec8, 0x0, ...)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/vendor/bazil.org/fuse/fs/serve.go:1288 +0x3e50 fp=0xc82ab3bd88 sp=0xc82ab3b278
github.com/ovh/svfs/vendor/bazil.org/fuse/fs.(*Server).serve(0xc82113ef00, 0x7f93c5c6a458, 0xc82ad150e0)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/vendor/bazil.org/fuse/fs/serve.go:871 +0x740 fp=0xc82ab3bf68 sp=0xc82ab3bd88
github.com/ovh/svfs/vendor/bazil.org/fuse/fs.(*Server).Serve.func1(0xc82113ef00, 0x7f93c5c6a458, 0xc82ad150e0)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/vendor/bazil.org/fuse/fs/serve.go:418 +0x6d fp=0xc82ab3bf88 sp=0xc82ab3bf68
runtime.goexit()
        /home/admin/.gvm/gos/go1.6.2/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc82ab3bf90 sp=0xc82ab3bf88
created by github.com/ovh/svfs/vendor/bazil.org/fuse/fs.(*Server).Serve
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/vendor/bazil.org/fuse/fs/serve.go:419 +0x580

goroutine 1 [syscall]:
syscall.Syscall(0x0, 0x7, 0xc821210000, 0x1001000, 0xc84ad1a060, 0x1001000, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/syscall/asm_linux_amd64.s:18 +0x5
syscall.read(0x7, 0xc821210000, 0x1001000, 0x1001000, 0xc82005e528, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/syscall/zsyscall_linux_amd64.go:783 +0x5f
syscall.Read(0x7, 0xc821210000, 0x1001000, 0x1001000, 0x20000, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/syscall/syscall_unix.go:161 +0x4d
github.com/ovh/svfs/vendor/bazil.org/fuse.(*Conn).ReadRequest(0xc82005e4e0, 0x0, 0x0, 0x0, 0x0)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/vendor/bazil.org/fuse/fuse.go:555 +0xf3
github.com/ovh/svfs/vendor/bazil.org/fuse/fs.(*Server).Serve(0xc82113ef00, 0x7f93c5cb06e8, 0xbe7188, 0x0, 0x0)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/vendor/bazil.org/fuse/fs/serve.go:407 +0x456
main.main()
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/main.go:192 +0x6fa

goroutine 17 [syscall, 593 minutes, locked to thread]:
runtime.goexit()
        /home/admin/.gvm/gos/go1.6.2/src/runtime/asm_amd64.s:1998 +0x1

goroutine 20 [chan receive, 174 minutes]:
github.com/ovh/svfs/svfs.processTasks(0xc82112e000)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:48 +0x76
created by github.com/ovh/svfs/svfs.(*Lister).Start
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:31 +0x87

goroutine 21 [chan receive, 175 minutes]:
github.com/ovh/svfs/svfs.processTasks(0xc82112e000)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:48 +0x76
created by github.com/ovh/svfs/svfs.(*Lister).Start
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:31 +0x87

goroutine 22 [chan receive, 173 minutes]:
github.com/ovh/svfs/svfs.processTasks(0xc82112e000)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:48 +0x76
created by github.com/ovh/svfs/svfs.(*Lister).Start
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:31 +0x87

goroutine 23 [chan receive, 173 minutes]:
github.com/ovh/svfs/svfs.processTasks(0xc82112e000)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:48 +0x76
created by github.com/ovh/svfs/svfs.(*Lister).Start
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:31 +0x87

goroutine 24 [chan receive, 172 minutes]:
github.com/ovh/svfs/svfs.processTasks(0xc82112e000)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:48 +0x76
created by github.com/ovh/svfs/svfs.(*Lister).Start
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:31 +0x87

goroutine 25 [chan receive, 172 minutes]:
github.com/ovh/svfs/svfs.processTasks(0xc82112e000)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:48 +0x76
created by github.com/ovh/svfs/svfs.(*Lister).Start
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:31 +0x87

goroutine 26 [chan receive, 29 minutes]:
github.com/ovh/svfs/svfs.processTasks(0xc82112e000)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:48 +0x76
created by github.com/ovh/svfs/svfs.(*Lister).Start
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:31 +0x87

goroutine 27 [chan receive, 169 minutes]:
github.com/ovh/svfs/svfs.processTasks(0xc82112e000)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:48 +0x76
created by github.com/ovh/svfs/svfs.(*Lister).Start
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:31 +0x87

goroutine 28 [chan receive, 28 minutes]:
github.com/ovh/svfs/svfs.processTasks(0xc82112e000)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:48 +0x76
created by github.com/ovh/svfs/svfs.(*Lister).Start
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:31 +0x87

goroutine 29 [chan receive]:
github.com/ovh/svfs/svfs.processTasks(0xc82112e000)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:48 +0x76
created by github.com/ovh/svfs/svfs.(*Lister).Start
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:31 +0x87

goroutine 30 [chan receive]:
github.com/ovh/svfs/svfs.processTasks(0xc82112e000)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:48 +0x76
created by github.com/ovh/svfs/svfs.(*Lister).Start
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:31 +0x87

goroutine 31 [chan receive, 10 minutes]:
github.com/ovh/svfs/svfs.processTasks(0xc82112e000)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:48 +0x76
created by github.com/ovh/svfs/svfs.(*Lister).Start
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:31 +0x87

goroutine 32 [chan receive, 8 minutes]:
github.com/ovh/svfs/svfs.processTasks(0xc82112e000)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:48 +0x76
created by github.com/ovh/svfs/svfs.(*Lister).Start
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:31 +0x87

goroutine 33 [chan receive, 11 minutes]:
github.com/ovh/svfs/svfs.processTasks(0xc82112e000)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:48 +0x76
created by github.com/ovh/svfs/svfs.(*Lister).Start
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:31 +0x87

goroutine 34 [chan receive, 29 minutes]:
github.com/ovh/svfs/svfs.processTasks(0xc82112e000)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:48 +0x76
created by github.com/ovh/svfs/svfs.(*Lister).Start
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:31 +0x87

goroutine 35 [chan receive, 12 minutes]:
github.com/ovh/svfs/svfs.processTasks(0xc82112e000)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:48 +0x76
created by github.com/ovh/svfs/svfs.(*Lister).Start
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:31 +0x87

goroutine 36 [chan receive, 3 minutes]:
github.com/ovh/svfs/svfs.processTasks(0xc82112e000)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:48 +0x76
created by github.com/ovh/svfs/svfs.(*Lister).Start
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:31 +0x87

goroutine 37 [chan receive, 5 minutes]:
github.com/ovh/svfs/svfs.processTasks(0xc82112e000)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:48 +0x76
created by github.com/ovh/svfs/svfs.(*Lister).Start
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:31 +0x87

goroutine 38 [chan receive, 6 minutes]:
github.com/ovh/svfs/svfs.processTasks(0xc82112e000)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:48 +0x76
created by github.com/ovh/svfs/svfs.(*Lister).Start
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:31 +0x87

goroutine 39 [chan receive, 5 minutes]:
github.com/ovh/svfs/svfs.processTasks(0xc82112e000)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:48 +0x76
created by github.com/ovh/svfs/svfs.(*Lister).Start
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:31 +0x87

goroutine 191258 [select]:
github.com/ovh/svfs/vendor/github.com/xlucas/swift.(*Connection).doTimeoutRequest(0xc82000ca00, 0xc82a9a1f80, 0xc836f4c7e0, 0xc8201ea160, 0x0, 0x0)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/vendor/github.com/xlucas/swift/swift.go:231 +0x21e
github.com/ovh/svfs/vendor/github.com/xlucas/swift.(*Connection).Call(0xc82000ca00, 0xc8201cb220, 0x45, 0x7ffd94a14406, 0x7, 0xc82aa85200, 0x55, 0x93d268, 0x3, 0x0, ...)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/vendor/github.com/xlucas/swift/swift.go:509 +0xa21
github.com/ovh/svfs/vendor/github.com/xlucas/swift.(*Connection).storage(0xc82000ca00, 0x7ffd94a14406, 0x7, 0xc82aa85200, 0x55, 0x93d268, 0x3, 0x0, 0xc820371a10, 0xc82001b650, ...)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/vendor/github.com/xlucas/swift/swift.go:568 +0x128
github.com/ovh/svfs/vendor/github.com/xlucas/swift.(*Connection).ObjectCreate.func1(0xc82002a988, 0xc82000ca00, 0x7ffd94a14406, 0x7, 0xc82aa85200, 0x55, 0xc820371a10, 0xc82002a990)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/vendor/github.com/xlucas/swift/swift.go:1215 +0x102
created by github.com/ovh/svfs/vendor/github.com/xlucas/swift.(*Connection).ObjectCreate
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/vendor/github.com/xlucas/swift/swift.go:1219 +0x436

goroutine 191273 [select]:
net/http.(*persistConn).writeLoop(0xc82ac665b0)
        /home/admin/.gvm/gos/go1.6.2/src/net/http/transport.go:1277 +0x472
created by net/http.(*Transport).dialConn
        /home/admin/.gvm/gos/go1.6.2/src/net/http/transport.go:858 +0x10cb

goroutine 191478 [IO wait]:
net.runtime_pollWait(0x7f93c5c61658, 0x77, 0x694ab4)
        /home/admin/.gvm/gos/go1.6.2/src/runtime/netpoll.go:160 +0x60
net.(*pollDesc).Wait(0xc82322a4c0, 0x77, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/net/fd_poll_runtime.go:73 +0x3a
net.(*pollDesc).WaitWrite(0xc82322a4c0, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/net/fd_poll_runtime.go:82 +0x36
net.(*netFD).connect(0xc82322a460, 0x0, 0x0, 0x7f93c5c69460, 0xc82322c440, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
        /home/admin/.gvm/gos/go1.6.2/src/net/fd_unix.go:127 +0x28e
net.(*netFD).dial(0xc82322a460, 0x7f93c5ca6f08, 0x0, 0x7f93c5ca6f08, 0xc8201fd740, 0x0, 0xc800000000, 0x0, 0x0, 0x0, ...)
        /home/admin/.gvm/gos/go1.6.2/src/net/sock_posix.go:137 +0x364
net.socket(0x943200, 0x3, 0x2, 0x1, 0x0, 0xc8201fd700, 0x7f93c5ca6f08, 0x0, 0x7f93c5ca6f08, 0xc8201fd740, ...)
        /home/admin/.gvm/gos/go1.6.2/src/net/sock_posix.go:89 +0x429
net.internetSocket(0x943200, 0x3, 0x7f93c5ca6f08, 0x0, 0x7f93c5ca6f08, 0xc8201fd740, 0x0, 0xc800000000, 0x0, 0x1, ...)
        /home/admin/.gvm/gos/go1.6.2/src/net/ipsock_posix.go:161 +0x153
net.dialTCP(0x943200, 0x3, 0x0, 0xc8201fd740, 0x0, 0x0, 0x0, 0x0, 0x10, 0x0, ...)
        /home/admin/.gvm/gos/go1.6.2/src/net/tcpsock_posix.go:171 +0x12b
net.dialSingle(0xc820457e60, 0x7f93c5ca6e78, 0xc8201fd740, 0x0, 0x7ffd00000000, 0x0, 0x0, 0x0, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/net/dial.go:371 +0x40c
net.dialSerial.func1(0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/net/dial.go:343 +0x75
net.dial(0x943200, 0x3, 0x7f93c5ca6e78, 0xc8201fd740, 0xc82322c420, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
        /home/admin/.gvm/gos/go1.6.2/src/net/fd_unix.go:40 +0x60
net.dialSerial(0xc820457e60, 0xc82383fb00, 0xa, 0x10, 0x0, 0x0, 0x0, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/net/dial.go:345 +0x7d0
net.(*Dialer).Dial(0xc82072f868, 0x943200, 0x3, 0xc82ab45620, 0x18, 0x0, 0x0, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/net/dial.go:239 +0x512
net.Dial(0x943200, 0x3, 0xc82ab45620, 0x18, 0x0, 0x0, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/net/dial.go:193 +0x96
net/http.(*Transport).dial(0xc82113e000, 0x943200, 0x3, 0xc82ab45620, 0x18, 0x0, 0x0, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/net/http/transport.go:665 +0x1d3
net/http.(*Transport).dialConn(0xc82113e000, 0x0, 0xc820fab600, 0x5, 0xc82ab45620, 0x18, 0xc8201fc780, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/net/http/transport.go:762 +0x1e3d
net/http.(*Transport).getConn.func4(0xc82113e000, 0x0, 0xc820fab600, 0x5, 0xc82ab45620, 0x18, 0xc82ad269c0)
        /home/admin/.gvm/gos/go1.6.2/src/net/http/transport.go:706 +0x66
created by net/http.(*Transport).getConn
        /home/admin/.gvm/gos/go1.6.2/src/net/http/transport.go:708 +0x262

goroutine 191454 [chan receive]:
github.com/ovh/svfs/vendor/github.com/xlucas/swift.(*ObjectCreateFile).Close(0xc82adf91d0, 0x0, 0x0)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/vendor/github.com/xlucas/swift/swift.go:1130 +0xa2
github.com/ovh/svfs/svfs.(*ObjectHandle).Release(0xc8205a8780, 0x7f93c5c6a1f0, 0xc82adcbbc0, 0xc82ad151d0, 0x0, 0x0)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/handle.go:51 +0xd0
github.com/ovh/svfs/vendor/bazil.org/fuse/fs.(*Server).handleRequest(0xc82113ef00, 0x7f93c5c6a1f0, 0xc82adcbbc0, 0x7f93c5c6fce0, 0xc82a9a2de0, 0xc82a9998c0, 0x7f93c5c6a458, 0xc82ad151d0, 0xc820731ec8, 0x0, ...)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/vendor/bazil.org/fuse/fs/serve.go:1288 +0x3e50
github.com/ovh/svfs/vendor/bazil.org/fuse/fs.(*Server).serve(0xc82113ef00, 0x7f93c5c6a458, 0xc82ad151d0)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/vendor/bazil.org/fuse/fs/serve.go:871 +0x740
github.com/ovh/svfs/vendor/bazil.org/fuse/fs.(*Server).Serve.func1(0xc82113ef00, 0x7f93c5c6a458, 0xc82ad151d0)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/vendor/bazil.org/fuse/fs/serve.go:418 +0x6d
created by github.com/ovh/svfs/vendor/bazil.org/fuse/fs.(*Server).Serve
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/vendor/bazil.org/fuse/fs/serve.go:419 +0x580

goroutine 191477 [select]:
net/http.(*Transport).getConn(0xc82113e000, 0xc836f4ca80, 0x0, 0xc820fab600, 0x5, 0xc82ab45620, 0x18, 0x0, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/net/http/transport.go:711 +0x4ef
net/http.(*Transport).RoundTrip(0xc82113e000, 0xc836f4ca80, 0xc82113e000, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/net/http/transport.go:311 +0x7e9
net/http.send(0xc836f4ca80, 0x7f93c5ca5550, 0xc82113e000, 0x0, 0x0, 0x0, 0xc820fab6b0, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/net/http/client.go:260 +0x6b7
net/http.(*Client).send(0xc82011c090, 0xc836f4ca80, 0x0, 0x0, 0x0, 0x20, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/net/http/client.go:155 +0x185
net/http.(*Client).doFollowingRedirects(0xc82011c090, 0xc836f4ca80, 0xa23540, 0x0, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/net/http/client.go:475 +0x8a4
net/http.(*Client).Do(0xc82011c090, 0xc836f4ca80, 0xc82002aa28, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/net/http/client.go:191 +0x1e4
github.com/ovh/svfs/vendor/github.com/xlucas/swift.(*Connection).doTimeoutRequest.func1(0xc82000ca00, 0xc836f4ca80, 0xc82ad26960)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/vendor/github.com/xlucas/swift/swift.go:227 +0x36
created by github.com/ovh/svfs/vendor/github.com/xlucas/swift.(*Connection).doTimeoutRequest
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/vendor/github.com/xlucas/swift/swift.go:229 +0x8b

goroutine 191475 [semacquire]:
sync.runtime_Syncsemacquire(0xc8207caf78)
        /home/admin/.gvm/gos/go1.6.2/src/runtime/sema.go:241 +0x201
sync.(*Cond).Wait(0xc8207caf68)
        /home/admin/.gvm/gos/go1.6.2/src/sync/cond.go:63 +0x9b
io.(*pipe).write(0xc8207caf00, 0xc82384e050, 0x1fff0, 0x1000fb0, 0x0, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/io/pipe.go:94 +0x23a
io.(*PipeWriter).Write(0xc82002aa30, 0xc82384e050, 0x1fff0, 0x1000fb0, 0x0, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/io/pipe.go:161 +0x50
github.com/ovh/svfs/vendor/github.com/xlucas/swift.(*ObjectCreateFile).Write(0xc82ad15400, 0xc82384e050, 0x1fff0, 0x1000fb0, 0x0, 0x0, 0x0)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/vendor/github.com/xlucas/swift/swift.go:1105 +0x61
github.com/ovh/svfs/svfs.(*ObjectHandle).Write(0xc82ad266c0, 0x7f93c5c6a1f0, 0xc82adcbc00, 0xc82ab49dc0, 0xc82ad23d58, 0x0, 0x0)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/handle.go:87 +0x118
github.com/ovh/svfs/vendor/bazil.org/fuse/fs.(*Server).handleRequest(0xc82113ef00, 0x7f93c5c6a1f0, 0xc82adcbc00, 0x7f93c5c6fce0, 0xc82a9a2ea0, 0xc82adcba00, 0x7f93c5cb4e18, 0xc82ab49dc0, 0xc82a937ec8, 0x0, ...)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/vendor/bazil.org/fuse/fs/serve.go:1252 +0x2538
github.com/ovh/svfs/vendor/bazil.org/fuse/fs.(*Server).serve(0xc82113ef00, 0x7f93c5cb4e18, 0xc82ab49dc0)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/vendor/bazil.org/fuse/fs/serve.go:871 +0x740
github.com/ovh/svfs/vendor/bazil.org/fuse/fs.(*Server).Serve.func1(0xc82113ef00, 0x7f93c5cb4e18, 0xc82ab49dc0)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/vendor/bazil.org/fuse/fs/serve.go:418 +0x6d
created by github.com/ovh/svfs/vendor/bazil.org/fuse/fs.(*Server).Serve
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/vendor/bazil.org/fuse/fs/serve.go:419 +0x580

goroutine 191476 [select]:
github.com/ovh/svfs/vendor/github.com/xlucas/swift.(*Connection).doTimeoutRequest(0xc82000ca00, 0xc82adcbc80, 0xc836f4ca80, 0xc8201ea160, 0x0, 0x0)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/vendor/github.com/xlucas/swift/swift.go:231 +0x21e
github.com/ovh/svfs/vendor/github.com/xlucas/swift.(*Connection).Call(0xc82000ca00, 0xc8201cb220, 0x45, 0x7ffd94a14406, 0x7, 0xc82aa85260, 0x55, 0x93d268, 0x3, 0x0, ...)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/vendor/github.com/xlucas/swift/swift.go:509 +0xa21
github.com/ovh/svfs/vendor/github.com/xlucas/swift.(*Connection).storage(0xc82000ca00, 0x7ffd94a14406, 0x7, 0xc82aa85260, 0x55, 0x93d268, 0x3, 0x0, 0xc8201fc780, 0xc82001b650, ...)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/vendor/github.com/xlucas/swift/swift.go:568 +0x128
github.com/ovh/svfs/vendor/github.com/xlucas/swift.(*Connection).ObjectCreate.func1(0xc82002aa20, 0xc82000ca00, 0x7ffd94a14406, 0x7, 0xc82aa85260, 0x55, 0xc8201fc780, 0xc82002aa28)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/vendor/github.com/xlucas/swift/swift.go:1215 +0x102
created by github.com/ovh/svfs/vendor/github.com/xlucas/swift.(*Connection).ObjectCreate
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/vendor/github.com/xlucas/swift/swift.go:1219 +0x436

goroutine 191272 [IO wait]:
net.runtime_pollWait(0x7f93c5c61c58, 0x72, 0xc8205ae400)
        /home/admin/.gvm/gos/go1.6.2/src/runtime/netpoll.go:160 +0x60
net.(*pollDesc).Wait(0xc82059b5d0, 0x72, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/net/fd_poll_runtime.go:73 +0x3a
net.(*pollDesc).WaitRead(0xc82059b5d0, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/net/fd_poll_runtime.go:78 +0x36
net.(*netFD).Read(0xc82059b570, 0xc8205ae400, 0x400, 0x400, 0x0, 0x7f93c5ca1050, 0xc8200101a0)
        /home/admin/.gvm/gos/go1.6.2/src/net/fd_unix.go:250 +0x23a
net.(*conn).Read(0xc820118c50, 0xc8205ae400, 0x400, 0x400, 0x0, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/net/net.go:172 +0xe4
crypto/tls.(*block).readFromUntil(0xc820273230, 0x7f93c5c69508, 0xc820118c50, 0x5, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/crypto/tls/conn.go:460 +0xcc
crypto/tls.(*Conn).readRecord(0xc8207d7800, 0xa23a17, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/crypto/tls/conn.go:562 +0x2d1
crypto/tls.(*Conn).Read(0xc8207d7800, 0xc838578000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/crypto/tls/conn.go:939 +0x167
net/http.noteEOFReader.Read(0x7f93c5cb04a8, 0xc8207d7800, 0xc82ac66618, 0xc838578000, 0x1000, 0x1000, 0x60, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/net/http/transport.go:1687 +0x67
net/http.(*noteEOFReader).Read(0xc838a0bf80, 0xc838578000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        <autogenerated>:284 +0xd0
bufio.(*Reader).fill(0xc8205a9260)
        /home/admin/.gvm/gos/go1.6.2/src/bufio/bufio.go:97 +0x1e9
bufio.(*Reader).Peek(0xc8205a9260, 0x1, 0x0, 0x0, 0x0, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/bufio/bufio.go:132 +0xcc
net/http.(*persistConn).readLoop(0xc82ac665b0)
        /home/admin/.gvm/gos/go1.6.2/src/net/http/transport.go:1073 +0x177
created by net/http.(*Transport).dialConn
        /home/admin/.gvm/gos/go1.6.2/src/net/http/transport.go:857 +0x10a6

goroutine 191259 [select]:
net/http.(*persistConn).roundTrip(0xc82ac665b0, 0xc8205ac010, 0x0, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/net/http/transport.go:1473 +0xf1f
net/http.(*Transport).RoundTrip(0xc82113e000, 0xc836f4c7e0, 0xc82113e000, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/net/http/transport.go:324 +0x9bb
net/http.send(0xc836f4c7e0, 0x7f93c5ca5550, 0xc82113e000, 0x0, 0x0, 0x0, 0xc820fab550, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/net/http/client.go:260 +0x6b7
net/http.(*Client).send(0xc82011c090, 0xc836f4c7e0, 0x0, 0x0, 0x0, 0x20, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/net/http/client.go:155 +0x185
net/http.(*Client).doFollowingRedirects(0xc82011c090, 0xc836f4c7e0, 0xa23540, 0x0, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/net/http/client.go:475 +0x8a4
net/http.(*Client).Do(0xc82011c090, 0xc836f4c7e0, 0xc82002a990, 0x0, 0x0)
        /home/admin/.gvm/gos/go1.6.2/src/net/http/client.go:191 +0x1e4
github.com/ovh/svfs/vendor/github.com/xlucas/swift.(*Connection).doTimeoutRequest.func1(0xc82000ca00, 0xc836f4c7e0, 0xc82adf3aa0)
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/vendor/github.com/xlucas/swift/swift.go:227 +0x36
created by github.com/ovh/svfs/vendor/github.com/xlucas/swift.(*Connection).doTimeoutRequest
        /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/vendor/github.com/xlucas/swift/swift.go:229 +0x8b
xlucas commented 8 years ago

Thanks for reporting this, it'll be fixed in the next release.

speed47 commented 8 years ago

I've just tried v0.7.1 and I have bad news: it didn't just crash, it actually almost crashed my entire machine. But the kernel succeeded in killing svfs after 10 minutes of oom condition : [3219249.984164] Killed process 20716 (svfs) total-vm:2211136kB, anon-rss:1914140kB, file-rss:4kB. I suspect a goroutine number explosion because of some global deadlock due to the new locks you added to fix this issue. I'll try to get more details on this issue between the moment it starts to get out of hand and before it brings the kernel on its knees and makes the host unusable.

speed47 commented 8 years ago

I managed to capture a moment with almost 2000 goroutines.

while : ; do echo $(ps faxu | awk '/ svfs/ {if($6>10000){print $6}}') mb ; nb=$(curl -sL localhost:12131/debug/pprof/goroutine?debug=1 | awk '/gorou/ {print $4}') ; echo $nb goroutines; [ $nb -gt 400 ] || continue ; echo WOW $nb ; for i in block goroutine heap threadcreate ; do curl -sL http://localhost:12131/debug/pprof/$i?debug=1 > svfs.$i ; done ; pkill svfs ; break ; done

Usually it's around 30 goroutines, but sometimes the number of goroutines seems to explode very quickly, along with the RAM usage.

Among the 2K goroutines, more than 1800 are actually executing this: # 0x531bc9 github.com/ovh/svfs/svfs.(*Lister).AddTask.func1+0x69 /home/admin/.gvm/pkgsets/go1.6.2/global/src/github.com/ovh/svfs/svfs/lister.go:43

pprof debug files attached.

svfs.block.txt svfs.goroutine.txt svfs.heap.txt svfs.threadcreate.txt

xlucas commented 8 years ago

I don't think this behavior is caused by the previous fix. I would say the directory lister has not enough workers and listing tasks are piling up due to asynchronous task add.

Just to get some context, what are you mount options ? How many files/directories do you have in your container(s) ?

Thanks for bringing these pprof extracts.

speed47 commented 8 years ago

This is an rsync of 100G of photos, with 30K files in 900 directories. There are no "huge" directories with thousands of files. Mount options from fstab:

noauto,users,hubic_auth=X,hubic_token=Y,container=default,uid=speed,extra_attr,hubic_times,profile_addr=127.0.0.1:12131,profile_cpu=/dev/shm/sfvs.cpu,profile_ram=/dev/shm/svfs.ram

profile_* options were only added for the above bug report, the crash happens without.

speed47 commented 8 years ago

To reproduce: rsync -rW --inplace --size-only --progress localdir/ hubicdir/ and running a concurrent du -shc hubicdir/ at the same time seems to trigger the issue more easily

xlucas commented 8 years ago

There's indeed something wrong going on.

Below is the GC activity while running while : ; do tree container; done. Heap is progressively draining a large amount of memory from the operation system and as heap size continues growing with allocation spikes, it's never returned to the OS due to the way go GC works.

svfs

I'll take a look at the go routine count.

xlucas commented 8 years ago

I tracked this down to be mainly related to overallocation of receive message buffers in the FUSE library (16 MiB by default). With 353aba9, memory consumption drops by a ratio of 20 and CPU usage by 3. Some work still need to be done in svfs to reduce nodes structs sizes and optimize caching.