Auto Upload of large files with server encryption enabled timeout

[bqq100]

Steps to reproduce

1. Enable server side encryption
2. Auto-upload a large file
3. If the MOVE operation takes > 60 seconds the app reports an error.

Expected behaviour

• Upload should complete successfully

Actual behaviour

• Error in the app and on the server. Error codes/messages vary depending on server configuration. For no reverse proxy and nginx configured with an extended timeout, the app reports "Upload failed... An error occurred while waiting for the server." The server reports a 499 Client Closed Request status code.

Can you reproduce this problem on https://try.nextcloud.com?

• No, need server side encryption enabled

Environment data

Android version: 10

Device model: Pixel 4A

Stock or customized system: Stock (rooted)

Nextcloud app version: 3.17

Nextcloud server version: 21.0.4

Reverse proxy: None

Web server error log

- [03/Oct/2021:04:17:29 +0000] "MOVE /remote.php/dav/uploads//023a5d7624722d912d18e255330e7f3c/.file HTTP/1.1" 499 0 "-" "Mozilla/5.0 (Android) Nextcloud-android/3.17.0"

Nextcloud log (data/nextcloud.log)

No Errors

NGINX stack trace for slow transaction (I believe I had slowlog timeout set to 15 seconds for this stack trace)

[pool www] pid 2362
script_filename = /var/www/nextcloud/remote.php
[0x00007f8df8017550] hash_hmac() /encryption/lib/Crypto/Crypt.php:520
[0x00007f8df80174d0] createSignature() /encryption/lib/Crypto/Crypt.php:199
[0x00007f8df80173e0] symmetricEncryptFileContent() /encryption/lib/Crypto/Encryption.php:347
[0x00007f8df8017320] encrypt() /var/www/nextcloud/lib/private/Files/Stream/Encryption.php:488
[0x00007f8df8017250] flush() /var/www/nextcloud/lib/private/Files/Stream/Encryption.php:400
[0x00007f8df8017170] stream_write() /var/www/nextcloud/lib/private/legacy/OC_Helper.php:261
[0x00007f8df8017100] fwrite() /var/www/nextcloud/lib/private/legacy/OC_Helper.php:261
[0x00007f8df8017030] streamCopy() /var/www/nextcloud/lib/private/Files/Storage/Wrapper/Encryption.php:1036
[0x00007f8df8016f60] writeStream() /var/www/nextcloud/lib/private/Files/Storage/Wrapper/Wrapper.php:629
[0x00007f8df8016e80] writeStream() /dav/lib/Connector/Sabre/File.php:207
[0x00007f8df8016c70] put() /dav/lib/Connector/Sabre/Directory.php:156
[0x00007f8df8016b60] createFile() /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Tree.php:305
[0x00007f8df8016a60] copyNode() /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Tree.php:133
[0x00007f8df8016990] copy() /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Tree.php:163
[0x00007f8df80168a0] move() /dav/lib/Upload/ChunkingPlugin.php:95
[0x00007f8df80167d0] performMove() /dav/lib/Upload/ChunkingPlugin.php:77
[0x00007f8df80166e0] beforeMove() /var/www/nextcloud/3rdparty/sabre/event/lib/WildcardEmitterTrait.php:89
[0x00007f8df8016600] emit() /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/CorePlugin.php:603
[0x00007f8df8016530] httpMove() /var/www/nextcloud/3rdparty/sabre/event/lib/WildcardEmitterTrait.php:89
[0x00007f8df8016450] emit() /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php:472
[0x00007f8df8016390] invokeMethod() /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php:253
[0x00007f8df8016290] start() /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php:321
[0x00007f8df8016240] exec() /dav/lib/Server.php:332
[0x00007f8df80161e0] exec() /dav/appinfo/v2/remote.php:35
[0x00007f8df8016140] INCLUDE_OR_EVAL /var/www/nextcloud/remote.php:167

[bqq100]

logcat capture of the error.... It looks like some setting I've changed on the server is causing the issue at 40 seconds now instead of 60 seconds.

