"Connection timed out" when client trying to MOVE file after upload #33803

vlddm · 2018-12-07T05:54:37Z

Steps to reproduce

owncloud 10.0.10.4 upgraded from 9.1.4 on CentOS 7
owncloud client 2.5.1 build 10807 on Windows7
File to sync about 4GB

Expected behaviour

Normal sync

Actual behaviour

Sync is ok, but throws this annoying errors "Connection timed out"

Where did you install ownCloud from: official rpm

Signing status (ownCloud 9.0 and above): ok

The content of config/config.php:

{
    "system": {
        "instanceid": "ocjypo7ec2ly",
        "passwordsalt": "***REMOVED SENSITIVE VALUE***",
        "secret": "***REMOVED SENSITIVE VALUE***",
        "trusted_domains": [
            "myservexample.com"
        ],
        "datadirectory": "\/var\/www\/html\/owncloud\/data",
        "overwrite.cli.url": "https:\/\/myservexample.com\/owncloud",
        "dbtype": "mysql",
        "version": "10.0.10.4",
        "dbname": "owncloud",
        "dbhost": "localhost",
        "dbtableprefix": "oc_",
        "dbuser": "***REMOVED SENSITIVE VALUE***",
        "dbpassword": "***REMOVED SENSITIVE VALUE***",
        "logtimezone": "UTC",
        "installed": true,
        "theme": "",
        "updatechecker": false,
        "loglevel": 0,
        "maintenance": false,
        "htaccess.RewriteBase": "\/owncloud",
        "memcache.local": "\\OC\\Memcache\\APCu",
        "filelocking.enabled": true,
        "memcache.locking": "\\OC\\Memcache\\Redis",
        "redis": {
            "host": "localhost",
            "port": 6379,
            "timeout": 0,
            "password": "***REMOVED SENSITIVE VALUE***"
        },
        "remember_login_cookie_lifetime": 1296000,
        "session_lifetime": 604800,
        "session_keepalive": true,
        "tempdirectory": "\/home\/owncloud\/tempdir",
        "enabledPreviewProviders": [
            "OC\\Preview\\PNG",
            "OC\\Preview\\JPEG",
            "OC\\Preview\\GIF",
            "OC\\Preview\\BMP",
            "OC\\Preview\\XBitmap",
            "OC\\Preview\\MP3",
            "OC\\Preview\\TXT",
            "OC\\Preview\\MarkDown",
            "OC\\Preview\\Movie"
        ]
    }
}

List of activated apps:

Enabled:
  - calendar: 1.6.0
  - contacts: 1.5.4
  - dav: 0.4.0
  - federatedfilesharing: 0.3.1
  - files: 1.5.1
  - files_external: 0.7.1
  - files_pdfviewer: 0.10.0
  - files_sharing: 0.11.0
  - files_texteditor: 2.3.0
  - files_trashbin: 0.9.1
  - files_versions: 1.3.0
  - files_videoplayer: 0.9.8
  - gallery: 16.1.0
  - market: 0.2.5
  - notifications: 0.3.5
  - provisioning_api: 0.5.0
  - updatenotification: 0.2.1

Are you using external storage, if yes which one:: no

Are you using encryption: no

Are you using an external user-backend, if yes which one: no

Logs

ownCloud log (data/owncloud.log)

