experiencing lockups

[cryfs]

experiencing lockups

[smessmer]

Yes, that works fine for me. Can you start CryFS in debug mode

cryfs basedir mountdir -- -d

and once it hangs (i.e. no new output lines), paste the output to http://pastebin.com/ ?

[mhogomchungu]

It just locked again with 160MB of log file size and i dont think pastebin will be happy with the size if they can accept it.The last 100 lines of the logfile is below

[mtz@ink ~]$ du log         
160M    log
[mtz@ink ~]$ tail -n 100 log
   unique: 860834, success, outsize: 24
unique: 860835, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28233728 flags: 0x8001
   write[32] 4096 bytes to 28233728
   unique: 860835, success, outsize: 24
unique: 860836, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28237824 flags: 0x8001
   write[32] 4096 bytes to 28237824
   unique: 860836, success, outsize: 24
unique: 860837, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28241920 flags: 0x8001
   write[32] 4096 bytes to 28241920
   unique: 860837, success, outsize: 24
unique: 860838, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28246016 flags: 0x8001
   write[32] 4096 bytes to 28246016
   unique: 860838, success, outsize: 24
unique: 860839, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28250112 flags: 0x8001
   write[32] 4096 bytes to 28250112
   unique: 860839, success, outsize: 24
unique: 860840, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28254208 flags: 0x8001
   write[32] 4096 bytes to 28254208
   unique: 860840, success, outsize: 24
unique: 860841, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28258304 flags: 0x8001
   write[32] 4096 bytes to 28258304
   unique: 860841, success, outsize: 24
unique: 860842, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28262400 flags: 0x8001
   write[32] 4096 bytes to 28262400
   unique: 860842, success, outsize: 24
unique: 860843, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28266496 flags: 0x8001
   write[32] 4096 bytes to 28266496
   unique: 860843, success, outsize: 24
unique: 860844, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28270592 flags: 0x8001
   write[32] 4096 bytes to 28270592
   unique: 860844, success, outsize: 24
unique: 860845, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28274688 flags: 0x8001
   write[32] 4096 bytes to 28274688
   unique: 860845, success, outsize: 24
unique: 860846, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28278784 flags: 0x8001
   write[32] 4096 bytes to 28278784
   unique: 860846, success, outsize: 24
unique: 860847, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28282880 flags: 0x8001
   write[32] 4096 bytes to 28282880
   unique: 860847, success, outsize: 24
unique: 860848, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28286976 flags: 0x8001
   write[32] 4096 bytes to 28286976
   unique: 860848, success, outsize: 24
unique: 860849, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28291072 flags: 0x8001
   write[32] 4096 bytes to 28291072
   unique: 860849, success, outsize: 24
unique: 860850, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28295168 flags: 0x8001
   write[32] 4096 bytes to 28295168
   unique: 860850, success, outsize: 24
unique: 860851, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28299264 flags: 0x8001
   write[32] 4096 bytes to 28299264
   unique: 860851, success, outsize: 24
unique: 860852, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28303360 flags: 0x8001
   write[32] 4096 bytes to 28303360
   unique: 860852, success, outsize: 24
unique: 860853, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28307456 flags: 0x8001
   write[32] 4096 bytes to 28307456
   unique: 860853, success, outsize: 24
unique: 860854, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28311552 flags: 0x8001
   write[32] 4096 bytes to 28311552
   unique: 860854, success, outsize: 24
unique: 860855, opcode: WRITE (16), nodeid: 34, insize: 2396, pid: 7347
write[32] 2316 bytes to 28315648 flags: 0x8001
   write[32] 2316 bytes to 28315648
   unique: 860855, success, outsize: 24
unique: 860856, opcode: FLUSH (25), nodeid: 34, insize: 64, pid: 7347
flush[32]
   unique: 860856, success, outsize: 16
unique: 860857, opcode: RELEASE (18), nodeid: 34, insize: 64, pid: 0
release[32] flags: 0x8001
   unique: 860857, success, outsize: 16
unique: 860858, opcode: LOOKUP (1), nodeid: 1, insize: 43, pid: 7347
LOOKUP /13
getattr /13
unique: 860859, opcode: GETATTR (3), nodeid: 1, insize: 56, pid: 10695
getattr /
   unique: 860859, success, outsize: 120
unique: 860860, opcode: GETATTR (3), nodeid: 1, insize: 56, pid: 11160
getattr /
   unique: 860860, success, outsize: 120
[mtz@ink ~]$ tail -n 100 log
   unique: 860834, success, outsize: 24
unique: 860835, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28233728 flags: 0x8001
   write[32] 4096 bytes to 28233728
   unique: 860835, success, outsize: 24
unique: 860836, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28237824 flags: 0x8001
   write[32] 4096 bytes to 28237824
   unique: 860836, success, outsize: 24
unique: 860837, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28241920 flags: 0x8001
   write[32] 4096 bytes to 28241920
   unique: 860837, success, outsize: 24
unique: 860838, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28246016 flags: 0x8001
   write[32] 4096 bytes to 28246016
   unique: 860838, success, outsize: 24
unique: 860839, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28250112 flags: 0x8001
   write[32] 4096 bytes to 28250112
   unique: 860839, success, outsize: 24
unique: 860840, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28254208 flags: 0x8001
   write[32] 4096 bytes to 28254208
   unique: 860840, success, outsize: 24
unique: 860841, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28258304 flags: 0x8001
   write[32] 4096 bytes to 28258304
   unique: 860841, success, outsize: 24
unique: 860842, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28262400 flags: 0x8001
   write[32] 4096 bytes to 28262400
   unique: 860842, success, outsize: 24
