encfs icon indicating copy to clipboard operation
encfs copied to clipboard

Published 20 hours ago • verified publisher icon vgough

MacOS - Frequent System Freezes and Crashes

Open Serubin opened this issue 7 years ago • 25 comments

Hello!

I've been having some odd problems on a Macbook Pro 2017 TB. When doing io intensive work such as npm i or rsyncing data off the EncFS drive my computer tends to freeze up and crash or EncFS becomes unreachable (though the EncFS drive is still mounted).

I've been collecting logs to see what might be the cause, but both FUSE and EncFS logs seem normal. Happy to provide if necessary. I'm using paranoid mode for this configuration. I'm partially wondering if external IV is to blame.

To clarify, these crashes cause the entire machine to freeze up and require a power cycle to remedy.

Thanks!

Serubin avatar Feb 03 '18 17:02 Serubin

Hi, Which version do you use ? Last 1.9.4 ? Did you experience same issue with older version ? Thx 👍

benrubson avatar Feb 03 '18 17:02 benrubson

I'm currently on version 1.9.2. I'll update the 1.9.4 I haven't noticed what version I've been on. I think it's consistently been 1.9.x

edit: accidentally hit close issue & comment

Serubin avatar Feb 03 '18 21:02 Serubin

Yes please test 1.9.4, many things have changed in the code, this could help.

benrubson avatar Feb 06 '18 19:02 benrubson

@benrubson Still appears to happen. It feels vaguely like an interrupt hangs causing the system to wait.

Serubin avatar Feb 10 '18 16:02 Serubin

Does encfs process grow abnormally while running, until it crashes ?

We could also be in a lock race. What about running encfs with -f -v switches, to see what happens when the bug occurs ?

Thank you 👍

benrubson avatar Feb 10 '18 16:02 benrubson

This is the log leading up to my last power cycling. I can't really look at the process when my computer freezes unfortunately.

