Socket timeout exception on file upload

[taaem]

Actual behaviour

When I upload a file there is a <80% chance of failing to upload. The app itself shows a error message "Es ist ein Fehler während des Wartens auf den Server aufgetreten", which translates to "There was an issue while waiting for the server".

Expected behaviour

It should upload the file and I can upload via the desktop client and even the web interface on the same device.

Steps to reproduce

1. Upload a file
2. Wait for it to fail

Environment data

Android version: 7.1.1

Device model: OnePlus X

Stock or customized system: Custom ROM

Nextcloud app version: 20170214

Nextcloud server version: 11.0.1

Logs

Web server error log

[14/Feb/2017:19:11:34 +0100] "GET /status.php HTTP/1.1" 200 157 "-" "Mozilla/5.0 (Android) nextcloud-android/20170214"
[14/Feb/2017:19:11:43 +0100] "HEAD /remote.php/webdav/ HTTP/1.1" 499 0 "-" "Mozilla/5.0 (Android) nextcloud-android/20170214"
 [14/Feb/2017:19:11:54 +0100] "GET /ocs/v1.php/cloud/capabilities?format=json HTTP/1.1" 200 1017 "-" "Mozilla/5.0 (Android) nextcloud-android/20170214"
[14/Feb/2017:19:11:54 +0100] "GET /ocs/v1.php/cloud/users/user?format=json HTTP/1.1" 200 280 "-" "Mozilla/5.0 (Android) nextcloud-android/20170214"
[14/Feb/2017:19:12:23 +0100] "GET /ocs/v1.php/cloud/users/user?format=json HTTP/1.1" 200 280 "-" "Mozilla/5.0 (Android) nextcloud-android/20170214"
[14/Feb/2017:19:12:29 +0100] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 852 "-" "Mozilla/5.0 (Android) nextcloud-android/20170214"
[14/Feb/2017:19:12:30 +0100] "GET /ocs/v1.php/apps/files_sharing/api/v1/shares?path=%2F&reshares=true&subfiles=true HTTP/1.1" 200 198 "-" "Mozilla/5.0 (Android) nextcloud-android/20170214"

Nextcloud log (logcat)