{"reqId":"5e2eb659-64b6-4dca-9d05-198300d2baf3","level":0,"time":"2018-12-07T04:48:45+00:00","remoteAddr":"my.ip.hid.den","user":"fly","app":"OC\\Authentication\\Token\\DefaultTokenProvider::updateToken","method":"PUT","url":"\/owncloud\/remote.php\/dav\/uploads\/fly\/87510300\/00000042","message":"updating token 8668, last check is now 1544155721"}
{"reqId":"5e2eb659-64b6-4dca-9d05-198300d2baf3","level":0,"time":"2018-12-07T04:48:45+00:00","remoteAddr":"my.ip.hid.den","user":"fly","app":"OC\\Authentication\\Token\\DefaultTokenProvider::getToken","method":"PUT","url":"\/owncloud\/remote.php\/dav\/uploads\/fly\/87510300\/00000042","message":"token 140b55dcd8a9ffc5adf41039bd3c8800a7b4e61a199e07d30a05035d721fa3af8f29f2a506d775f08b65419e8c61b76ad401637ba3a3bd2b822142a7cd479f62 does not exist"}
{"reqId":"790a30ea-ee92-4941-a692-2e7b1f3f90f1","level":0,"time":"2018-12-07T04:49:17+00:00","remoteAddr":"my.ip.hid.den","user":"fly","app":"OC\\Authentication\\Token\\DefaultTokenProvider::updateToken","method":"PUT","url":"\/owncloud\/remote.php\/dav\/uploads\/fly\/87510300\/00000043","message":"updating token 8668, last check is now 1544155721"}
{"reqId":"790a30ea-ee92-4941-a692-2e7b1f3f90f1","level":0,"time":"2018-12-07T04:49:17+00:00","remoteAddr":"my.ip.hid.den","user":"fly","app":"OC\\Authentication\\Token\\DefaultTokenProvider::getToken","method":"PUT","url":"\/owncloud\/remote.php\/dav\/uploads\/fly\/87510300\/00000043","message":"token 140b55dcd8a9ffc5adf41039bd3c8800a7b4e61a199e07d30a05035d721fa3af8f29f2a506d775f08b65419e8c61b76ad401637ba3a3bd2b822142a7cd479f62 does not exist"}
{"reqId":"ae87b7f3-6ac2-4b6c-88f9-c78918d975ff","level":0,"time":"2018-12-07T04:49:42+00:00","remoteAddr":"my.ip.hid.den","user":"fly","app":"OC\\Authentication\\Token\\DefaultTokenProvider::updateToken","method":"MOVE","url":"\/owncloud\/remote.php\/dav\/uploads\/fly\/87510300\/.file","message":"updating token 8668, last check is now 1544155721"}
{"reqId":"ae87b7f3-6ac2-4b6c-88f9-c78918d975ff","level":0,"time":"2018-12-07T04:49:42+00:00","remoteAddr":"my.ip.hid.den","user":"fly","app":"OC\\Authentication\\Token\\DefaultTokenProvider::getToken","method":"MOVE","url":"\/owncloud\/remote.php\/dav\/uploads\/fly\/87510300\/.file","message":"token 140b55dcd8a9ffc5adf41039bd3c8800a7b4e61a199e07d30a05035d721fa3af8f29f2a506d775f08b65419e8c61b76ad401637ba3a3bd2b822142a7cd479f62 does not exist"}
{"reqId":"9539eed7-77b6-4f63-98e2-41ac427df81e","level":0,"time":"2018-12-07T05:03:36+00:00","remoteAddr":"my.ip.hid.den","user":"fly","app":"OC\\Authentication\\Token\\DefaultTokenProvider::updateToken","method":"DELETE","url":"\/owncloud\/remote.php\/dav\/uploads\/fly\/87510300","message":"updating token 8668, last check is now 1544155721"}
{"reqId":"9539eed7-77b6-4f63-98e2-41ac427df81e","level":0,"time":"2018-12-07T05:03:36+00:00","remoteAddr":"my.ip.hid.den","user":"fly","app":"OC\\Authentication\\Token\\DefaultTokenProvider::getToken","method":"DELETE","url":"\/owncloud\/remote.php\/dav\/uploads\/fly\/87510300","message":"token 140b55dcd8a9ffc5adf41039bd3c8800a7b4e61a199e07d30a05035d721fa3af8f29f2a506d775f08b65419e8c61b76ad401637ba3a3bd2b822142a7cd479f62 does not exist"}
{"reqId":"9539eed7-77b6-4f63-98e2-41ac427df81e","level":2,"time":"2018-12-07T05:03:36+00:00","remoteAddr":"my.ip.hid.den","user":"fly","app":"dav","method":"DELETE","url":"\/owncloud\/remote.php\/dav\/uploads\/fly\/87510300","message":"Could not get node for path: \"uploads\/fly\/87510300\" : File with name \/\/87510300 could not be located"}
{"reqId":"9539eed7-77b6-4f63-98e2-41ac427df81e","level":0,"time":"2018-12-07T05:03:36+00:00","remoteAddr":"my.ip.hid.den","user":"fly","app":"webdav","method":"DELETE","url":"\/owncloud\/remote.php\/dav\/uploads\/fly\/87510300","message":"Exception: HTTP\/1.1 404 File with name \/\/87510300 could not be located: {\"Exception\":\"Sabre\\\\DAV\\\\Exception\\\\NotFound\",\"Message\":\"File with name \\\/\\\/87510300 could not be located\",\"Code\":0,\"Trace\":\"#0 \\\/var\\\/www\\\/html\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/Upload\\\/UploadHome.php(52): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Directory->getChild('87510300')\\n#1 \\\/var\\\/www\\\/html\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Tree.php(76): OCA\\\\DAV\\\\Upload\\\\UploadHome->getChild('87510300')\\n#2 \\\/var\\\/www\\\/html\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/Tree.php(48): Sabre\\\\DAV\\\\Tree->getNodeForPath('uploads\\\/fly\\\/875...')\\n#3 \\\/var\\\/www\\\/html\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Tree.php(178): OCA\\\\DAV\\\\Tree->getNodeForPath('uploads\\\/fly\\\/875...')\\n#4 \\\/var\\\/www\\\/html\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/CorePlugin.php(287): Sabre\\\\DAV\\\\Tree->delete('uploads\\\/fly\\\/875...')\\n#5 [internal function]: Sabre\\\\DAV\\\\CorePlugin->httpDelete(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#6 \\\/var\\\/www\\\/html\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#7 \\\/var\\\/www\\\/html\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(479): Sabre\\\\Event\\\\EventEmitter->emit('method:DELETE', Array)\\n#8 \\\/var\\\/www\\\/html\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(254): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#9 \\\/var\\\/www\\\/html\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/Server.php(298): Sabre\\\\DAV\\\\Server->exec()\\n#10 \\\/var\\\/www\\\/html\\\/owncloud\\\/apps\\\/dav\\\/appinfo\\\/v2\\\/remote.php(31): OCA\\\\DAV\\\\Server->exec()\\n#11 \\\/var\\\/www\\\/html\\\/owncloud\\\/remote.php(165): require_once('\\\/var\\\/www\\\/html\\\/o...')\\n#12 {main}\",\"File\":\"\\\/var\\\/www\\\/html\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Directory.php\",\"Line\":262}"}

