search

owncloud / core

:cloud: ownCloud web server core (Files, DAV, etc.)
https://owncloud.com
GNU Affero General Public License v3.0
8.37k stars 2.06k forks source link

Decrypt all files after disabling encryption app is too long #6949

Closed seal20 closed 9 years ago

seal20 commented 10 years ago

Expected behaviour

1) enable the encryption apps, the files get encrypted 2) disable the encryption apps the banner "need to decrypt your files" appears 3) enter my password hit "decrypt all" the files get decrypted in a reasonnable time and an indicator shows how many percent/files remain 4) uncryption continues even if i close the session and I am greeted with an success/still on goind/error banner at next login.

Actual behaviour

1) enable the encryption apps, the files get encrypted 2) disable the encryption apps the banner "need to decrypt your files" appears 3) enter my password hit "decrypt all" the files seems to be decrypted but it takes days (litterally), there is no indication how many files remain to be decrypted or even if it is working. 4) I don't know if uncryption continues after closing the session. I had to look in my data folder to finally found 2 files uncrypted and many still encrypted... I have 7Go of data and it has been running for days.

Steps to reproduce

  1. enable encryption and encrypt a ot of files
  2. disable encryption

    Server configuration

Operating system: Linux (hared hosting)

Web server: Apache

Database:MySQL

PHP version:5.4.24

ownCloud version: 6.0.1

Updated from an older ownCloud or fresh install: updated from 6.0.0a

List of activated app: core apps + news

The content of config/config.php: 

<?php
$CONFIG = array (
  'instanceid' => 'oc3053678514',
  'passwordsalt' => 'salt',
  'datadirectory' => '/home/agoremix/public_html/owncloud/data',
  'dbtype' => 'mysql',
  'version' => '6.0.0.16',
  'dbname' => 'agoremix_owncloud',
  'dbhost' => 'localhost',
  'dbtableprefix' => 'oc_',
  'dbuser' => 'agoremix_sylvain',
  'dbpassword' => 'pass',
  'installed' => true,
  'forcessl' => true,
  'maxZipInputSize' => 838860800,
  'allowZipDownload' => true,
  'loglevel' => '0',
  'theme' => '',
  'maintenance' => false,
);

Are you using external storage, if yes which one: used sftp and dropbox but disabled them before any files were uploaded to them.

Logs

Web server error log

empty

ownCloud log (data/owncloud.log)

 Error  PHP     PHP Startup: Unable to load dynamic library '/usr/local/lib/php/extensions/no-debug-non-zts-20100525/suhosin.so' - /usr/local/lib/php/extensions/no-debug-non-zts-20100525/suhosin.so: cannot open shared object file: No such file or directory at Unknown#0   2014-01-26T06:06:24+00:00
Error   PHP     PHP Startup: Unable to load dynamic library '/usr/local/lib/php/extensions/no-debug-non-zts-20100525/suhosin.so' - /usr/local/lib/php/extensions/no-debug-non-zts-20100525/suhosin.so: cannot open shared object file: No such file or directory at Unknown#0   2014-01-26T06:06:22+00:00
Error   PHP     PHP Startup: Unable to load dynamic library '/usr/local/lib/php/extensions/no-debug-non-zts-20100525/suhosin.so' - /usr/local/lib/php/extensions/no-debug-non-zts-20100525/suhosin.so: cannot open shared object file: No such file or directory at Unknown#0
DeepDiver1975 commented 10 years ago

@schiesbn

schiessle commented 10 years ago

I had to look in my data folder to finally found 2 files uncrypted and many still encrypted... I have 7Go of data and it has been running for days.

7GB? This shouldn't take days, of course it depends on the computation power of your server. I just tried to decrypt 7 files, together 8,1GB encrypted file size (largest single file 4.1GB), it took about 3 minutes (hardware: Intel Core i7 2.90GH). Of course if you use external storages this can also decrease the speed significantly. Another problem could be a to low max execution time for PHP scripts on your server.

I added your general idea regarding a progress bar and notifications if the user logout/login in between as possible enhancements for OC7.

seal20 commented 10 years ago

Sorry it should have read 70Go and not 7... I don't have external storage activated at the moment. The hardware is much lower spec I would think as it is shared hosting. And the 70Go are composed by a lot of small files may explain why it is so long... I am ready to wait, if it still shorter than really upload but how can I check if it is working? No errors in the log means all is good? And do I need to keep a session opened or it keep running even if I close the browser? On Jan 27, 2014 7:33 PM, "Björn Schießle" notifications@github.com wrote:

I had to look in my data folder to finally found 2 files uncrypted and many still encrypted... I have 7Go of data and it has been running for days.

7GB? This shouldn't take days, of course it depends on the computation power of your server. I just tried to decrypt 7 files, together 8,1GB encrypted file size (largest single file 4.1GB), it took about 3 minutes (hardware: Intel Core i7 2.90GH). Of course if you use external storages this can also decrease the speed significantly.

I added your general idea regarding a progress bar and notifications if the user logout/login in between as possible enhancements for OC7.

— Reply to this email directly or view it on GitHubhttps://github.com/owncloud/core/issues/6949#issuecomment-33356477 .

schiessle commented 10 years ago

I am ready to wait, if it still shorter than really upload but how can I check if it is working? No errors in the log means all is good?

If no error occurs everything should be good. Unless the script was stopped by the server, e.g. because of the max execution time I mentioned above. I could imagine that some shared hoster have quite strict limitations in this regard.

If you want to get some more output about the progress you could add at the beginning of this foreach loop https://github.com/owncloud/core/blob/master/apps/files_encryption/lib/util.php#L697 something like

\OCP\Util::writeLog('Encryption library', 'Start Decrypting: ' . $encryptedFile['path'], \OCP\Util::ERROR);

Than you will get a log message every time ownCloud starts to decrypt a new file.

And do I need to keep a session opened or it keep running even if I close the browser?

It should keep running if you close the browser, but this way you will get no success or error message at the end of the process. Therefore I would recommend to keep the browser open.

seal20 commented 10 years ago

I asked my hosting support and the php max is 60min, which seems to not be enough. Would it be possible to check if the function is still running and if not relaunch it. At least it should spit an error if it is stopped before. I have been waiting for days for nothing... what is weird is that I can't see any error in my server log, perhaps I do not have access to php logs.

Within 60min while the files are being decrypted I can't login (open a new session) on owncloud, get error 500, which is reasonable because it is better to not touch the files during the process i would think. However I cannot check the log in during this time so I accessed the logs through ftp. I tried to add the logging function at the begining of the foreach loop but I don't get anything in the logs. ( I putted it FATAL so that it is easier to find it in the middle of suhosin.so error). Did I made a mistake or it means it doesn't even start to decrypt?

