Android: Upload from Android app fails

Created on 23 Sep 2016 · 75Comments · Source: nextcloud/android

Actual behaviour

-(Auto)upload from Android app fails ALMOST always after a variable progress

Expected behaviour

-(Auto)upload from Android app should succeed :)

Steps to reproduce

Configure App to upload new photos (here: in Wifi, without charging)
Take photo
See upload progress to a variable level, then fail with "connection error" ("Verbindungsfehler")

Further info

Uploading AND autouploading of certain files fails. The failing seems pretty reproducible for some file, especially most (but not all) camera images. Some other file can be uploaded without problems (including a 400+MB video). Some other videos also fail. I cannot find any pattern. Behavior is observed in 2 generally stable wifis.
I should perhaps note: The file for the logs belowis 4197043 bytes large. The error says it expected 353728 got 101043.
If the last chunk has 101043, this would leave 1024000 bytes for each of the other chunks, with is a number that makes a lot of sense. Why did it expect 353728 bytes?
I am pretty sure this is a very strong pointer to the root of the problem.

Environment data

Android version: 6 (OxygenOS 3.5.1)

Device model: Oneplus 3

Stock or customized system: Stock (Community release)

Nextcloud app version: 1.3.1-gplay

Nextcloud server version: 10.0

Logs

Web server error log

access.log:

195.37.61.2 - kay [23/Sep/2016:09:56:35 +0200] "HEAD /remote.php/webdav/SofortUpload/2016/09/ HTTP/1.1" 200 1366 "-" "Mozilla/5.0 (Android) ownCloud-android/1.3.1"
195.37.61.2 - kay [23/Sep/2016:09:56:36 +0200] "HEAD /remote.php/webdav/SofortUpload/2016/09/IMG_20160923_095633.jpg HTTP/1.1" 404 1240 "-" "Mozilla/5.0 (Android) ownCloud-android/1.3.1"
195.37.61.2 - kay [23/Sep/2016:09:56:36 +0200] "PUT /remote.php/webdav/SofortUpload/2016/09/IMG_20160923_095633.jpg-chunking-19670429-5-0 HTTP/1.1" 201 1261 "-" "Mozilla/5.0 (Android) ownCloud-android/1.3.1"
195.37.61.2 - kay [23/Sep/2016:09:56:37 +0200] "PUT /remote.php/webdav/SofortUpload/2016/09/IMG_20160923_095633.jpg-chunking-19670429-5-1 HTTP/1.1" 201 1253 "-" "Mozilla/5.0 (Android) ownCloud-android/1.3.1"
195.37.61.2 - kay [23/Sep/2016:09:56:38 +0200] "PUT /remote.php/webdav/SofortUpload/2016/09/IMG_20160923_095633.jpg-chunking-19670429-5-2 HTTP/1.1" 201 1257 "-" "Mozilla/5.0 (Android) ownCloud-android/1.3.1"
195.37.61.2 - kay [23/Sep/2016:09:56:39 +0200] "PUT /remote.php/webdav/SofortUpload/2016/09/IMG_20160923_095633.jpg-chunking-19670429-5-3 HTTP/1.1" 201 1253 "-" "Mozilla/5.0 (Android) ownCloud-android/1.3.1"
195.37.61.2 - kay [23/Sep/2016:09:56:39 +0200] "PUT /remote.php/webdav/SofortUpload/2016/09/IMG_20160923_095633.jpg-chunking-19670429-5-4 HTTP/1.1" 400 1548 "-" "Mozilla/5.0 (Android) ownCloud-android/1.3.1"
195.37.61.2 - kay [23/Sep/2016:09:56:42 +0200] "GET /index.php/avatar/kay/384 HTTP/1.1" 200 1652 "-" "Mozilla/5.0 (Android) ownCloud-android/1.3.1"
195.37.61.2 - kay [23/Sep/2016:09:56:42 +0200] "GET /ocs/v1.php/cloud/users/kay?format=json HTTP/1.1" 200 2521 "-" "Mozilla/5.0 (Android) ownCloud-android/1.3.1"
195.37.61.2 - kay [23/Sep/2016:09:56:42 +0200] "GET /ocs/v1.php/cloud/users/kay?format=json HTTP/1.1" 200 2519 "-" "Mozilla/5.0 (Android) ownCloud-android/1.3.1"
195.37.61.2 - kay [23/Sep/2016:09:56:42 +0200] "GET /index.php/avatar/kay/384 HTTP/1.1" 200 1505 "-" "Mozilla/5.0 (Android) ownCloud-android/1.3.1"

error.log
_nothing_

Nextcloud log (data/nextcloud.log)