Client log

12-07 04:49:09:259 [ debug sync.cookiejar ]     [ OCC::CookieJar::cookiesForUrl ]:      QUrl("https://myservexample.com/owncloud/remote.php/dav/uploads/fly/87510300/00000043") requests: (QNetworkCookie("oc_sessionPassphrase=C9iBWbUWH8PN%2FdYga8YEk2UQg%2Fq45IrZ6Wf72i7BpXfFVahokfoH6C9Pan%2FZ%2B7NU3CMcTiHi663LSmDuxLMawjTW2jakisxWwDm%2F86fCRJ1O8M1oxvHIcjcO9oosHu8%2F; secure; HttpOnly; domain=myservexample.com; path=/owncloud"), QNetworkCookie("ocjypo7ec2ly=7opk77ke1qtokuppu2hlme11l6; secure; HttpOnly; domain=myservexample.com; path=/owncloud"))
12-07 04:49:34:632 [ info sync.networkjob.put ]:        PUT of "https://myservexample.com/owncloud/remote.php/dav/uploads/fly/87510300/00000043" FINISHED WITH STATUS "OK" QVariant(int, 201) QVariant(QString, "Created")
12-07 04:49:34:633 [ info sync.accessmanager ]: 6 "MOVE" "https://myservexample.com/owncloud/remote.php/dav/uploads/fly/87510300/.file" has X-Request-ID "ae87b7f3-6ac2-4b6c-88f9-c78918d975ff"
12-07 04:49:34:633 [ debug sync.cookiejar ]     [ OCC::CookieJar::cookiesForUrl ]:      QUrl("https://myservexample.com/owncloud/remote.php/dav/uploads/fly/87510300/.file") requests: (QNetworkCookie("oc_sessionPassphrase=C9iBWbUWH8PN%2FdYga8YEk2UQg%2Fq45IrZ6Wf72i7BpXfFVahokfoH6C9Pan%2FZ%2B7NU3CMcTiHi663LSmDuxLMawjTW2jakisxWwDm%2F86fCRJ1O8M1oxvHIcjcO9oosHu8%2F; secure; HttpOnly; domain=myservexample.com; path=/owncloud"), QNetworkCookie("ocjypo7ec2ly=7opk77ke1qtokuppu2hlme11l6; secure; HttpOnly; domain=myservexample.com; path=/owncloud"))
12-07 05:02:27:633 [ warning sync.networkjob ]: Network job timeout QUrl("https://myservexample.com/owncloud/remote.php/dav/uploads/fly/87510300/.file")
12-07 05:02:27:633 [ info sync.networkjob.move ]:       MOVE of QUrl("https://myservexample.com/owncloud/remote.php/dav/uploads/fly/87510300/.file") FINISHED WITH STATUS "OperationCanceledError Connection timed out"
12-07 05:03:28:428 [ info sync.accessmanager ]: 5 "" "https://myservexample.com/owncloud/remote.php/dav/uploads/fly/87510300" has X-Request-ID "9539eed7-77b6-4f63-98e2-41ac427df81e"
12-07 05:03:28:428 [ debug sync.cookiejar ]     [ OCC::CookieJar::cookiesForUrl ]:      QUrl("https://myservexample.com/owncloud/remote.php/dav/uploads/fly/87510300") requests: (QNetworkCookie("oc_sessionPassphrase=C9iBWbUWH8PN%2FdYga8YEk2UQg%2Fq45IrZ6Wf72i7BpXfFVahokfoH6C9Pan%2FZ%2B7NU3CMcTiHi663LSmDuxLMawjTW2jakisxWwDm%2F86fCRJ1O8M1oxvHIcjcO9oosHu8%2F; secure; HttpOnly; domain=myservexample.com; path=/owncloud"), QNetworkCookie("ocjypo7ec2ly=7opk77ke1qtokuppu2hlme11l6; secure; HttpOnly; domain=myservexample.com; path=/owncloud"))
12-07 05:03:28:642 [ warning sync.networkjob ]: QNetworkReply::NetworkError(ContentNotFoundError) "Server replied \"404 Not Found\" to \"DELETE https://myservexample.com/owncloud/remote.php/dav/uploads/fly/87510300\"" QVariant(int, 404)
12-07 05:03:28:643 [ info sync.networkjob.delete ]:     DELETE of QUrl("https://myservexample.com/owncloud/remote.php/dav/uploads/fly/87510300") FINISHED WITH STATUS "ContentNotFoundError Server replied \"404 Not Found\" to \"DELETE https://myservexample.com/owncloud/remote.php/dav/uploads/fly/87510300\""