2018-02-10 11:41:39,207 DEBUG op: getattr error: No such file or directory [encfs.cpp:175]
2018-02-10 11:41:39,207 VERBOSE fs block size = 1024, macBytes = 8, randBytes = 0 [MACFileIO.cpp:70]
2018-02-10 11:41:39,207 DEBUG getAttr error on /Users/seru/Dropbox/.encrypted/nNKHf7bLxVVdygHp1HX2UQ9d: No such file or directory [RawFileIO.cpp:177]
2018-02-10 11:41:39,207 VERBOSE in setIV, current IV = 0, new IV = 15980112261154799922, fileIV = 0 [CipherFileIO.cpp:88]
2018-02-10 11:41:39,207 VERBOSE created FileNode for /Users/seru/Dropbox/.encrypted/nNKHf7bLxVVdygHp1HX2UQ9d [DirNode.cpp:693]
2018-02-10 11:41:39,207 VERBOSE op: getattr : /Users/seru/Dropbox/.encrypted/nNKHf7bLxVVdygHp1HX2UQ9d [encfs.cpp:152]
2018-02-10 11:41:39,207 DEBUG getAttr error on /Users/seru/Dropbox/.encrypted/nNKHf7bLxVVdygHp1HX2UQ9d: No such file or directory [RawFileIO.cpp:177]
2018-02-10 11:41:39,207 DEBUG op: getattr error: No such file or directory [encfs.cpp:175]
2018-02-10 11:41:39,207 VERBOSE fs block size = 1024, macBytes = 8, randBytes = 0 [MACFileIO.cpp:70]
2018-02-10 11:41:39,207 DEBUG getAttr error on /Users/seru/Dropbox/.encrypted/nNKHf7bLxVVdygHp1HX2UQ9d: No such file or directory [RawFileIO.cpp:177]
2018-02-10 11:41:39,207 VERBOSE in setIV, current IV = 0, new IV = 15980112261154799922, fileIV = 0 [CipherFileIO.cpp:88]
2018-02-10 11:41:39,207 VERBOSE created FileNode for /Users/seru/Dropbox/.encrypted/nNKHf7bLxVVdygHp1HX2UQ9d [DirNode.cpp:693]
2018-02-10 11:41:39,207 VERBOSE op: getattr : /Users/seru/Dropbox/.encrypted/nNKHf7bLxVVdygHp1HX2UQ9d [encfs.cpp:152]
2018-02-10 11:41:39,207 DEBUG getAttr error on /Users/seru/Dropbox/.encrypted/nNKHf7bLxVVdygHp1HX2UQ9d: No such file or directory [RawFileIO.cpp:177]
2018-02-10 11:41:39,207 DEBUG op: getattr error: No such file or directory [encfs.cpp:175]
2018-02-10 11:41:39,219 VERBOSE doing statfs of /Users/seru/Dropbox/.encrypted [encfs.cpp:770]
2018-02-10 11:41:39,219 VERBOSE fs block size = 1024, macBytes = 8, randBytes = 0 [MACFileIO.cpp:70]
2018-02-10 11:41:39,219 DEBUG getAttr error on /Users/seru/Dropbox/.encrypted/NENLoYJgHtNuKGO5PH0G8JlZ: No such file or directory [RawFileIO.cpp:177]
2018-02-10 11:41:39,220 VERBOSE in setIV, current IV = 0, new IV = 7125712736274286486, fileIV = 0 [CipherFileIO.cpp:88]
2018-02-10 11:41:39,220 VERBOSE created FileNode for /Users/seru/Dropbox/.encrypted/NENLoYJgHtNuKGO5PH0G8JlZ [DirNode.cpp:693]
2018-02-10 11:41:39,220 VERBOSE op: getattr : /Users/seru/Dropbox/.encrypted/NENLoYJgHtNuKGO5PH0G8JlZ [encfs.cpp:152]
2018-02-10 11:41:39,220 DEBUG getAttr error on /Users/seru/Dropbox/.encrypted/NENLoYJgHtNuKGO5PH0G8JlZ: No such file or directory [RawFileIO.cpp:177]
2018-02-10 11:41:39,220 DEBUG op: getattr error: No such file or directory [encfs.cpp:175]
2018-02-10 11:41:39,220 VERBOSE fs block size = 1024, macBytes = 8, randBytes = 0 [MACFileIO.cpp:70]
2018-02-10 11:41:39,220 DEBUG getAttr error on /Users/seru/Dropbox/.encrypted/NENLoYJgHtNuKGO5PH0G8JlZ: No such file or directory [RawFileIO.cpp:177]
2018-02-10 11:41:39,220 VERBOSE in setIV, current IV = 0, new IV = 7125712736274286486, fileIV = 0 [CipherFileIO.cpp:88]
2018-02-10 11:41:39,220 VERBOSE created FileNode for /Users/seru/Dropbox/.encrypted/NENLoYJgHtNuKGO5PH0G8JlZ [DirNode.cpp:693]
2018-02-10 11:41:39,220 VERBOSE op: getattr : /Users/seru/Dropbox/.encrypted/NENLoYJgHtNuKGO5PH0G8JlZ [encfs.cpp:152]
2018-02-10 11:41:39,220 DEBUG getAttr error on /Users/seru/Dropbox/.encrypted/NENLoYJgHtNuKGO5PH0G8JlZ: No such file or directory [RawFileIO.cpp:177]
2018-02-10 11:41:39,220 DEBUG op: getattr error: No such file or directory [encfs.cpp:175]
2018-02-10 11:41:39,220 VERBOSE fs block size = 1024, macBytes = 8, randBytes = 0 [MACFileIO.cpp:70]
2018-02-10 11:41:39,220 DEBUG getAttr error on /Users/seru/Dropbox/.encrypted/NENLoYJgHtNuKGO5PH0G8JlZ: No such file or directory [RawFileIO.cpp:177]
2018-02-10 11:41:39,220 VERBOSE in setIV, current IV = 0, new IV = 7125712736274286486, fileIV = 0 [CipherFileIO.cpp:88]
2018-02-10 11:41:39,220 VERBOSE created FileNode for /Users/seru/Dropbox/.encrypted/NENLoYJgHtNuKGO5PH0G8JlZ [DirNode.cpp:693]
2018-02-10 11:41:39,220 VERBOSE op: getattr : /Users/seru/Dropbox/.encrypted/NENLoYJgHtNuKGO5PH0G8JlZ [encfs.cpp:152]
2018-02-10 11:41:39,221 DEBUG getAttr error on /Users/seru/Dropbox/.encrypted/NENLoYJgHtNuKGO5PH0G8JlZ: No such file or directory [RawFileIO.cpp:177]
2018-02-10 11:41:39,221 DEBUG op: getattr error: No such file or directory [encfs.cpp:175]
2018-02-10 11:41:39,223 VERBOSE doing statfs of /Users/seru/Dropbox/.encrypted [encfs.cpp:770]
2018-02-10 11:41:39,224 VERBOSE doing statfs of /Users/seru/Dropbox/.encrypted [encfs.cpp:770]
2018-02-10 11:41:39,226 VERBOSE doing statfs of /Users/seru/Dropbox/.encrypted [encfs.cpp:770]
2018-02-10 11:41:39,271 VERBOSE doing statfs of /Users/seru/Dropbox/.encrypted [encfs.cpp:770]
2018-02-10 11:41:41,419 VERBOSE fs block size = 1024, macBytes = 8, randBytes = 0 [MACFileIO.cpp:70]
2018-02-10 11:41:41,419 VERBOSE created FileNode for /Users/seru/Dropbox/.encrypted/ [DirNode.cpp:693]
2018-02-10 11:41:41,419 VERBOSE op: getattr : /Users/seru/Dropbox/.encrypted/ [encfs.cpp:152]
2018-02-10 11:41:41,420 VERBOSE fs block size = 1024, macBytes = 8, randBytes = 0 [MACFileIO.cpp:70]
2018-02-10 11:41:41,420 VERBOSE created FileNode for /Users/seru/Dropbox/.encrypted/Tbq-ZqX60cfImR1rsLw6hYI,/tFmqrnE,kKVCSKZgJJPpCeel/-AXB0hqlcaPpU73,0llldLoQ [DirNode.cpp:693]
2018-02-10 11:41:41,420 VERBOSE op: getattr : /Users/seru/Dropbox/.encrypted/Tbq-ZqX60cfImR1rsLw6hYI,/tFmqrnE,kKVCSKZgJJPpCeel/-AXB0hqlcaPpU73,0llldLoQ [encfs.cpp:152]
2018-02-10 11:41:44,378 VERBOSE fs block size = 1024, macBytes = 8, randBytes = 0 [MACFileIO.cpp:70]
2018-02-10 11:41:44,378 VERBOSE created FileNode for /Users/seru/Dropbox/.encrypted/Tbq-ZqX60cfImR1rsLw6hYI,/tFmqrnE,kKVCSKZgJJPpCeel/-AXB0hqlcaPpU73,0llldLoQ/B11LozucLdxu2s2a1tKRSE4y [DirNode.cpp:693]
2018-02-10 11:41:44,378 VERBOSE op: getattr : /Users/seru/Dropbox/.encrypted/Tbq-ZqX60cfImR1rsLw6hYI,/tFmqrnE,kKVCSKZgJJPpCeel/-AXB0hqlcaPpU73,0llldLoQ/B11LozucLdxu2s2a1tKRSE4y [encfs.cpp:152]
2018-02-10 11:41:44,378 VERBOSE fs block size = 1024, macBytes = 8, randBytes = 0 [MACFileIO.cpp:70]
2018-02-10 11:41:44,378 VERBOSE created FileNode for /Users/seru/Dropbox/.encrypted/ [DirNode.cpp:693]
2018-02-10 11:41:44,378 VERBOSE op: getattr : /Users/seru/Dropbox/.encrypted/ [encfs.cpp:152]
2018-02-10 11:41:44,378 VERBOSE fs block size = 1024, macBytes = 8, randBytes = 0 [MACFileIO.cpp:70]
2018-02-10 11:41:44,379 VERBOSE created FileNode for /Users/seru/Dropbox/.encrypted/Tbq-ZqX60cfImR1rsLw6hYI,/tFmqrnE,kKVCSKZgJJPpCeel/-AXB0hqlcaPpU73,0llldLoQ [DirNode.cpp:693]
2018-02-10 11:41:44,379 VERBOSE op: getattr : /Users/seru/Dropbox/.encrypted/Tbq-ZqX60cfImR1rsLw6hYI,/tFmqrnE,kKVCSKZgJJPpCeel/-AXB0hqlcaPpU73,0llldLoQ [encfs.cpp:152]
2018-02-10 11:41:44,379 VERBOSE fs block size = 1024, macBytes = 8, randBytes = 0 [MACFileIO.cpp:70]
2018-02-10 11:41:44,379 VERBOSE created FileNode for /Users/seru/Dropbox/.encrypted/Tbq-ZqX60cfImR1rsLw6hYI,/tFmqrnE,kKVCSKZgJJPpCeel/-AXB0hqlcaPpU73,0llldLoQ/B11LozucLdxu2s2a1tKRSE4y [DirNode.cpp:693]
2018-02-10 11:41:44,379 VERBOSE op: getattr : /Users/seru/Dropbox/.encrypted/Tbq-ZqX60cfImR1rsLw6hYI,/tFmqrnE,kKVCSKZgJJPpCeel/-AXB0hqlcaPpU73,0llldLoQ/B11LozucLdxu2s2a1tKRSE4y [encfs.cpp:152]