line 703 to 719

        if ($found) {

            $versionStatus = \OCP\App::isEnabled('files_versions');
            \OC_App::disable('files_versions');

            $decryptedFiles = array();

            // Encrypt unencrypted files
            foreach ($found['encrypted'] as $encryptedFile) {

                \OCP\Util::writeLog('Encryption library', 'Start Decrypting: ' . $encryptedFile['path'], \OCP\Util::FATAL);

                //relative to data/<user>/file
                $relPath = Helper::stripUserFilesPath($encryptedFile['path']);

                //get file info
                $fileInfo = \OC\Files\Filesystem::getFileInfo($relPath);

By the way the comment line 710 should read "Unencrypt encrypted files" no? Or I am in the wrong sections..

schiessle commented 10 years ago

However I cannot check the log in during this time so I accessed the logs through ftp. I tried to add the logging function at the begining of the foreach loop but I don't get anything in the logs. ( I putted it FATAL so that it is easier to find it in the middle of suhosin.so error). Did I made a mistake or it means it doesn't even start to decrypt?

That's strange. You should see another log message every time the decryption start for a file. Maybe there is a different problem and you don't even enter the foreach loop? But than the script should be finished in a few seconds. Can you try to add some more writeLog-messages to the code. For example one directly at the beginning of the function and one directly after the if ($found) { ?

If this also doesn't create any error message you could add some writeLog-messages to settings/ajax/decryptall.php. Maybe one at the top of the script and one directly before $util->decryptAll(); is called.

Make sure that you give every message a different text so that we can distinguish them, e.g. 

\OCP\Util::writeLog('Encryption library', 'Enter decryptAll function()', \OCP\Util::FATAL);
\OCP\Util::writeLog('Encryption library', 'After the if statement', \OCP\Util::FATAL);
... and so on

This way we might be able to find out where the script stops for you

seal20 commented 10 years ago

Ok I could debug the problem a little more. So the decrypt foreach loop starts 13 min after the decryptall function is called which is quite long considering I have a max execution time of 60 min. Then the first file starts to be decrypted and it never ends and fails silently (at least I cannot see anything in the log. The file has nothing special, it is a gimp file of 670 kB named text007.pdf-1.xcf. It should not take > 40 min to decrypt it so there may be a problem elsewhere. I can send the file if required but I am not sure it will be useful. I tried to add some more log to see where it stops in the util php but I get some syntax error. I never wrote php code so could you tell me where to put the log functions.

Here is the log I get: the first line comes from the decryptall.php and the second one from util.php

{"app":"Encryption library","message":"the decryptall.php started","level":4,"time":"2014-01-29T08:03:46+00:00"}
{"app":"Encryption library","message":"Start Decrypting: sylvain\/files\/Research\/Oceano\/200805 Okinawa\/2008 Volunteer text\/text007.pdf-1.xcf","level":4,"time":"2014-01-29T08:17:38+00:00"}

The modified util.php decrypt function but I get syntax errors.

    public function decryptAll() {

        $found = $this->findEncFiles($this->userId . '/files');

        $successful = true;

        if ($found) {

            \OCP\Util::writeLog('Enter if ($found)', \OCP\Util::FATAL);

            $versionStatus = \OCP\App::isEnabled('files_versions');
            \OC_App::disable('files_versions');

            $decryptedFiles = array();

            // Encrypt unencrypted files
            foreach ($found['encrypted'] as $encryptedFile) {

                \OCP\Util::writeLog('Encryption library', 'Start Decrypting: ' . $encryptedFile['path'], \OCP\Util::FATAL);

                //relative to data/<user>/file
                $relPath = Helper::stripUserFilesPath($encryptedFile['path']);

                //get file info
                $fileInfo = \OC\Files\Filesystem::getFileInfo($relPath);

                //relative to /data
                $rawPath = $encryptedFile['path'];

                //get timestamp
                \OCP\Util::writeLog('Encryption library', 'Get time stamp'], \OCP\Util::FATAL);
                $timestamp = $fileInfo['mtime'];

                //enable proxy to use OC\Files\View to access the original file
                \OC_FileProxy::$enabled = true;

                // Open enc file handle for binary reading
                $encHandle = $this->view->fopen($rawPath, 'rb');

                // Disable proxy to prevent file being encrypted again
                \OC_FileProxy::$enabled = false;

                if ($encHandle === false) {
                    \OCP\Util::writeLog('Encryption library', 'couldn\'t open "' . $rawPath . '", decryption failed!', \OCP\Util::FATAL);
                    $successful = false;
                    \OCP\Util::writeLog('Encryption library', 'Opened enc file handle for binary reading'], \OCP\Util::FATAL);
                    continue;
                }

                // Open plain file handle for binary writing, with same filename as original plain file
                $plainHandle = $this->view->fopen($rawPath . '.part', 'wb');
                if ($plainHandle === false) {
                    \OCP\Util::writeLog('Encryption library', 'couldn\'t open "' . $rawPath . '.part", decryption failed!', \OCP\Util::FATAL);
                    $successful = false;
                    \OCP\Util::writeLog('Encryption library', 'Opened plain file handle for binary writing'], \OCP\Util::FATAL);
                    continue;
                }

                // Move plain file to a temporary location
                $size = stream_copy_to_stream($encHandle, $plainHandle);
                if ($size === 0) {
                    \OCP\Util::writeLog('Encryption library', 'Zero bytes copied of "' . $rawPath . '", decryption failed!', \OCP\Util::FATAL);
                    $successful = false;
                    \OCP\Util::writeLog('Encryption library', 'Moved plain file to a temporary location'], \OCP\Util::FATAL);
                    continue;
                }

                fclose($encHandle);
                fclose($plainHandle);

                $fakeRoot = $this->view->getRoot();
                $this->view->chroot('/' . $this->userId . '/files');

                $this->view->rename($relPath . '.part', $relPath);

                //set timestamp
                $this->view->touch($relPath, $timestamp);

                $this->view->chroot($fakeRoot);

                // Add the file to the cache
                \OCP\Util::writeLog('Encryption library', 'Add the file to the cache'], \OCP\Util::FATAL);
                \OC\Files\Filesystem::putFileInfo($relPath, array(
                    'encrypted' => false,
                    'size' => $size,
                    'unencrypted_size' => 0,
                    'etag' => $fileInfo['etag']
                ));

                $decryptedFiles[] = $relPath;

            }

            if ($versionStatus) {
                \OC_App::enable('files_versions');
            }

            if (!$this->decryptVersions($decryptedFiles)) {
                $successful = false;
            }

            if ($successful) {
                $this->view->deleteAll($this->keyfilesPath);
                $this->view->deleteAll($this->shareKeysPath);
            }

            \OC_FileProxy::$enabled = true;
        }

        return $successful;
    }