10-04 00:15:08.612 11988 12767 D OwnCloudClient #0: REQUEST MOVE /remote.php/dav/uploads/<EMAIL>/d1ad14f6295aa20703f1a1ca52515f86/.file 10-04 00:15:48.771 11988 12767 E UploadFileOperation: Upload of /storage/emulated/0/<FOLDER>/<FILE> to /<FOLDER>/<FILE>: Socket timeout exception 10-04 00:15:48.771 11988 12767 E UploadFileOperation: java.net.SocketTimeoutException: Read timed out 10-04 00:15:48.771 11988 12767 E UploadFileOperation: at com.google.android.gms.org.conscrypt.NativeCrypto.SSL_read(Native Method) 10-04 00:15:48.771 11988 12767 E UploadFileOperation: at com.google.android.gms.org.conscrypt.NativeSsl.read(:com.google.android.gms@213614037@21.36.14 (120400-395708125):3) 10-04 00:15:48.771 11988 12767 E UploadFileOperation: at com.google.android.gms.org.conscrypt.ConscryptFileDescriptorSocket$SSLInputStream.read(:com.google.android.gms@213614037@21.36.14 (120400-395708125):6) 10-04 00:15:48.771 11988 12767 E UploadFileOperation: at java.io.BufferedInputStream.fill(BufferedInputStream.java:248) 10-04 00:15:48.771 11988 12767 E UploadFileOperation: at java.io.BufferedInputStream.read(BufferedInputStream.java:267) 10-04 00:15:48.771 11988 12767 E UploadFileOperation: at org.apache.commons.httpclient.HttpParser.readRawLine(HttpParser.java:78) 10-04 00:15:48.771 11988 12767 E UploadFileOperation: at org.apache.commons.httpclient.HttpParser.readLine(HttpParser.java:106) 10-04 00:15:48.771 11988 12767 E UploadFileOperation: at org.apache.commons.httpclient.HttpConnection.readLine(HttpConnection.java:1116) 10-04 00:15:48.771 11988 12767 E UploadFileOperation: at org.apache.commons.httpclient.MultiThreadedHttpConnectionManager$HttpConnectionAdapter.readLine(MultiThreadedHttpConnectionManager.java:1413) 10-04 00:15:48.771 11988 12767 E UploadFileOperation: at org.apache.commons.httpclient.HttpMethodBase.readStatusLine(HttpMethodBase.java:1973) 10-04 00:15:48.771 11988 12767 E UploadFileOperation: at org.apache.commons.httpclient.HttpMethodBase.readResponse(HttpMethodBase.java:1735) 10-04 00:15:48.771 11988 12767 E UploadFileOperation: at org.apache.commons.httpclient.HttpMethodBase.execute(HttpMethodBase.java:1098) 10-04 00:15:48.771 11988 12767 E UploadFileOperation: at org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry(HttpMethodDirector.java:398) 10-04 00:15:48.771 11988 12767 E UploadFileOperation: at org.apache.commons.httpclient.HttpMethodDirector.executeMethod(HttpMethodDirector.java:171) 10-04 00:15:48.771 11988 12767 E UploadFileOperation: at org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:397) 10-04 00:15:48.771 11988 12767 E UploadFileOperation: at org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:323) 10-04 00:15:48.771 11988 12767 E UploadFileOperation: at com.owncloud.android.lib.common.OwnCloudClient.executeMethod(OwnCloudClient.java:219) 10-04 00:15:48.771 11988 12767 E UploadFileOperation: at com.owncloud.android.lib.resources.files.ChunkedFileUploadRemoteOperation.run(ChunkedFileUploadRemoteOperation.java:184) 10-04 00:15:48.771 11988 12767 E UploadFileOperation: at com.owncloud.android.lib.common.operations.RemoteOperation.execute(RemoteOperation.java:187) 10-04 00:15:48.771 11988 12767 E UploadFileOperation: at com.owncloud.android.operations.UploadFileOperation.normalUpload(UploadFileOperation.java:831) 10-04 00:15:48.771 11988 12767 E UploadFileOperation: at com.owncloud.android.operations.UploadFileOperation.run(UploadFileOperation.java:433) 10-04 00:15:48.771 11988 12767 E UploadFileOperation: at com.owncloud.android.lib.common.operations.RemoteOperation.execute(RemoteOperation.java:187) 10-04 00:15:48.771 11988 12767 E UploadFileOperation: at com.owncloud.android.operations.common.SyncOperation.execute(SyncOperation.java:87) 10-04 00:15:48.771 11988 12767 E UploadFileOperation: at com.owncloud.android.files.services.FileUploader.uploadFile(FileUploader.java:642) 10-04 00:15:48.771 11988 12767 E UploadFileOperation: at com.owncloud.android.files.services.FileUploader$ServiceHandler.handleMessage(FileUploader.java:1402) 10-04 00:15:48.771 11988 12767 E UploadFileOperation: at android.os.Handler.dispatchMessage(Handler.java:107) 10-04 00:15:48.771 11988 12767 E UploadFileOperation: at android.os.Looper.loop(Looper.java:214) 10-04 00:15:48.771 11988 12767 E UploadFileOperation: at android.os.HandlerThread.run(HandlerThread.java:67) 10-04 00:15:48.777 11988 12767 D UploadsStorageManager: updateDatabaseUploadResult uploadResult: RemoteOperationResult(mSuccess=false, mHttpCode=-1, mHttpPhrase=null, mException=java.net.SocketTimeoutException: Read timed out, mCode=TIMEOUT, message=null, getLogMessage=Socket timeout exception) upload: com.owncloud.android.operations.UploadFileOperation@da9509b 10-04 00:15:48.792 11988 12767 V UploadsStorageManager: Updating /storage/emulated/0/<FOLDER>/<FILE> with status:UPLOAD_FAILED and result:NETWORK_CONNECTION (old:/storage/emulated/0/<FOLDER>/<FILE> status:UPLOAD_IN_PROGRESS result:-1) 10-04 00:15:48.792 11988 12767 V UploadsStorageManager: Updating /storage/emulated/0/<FOLDER>/<FILE> with status=UPLOAD_FAILED 10-04 00:15:48.800 11988 12767 D UploadsStorageManager: updateUpload returns with: 1 for file: /storage/emulated/0/<FOLDER>/<FILE> 10-04 00:15:48.800 11988 12767 D UploadsStorageManager: notifyObserversNow 10-04 00:15:48.802 11988 12767 D FileUploader: NotifyUploadResult with resultCode: TIMEOUT 10-04 00:15:48.818 11988 12767 D FileUploader: Stopping command after id 47

[bqq100]

I turned slowlog trace off in php-fpm and the timeout issue returned to 60 seconds.

I also manually tested using curl and I was able to do a MOVE operation that took 114 seconds and I got a 201 status code as expected, so the server seems to be configured correctly.

Also MOVE_READ_TIMEOUT looks like it's already configured for 600 seconds, so not sure why the app is timing out after 60 seconds....
https://github.com/nextcloud/android-library/blob/master/src/main/java/com/owncloud/android/lib/resources/files/MoveFileRemoteOperation.java

[AlvaroBrey]

This should be fixed by nextcloud/android-library#709, which is available on version 3.18.0 RC2, and will be on 3.18.0 final release in some weeks.