Serubin avatar Feb 10 '18 17:02 Serubin

Thank you for the log. Unfortunately, according to me, nothing relevant :-/ But the fact you are certainly using external IV chaining in a Dropbox share (due to paranoia mode), which is discouraged (see man page), however encfs should not freeze your machine.

I can't really look at the process when my computer freezes unfortunately.

A quick command like this while encfs is running ?

while [ 1 ]; do ps -ef -o command,vsize,rss,%mem | grep encfs | grep -v grep; sleep 0.5; done

(you could also redirect to a file)

benrubson avatar Feb 10 '18 17:02 benrubson

@benrubson Yes, I figured it wasn't relevant. And yes I know it's discouraged - but i haven't encountered any issues just yet.

I'll keep an eye on process usage.

Serubin avatar Feb 10 '18 17:02 Serubin

Ddi you manage to collect further debug data @Serubin ?

benrubson avatar Mar 06 '18 15:03 benrubson

@benrubson Thanks for checking in. I've been busy with work and not using encfs much - I had a crash last night but I didn't have my load average script running.

I'll continue to watch it over the next week or so, hopefully something will come up.

Serubin avatar Mar 06 '18 21:03 Serubin

You certainly already checked this, but as you running the last fuse version (29 ?) available ?

benrubson avatar Mar 06 '18 21:03 benrubson