schiessle commented 10 years ago

Ok I could debug the problem a little more. So the decrypt foreach loop starts 13 min after the decryptall function is called which is quite long considering I have a max execution time of 60 min.

I looks like findEncFiles() takes that long. The only reason I see why this could take so long is this code part: https://github.com/owncloud/core/blob/master/apps/files_encryption/lib/util.php#L434

If fseek fails we make a local copy and read this file, this is a fall back for external storages which doesn't support fseek. But since you doesn't use external storage this shouldn't happen. Still can you add two writeLog's on to the if-condition and one to the else-condition so that we can see which code path gets executed here?

Then the first file starts to be decrypted and it never ends and fails silently.

That's strange. Can you try to enable encryption again and see if you are able to view/download the file successfully? Did the encryption app worked for you flawlessly until you decided to disable it?

\OCP\Util::writeLog('Enter if ($found)', \OCP\Util::FATAL);

You need to provide two strings, the first one is the app which triggers the error and second one is the error message, e.g.:

\OCP\Util::writeLog('files_encryption', 'Enter if ($found)', \OCP\Util::FATAL);
seal20 commented 10 years ago

Thanks for all your help. I re-enabled the encryption app and I get an error on this file: Cannot decrypt... It is not a shared file, and I never accessed it so I couldn't know it was broken. Would be good to know why it got broken in the first place but I can't say. I re-run the decryptall with all logging (sorry I should have read your example better) and it enters the if statement go up to "enable proxy" but don't go to "Open enc file handle for binary reading". Would be good if it fails and spit an error. Perhaps adding an if statement succesful or not at enable proxy would solve this...? 

{"app":"Encryption library","message":"the decryptall.php started","level":4,"time":"2014-01-30T04:24:59+00:00"}
{"app":"Encryption library","message":"Enter if ($found)","level":4,"time":"2014-01-30T05:00:52+00:00"}
{"app":"Encryption library","message":"Start Decrypting: sylvain\/files\/Photos\/2000\/2000 nouvel an\/IMG_0002.jpg","level":4,"time":"2014-01-30T05:00:54+00:00"}
{"app":"Encryption library","message":"Get time stamp","level":4,"time":"2014-01-30T05:00:54+00:00"}
{"app":"Encryption library","message":"Enable proxy","level":4,"time":"2014-01-30T05:00:54+00:00"}
{"app":"Encryption library","message":"Add the file to the cache","level":4,"time":"2014-01-30T05:01:00+00:00"}
{"app":"Encryption library","message":"Start Decrypting: sylvain\/files\/Photos\/2000\/2000 nouvel an\/IMG.jpg","level":4,"time":"2014-01-30T05:01:00+00:00"}

Many many files...

{"app":"Encryption library","message":"Start Decrypting: sylvain\/files\/Research\/Oceano\/201005 Okinawa\/bleaching\/Bacteria Bleaching paper\/Bacteria Bleaching\/bacteria results\/SuzukiBFasta\/wf_jack\/unweighted_unifrac\/rare_dm\/unweighted_unifrac_rarefaction_5507_0.txt","level":4,"time":"2014-01-30T08:17:56+00:00"}
{"app":"Encryption library","message":"Get time stamp","level":4,"time":"2014-01-30T08:17:56+00:00"}
{"app":"Encryption library","message":"Enable proxy","level":4,"time":"2014-01-30T08:17:56+00:00"}
{"app":"Encryption library","message":"Add the file to the cache","level":4,"time":"2014-01-30T08:17:56+00:00"}
{"app":"Encryption library","message":"Start Decrypting: sylvain\/files\/Research\/Oceano\/200805 Okinawa\/2008 Volunteer text\/text007.pdf-1.xcf","level":4,"time":"2014-01-30T08:17:56+00:00"}
{"app":"Encryption library","message":"Get time stamp","level":4,"time":"2014-01-30T08:17:57+00:00"}
{"app":"Encryption library","message":"Enable proxy","level":4,"time":"2014-01-30T08:17:57+00:00"}