The text was updated successfully, but these errors were encountered:

ownclouders · 2018-12-07T06:20:13Z

GitMate.io thinks the contributors most likely able to help are @ownclouders, and @PVince81.

Possibly related issues are #8103 (Move File), #481 (moving files), #8346 (Trying to upload same files with no changes..), #805 (Client sync stops after some time), and #9178 (Concurrent file uploads from client.).

vlddm · 2018-12-07T06:46:44Z

Updated client to version 2.5.2-daily20181206 and now it looks better - MOVE took long time but finished properly.
owncloud.log

{"reqId":"2557d510-10c1-4e9b-83fa-0062bacdb02a","level":0,"time":"2018-12-07T06:42:24+00:00","remoteAddr":"my.ip.hid.den","user":"fly","app":"OC\\Authentication\\Token\\DefaultTokenProvider::getToken","method":"PUT","url":"\/owncloud\/remote.php\/dav\/uploads\/fly\/1916559632\/00000043","message":"token 140b55dcd8a9ffc5adf41039bd3c8800a7b4e61a199e07d30a05035d721fa3af8f29f2a506d775f08b65419e8c61b76ad401637ba3a3bd2b822142a7cd479f62 does not exist"}
{"reqId":"c8d612dd-9b31-42da-b689-61ada3aff945","level":0,"time":"2018-12-07T06:42:45+00:00","remoteAddr":"my.ip.hid.den","user":"fly","app":"OC\\Authentication\\Token\\DefaultTokenProvider::updateToken","method":"MOVE","url":"\/owncloud\/remote.php\/dav\/uploads\/fly\/1916559632\/.file","message":"updating token 8670, last check is now 1544163854"}
{"reqId":"c8d612dd-9b31-42da-b689-61ada3aff945","level":0,"time":"2018-12-07T06:42:45+00:00","remoteAddr":"my.ip.hid.den","user":"fly","app":"OC\\Authentication\\Token\\DefaultTokenProvider::getToken","method":"MOVE","url":"\/owncloud\/remote.php\/dav\/uploads\/fly\/1916559632\/.file","message":"token 140b55dcd8a9ffc5adf41039bd3c8800a7b4e61a199e07d30a05035d721fa3af8f29f2a506d775f08b65419e8c61b76ad401637ba3a3bd2b822142a7cd479f62 does not exist"}