I'm using the latest version of 3.7.1 of MacOS Fuse

Serubin avatar Mar 06 '18 22:03 Serubin

@benrubson After looking through, there's a slight bump in usage when it crashes, but nothing significant

Serubin avatar Mar 16 '18 19:03 Serubin

Did you try to put your EncFS directory out of the Dropbox directory, so locally in a standard folder, and run the same workload ? Goal would be to see if issue comes from Dropbox or EncFS. Btw, no Dropbox log at the time of the crash ?

benrubson avatar Mar 16 '18 20:03 benrubson

I'll sift through the Dropbox logs, but I don't think that's the case - I can turn dropbox off and see if that does anything but it shouldn't act any different than any other files.

I'm wondering if it has to do with trying with trying to write/read from a file simultaneously from two processes.

Serubin avatar Mar 16 '18 22:03 Serubin

Dont' you use a lock mechanism for such a use case ? I did a quick test, a least on FreeBSD locking files (with lockf cmd) over Fuse (so in EncFS) works.

@rfjakob any thoughts on this issue, particularly after your last investigations on Mac OS ?

benrubson avatar Mar 17 '18 09:03 benrubson

@benrubson I'd expect the OS/Fuse to handle the locking between different applications.

Serubin avatar Mar 17 '18 16:03 Serubin

No, locking is an applications' matter. Test it by yourself writing content simultaneously from 2 processes into the same file. It should produce garbage.

benrubson avatar Mar 17 '18 16:03 benrubson

That's what I'm getting at though. I'm wondering if on Mac Fuse/Encfs can't handle a single file being open twice.

Serubin avatar Mar 17 '18 16:03 Serubin

Of course EncFS allows (and support) a file to be opened several times. I don't know however if there may be an issue with OSXFuse (sounds like you also asked them directly : https://github.com/osxfuse/osxfuse/issues/492) Did you manage to investigate further ? An application locking issue as suspected ?

benrubson avatar May 05 '18 16:05 benrubson

I have heard nothing back from osxfuse. Based on the fuse logs, I think it's specific to encfs.

I was able to determine that this is the most common error that comes up during a crash

