Timeout while merging chunks on server

[kubco2]

I find out that, when I sync large file, it depends on server write speed for me it is 8GB file with encryption plugin(7.6GB is done with no errors). All is OK while it is uploading chunks. But when merging start, client try to ask for something(if is file on server?) after 300sec timeout, but server still merging file so it is not there. Client timeouts with error(operation canceled) and start resyncing file. If I pause sync client after uploading is complete and while merging and resume after server merged file, sync is OK.

sync client: 1.6.2
owncloud: 6.0.4
network: LAN

client log

08-15 21:42:21:593 folderman.cpp:397  the current folder is currently syncing.
08-15 21:42:23:421 propagator_qnam.cpp:261 void Mirall::PropagateUploadFileQNAM::slotPutFinished()  QUrl( "https://172.30.1.20:8443/remote.php/webdav/test.img-chunking-1957771249-792-790" )  FINISHED WITH STATUS 0 "" QVariant(int, 201) QVariant(QString, "Created")
08-15 21:42:23:421 syncjournaldb.cpp:672 "INSERT OR REPLACE INTO uploadinfo (path, chunk, transferid, errorcount, size, modtime) VALUES ( ? , ?, ? , ? ,  ? , ? )" "test.img" 791 1947285489 0
08-15 21:42:23:421 syncjournaldb.cpp:870 Transaction Start  "Upload info"
08-15 21:42:23:468 networkjobs.cpp:65 void Mirall::AbstractNetworkJob::setTimeout(qint64) 300000
08-15 21:42:23:468 networkjobs.cpp:191 !!! Mirall::PUTFileJob created for  QUrl( "https://172.30.1.20:8443" )  querying "/test.img-chunking-1957771249-792-791"
08-15 21:42:23:484 folderwatcher.cpp:154 detected changes in folders: QSet("D:/testcloud/")
08-15 21:42:23:484 folderman.cpp:397  the current folder is currently syncing.
08-15 21:42:24:718 networkjobs.cpp:191 !!! Mirall::CheckQuotaJob created for  QUrl( "https://172.30.1.20:8443" )  querying "/"
08-15 21:42:24:734 account.cpp:338 SSL-Errors happened for url  "https://172.30.1.20:8443/remote.php/webdav/"
08-15 21:42:24:734 account.cpp:340    Error in  QSslCertificate( "3" , "43:ae:36:09:ae:5b:b3:8e:b4:13:38:c5:27:8a:17:00" , "En7gcDbC/c6ApSny7C0iZg==" , ("COMODO CA Limited") , () , QMap((1, "xxx")(1, "xxx")) , QDateTime("2014-08-14 00:00:00.000 UTC Qt::UTC") , QDateTime("2014-11-12 23:59:59.000 UTC Qt::UTC") ) : "The host name did not match any of the valid hosts for this certificate" ( "The host name did not match any of the valid hosts for this certificate" )
08-15 21:42:24:734 account.cpp:358 Certs are already known and trusted, Errors are not valid.
08-15 21:47:24:406 networkjobs.cpp:139 void Mirall::AbstractNetworkJob::slotFinished() 5 "Operation canceled"
08-15 21:47:24:406 propagator_qnam.cpp:261 void Mirall::PropagateUploadFileQNAM::slotPutFinished()  QUrl( "https://172.30.1.20:8443/remote.php/webdav/test.img-chunking-1957771249-792-791" )  FINISHED WITH STATUS 5 "Operation canceled" QVariant(Invalid) QVariant(Invalid)
08-15 21:47:24:406 qiodevice.cpp:821 QIODevice::read: device not open
08-15 21:47:24:421 propagator_qnam.cpp:279 ""
08-15 21:47:24:421 syncengine.cpp:634 void Mirall::SyncEngine::slotJobCompleted(const Mirall::SyncFileItem&) "test.img" 1 "Connection Timeout"
08-15 21:47:24:437 propagator_qnam.cpp:390 virtual void Mirall::PropagateUploadFileQNAM::abort() "test.img"
08-15 21:47:24:546 syncjournaldb.cpp:870 Transaction Start  "All Finished."
08-15 21:47:24:546 syncengine.cpp:678 CSync run took  1784698
08-15 21:47:24:562 folder.cpp:644 -> CSync Finished slot with error  true warn count 0
08-15 21:47:24:578 folder.cpp:385 Processing result list and logging took  7  Milliseconds.
08-15 21:47:24:578 folder.cpp:403 OO folder slotSyncFinished: result:  3
08-15 21:47:24:578 folder.cpp:656   ** error Strings:  ("Connection Timeout", "test.img: Connection Timeout")
08-15 21:47:24:578 folder.cpp:658     * owncloud csync thread finished with error 