{"reqId":"rRs5BlHKp0igYvtlOY7J","remoteAddr":"195.37.61.2","app":"webdav","message":"Exception: {\"Message\":\"HTTP\\\/1.1 400 expected filesize 353728 got 101043\",\"Exception\":\"Sabre\\\\DAV\\\\Exception\\\\BadRequest\",\"Code\":0,\"Trace\":\"#0 \\\/var\\\/www\\\/example.net\\\/cloud\\\/nextcloud-10.0.0\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/File.php(104): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\File->createFileChunked(Resource id #81)\\n#1 \\\/var\\\/www\\\/example.net\\\/cloud\\\/nextcloud-10.0.0\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Directory.php(137): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\File->put(Resource id #81)\\n#2 \\\/var\\\/www\\\/example.net\\\/cloud\\\/nextcloud-10.0.0\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(1036): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Directory->createFile('IMG_20160923_09...', Resource id #81)\\n#3 \\\/var\\\/www\\\/example.net\\\/cloud\\\/nextcloud-10.0.0\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/CorePlugin.php(523): Sabre\\\\DAV\\\\Server->createFile('SofortUpload\\\/20...', Resource id #81, NULL)\\n#4 [internal function]: Sabre\\\\DAV\\\\CorePlugin->httpPut(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#5 \\\/var\\\/www\\\/example.net\\\/cloud\\\/nextcloud-10.0.0\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#6 \\\/var\\\/www\\\/example.net\\\/cloud\\\/nextcloud-10.0.0\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(459): Sabre\\\\Event\\\\EventEmitter->emit('method:PUT', Array)\\n#7 \\\/var\\\/www\\\/example.net\\\/cloud\\\/nextcloud-10.0.0\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(248): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#8 \\\/var\\\/www\\\/example.net\\\/cloud\\\/nextcloud-10.0.0\\\/apps\\\/dav\\\/appinfo\\\/v1\\\/webdav.php(60): Sabre\\\\DAV\\\\Server->exec()\\n#9 \\\/var\\\/www\\\/example.net\\\/cloud\\\/nextcloud-10.0.0\\\/remote.php(165): require_once('\\\/var\\\/www\\\/example....')\\n#10 {main}\",\"File\":\"\\\/var\\\/www\\\/example.net\\\/cloud\\\/nextcloud-10.0.0\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/File.php\",\"Line\":405,\"User\":\"kay\"}","level":4,"time":"2016-09-23T07:56:40+00:00","method":"PUT","url":"\/remote.php\/webdav\/SofortUpload\/2016\/09\/IMG_20160923_095633.jpg-chunking-19670429-5-4","user":"kay"}

I know there are a lot of similar bug reports around, with various configuration solutions. I think I have added them all to my configs:

PHP (7.0.8-0ubuntu0.16.04.2, values from phpinfo(), so I know it is active):

max_execution_time = 3600
max_input_time = 3600
max_file_uploads = 50
upload_max_filesize = 16G
post_max_size = 16G
upload_tmp_dir = /data/tmp (disk has enough space, tried /tmp on SSD before, too)
memory_limit = 256M

Apache (Apache/2.4.18 (Ubuntu)):

KeepAlive On
MaxKeepAliveRequests 500
KeepAliveTimeout 500

<VirtualHost *:443>
    ServerAdmin [email protected]
    ServerName cloud.example.net

    DocumentRoot /var/www/example.net/cloud/current

    <Directory />
        Options +FollowSymLinks -Indexes
        AllowOverride None
    </Directory>
    <Directory /var/www/>
        Options FollowSymLinks MultiViews
        AllowOverride None
        Order allow,deny
        allow from all
    </Directory>
    <Directory /var/www/example.net/cloud>
        SSLRenegBufferSize 10486000

        <Limit GET POST OPTIONS PROPFIND PUT DELETE MKCOL MOVE>
                Order allow,deny
                Allow from all
        </Limit>
        <LimitExcept GET POST OPTIONS PROPFIND PUT DELETE MKCOL MOVE>
                Order deny,allow
                Deny from all
        </LimitExcept>
    </Directory>

    ErrorLog ${APACHE_LOG_DIR}/error.log
    # Possible values include: debug, info, notice, warn, error, crit, alert, emerg.
    LogLevel warn
    CustomLog ${APACHE_LOG_DIR}/ssl_access.log combined

    SSLEngine on
    Header always set Strict-Transport-Security "max-age=15552000; includeSubDomains"

    SSLCertificateFile    /etc/letsencrypt/live/cloud.example.net/fullchain.pem
    SSLCertificateKeyFile /etc/letsencrypt/live/cloud.example.net/privkey.pem

    SSLProtocol All -SSLv2 -SSLv3
    SSLHonorCipherOrder on
    SSLCipherSuite "EECDH+ECDSA+AESGCM EECDH+aRSA+AESGCM EECDH+ECDSA+SHA384 EECDH+ECDSA+SHA256 EECDH+aRSA+SHA384 EECDH+aRSA+SHA256 EECDH EDH+aRSA !RC4 !aNULL !eNULL !LOW !3DES !MD5 !EXP !PSK !SRP !DSS"