02-14 19:11:33.468  4025  4025 D UploadsStorageManager: storeUpload returns with: content://org.nextcloud.beta.provider/uploads/934 for file: /storage/39C9-10FA/DCIM/Camera/IMG_20160303_080852.jpg
02-14 19:11:33.468  4025  4025 D UploadsStorageManager: notifyObserversNow
02-14 19:11:33.469  4025  4025 D FileDisplayActivity: Received broadcast com.owncloud.android.operations.RefreshFolderOperation.EVENT_SINGLE_FOLDER_CONTENTS_SYNCED
02-14 19:11:33.474  4025  2332 V UploadsStorageManager: Updating /storage/39C9-10FA/DCIM/Camera/IMG_20160303_080852.jpg with status:UPLOAD_IN_PROGRESS and result:UNKNOWN (old:/storage/39C9-10FA/DCIM/Camera/IMG_20160303_080852.jpg status:UPLOAD_IN_PROGRESS result:-1)
02-14 19:11:33.474  4025  2332 V UploadsStorageManager: Updating /storage/39C9-10FA/DCIM/Camera/IMG_20160303_080852.jpg with status=UPLOAD_IN_PROGRESS
02-14 19:11:33.488  4025  2332 D UploadsStorageManager: updateUpload returns with: 1 for file: /storage/39C9-10FA/DCIM/Camera/IMG_20160303_080852.jpg
02-14 19:11:33.488  4025  2332 D UploadsStorageManager: notifyObserversNow
02-14 19:11:33.504  4025  2332 D SimpleFactoryManager: getClientFor(OwnCloudAccount ... : 
02-14 19:11:33.504  4025  2332 D OwnCloudClient #10: Creating OwnCloudClient
02-14 19:11:33.504  4025  2332 V SimpleFactoryManager:     new client {taaem@yellowhouse.ddns.net, 230321393}
02-14 19:11:33.509  4025  2332 D OwnCloudClient #10: REQUEST HEAD /remote.php/webdav/
02-14 19:11:33.521  4025  4025 D FileDisplayActivity: Setting progress visibility to true
02-14 19:11:33.521  4025  4025 D FileDisplayActivity: Received broadcast com.owncloud.android.operations.RefreshFolderOperation.EVENT_SINGLE_FOLDER_SHARES_SYNCED
02-14 19:11:33.554  4025  4025 D FileDisplayActivity: Setting progress visibility to false
02-14 19:11:33.867  4025  4025 D UploadFilesActivity: onStop() ending
02-14 19:11:34.204  4025  4025 D UploadFilesActivity: onDestroy() ending
02-14 19:11:34.270  4025  2719 D SimpleFactoryManager: getClientFor(OwnCloudAccount ... : 
02-14 19:11:34.270  4025  2719 D OwnCloudClient #11: Creating OwnCloudClient
02-14 19:11:34.271  4025  2719 V SimpleFactoryManager:     new client {"Here was the URL", 83502551}
02-14 19:11:34.281  4025  2719 D OwnCloudClient #11: REQUEST GET /status.php
02-14 19:11:34.435  4025  2719 W HttpMethodBase: Going to buffer response body of large or unknown size. Using getResponseBodyAsStream instead is recommended.
02-14 19:11:34.470  4025  2719 D UpdateOCVersionOperation: Got new OC version 11.0.1.2
02-14 19:11:34.470  4025  2719 I UpdateOCVersionOperation: Check for update of ownCloud server version at https://"Here was the URL"/remote.php/webdav: Operation finished with HTTP status code -1 (success)
02-14 19:11:34.474  4025  2719 D SimpleFactoryManager: getClientFor(OwnCloudAccount ... : 
02-14 19:11:34.474  4025  2719 D OwnCloudClient #12: Creating OwnCloudClient
02-14 19:11:34.475  4025  2719 V SimpleFactoryManager:     new client {"Here was the URL", 22269636}
02-14 19:11:34.481  4025  2719 D OwnCloudClient #12: REQUEST GET /ocs/v1.php/cloud/capabilities
02-14 19:11:35.921  2329 16236 I ActivityManager: Setting hasTopUi=true for pid=8151
02-14 19:11:43.681  4025  2332 E ExistenceCheckRemoteOperation: Existence check for https://yellowhouse.ddns.net/remote.php/webdav/ targeting for  existence : Socket timeout exception
02-14 19:11:43.681  4025  2332 E ExistenceCheckRemoteOperation: java.net.SocketTimeoutException: Read timed out
02-14 19:11:43.681  4025  2332 E ExistenceCheckRemoteOperation: 	at com.android.org.conscrypt.NativeCrypto.SSL_read(Native Method)
02-14 19:11:43.681  4025  2332 E ExistenceCheckRemoteOperation: 	at com.android.org.conscrypt.OpenSSLSocketImpl$SSLInputStream.read(OpenSSLSocketImpl.java:758)
02-14 19:11:43.681  4025  2332 E ExistenceCheckRemoteOperation: 	at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)
02-14 19:11:43.681  4025  2332 E ExistenceCheckRemoteOperation: 	at java.io.BufferedInputStream.read(BufferedInputStream.java:254)
02-14 19:11:43.681  4025  2332 E ExistenceCheckRemoteOperation: 	at org.apache.commons.httpclient.HttpParser.readRawLine(HttpParser.java:78)
02-14 19:11:43.681  4025  2332 E ExistenceCheckRemoteOperation: 	at org.apache.commons.httpclient.HttpParser.readLine(HttpParser.java:106)
02-14 19:11:43.681  4025  2332 E ExistenceCheckRemoteOperation: 	at org.apache.commons.httpclient.HttpConnection.readLine(HttpConnection.java:1116)
02-14 19:11:43.681  4025  2332 E ExistenceCheckRemoteOperation: 	at org.apache.commons.httpclient.MultiThreadedHttpConnectionManager$HttpConnectionAdapter.readLine(MultiThreadedHttpConnectionManager.java:1413)
02-14 19:11:43.681  4025  2332 E ExistenceCheckRemoteOperation: 	at org.apache.commons.httpclient.HttpMethodBase.readStatusLine(HttpMethodBase.java:1973)
02-14 19:11:43.681  4025  2332 E ExistenceCheckRemoteOperation: 	at org.apache.commons.httpclient.HttpMethodBase.readResponse(HttpMethodBase.java:1735)
02-14 19:11:43.681  4025  2332 E ExistenceCheckRemoteOperation: 	at org.apache.commons.httpclient.HttpMethodBase.execute(HttpMethodBase.java:1098)
02-14 19:11:43.681  4025  2332 E ExistenceCheckRemoteOperation: 	at org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry(HttpMethodDirector.java:398)
02-14 19:11:43.681  4025  2332 E ExistenceCheckRemoteOperation: 	at org.apache.commons.httpclient.HttpMethodDirector.executeMethod(HttpMethodDirector.java:171)
02-14 19:11:43.681  4025  2332 E ExistenceCheckRemoteOperation: 	at org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:397)
02-14 19:11:43.681  4025  2332 E ExistenceCheckRemoteOperation: 	at org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:323)
02-14 19:11:43.681  4025  2332 E ExistenceCheckRemoteOperation: 	at com.owncloud.android.lib.common.OwnCloudClient.executeMethod(OwnCloudClient.java:222)
02-14 19:11:43.681  4025  2332 E ExistenceCheckRemoteOperation: 	at com.owncloud.android.lib.common.OwnCloudClient.executeMethod(OwnCloudClient.java:192)
02-14 19:11:43.681  4025  2332 E ExistenceCheckRemoteOperation: 	at com.owncloud.android.lib.resources.files.ExistenceCheckRemoteOperation.run(ExistenceCheckRemoteOperation.java:91)
02-14 19:11:43.681  4025  2332 E ExistenceCheckRemoteOperation: 	at com.owncloud.android.lib.common.operations.RemoteOperation.execute(RemoteOperation.java:136)
02-14 19:11:43.681  4025  2332 E ExistenceCheckRemoteOperation: 	at com.owncloud.android.operations.UploadFileOperation.grantFolderExistence(UploadFileOperation.java:496)
02-14 19:11:43.681  4025  2332 E ExistenceCheckRemoteOperation: 	at com.owncloud.android.operations.UploadFileOperation.run(UploadFileOperation.java:322)
02-14 19:11:43.681  4025  2332 E ExistenceCheckRemoteOperation: 	at com.owncloud.android.lib.common.operations.RemoteOperation.execute(RemoteOperation.java:136)
02-14 19:11:43.681  4025  2332 E ExistenceCheckRemoteOperation: 	at com.owncloud.android.operations.common.SyncOperation.execute(SyncOperation.java:93)
02-14 19:11:43.681  4025  2332 E ExistenceCheckRemoteOperation: 	at com.owncloud.android.files.services.FileUploader.uploadFile(FileUploader.java:931)
02-14 19:11:43.681  4025  2332 E ExistenceCheckRemoteOperation: 	at com.owncloud.android.files.services.FileUploader$ServiceHandler.handleMessage(FileUploader.java:876)
02-14 19:11:43.681  4025  2332 E ExistenceCheckRemoteOperation: 	at android.os.Handler.dispatchMessage(Handler.java:102)
02-14 19:11:43.681  4025  2332 E ExistenceCheckRemoteOperation: 	at android.os.Looper.loop(Looper.java:153)
02-14 19:11:43.681  4025  2332 E ExistenceCheckRemoteOperation: 	at android.os.HandlerThread.run(HandlerThread.java:61)
02-14 19:11:43.700  4025  2332 E UploadFileOperation: Upload of /storage/39C9-10FA/DCIM/Camera/IMG_20160303_080852.jpg to /IMG_20160303_080852.jpg: Socket timeout exception
02-14 19:11:43.700  4025  2332 E UploadFileOperation: java.net.SocketTimeoutException: Read timed out
02-14 19:11:43.700  4025  2332 E UploadFileOperation: 	at com.android.org.conscrypt.NativeCrypto.SSL_read(Native Method)
02-14 19:11:43.700  4025  2332 E UploadFileOperation: 	at com.android.org.conscrypt.OpenSSLSocketImpl$SSLInputStream.read(OpenSSLSocketImpl.java:758)
02-14 19:11:43.700  4025  2332 E UploadFileOperation: 	at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)
02-14 19:11:43.700  4025  2332 E UploadFileOperation: 	at java.io.BufferedInputStream.read(BufferedInputStream.java:254)
02-14 19:11:43.700  4025  2332 E UploadFileOperation: 	at org.apache.commons.httpclient.HttpParser.readRawLine(HttpParser.java:78)
02-14 19:11:43.700  4025  2332 E UploadFileOperation: 	at org.apache.commons.httpclient.HttpParser.readLine(HttpParser.java:106)
02-14 19:11:43.700  4025  2332 E UploadFileOperation: 	at org.apache.commons.httpclient.HttpConnection.readLine(HttpConnection.java:1116)
02-14 19:11:43.700  4025  2332 E UploadFileOperation: 	at org.apache.commons.httpclient.MultiThreadedHttpConnectionManager$HttpConnectionAdapter.readLine(MultiThreadedHttpConnectionManager.java:1413)
02-14 19:11:43.700  4025  2332 E UploadFileOperation: 	at org.apache.commons.httpclient.HttpMethodBase.readStatusLine(HttpMethodBase.java:1973)
02-14 19:11:43.700  4025  2332 E UploadFileOperation: 	at org.apache.commons.httpclient.HttpMethodBase.readResponse(HttpMethodBase.java:1735)
02-14 19:11:43.700  4025  2332 E UploadFileOperation: 	at org.apache.commons.httpclient.HttpMethodBase.execute(HttpMethodBase.java:1098)
02-14 19:11:43.700  4025  2332 E UploadFileOperation: 	at org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry(HttpMethodDirector.java:398)
02-14 19:11:43.700  4025  2332 E UploadFileOperation: 	at org.apache.commons.httpclient.HttpMethodDirector.executeMethod(HttpMethodDirector.java:171)
02-14 19:11:43.700  4025  2332 E UploadFileOperation: 	at org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:397)
02-14 19:11:43.700  4025  2332 E UploadFileOperation: 	at org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:323)
02-14 19:11:43.700  4025  2332 E UploadFileOperation: 	at com.owncloud.android.lib.common.OwnCloudClient.executeMethod(OwnCloudClient.java:222)
02-14 19:11:43.700  4025  2332 E UploadFileOperation: 	at com.owncloud.android.lib.common.OwnCloudClient.executeMethod(OwnCloudClient.java:192)
02-14 19:11:43.700  4025  2332 E UploadFileOperation: 	at com.owncloud.android.lib.resources.files.ExistenceCheckRemoteOperation.run(ExistenceCheckRemoteOperation.java:91)
02-14 19:11:43.700  4025  2332 E UploadFileOperation: 	at com.owncloud.android.lib.common.operations.RemoteOperation.execute(RemoteOperation.java:136)
02-14 19:11:43.700  4025  2332 E UploadFileOperation: 	at com.owncloud.android.operations.UploadFileOperation.grantFolderExistence(UploadFileOperation.java:496)
02-14 19:11:43.700  4025  2332 E UploadFileOperation: 	at com.owncloud.android.operations.UploadFileOperation.run(UploadFileOperation.java:322)
02-14 19:11:43.700  4025  2332 E UploadFileOperation: 	at com.owncloud.android.lib.common.operations.RemoteOperation.execute(RemoteOperation.java:136)
02-14 19:11:43.700  4025  2332 E UploadFileOperation: 	at com.owncloud.android.operations.common.SyncOperation.execute(SyncOperation.java:93)
02-14 19:11:43.700  4025  2332 E UploadFileOperation: 	at com.owncloud.android.files.services.FileUploader.uploadFile(FileUploader.java:931)
02-14 19:11:43.700  4025  2332 E UploadFileOperation: 	at com.owncloud.android.files.services.FileUploader$ServiceHandler.handleMessage(FileUploader.java:876)
02-14 19:11:43.700  4025  2332 E UploadFileOperation: 	at android.os.Handler.dispatchMessage(Handler.java:102)
02-14 19:11:43.700  4025  2332 E UploadFileOperation: 	at android.os.Looper.loop(Looper.java:153)
02-14 19:11:43.700  4025  2332 E UploadFileOperation: 	at android.os.HandlerThread.run(HandlerThread.java:61)
02-14 19:11:43.701  4025  2332 D UploadsStorageManager: updateDataseUploadResult uploadResult: com.owncloud.android.lib.common.operations.RemoteOperationResult@1211330 upload: com.owncloud.android.operations.UploadFileOperation@60dfba9
02-14 19:11:43.710  4025  2332 V UploadsStorageManager: Updating /storage/39C9-10FA/DCIM/Camera/IMG_20160303_080852.jpg with status:UPLOAD_FAILED and result:NETWORK_CONNECTION (old:/storage/39C9-10FA/DCIM/Camera/IMG_20160303_080852.jpg status:UPLOAD_IN_PROGRESS result:-1)
02-14 19:11:43.710  4025  2332 V UploadsStorageManager: Updating /storage/39C9-10FA/DCIM/Camera/IMG_20160303_080852.jpg with status=UPLOAD_FAILED
02-14 19:11:43.762  4025  2332 D UploadsStorageManager: updateUpload returns with: 1 for file: /storage/39C9-10FA/DCIM/Camera/IMG_20160303_080852.jpg
02-14 19:11:43.762  4025  2332 D UploadsStorageManager: notifyObserversNow
02-14 19:11:43.765  4025  2332 D FileUploader: NotifyUploadResult with resultCode: TIMEOUT
02-14 19:11:43.908  4025  2332 D FileUploader: Stopping command after id 1

