Desktop sync fails with big files (OC 8.2.0, client 2.0.2)

[ormajollila]

Hi,

I'm having a trouble uploading a 9GB file using desktop sync client 2.0.2 (and owncloud 8.2.0).

The uploading goes well but when uploading is done, owncloud starts to assemble the file. During the assembly a temporary file is created in the user's files folder.

Then, for some reason, the desktop client tries to sync the temporary file, it fails and syncing is restarted (including uploading of the 9GB file or at least the missing bits).

I have filesystem_check_changes = 0. Shouldn't it prevent stuff like this?

Would it be better to assemble the final file in the cache folder and then move the file to files folder after assembly is done?

[PVince81]

for some reason the desktop client tries to sync the temporary file

With temporary file you probably mean the part file which is stored directly under "data/username/files/path/to/finalfile.part"

The sync client should never be able to download part files, such files are not exposed through the API at all. Something weird is happening on your environment.
Can you try using a regular webdav client (doplhin or cadaver) and display the folder contents of that folder ? You should not be able to see the ".part" file in the result. If you can, then this is an issue.

Do you have any logs related to the event ? (also, see issue template https://raw.githubusercontent.com/owncloud/core/master/issue_template.md)

[ormajollila]

Steps to reproduce

1. Setup desktop sync
2. Try to sych 9GB file
3. Wait
4. Fail

Expected behaviour

File to be synced to the server

Actual behaviour

It fails due to ?? (see logs)

Server configuration

Operating system: Fresh install of Ubuntu 14.04.03 (x64) + with latest patches
Webserver: Apache 2.4.7-1ubuntu4.8
Database: Mysql 5.5.46-0ubuntu0.14.04.2
PHP: PHP 5.5.9+dfsg-1ubuntu4.14
ownCloud version: 8.2.0 (Installed from owncloud xUbuntu repository)

Activated Apps:

• activity: 2.1.3
• files: 1.2.0
• files_sharing: 0.7.0
• files_videoviewer: 0.1.3
• gallery: 14.2.0
• notifications: 0.1.0
• templateeditor: 0.1

The content of config/config.php:

 $CONFIG = array (
  'instanceid' => 'xxxx',
  'passwordsalt' => 'xxx',
  'secret' => 'xxxx',
  'trusted_domains' =>
  array (
    0 => 'xxx.yyy.zzz',
  ),
  'datadirectory' => '/mnt/owncloud/data',
  'overwrite.cli.url' => 'https://xxx.yyy.zzz',
  'dbtype' => 'mysql',
  'version' => '8.2.0.12',
  'dbname' => 'owncloud',
  'dbhost' => 'localhost',
  'dbtableprefix' => 'oc_',
  'dbuser' => 'owncloud',
  'dbpassword' => '---------',
  'logtimezone' => 'UTC',
  'installed' => true,
  'mail_from_address' => 'owncloud',
  'mail_smtpmode' => 'php',
  'mail_domain' => 'yyy.zzz',
  'forcessl' => true,
  'loglevel' => 0,
  'filesystem_check_changes' => 0,
);

External storage: No
Encryption: No
External user backend: No

##Client configuration:
Desktop Sync Client 2.0.2 on windows 8.1 x64
Operating system: Windows 8.1 pro x64

Logs

Web server error log:

[Tue Nov 03 14:32:00.508035 2015] [:error] [pid 18708] [client [redacted ip]:24557] PHP Fatal error:  Allowed memory size of 1073741824 bytes exhausted (tried to allocate 5251072 bytes) in /var/www/owncloud/lib/private/files/storage/local.php on line 179

ownCloud Log:

{"reqId":"PfzQIrP2azc1GCpTHQSM","remoteAddr":"[redacted ip]","app":"PHP","message":"Allowed memory size of 1073741824 bytes exhausted (tried to allocate 5251072 bytes) at /var/www/owncloud/lib/private/files/storage/local.php#179","level":3,"time":"2015-11-03T12:32:00+00:00","method":"PUT","url":"/remote.php/webdav/foobar.txt-chunking-4126479217-1853-1852"}

Client (desktop sync) log:

3.11.2015 14:32:00foobar.txt                                                      E:\owncloud                   Error downloading https://[HOSTNAME]/remote.php/webdav/foobar.txt-chunking-4126479217-1853-1852 - server replied: Internal Server Error9 GB      

[ormajollila]

Also, the system has 32GB of memory and 750GB of free hard disk space.

.htaccess php part (these show up in phpinfo() too).

php_value upload_max_filesize 16G
php_value post_max_size 16400M
php_value memory_limit 1024M
php_value output_buffering 0
php_value execution_time 3600
php_value max_input_time 3600

Also, now that I look, it's not the .part files it's trying to download.

[ormajollila]

I recorded php memory usage when owncloud assembles the file from chunks (filechunking.php / assemble($f)). At first everything seems fine but then...

Left column is chunk file currently being appended to the final file and right column the amount of memory php is using at the giving moment.

4.7GB file has total of 927 chunks and 9GB file 1853.

4.7GB file http://pastebin.com/vUkSzJEP

~9GB file http://pastebin.com/7cCj5eU0

[PVince81]

Thanks for the info.

Does this always happen for the last chunk ? The chunk file name in the log uses the format "foobar.txt-chunking-$transferid-$chunkCount-$chunkIndex". So my question is whether the chunk that fails is always the one where $chunkIndex == $chunkCount - 1 ?

That could be a clue.

[PVince81]

From what I see this is the place where it happens: https://github.com/owncloud/core/blob/v8.2.0/lib/private/files/storage/local.php#L179
This is possibly the moment where the chunks are being assembled into the final file, for this the chunks are read from disk one by one.

@ormajollila can you also tell me how big the chunk file from the message is in the folder "data/$user/files/cache" folder ? It shouldn't be bigger than 20mb in general.

I suspect that memory isn't being released properly when assembling chunks.

[ormajollila]

_Does this always happen for the last chunk ? The chunk file name in the log uses the format "foobar.txt-chunking-$transferid-$chunkCount-$chunkIndex". So my question is whether the chunk that fails is always the one where $chunkIndex == $chunkCount - 1 ?_

Yes, looks like it's always at $chunkCount - 1. Total number of chunks is correct, though. They start at 0.

_can you also tell me how big the chunk file from the message is in the folder "data/$user/files/cache" folder ? It shouldn't be bigger than 20mb in general._

The last one is 250026 bytes.

5242880 * 926 + 250026 = 4855156906 which is the size of the file I'm trying to sync.

[PVince81]

Ok thanks.

Is that the same for both the 4 GB and 9 GB file ?
I'd expect the 9 GB file to fail for an earlier chunk (maybe half-way through) by running out of memory sooner ?

[ormajollila]

Yes, same for both 4GB and 9GB. The chunks are transferred ok but assembly at owncloud server end fails.

Funny thing: Both files are in 5MB chunks but for some reason 9GB assembly goes crazy earlier.

You can see this from the links I posted earlier:
4.7GB file http://pastebin.com/vUkSzJEP
~9GB file http://pastebin.com/7cCj5eU0

[PVince81]

Okay, if you say "go crazy earlier" by meaning "it doesn't fail on the last chunk for 9 GB but in one from the middle", then it makes sense.

We should double check the assembly code and look for possible memory leaks.
CC @icewind1991

[ormajollila]

Yes, it fails in the middle (pastebin logs). Owncloud server and owncloud client logs say last chunk because it's the one triggering the assembly process :)

[PVince81]

Ah yes, of course, that makes sense 😄

[PVince81]

This is the loop that assembles the chunks one by one: https://github.com/owncloud/core/blob/v8.2.0/lib/private/filechunking.php#L103

It first reads a chunk from disk, stores it in the $chunk.
Then it deletes the chunk from disk.
Then it writes it to the final file.

Then goes the next one. At the time where $chunk is assigned, its old value should disappear from memory.

Now I can imagine that at the time $cache->get() is running, the variable $chunk hasn't be cleared yet so it will still be using the memory. Hmmmm.

[PVince81]

I don't see anything wrong and in my local tests the memory seems to be freed properly.

Maybe you can run the same test on your system, modify the assemble() function with debug logging:

    public function assemble($f) {
        $cache = $this->getCache();
        $prefix = $this->getPrefix();
        $count = 0;
        for ($i = 0; $i < $this->info['chunkcount']; $i++) {
            \OC::$server->getLogger()->debug('Memory usage begin: ' . memory_get_usage());
            $chunk = $cache->get($prefix.$i);
            // remove after reading to directly save space
            $cache->remove($prefix.$i);
            $count += fwrite($f, $chunk);
            \OC::$server->getLogger()->debug('Memory usage end: ' . memory_get_usage());
        }

        return $count;
    }

here https://github.com/owncloud/core/blob/v8.2.0/lib/private/filechunking.php#L103

This will log the used memory for every chunk that got assembled.
In your setup I expected this value to increase quickly.

Beware, it might fill up your log!

You might also want to try upgrading your PHP version, it sounds like it could be a PHP bug.

[ormajollila]

Ok, I tried logging by using the code above. And for some reason it works. I tried it again a few times and every time it worked.

Then I removed the logging and failing started again. I tried again a few times, still not working.

Put it back, and it worked again.

Also, I tried upgrading to PHP 5.6. No effect.

[ormajollila]

Just out of curiosity I wanted to see what happens to memory usage when I remove \OC::$server->getLogger()->debug(); lines so I edited the function:

        public function assemble($f) {
                $cache = $this->getCache();
                $prefix = $this->getPrefix();
                $count = 0;
                for ($i = 0; $i < $this->info['chunkcount']; $i++) {
                        \OC::$server->getLogger()->debug('Memory usage begin: ' . memory_get_usage());
                        $chunk = $cache->get($prefix.$i);
                        // remove after reading to directly save space
                        $cache->remove($prefix.$i);
                        $count += fwrite($f, $chunk);
                        \OC::$server->getLogger()->debug('Memory usage end: ' . memory_get_usage());

                        $wr = fopen("/tmp/memory_usage", "a");
                        fputs($wr, "Chunk: " . $prefix.$i . "\t\t" . memory_get_usage(true) . "\n");
                        fclose($wr);

                }
                return $count;
        }

With OC logging: http://pastebin.com/SaXHepyN
Without OC logging: http://pastebin.com/H8gjgzc3

The one without OC logging dies at chunk 911 (912).

[PVince81]

Strange. In both cases the memory usage seems to increase every 100-200 chunks.
Even stranger is why would OC logging make the issue disappear! But that one also seems to have increased memory consumption after a few chunks.

[chriseqipe]

There seems to be a still a memory leaking problem with lib/private/files/storage/local.php on line 179:
return file_get_contents($this->getSourcePath($path));

This guys here had the same problem and kvz answered Nov 9 2010, that the is a leak in file_get_contents.

Bug was reported here:
https://bugs.php.net/bug.php?id=61961

But to me it seems as if the memory leaking problem still exists...
PHP 5.6 at least.

And btw:

I think the way how the filechunking is solved, is IMHO not done the clever way.
The bigger number the number of the chunks the longer it takes to assemble them.
And the loop that checks if all chunks have been received gets also slower and slower...

[chriseqipe]

in lib/private/files/storage/local.php in changed to:

public function file_get_contents($path) {
                // return file_get_contents($this->getSourcePath($path));
                $filename = $this->getSourcePath($path);
                $handle = fopen($filename,'rb');
                $content = fread($handle, filesize($filename));
                fclose($handle);
                return $content;
        }

in lib/private/filechunking.php:

public function assemble($f) {
                $cache = $this->getCache();
                $prefix = $this->getPrefix();
                $count = 0;
                for ($i = 0; $i < $this->info['chunkcount']; $i++) {
                        $chunk = $cache->get($prefix.$i);
                        // remove after reading to directly save space
                        $cache->remove($prefix.$i);
                        $count += fwrite($f, $chunk);
                        // let php release the memory to work around memory exhausted error with php 5.6
                        $chunk=null;
                }

                return $count;
        }

Solved my out of memory problems...

[guruz]

@chriseqipe Are you sending a pull request for this?

[guruz]

And the loop that checks if all chunks have been received gets also slower and slower...

FYI @DeepDiver1975 @dragotin what we had discussed..

[chriseqipe]

I will make a pull request... I just inspected the 9.0 branch and still php native file_get_contents() in charge...

[MorrisJobke]

I will make a pull request... I just inspected the 9.0 branch and still php native file_get_contents() in charge...

Done #23304

[mcxgr]

I have above behavior on a "properly" configured (for large files) virgin 9.0 + Debian 8.x + Apache2 installation @MorrisJobke

[guruz]

@mcxgr Have you checked with #23304 added too?

[lock]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.