ESC[31m2018-05-11 21:12:59,825 ERROR Invalid data size, not multiple of block size
ESC[0mESC[31m2018-05-11 21:13:00,050 ERROR Invalid data size, not multiple of block size
ESC[0mESC[31m2018-05-11 21:13:00,058 ERROR Invalid data size, not multiple of block size
ESC[0mESC[31m2018-05-11 21:13:00,060 ERROR Invalid data size, not multiple of block size
ESC[0mESC[31m2018-05-11 21:13:00,060 ERROR Invalid data size, not multiple of block size
ESC[0mESC[31m2018-05-11 21:13:00,060 ERROR Invalid data size, not multiple of block size
ESC[0mESC[31m2018-05-11 21:13:00,063 ERROR Invalid data size, not multiple of block size
ESC[0mESC[31m2018-05-11 21:13:00,063 ERROR Invalid data size, not multiple of block size
ESC[0mESC[31m2018-05-11 21:13:00,063 ERROR Invalid data size, not multiple of block size
ESC[0mESC[31m2018-05-11 21:13:00,063 ERROR Invalid data size, not multiple of block size
ESC[0mESC[31m2018-05-11 21:13:00,068 ERROR Invalid data size, not multiple of block size
ESC[0mESC[31m2018-05-11 21:13:05,181 ERROR Invalid data size, not multiple of block size
ESC[0mESC[31m2018-05-11 21:13:05,181 ERROR Invalid data size, not multiple of block size
ESC[0mESC[31m2018-05-11 21:13:05,181 ERROR Invalid data size, not multiple of block size
ESC[0mESC[31m2018-05-11 21:13:05,181 ERROR Invalid data size, not multiple of block size
ESC[0mESC[31m2018-05-11 21:13:05,181 ERROR Invalid data size, not multiple of block size
ESC[0mESC[31m2018-05-11 21:13:05,181 ERROR Invalid data size, not multiple of block size
ESC[0mESC[31m2018-05-11 21:13:05,457 ERROR Invalid data size, not multiple of block size
ESC[0mESC[31m2018-05-11 21:13:05,457 ERROR Invalid data size, not multiple of block size
ESC[0mESC[31m2018-05-11 21:13:05,458 ERROR Invalid data size, not multiple of block size
ESC[0mESC[31m2018-05-11 21:13:05,461 ERROR Invalid data size, not multiple of block size
ESC[0mESC[31m2018-05-11 21:13:05,461 ERROR Invalid data size, not multiple of block size
ESC[0mESC[31m2018-05-11 21:13:05,464 ERROR Invalid data size, not multiple of block size
ESC[0mESC[31m2018-05-11 21:13:05,464 ERROR Invalid data size, not multiple of block size
ESC[0mESC[31m2018-05-11 21:13:05,466 ERROR Invalid data size, not multiple of block size
ESC[0m

Serubin avatar May 12 '18 01:05 Serubin

Rather strange, the (SSL) block cipher tells us it has been provided with a malformed (wrong size) data block, so read from (or write to) the impacted file(s) fails. This should not happen as block cipher is used only if it can be used : https://github.com/vgough/encfs/blob/v1.9.5/encfs/CipherFileIO.cpp#L349 https://github.com/vgough/encfs/blob/v1.9.5/encfs/CipherFileIO.cpp#L391 Do you have a known way to reproduce the issue ?

benrubson avatar May 12 '18 15:05 benrubson

I was moving large amounts of files. I have some code repositories that I have in encfs so deleting node_module folders or even .git folders can cause it.

Serubin avatar May 13 '18 03:05 Serubin

So when you delete these directories, you have the error messages above, and your Mac freezes ? Do you have other error messages ?

Rather strange, the (SSL) block cipher tells us it has been provided with a malformed (wrong size) data block, so read from (or write to) the impacted file(s) fails.

This could also be due to filenames : https://github.com/vgough/encfs/blob/v1.9.4/encfs/BlockNameIO.cpp#L167 https://github.com/vgough/encfs/blob/v1.9.4/encfs/BlockNameIO.cpp#L227

Could you give us your .encfs6.xml file content (without the key data) ?

benrubson avatar May 13 '18 07:05 benrubson

There aren't any other apparent errors.

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE boost_serialization>
<boost_serialization signature="serialization::archive" version="7">
    <cfg class_id="0" tracking_level="0" version="20">
        <version>20100713</version>
        <creator>EncFS 1.9.1</creator>
        <cipherAlg class_id="1" tracking_level="0" version="0">
            <name>ssl/aes</name>
            <major>3</major>
            <minor>0</minor>
        </cipherAlg>
        <nameAlg>
            <name>nameio/block</name>
            <major>4</major>
            <minor>0</minor>
        </nameAlg>
        <keySize>256</keySize>
        <blockSize>1024</blockSize>
        <uniqueIV>1</uniqueIV>
        <chainedNameIV>1</chainedNameIV>
        <externalIVChaining>1</externalIVChaining>
        <blockMACBytes>8</blockMACBytes>
        <blockMACRandBytes>0</blockMACRandBytes>
        <allowHoles>1</allowHoles>
        <encodedKeySize>52</encodedKeySize>
        <kdfIterations>2208176</kdfIterations>
        <desiredKDFDuration>3000</desiredKDFDuration>
    </cfg>
</boost_serialization>

Serubin avatar May 15 '18 01:05 Serubin