unique: 860843, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28266496 flags: 0x8001
   write[32] 4096 bytes to 28266496
   unique: 860843, success, outsize: 24
unique: 860844, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28270592 flags: 0x8001
   write[32] 4096 bytes to 28270592
   unique: 860844, success, outsize: 24
unique: 860845, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28274688 flags: 0x8001
   write[32] 4096 bytes to 28274688
   unique: 860845, success, outsize: 24
unique: 860846, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28278784 flags: 0x8001
   write[32] 4096 bytes to 28278784
   unique: 860846, success, outsize: 24
unique: 860847, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28282880 flags: 0x8001
   write[32] 4096 bytes to 28282880
   unique: 860847, success, outsize: 24
unique: 860848, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28286976 flags: 0x8001
   write[32] 4096 bytes to 28286976
   unique: 860848, success, outsize: 24
unique: 860849, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28291072 flags: 0x8001
   write[32] 4096 bytes to 28291072
   unique: 860849, success, outsize: 24
unique: 860850, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28295168 flags: 0x8001
   write[32] 4096 bytes to 28295168
   unique: 860850, success, outsize: 24
unique: 860851, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28299264 flags: 0x8001
   write[32] 4096 bytes to 28299264
   unique: 860851, success, outsize: 24
unique: 860852, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28303360 flags: 0x8001
   write[32] 4096 bytes to 28303360
   unique: 860852, success, outsize: 24
unique: 860853, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28307456 flags: 0x8001
   write[32] 4096 bytes to 28307456
   unique: 860853, success, outsize: 24
unique: 860854, opcode: WRITE (16), nodeid: 34, insize: 4176, pid: 7347
write[32] 4096 bytes to 28311552 flags: 0x8001
   write[32] 4096 bytes to 28311552
   unique: 860854, success, outsize: 24
unique: 860855, opcode: WRITE (16), nodeid: 34, insize: 2396, pid: 7347
write[32] 2316 bytes to 28315648 flags: 0x8001
   write[32] 2316 bytes to 28315648
   unique: 860855, success, outsize: 24
unique: 860856, opcode: FLUSH (25), nodeid: 34, insize: 64, pid: 7347
flush[32]
   unique: 860856, success, outsize: 16
unique: 860857, opcode: RELEASE (18), nodeid: 34, insize: 64, pid: 0
release[32] flags: 0x8001
   unique: 860857, success, outsize: 16
unique: 860858, opcode: LOOKUP (1), nodeid: 1, insize: 43, pid: 7347
LOOKUP /13
getattr /13

[smessmer]

/13 is one of your files? Strange, there's nothing odd in the logs. I'll try to reproduce it here. Can you give me some more information? Which boost version, which operating system (incl. version), 32bit or 64bit?

Furthermore, it would be interesting to have a minimal example that causes this. Can you write a small bash script that creates some files and copies them into the CryFS file system, causing the deadlock?

Is this deadlock happening every time, or only sometimes?

[mhogomchungu]

"/13" is a name of a folder with files in it i was copying out.

I am using 64 bit version of PCLinuxOS with kernel version 4.4.1.

boost version is 1.60.0.

fuse version is 2.9.3

Just added a folder with close to 50,000 files taking 905MB and the process finish up successfully,

I have a folder with 46 files taking 4.8GB and i have so far been unable to transfer to crypfs because it will sooner or later lock up before the transfer is complete and the only way out is to reboot.After the lockup any process that attempts to access the mount point will also lock up. This is why i asked you if you could do the test with a lot of files that takes a lot of space causing the transfer to take a while because the problem does not seem to happen immediately but later on and it seems to work all the time when transferring small files.

I just tried again to transfer this folder to cryfs volume and it locked up again.

The cryfs encrypted folder has so far these properties:

[mtz@ink images]$ du cryfs/
916M    cryfs/
[mtz@ink images]$ cd cryfs/
[mtz@ink cryfs]$ ls | wc -l
25991
[mtz@ink cryfs]$ 

If the problem is not local and i cant see why it will be,the problem will there be in how large files are handled.

[smessmer]

Ok I'll try to reproduce.

Btw you can get out of such a lock by force-killing the cryfs process ("killall -9 cryfs") and then unmounting the mountdir ("fusermount -u mountdir").

[mhogomchungu]

"killall -9 cryfs" seems to work so testing will be a lot easier now.

When testing this problem,try to put your computer under stress of some sort.

[smessmer]

It's weird, I tried a lot of things already and nothing worked (so far).
Tried copying a set of large files into the file system, tried writing to different files in parallel (i.e. 15 "dd" applications writing at the same time), tried writing to the same file in parallel, it never deadlocked.
I looked through the code handling file writes and didn't find a possible deadlock situation (but that doesn't mean anything).
You're running version 0.9.0 and you had a release build running (i.e. cryfs doesn't warn on startup that it's a debug build), right?

What we could do next is that I implement some more debugging outputs and you try to get more information running that.

[smessmer]

Is the process manager still showing that CryFS is taking CPU time when it hangs? If it is a deadlock, it should go down to zero CPU utilization. Otherwise, it's maybe something else.

[mhogomchungu]

It did not deadlock yesterday and i manage to transfer all my encfs volumes to cryfs and will continue to pay attention to this behavior and report back if i can reproduce it with certainty,for now i think its ok you can mark this one as "local problem" until further notice.

Maybe it is a local problem because i moved the same files to a LUKS container and the process failed twice with "permission denied,read only file system" error and i had to start the process again to finish up transferring files.I forgot about this behavior since its been a file since i have transfer large files to my LUKS container but it always seems to happen when i move too many of large enough files.

[smessmer]

ok I'll also keep an eye out for potential deadlocks.