client.log

12-07 06:42:15:198 [ info sync.networkjob.put ]:        PUT of "https://bck.ihome.ru/owncloud/remote.php/dav/uploads/fly/1916559632/00000042" FINISHED WITH STATUS "OK" QVariant(int, 201) QVariant(QString, "Created")
12-07 06:42:15:971 [ info sync.accessmanager ]: 3 "" "https://bck.ihome.ru/owncloud/remote.php/dav/uploads/fly/1916559632/00000043" has X-Request-ID "2557d510-10c1-4e9b-83fa-0062bacdb02a"
12-07 06:42:37:029 [ info sync.networkjob.put ]:        PUT of "https://bck.ihome.ru/owncloud/remote.php/dav/uploads/fly/1916559632/00000043" FINISHED WITH STATUS "OK" QVariant(int, 201) QVariant(QString, "Created")
12-07 06:42:37:031 [ info sync.accessmanager ]: 6 "MOVE" "https://bck.ihome.ru/owncloud/remote.php/dav/uploads/fly/1916559632/.file" has X-Request-ID "c8d612dd-9b31-42da-b689-61ada3aff945"
12-07 06:44:06:765 [ info sync.networkjob.move ]:       MOVE of QUrl("https://bck.ihome.ru/owncloud/remote.php/dav/uploads/fly/1916559632/.file") FINISHED WITH STATUS "OK"

Why does it take so long to get OK (89sec)?

PVince81 · 2019-01-11T13:01:29Z

this is because of chunk assembly: first file chunks get uploaded through individual PUT requests, then at the end, in that MOVE request, the server will assemble all chunks into the final file, which has an additional overhead.

vlddm · 2019-01-13T17:05:45Z

this is because of chunk assembly: first file chunks get uploaded through individual PUT requests, then at the end, in that MOVE request, the server will assemble all chunks into the final file, which has an additional overhead.

Good to know, but like I said I got connection timeout and stopped sync for every big (over 2Gb) file.
Any ways to fix it?

PVince81 · 2019-01-14T09:58:03Z

you could try increasing the timeout value in php.ini

PVince81 closed this as completed Jan 11, 2019

lock bot locked as resolved and limited conversation to collaborators Jan 14, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

"Connection timed out" when client trying to MOVE file after upload #33803

"Connection timed out" when client trying to MOVE file after upload #33803

vlddm commented Dec 7, 2018 •

edited

Loading

ownclouders commented Dec 7, 2018

vlddm commented Dec 7, 2018 •

edited

Loading

PVince81 commented Jan 11, 2019

vlddm commented Jan 13, 2019

PVince81 commented Jan 14, 2019

"Connection timed out" when client trying to MOVE file after upload #33803

"Connection timed out" when client trying to MOVE file after upload #33803

Comments

vlddm commented Dec 7, 2018 • edited Loading

Steps to reproduce

Expected behaviour

Actual behaviour

Logs

ownCloud log (data/owncloud.log)

Client log

ownclouders commented Dec 7, 2018

vlddm commented Dec 7, 2018 • edited Loading

PVince81 commented Jan 11, 2019

vlddm commented Jan 13, 2019

PVince81 commented Jan 14, 2019

vlddm commented Dec 7, 2018 •

edited

Loading

vlddm commented Dec 7, 2018 •

edited

Loading