What do you want me to do? 1) I delete the file through the web interface, hope that the issue is resolved and that another file will not pose problem. But we don't know why it happened. 2) Continue to troubleshoot it, which is ok for me but I will need some help to know what to do next. For example try to put an succesfull check after open proxy.

By the way it seems the max execution time is not a problem as decryptall ran for 4h. I think, if I understand the code well, each file decryption is independant, so except for a huge file which would take more than 40 min to decrypt it should not be a problem.

sixtyfive commented 10 years ago

I seem to have a similar problem:

Unfortunately there's nothing in the log files that seems to be specific to the problem of encrypting/decrypting large amounts of data. At this point I'm just looking for a command line to handle decrypting the files in the hopes of getting some useful error message out of that...

seal20 commented 10 years ago

Hi Sixtyfive, I was able to get the files to decrypt by deleting the culprit file. I found it by adding a bunch of debugging lines in the code. Fortunately I had a backup copy of it. The reason your decryption and mine doesn't work (in your case encryption clearly failed) may be different but the main problem is that decryption should not abort without logging the error. The user should have a way to debug it without touching the files and best a way to fix it even if it includes deleting the non decryptable files.

sixtyfive commented 10 years ago

Seal, thank you for the reply! I'll leave the files be for now and wait if there'll be another reply by schiessbn. I'd really love to have a command line program to do the encrypting/decrypting if need-be.

That sad, all the things suggested by you above seem to make a lot of sense!

etiess commented 9 years ago

Hello, Any news on this one? I'm running 7.0.3 and I'm in the same situation: it's decrypting about 50 GB of files for more than a day.

simonspa commented 9 years ago

I also built in some debug messages to see what happens. First, the crawling for files (findEncFiles) takes ages:

{"app":"Encryption library","message":"Enter decryptAll function()","level":4,"time":"2015-01-07T12:22:33+00:00"}
{"app":"Encryption library","message":"findEncFiles return: Array","level":4,"time":"2015-01-07T13:19:23+00:00"}

that is more than one hour for just a couple of thousand of files (all in all less than 8GB)

When finally starting decryption, everything first looks fine:

{"app":"Encryption library","message":"After the if statement","level":4,"time":"2015-01-07T13:19:23+00:00"}
{"app":"Encryption library","message":"Start Decrypting: whatever/file/image.png","level":3,"time":"2015-01-07T13:19:23+00:00"}
{"app":"Encryption library","message":"Start Decrypting: whatever/file/image2.png","level":3,"time":"2015-01-07T13:19:31+00:00"}

But then the decryption routine reaches one of these ocTransferId<>.part files which might result from a broken upload (missing e-tag, see #12725) I get the following:

Additional output from the findEncFiles function for this file:

{"app":"Encryption library","message":"Filepath user/myfiles/panel.css.ocTransferId1419129547.part is encrypted: 1","level":4,"time":"2015-01-07T12:23:55+00:00"}

Output from the decrypt routine:

{"app":"Encryption library","message":"Start Decrypting: user/myfiles/panel.css.ocTransferId1419129547.part","level":3,"time":"2015-01-07T13:25:01+00:00"}
{"app":"PHP","message":"Call to a member function getPath() on a non-object at \/var\/www\/owncloud\/lib\/private\/share\/share.php#112","level":3,"time":"2015-01-07T13:25:07+00:00"}

Can anyone make sense of this?

PVince81 commented 9 years ago

@schiesbn is there a ticket for adding a progress bar ?

CrossVR commented 9 years ago

I also can't decrypt the file storage when a large amount of files are present. It seems to be unrelated to the size of the files, but rather the number of them.

For example in case a git repository has been uploaded to owncloud, decryption it is almost certain to fail.

I am hosting ownCloud myself and the maximum PHP execution time is 1 hour.

@PVince81 There is: https://github.com/owncloud/core/issues/6387

DeepDiver1975 commented 9 years ago

we need to move off all these long running tasks to async jobs - in case of encryption this requires the capability to pass the user password to the executing process - which will not run in the session context (most probably :speak_no_evil: ).

nickvergessen commented 9 years ago

Closing because the feature has been removed for now.