[boldt]

I can confirm this, with the difference that I'm using the auto upload function, and it doesnt work at all. I'm getting the same error on my Android 7 (Xperia Z5).

[mario]

@boldt can you try using 3g/4g instead of wifi? Just for debugging.

[boldt]

Just tested with H+ (3G), same error.

[mario]

@boldt please try this apk:

https://github.com/nextcloud/android/blob/auto-upload-ng-apk/apks/android-debug.apk?raw=true

Thanks! :)

[boldt]

I uninstalled 1.4.1, because I could not update. Now, I cannot login.

Errror message: "The server took too long to respond"

[mario]

Using LDAP maybe?

[boldt]

No LDAP. Just a standard installation with users handled by nextcloud.
If you're interested, I could create you a debugging account on my instance.

[mario]

Sure, please - mario AT nextcloud DOT com.

[boldt]

See mail. Just realized that the login with the web page takes at least 20s. Probably that's the main issue? ;)

[mario]

Yes, that's the issue :P So I don't even have to take a look hehe - sorry! :)

[boldt]

What's the configured timeout?

[mario]

What are you running this on / can I help debug the server config? :) With this APK, more than enough :D 3000 ms for connect, 50000 ms for socket timeout if I remember right :)

[boldt]

I disabled auth.bruteforce.protection.enabled and cleaned table oc_bruteforce_attempts. Now the login is quite fast again.

[mario]

And login on android works too? :P