search

vgough / encfs

EncFS: an Encrypted Filesystem for FUSE.
https://vgough.github.io/encfs/
Other
2.07k stars 276 forks source link

MacOS - Frequent System Freezes and Crashes #466

Open Serubin opened 6 years ago

Serubin commented 6 years ago

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!

benrubson commented 6 years ago

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

Serubin commented 6 years ago

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

benrubson commented 6 years ago

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

Serubin commented 6 years ago

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

benrubson commented 6 years ago

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 👍

Serubin commented 6 years ago

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]
benrubson commented 6 years ago

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)

Serubin commented 6 years ago

@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.

benrubson commented 6 years ago

Ddi you manage to collect further debug data @Serubin ?

Serubin commented 6 years ago

@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.

benrubson commented 6 years ago

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

Serubin commented 6 years ago

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

Serubin commented 6 years ago

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

benrubson commented 6 years ago

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 ?

Serubin commented 6 years ago

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.

benrubson commented 6 years ago

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 ?

Serubin commented 6 years ago

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

benrubson commented 6 years ago

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

Serubin commented 6 years ago

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.

benrubson commented 6 years ago

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 ?

Serubin commented 6 years ago

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
benrubson commented 6 years ago

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 ?

Serubin commented 6 years ago

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.

benrubson commented 6 years ago

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) ?

Serubin commented 6 years ago

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>