</VirtualHost>

Nextcloud:

<?php
$CONFIG = array (
  'instanceid' => '[...]',
  'passwordsalt' => '[...]',
  'trusted_domains' => 
  array (
    0 => 'cloud.example.net',
    1 => 'owncloud.example.net',
  ),
  'datadirectory' => '/data/programs/nextcloud',
  'dbtype' => 'mysql',
  'version' => '9.1.0.16',
  'dbname' => 'nextcloud',
  'dbhost' => '127.0.0.1',
  'dbtableprefix' => 'oc_',
  'dbuser' => 'nextcloud',
  'dbpassword' => '[...]',
  'installed' => true,
  'theme' => '',
  'maintenance' => false,
  'forcessl' => true,
  'mail_smtpmode' => 'smtp',
  'mail_from_address' => 'owncloud-admin',
  'mail_domain' => 'example.net',
  'mail_smtphost' => 'localhost',
  'mail_smtpport' => '25',
  'overwritewebroot' => '/',
  'secret' => '[...]',
  'loglevel' => 2,
  'overwrite.cli.url' => '/',
  'updatechecker' => false,
  'trashbin_retention_obligation' => 'auto',
  'htaccess.RewriteBase' => '/',
  'memcache.local' => '\\OC\\Memcache\\APCu',
  'memcache.locking' => '\\OC\\Memcache\\Redis',
  'filelocking.enabled' => 'true',
  'redis' => 
  array (
    'host' => '/var/run/redis/redis.sock',
    'port' => 0,
    'timeout' => 0.0,
  ),
);

In the last config I notice the version. Why is this not 10?

sudo -u www-data php ./occ upgrade
Nextcloud is already latest version

bug pr exists

Source

kvoit

All 75 comments

I would really like to try to increase chunk size for further testing, but that does not seem possible.

kvoit on 23 Sep 2016

Please note that this is most probably not a duplicate of #85. There, full chunks with an expected size of 1024000 prematurely fail. Here, only last chunks fail, apparently because SabreDAV expects something bigger than (file size - n*1024000).

Is this beta with better logging still available? The version I see on F-Droid is from more than 3 month ago.

kvoit on 24 Sep 2016

More info: I tried the same thing on the Sony Z3@Stock of my wife, and I could replicate the problem. A little more in detail, a first run of quite a lot of images works fine. Perhaps 50 to 100 (on both devices, I initially uploaded the DCIM folder with all old images). After those, any further attempt fails with the error above.

I also did not find any file with bytes ending with 728 (which could indicate some kind of mixup).

kvoit on 24 Sep 2016

@kvoit the beta is still available and is 5 days old: https://f-droid.org/repository/browse/?fdfilter=com.nextcloud&fdid=com.nextcloud.android.beta

The issue with the last chunk is likely related to the number of chunks and overall file size since the server then puts everything together with the last chunk which sometimes ends with a http timeout on the client side.

AndyScherzinger on 27 Sep 2016

Oh, indeed. My F-Droid didn't update properly. I have it installed now. The uploads still fail, the protocol is empty.
I do not think this is a timeout problem. It happens too fast. And it does not (always) happen with large files. A 400MB video works, 4MB pictures regularly fail. I am also not exactly doing this on a supercomputer, but the N36L is still more powerful than a Raspberry Pi, which people seem to use. Also, this is not a "sometimes" problem, but a "my upload is effectively dysfunktional" problem.

Have you taken into account that according to the log, the server receives exactly the size of the image, but for some reason expects more, as stated in the further info section of my report?

kvoit on 27 Sep 2016

Hi @kvoit sorry, I missed that in the logs. @tobiasKaminsky any idea as to why this happens?

AndyScherzinger on 27 Sep 2016

I confirm, i have the same problem on my OnePlus 3.
All was fine, but since a week, upload of photos does not work.
Don't work on server 9.5 so i upgrade to 10.0.
But it don't work on server 10.0.

ArnaudAUBERT on 28 Sep 2016

@ArnaudAUBERT what is the Operating System version on your OnePlus3 and do you know on which Android version it is based on? Simply asking since at the moment instant uploads are broken for phones running Android Nougat / 7 which is an issue we are currently working on.