server log:

{"reqId":"53ee642185925","app":"OC\\Files\\Cache\\Scanner","message":"!!! Path 'files\/test.img' is not readable !!!","level":0,"time":"2014-08-15T21:48:50+02:00","method":"PUT","url":"\/remote.php\/webdav\/
{"reqId":"53ee642185925","app":"OC\\Files\\Cache\\Scanner","message":"!!! No reuse of etag for 'files\/test.img' !!! \ncache: Array\n(\n    [fileid] => 418759\n    [storage] => home::test1\n    [path] => fil
{"reqId":"53ee658a09b23","app":"core","message":"redirectToDefaultPage: https:\/\/172.30.1.20:8443\/index.php\/settings\/admin","level":0,"time":"2014-08-15T21:54:50+02:00","method":"POST","url":"\/index.php

apache log:

172.18.19.111 - test1 [15/Aug/2014:21:41:05 +0200] "PUT /remote.php/webdav/test.img-chunking-1957771249-792-785 HTTP/1.1" 201 876 "-" "Mozilla/5.0 (Windows) mirall/1.6.2"
172.18.19.111 - test1 [15/Aug/2014:21:41:07 +0200] "PUT /remote.php/webdav/test.img-chunking-1957771249-792-786 HTTP/1.1" 201 876 "-" "Mozilla/5.0 (Windows) mirall/1.6.2"
172.18.19.111 - test1 [15/Aug/2014:21:41:09 +0200] "PUT /remote.php/webdav/test.img-chunking-1957771249-792-787 HTTP/1.1" 201 876 "-" "Mozilla/5.0 (Windows) mirall/1.6.2"
172.18.19.111 - test1 [15/Aug/2014:21:41:11 +0200] "PUT /remote.php/webdav/test.img-chunking-1957771249-792-788 HTTP/1.1" 201 876 "-" "Mozilla/5.0 (Windows) mirall/1.6.2"
172.18.19.111 - test1 [15/Aug/2014:21:41:13 +0200] "PUT /remote.php/webdav/test.img-chunking-1957771249-792-789 HTTP/1.1" 201 876 "-" "Mozilla/5.0 (Windows) mirall/1.6.2"
172.18.19.111 - test1 [15/Aug/2014:21:41:15 +0200] "PUT /remote.php/webdav/test.img-chunking-1957771249-792-790 HTTP/1.1" 201 876 "-" "Mozilla/5.0 (Windows) mirall/1.6.2"
172.18.19.111 - test1 [15/Aug/2014:21:41:16 +0200] "PUT /remote.php/webdav/test.img-chunking-1957771249-792-791 HTTP/1.1" 201 954 "-" "Mozilla/5.0 (Windows) mirall/1.6.2"
172.18.19.111 - test1 [15/Aug/2014:21:41:18 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 1397 "-" "Mozilla/5.0 (Windows) mirall/1.6.2"
172.18.19.111 - test1 [15/Aug/2014:21:49:24 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 6943 "-" "Mozilla/5.0 (Windows) mirall/1.6.2"
172.18.19.111 - test1 [15/Aug/2014:21:49:54 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 1397 "-" "Mozilla/5.0 (Windows) mirall/1.6.2"
172.18.19.111 - test1 [15/Aug/2014:21:50:24 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 1397 "-" "Mozilla/5.0 (Windows) mirall/1.6.2"

[scolebrook]

Seeing the same thing here. Syncing a large file results in the desktop client timing out before the "dechunking" and virus scan is done. It will then start uploading the file all over again, even after the server is finished it's work. If you pause and resume it will detect that the file is already there.

It would appear that the client is waiting for a response from the server and gives up. While increasing the time out is an obvious "fix" it only moves the problem. A real fix would need to involve the server being able to respond while it's still processing the file to let the client know that it's still working on it. The client can then close the connection, open another and wait for another response of working, error or success.

Short term fix - is this timeout set in MirallConfigFile::timeout() (/src/mirall/mirallconfigfile.cpp)? Would changing this form 300 to 600 or higher resolve the situation until a more complete fix is in place on both client and server?

[kubco2]

Should I report this to server issues too?

[dragotin]

There is a solution to this problem, keyword is "poll url". Basically what we do is opening a connection to the server and poll for progress on the operation. @ogoffart and @guruz did that, but we will need server support for that. @karlitschek and @DeepDiver1975

[ogoffart]

Issue on the server:
owncloud/core#12097