Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[1.6.0/1.6.1] Upload is failing, when uploading multiple, big files #1899

Closed
Commifreak opened this issue Jun 24, 2014 · 18 comments
Closed

[1.6.0/1.6.1] Upload is failing, when uploading multiple, big files #1899

Commifreak opened this issue Jun 24, 2014 · 18 comments
Labels
type:bug
Milestone
1.7.1

Comments

@Commifreak
Copy link

Hi :)

I use ocServer 6.0.3 and mirall 1.6.0 for Mac OSX on a Debian wheezy with PHP-FPM 5.

I've configured the FastCGIServer Idletimeout to 300 seconds [previously it worked with only 120!].

After that time, I get:

[Tue Jun 24 22:56:00 2014] [error] [client 62.227.93.31] FastCGI: comm with server "/var/www/php-fpm/kluthr/cloud.kluthr.de/ssl-fpm.external" aborted: idle timeout (300 sec)
[Tue Jun 24 22:56:00 2014] [error] [client 62.227.93.31] FastCGI: incomplete headers (0 bytes) received from server "/var/www/php-fpm/kluthr/cloud.kluthr.de/ssl-fpm.external"

Here's the access-log:

2.227.93.31 - - [24/Jun/2014:22:46:49 +0200] "GET /status.php HTTP/1.1" 200 4933 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.93.31 - - [24/Jun/2014:22:46:49 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 1337 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.93.31 - - [24/Jun/2014:22:46:50 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 1304 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.93.31 - - [24/Jun/2014:22:46:51 +0200] "PROPFIND /remote.php/webdav HTTP/1.1" 401 5038 "-" "Mozilla/5.0 (Macintosh) csyncoC/0.91.5 neon/0.30.0"
62.227.93.31 - - [24/Jun/2014:22:46:51 +0200] "PROPFIND /remote.php/webdav HTTP/1.1" 207 2842 "-" "Mozilla/5.0 (Macintosh) csyncoC/0.91.5 neon/0.30.0"
62.227.93.31 - - [24/Jun/2014:22:46:51 +0200] "PUT /remote.php/webdav/Public/XXX/XXX.zip-chunking-1008674555-14-2 HTTP/1.1" 201 987 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.93.31 - - [24/Jun/2014:22:46:51 +0200] "PUT /remote.php/webdav/Public/XXX/XXX.zip-chunking-325484077-20-0 HTTP/1.1" 200 265 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.93.31 - - [24/Jun/2014:22:47:21 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 1438 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.93.31 - - [24/Jun/2014:22:50:58 +0200] "PUT /remote.php/webdav/Public/XXX/XXX.zip-chunking-325484077-20-0 HTTP/1.1" 500 868 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.93.31 - - [24/Jun/2014:22:50:57 +0200] "PUT /remote.php/webdav/Public/XXX/XXX.zip-chunking-1008674555-14-3 HTTP/1.1" 200 132 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.93.31 - - [24/Jun/2014:22:51:27 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 1438 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"

The previous version seemed to work well, I've uploaded such big files multiple times.

How can I check if the upload is chunked? What else could be the problem?

Thanks in advance!

06-24 22:08:43:353 folder.cpp:257 * Polling "ownCloud" for changes. (time since last sync: 29 s) 
06-24 22:08:43:354 folder.cpp:261 ** Force Sync now, state is  "Error" 
06-24 22:08:43:354 folderman.cpp:400 Schedule folder  "ownCloud"  to sync! 
06-24 22:08:43:354 folderman.cpp:408 Folder is not enabled, not scheduled! 
06-24 22:08:45:354 networkjobs.cpp:191 !!! Mirall::CheckServerJob created for  QUrl( "https://cloud.kluthr.de" )  querying "status.php" 
06-24 22:08:45:620 networkjobs.cpp:417 status.php returns:  QMap(("edition", QVariant(QString, "") ) ( "installed" ,  QVariant(QString, "true") ) ( "version" ,  QVariant(QString, "6.0.3.1") ) ( "versionstring" ,  QVariant(QString, "6.0.3") ) )    0  Reply:  QNetworkReplyHttpImpl(0x7fca4a5bc9c0) 
06-24 22:08:45:621 connectionvalidator.cpp:99 ** Application: ownCloud found:   QUrl( "https://cloud.kluthr.de/status.php" )   with version  "6.0.3" ( "6.0.3.1" ) 
06-24 22:08:45:621 networkjobs.cpp:191 !!! Mirall::PropfindJob created for  QUrl( "https://cloud.kluthr.de" )  querying "/" 
06-24 22:08:45:621 connectionvalidator.cpp:146 # checking for authentication settings. 
06-24 22:08:46:753 networkjobs.cpp:191 !!! Mirall::CheckQuotaJob created for  QUrl( "https://cloud.kluthr.de" )  querying "/" 
06-24 22:08:47:141 owncloudgui.cpp:209 Folder in overallStatus Message:  Mirall::Folder(0x7fca4c85fdd0)  with name  "ownCloud" 
06-24 22:08:47:142 folderman.cpp:400 Schedule folder  "ownCloud"  to sync! 
06-24 22:08:47:142 application.cpp:292 Connection Validator Result:  "Connected" 
06-24 22:08:47:142 application.cpp:297 ######## Connection and Credentials are ok! 
06-24 22:08:47:142 folderman.cpp:400 Schedule folder  "ownCloud"  to sync! 
06-24 22:08:47:142 folderman.cpp:415  II> Sync for folder  "ownCloud"  already scheduled, do not enqueue! 
06-24 22:08:47:142 owncloudgui.cpp:157 ######## connected to ownCloud Server! 
06-24 22:08:47:649 folderman.cpp:453 XX slotScheduleFolderSync: folderQueue size:  1 
06-24 22:08:47:649 clientproxy.cpp:106 Passing NO proxy to csync for "https://cloud.kluthr.de" 
06-24 22:08:47:844 owncloudgui.cpp:209 Folder in overallStatus Message:  Mirall::Folder(0x7fca4c85fdd0)  with name  "ownCloud" 
06-24 22:08:47:845 owncloudgui.cpp:124 Sync state changed for folder  "ownCloud" :  "SyncPrepare" 
06-24 22:08:47:845 socketapi.cpp:131 SocketApi:  Broadcasting to 0 listeners:  "UPDATE_VIEW" 
06-24 22:08:47:845 folder.cpp:578 *** Start syncing 
06-24 22:08:47:845 folder.cpp:526 ==== added system ignore list to csync: "/Applications/owncloud.app/Contents/Resources/sync-exclude.lst" 
06-24 22:08:47:846 csync_exclude_load: Adding entry: *.filepart
06-24 22:08:47:846 csync_exclude_load: Adding entry: *~
06-24 22:08:47:846 csync_exclude_load: Adding entry: *.part
06-24 22:08:47:846 csync_exclude_load: Adding entry: *.crdownload
06-24 22:08:47:846 csync_exclude_load: Adding entry: *.unison*
06-24 22:08:47:846 csync_exclude_load: Adding entry: *csync_timedif.ctmp*
06-24 22:08:47:846 csync_exclude_load: Adding entry: .csync_journal.db
06-24 22:08:47:846 csync_exclude_load: Adding entry: .csync_journal.db.ctmp
06-24 22:08:47:846 csync_exclude_load: Adding entry: .owncloudsync.log
06-24 22:08:47:846 csync_exclude_load: Adding entry: .*.sw?
06-24 22:08:47:847 csync_exclude_load: Adding entry: .*.*sw?
06-24 22:08:47:847 csync_exclude_load: Adding entry: ].csync-progressdatabase
06-24 22:08:47:847 csync_exclude_load: Adding entry: ].DS_Store
06-24 22:08:47:847 csync_exclude_load: Adding entry: ].ds_store
06-24 22:08:47:847 csync_exclude_load: Adding entry: ._*
06-24 22:08:47:847 csync_exclude_load: Adding entry: ]Thumbs.db
06-24 22:08:47:847 csync_exclude_load: Adding entry: desktop.ini
06-24 22:08:47:847 csync_exclude_load: Adding entry: *.kate-swp
06-24 22:08:47:847 csync_exclude_load: Adding entry: *_conflict-*
06-24 22:08:47:847 csync_exclude_load: Adding entry: ]*.~*
06-24 22:08:47:847 csync_exclude_load: Adding entry: ].TemporaryItems
06-24 22:08:47:848 csync_exclude_load: Adding entry: ].Trashes
06-24 22:08:47:848 csync_exclude_load: Adding entry: ].DocumentRevisions-V100
06-24 22:08:47:848 csync_exclude_load: Adding entry: .fseventd
06-24 22:08:47:848 csync_exclude_load: Adding entry: .apdisk
06-24 22:08:47:848 csync_exclude_load: Adding entry: .htaccess
06-24 22:08:47:848 csync_exclude_load: Adding entry: ]Icon\r*
06-24 22:08:47:848 csync_exclude_load: Adding entry: ~$*
06-24 22:08:47:848 csync_exclude_load: Adding entry: .~lock.*
06-24 22:08:47:848 csync_exclude_load: Adding entry: ~*.tmp
06-24 22:08:47:848 folder.cpp:531 ==== added user defined ignore list to csync: "/Users/robin/Library/Application Support/ownCloud/sync-exclude.lst" 
06-24 22:08:47:849 folderman.cpp:469 >===================================== sync started for  "ownCloud" 
06-24 22:08:47:849 folderman.cpp:444 Currently folder  "ownCloud"  is running, wait for finish! 
06-24 22:08:47:850 syncjournaldb.cpp:76 No database Transaction to commit 
06-24 22:08:47:851 syncengine.cpp:457 =====sync with existing DB 
06-24 22:08:47:851 syncengine.cpp:500 #### Update start #################################################### >> 
[...]
06-24 22:08:47:962 csync_ftw:  <= Closing walk for /Users/robin/ownCloud/Public/Stirling with read_from_db 0
06-24 22:08:47:962 csync_ftw:  <= Closing walk for /Users/robin/ownCloud/Public with read_from_db 0
06-24 22:08:47:962 csync_ftw:  <= Closing walk for /Users/robin/ownCloud with read_from_db 0
06-24 22:08:47:962 csync_update: Update detection for local replica took 0,11 seconds walking 440 files.
06-24 22:08:47:962 oc_module: opendir method called on ownclouds://cloud.kluthr.de/remote.php/webdav
06-24 22:08:47:962 oc_module: * scheme ownclouds
06-24 22:08:47:962 oc_module: * host cloud.kluthr.de
06-24 22:08:47:962 oc_module: * port 0
06-24 22:08:47:962 oc_module: * path /remote.php/webdav
06-24 22:08:47:962 oc_module: * user 
06-24 22:08:47:962 oc_module: Timeout set to 300 seconds
06-24 22:08:47:962 oc_module: No proxy configured.
06-24 22:08:48:170 oc_module: Call the csync callback for SSL problems
06-24 22:08:48:170 credentialscommon.cpp:58 SSL Fingerprint from neon:  "9a:14:23:33:a4:26:5f:d6:62:21:be:ff:6b:bd:54:80:dc:19:d8:53"  compared to verified:  "9a:14:23:33:a4:26:5f:d6:62:21:be:ff:6b:bd:54:80:dc:19:d8:53" 
06-24 22:08:48:170 oc_module: ## VERIFY_SSL CERT: 0
06-24 22:08:48:340 oc_module: Authentication required 
06-24 22:08:48:340 oc_module: Call the csync callback for ownCloud
06-24 22:08:48:526 oc_module: Simple propfind result code 207.
06-24 22:08:48:526 oc_module: opendir returning handle 0x7fca4f033590 (count=3)
06-24 22:08:48:526 csync_walker: directory: ownclouds://cloud.kluthr.de/remote.php/webdav/Public [file_id=00000023oc7e01f5a297]
06-24 22:08:48:526 _csync_detect_update: Database entry found, compare: 1403638475 <-> 1403638475, etag: 53a9d2cb7e6bd <-> 53a9d2cb7e6bd, inode: 0 <-> 2520499
06-24 22:08:48:526 _csync_detect_update: Reading from database: Public
06-24 22:08:48:526 _csync_detect_update: file: Public, instruction: INSTRUCTION_NONE <<=
06-24 22:08:48:527 csync_statedb_get_below_path: 23 entries read below path Public from db.
06-24 22:08:48:527 csync_walker: directory: ownclouds://cloud.kluthr.de/remote.php/webdav/ABiMa [file_id=00000024oc7e01f5a297]
06-24 22:08:48:527 _csync_detect_update: Database entry found, compare: 1401781837 <-> 1401869815, etag: 538ed5f75bf8b <-> 538ed5f75bf8b, inode: 0 <-> 2523516
06-24 22:08:48:527 _csync_detect_update: Reading from database: ABiMa
06-24 22:08:48:527 _csync_detect_update: file: ABiMa, instruction: INSTRUCTION_NONE <<=
06-24 22:08:48:527 csync_statedb_get_below_path: 413 entries read below path ABiMa from db.
06-24 22:08:48:527 csync_ftw:  <= Closing walk for ownclouds://cloud.kluthr.de/remote.php/webdav with read_from_db 0
06-24 22:08:48:527 csync_update: Update detection for remote replica took 0,57 seconds walking 438 files.
06-24 22:08:48:529 syncengine.cpp:514 <<#### Update end ####################################################  678 
[...]
06-24 22:08:48:634 csync_reconcile: Reconciliation for remote replica took 0,05 seconds visiting 438 files.
06-24 22:08:48:636 syncjournaldb.cpp:848 Transaction Start  "checkConnect" 
06-24 22:08:48:637 syncjournaldb.cpp:346 Columns in the current journal:  ("phash", "pathlen", "path", "inode", "uid", "gid", "mode", "modtime", "type", "md5", "fileid") 
06-24 22:08:48:639 owncloudpropagator.cpp:256 Using QNAM/HTTP parallel code path 
06-24 22:08:48:642 folder.cpp:621     * csync thread started 
06-24 22:08:48:835 owncloudgui.cpp:209 Folder in overallStatus Message:  Mirall::Folder(0x7fca4c85fdd0)  with name  "ownCloud" 
06-24 22:08:48:835 owncloudgui.cpp:124 Sync state changed for folder  "ownCloud" :  "Sync Running" 
06-24 22:08:48:835 socketapi.cpp:131 SocketApi:  Broadcasting to 0 listeners:  "UPDATE_VIEW" 
06-24 22:08:48:942 networkjobs.cpp:65 void Mirall::AbstractNetworkJob::setTimeout(qint64) 300000 
06-24 22:08:48:942 networkjobs.cpp:191 !!! Mirall::PUTFileJob created for  QUrl( "https://cloud.kluthr.de" )  querying "/Public/XXX/SXXX.zip-chunking-1945299614-14-0" 
06-24 22:08:48:943 networkjobs.cpp:65 void Mirall::AbstractNetworkJob::setTimeout(qint64) 300000 
06-24 22:08:48:943 networkjobs.cpp:191 !!! Mirall::PUTFileJob created for  QUrl( "https://cloud.kluthr.de" )  querying "/Public/XXX/XXX.zip-chunking-1416701388-20-0" 
06-24 22:09:03:931 accountsettings.cpp:450 Toggle enabled/disabled Folder alias  "ownCloud"  - current state:  true 
06-24 22:09:03:931 accountsettings.cpp:454 Application: enable folder with alias  "ownCloud" 
06-24 22:09:06:677 folder.cpp:479 folder  "ownCloud"  Terminating! 
06-24 22:09:06:678 propagator_qnam.cpp:354 virtual void Mirall::PropagateUploadFileQNAM::abort() "Public/XXX/XXX.zip" 
06-24 22:09:06:679 networkjobs.cpp:139 void Mirall::AbstractNetworkJob::slotFinished() 5 "Operation canceled" 
06-24 22:09:06:680 propagator_qnam.cpp:236 void Mirall::PropagateUploadFileQNAM::slotPutFinished()  QUrl( "https://cloud.kluthr.de/remote.php/webdav/Public/XXX/XXX.zip-chunking-1945299614-14-0" )  FINISHED WITH STATUS 5 "Operation canceled" QVariant(Invalid) QVariant(Invalid) 
06-24 22:09:06:681 qiodevice.cpp:821 QIODevice::read: device not open
06-24 22:09:06:682 propagator_qnam.cpp:254 "" 
06-24 22:09:06:682 syncengine.cpp:626 void Mirall::SyncEngine::slotJobCompleted(const Mirall::SyncFileItem &) "Public/XXX/XXXX.zip" 1 "Operation canceled" 
06-24 22:09:06:684 propagator_qnam.cpp:354 virtual void Mirall::PropagateUploadFileQNAM::abort() "Public/XXX/XXX XXX.zip" 
06-24 22:09:06:685 networkjobs.cpp:139 void Mirall::AbstractNetworkJob::slotFinished() 5 "Operation canceled" 
06-24 22:09:06:685 propagator_qnam.cpp:236 void Mirall::PropagateUploadFileQNAM::slotPutFinished()  QUrl( "https://cloud.kluthr.de/remote.php/webdav/Public/XXX/XXX.zip-chunking-1416701388-20-0" )  FINISHED WITH STATUS 5 "Operation canceled" QVariant(Invalid) QVariant(Invalid) 
06-24 22:09:06:686 qiodevice.cpp:821 QIODevice::read: device not open
06-24 22:09:06:687 propagator_qnam.cpp:254 "" 
06-24 22:09:06:687 syncengine.cpp:626 void Mirall::SyncEngine::slotJobCompleted(const Mirall::SyncFileItem &) "Public/XXX/XXX" 1 "Operation canceled" 
06-24 22:09:06:689 folderman.cpp:397  the current folder is currently syncing. 
06-24 22:09:06:884 owncloudgui.cpp:209 Folder in overallStatus Message:  Mirall::Folder(0x7fca4c85fdd0)  with name  "ownCloud" 
06-24 22:09:06:886 owncloudgui.cpp:124 Sync state changed for folder  "ownCloud" :  "Sync Paused" 
06-24 22:09:06:886 socketapi.cpp:131 SocketApi:  Broadcasting to 0 listeners:  "UPDATE_VIEW" 
06-24 22:09:06:895 propagator_qnam.cpp:354 virtual void Mirall::PropagateUploadFileQNAM::abort() "Public/XXX/YYY.zip" 
06-24 22:09:06:896 propagator_qnam.cpp:354 virtual void Mirall::PropagateUploadFileQNAM::abort() "Public/XXX/XXX.zip" 
06-24 22:09:06:684 qiodevice.cpp:1307 QIODevice::write: device not open
06-24 22:09:06:897 propagator_qnam.cpp:354 virtual void Mirall::PropagateUploadFileQNAM::abort() "Public/XXX/XXX.zip" 
06-24 22:09:06:900 syncjournaldb.cpp:848 Transaction Start  "All Finished." 
06-24 22:09:06:901 syncengine.cpp:667 CSync run took  19051 
06-24 22:09:06:689 qiodevice.cpp:1307 QIODevice::write: device not open
06-24 22:09:06:928 folder.cpp:633 -> CSync Finished slot with error  true warn count 0 
06-24 22:09:06:929 folder.cpp:374 Processing result list and logging took  0  Milliseconds. 
06-24 22:09:06:930 folder.cpp:392 OO folder slotSyncFinished: result:  9 
06-24 22:09:06:931 folder.cpp:645   ** error Strings:  ("Operation canceled", "Operation canceled", "Public/XXX/XXX.zip: Operation canceled", "Public/XXX/YYY.zip: Operation canceled") 
06-24 22:09:06:932 folder.cpp:647     * owncloud csync thread finished with error 
06-24 22:09:07:127 owncloudgui.cpp:209 Folder in overallStatus Message:  Mirall::Folder(0x7fca4c85fdd0)  with name  "ownCloud" 
06-24 22:09:07:128 owncloudgui.cpp:124 Sync state changed for folder  "ownCloud" :  "Error" 
06-24 22:09:07:129 socketapi.cpp:131 SocketApi:  Broadcasting to 0 listeners:  "UPDATE_VIEW" 
06-24 22:09:07:331 folderman.cpp:478 <===================================== sync finished for  "ownCloud" 
06-24 22:09:07:533 folderman.cpp:453 XX slotScheduleFolderSync: folderQueue size:  0 
06-24 22:09:37:352 folder.cpp:257 * Polling "ownCloud" for changes. (time since last sync: 30 s) 
06-24 22:09:37:353 folder.cpp:261 ** Force Sync now, state is  "Error" 
06-24 22:09:37:354 folderman.cpp:400 Schedule folder  "ownCloud"  to sync! 
06-24 22:09:37:355 folderman.cpp:408 Folder is not enabled, not scheduled! 
06-24 22:09:44:352 networkjobs.cpp:191 !!! Mirall::CheckQuotaJob created for  QUrl( "https://cloud.kluthr.de" )  querying "/" 
06-24 22:10:07:351 folder.cpp:257 * Polling "ownCloud" for changes. (time since last sync: 60 s) 
06-24 22:10:07:352 folder.cpp:261 ** Force Sync now, state is  "Error" 
06-24 22:10:07:353 folderman.cpp:400 Schedule folder  "ownCloud"  to sync! 
06-24 22:10:07:354 folderman.cpp:408 Folder is not enabled, not scheduled! 
06-24 22:10:14:351 networkjobs.cpp:191 !!! Mirall::CheckQuotaJob created for  QUrl( "https://cloud.kluthr.de" )  querying "/"
@Commifreak
Copy link
Author

Got some news :)

I've tried it again today with a 93MB .mp4 file - single upload, just this one file: It is working! :O

[...]
62.227.112.201 - - [25/Jun/2014:19:51:47 +0200] "PUT /remote.php/webdav/Public/MeinKopter/Mein%20Film.mp4-chunking-3402292546-10-0 HTTP/1.1" 201 1121 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.112.201 - - [25/Jun/2014:19:51:56 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 1438 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.112.201 - - [25/Jun/2014:19:54:19 +0200] "PUT /remote.php/webdav/Public/MeinKopter/Mein%20Film.mp4-chunking-3402292546-10-1 HTTP/1.1" 201 987 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.112.201 - - [25/Jun/2014:19:54:50 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 1438 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.112.201 - - [25/Jun/2014:19:56:50 +0200] "PUT /remote.php/webdav/Public/MeinKopter/Mein%20Film.mp4-chunking-3402292546-10-2 HTTP/1.1" 201 987 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.112.201 - - [25/Jun/2014:19:57:20 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 5125 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.112.201 - - [25/Jun/2014:19:59:19 +0200] "PUT /remote.php/webdav/Public/MeinKopter/Mein%20Film.mp4-chunking-3402292546-10-3 HTTP/1.1" 201 987 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.112.201 - - [25/Jun/2014:19:59:49 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 1438 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
[...]

Hold on, I let it do its upload and will check that again with the problematic files from yesterday! Stay tuned :)

@Commifreak
Copy link
Author

Damn - I cannot reproduce it anymore :(

I've tried the two .zip's from yesterday again: It is working too! Why?

62.227.112.201 - - [25/Jun/2014:20:17:44 +0200] "PROPFIND /remote.php/webdav HTTP/1.1" 401 5038 "-" "Mozilla/5.0 (Macintosh) csyncoC/0.91.5 neon/0.30.0"
62.227.112.201 - - [25/Jun/2014:20:17:44 +0200] "PROPFIND /remote.php/webdav HTTP/1.1" 207 2842 "-" "Mozilla/5.0 (Macintosh) csyncoC/0.91.5 neon/0.30.0"
62.227.112.201 - - [25/Jun/2014:20:17:44 +0200] "PUT /remote.php/webdav/Archive1.zip-chunking-1101888966-14-0 HTTP/1.1" 201 1121 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.112.201 - - [25/Jun/2014:20:17:44 +0200] "PUT /remote.php/webdav/Archive2.zip-chunking-500965809-20-0 HTTP/1.1" 200 265 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.112.201 - - [25/Jun/2014:20:17:50 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 1438 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.112.201 - - [25/Jun/2014:20:19:34 +0200] "PUT /remote.php/webdav/Archive1.zip-chunking-1101888966-14-1 HTTP/1.1" 201 987 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.112.201 - - [25/Jun/2014:20:19:35 +0200] "PUT /remote.php/webdav/Archive2.zip-chunking-500965809-20-0 HTTP/1.1" 201 1121 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.112.201 - - [25/Jun/2014:20:20:04 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 1438 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.112.201 - - [25/Jun/2014:20:21:23 +0200] "PUT /remote.php/webdav/Archive1.zip-chunking-1101888966-14-2 HTTP/1.1" 200 132 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.112.201 - - [25/Jun/2014:20:23:11 +0200] "PUT /remote.php/webdav/Archive2.zip-chunking-500965809-20-1 HTTP/1.1" 201 987 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"

Who decides, when a file gets splitted? After XX MB? I changed nothing since yesterday... Now it is working again...

@Commifreak
Copy link
Author

Ok, I was able to reproduce it - almost... I can't reproduce a timeout anymore, but mirall is failing anyway:

06-25 21:37:19:229 csync_reconcile: Reconciliation for remote replica took 0,04 seconds visiting 446 files.
06-25 21:37:19:230 syncjournaldb.cpp:848 Transaction Start  "checkConnect" 
06-25 21:37:19:231 syncjournaldb.cpp:346 Columns in the current journal:  ("phash", "pathlen", "path", "inode", "uid", "gid", "mode", "modtime", "type", "md5", "fileid") 
06-25 21:37:19:233 owncloudpropagator.cpp:256 Using QNAM/HTTP parallel code path 
06-25 21:37:19:236 folder.cpp:621     * csync thread started 
06-25 21:37:19:480 owncloudgui.cpp:209 Folder in overallStatus Message:  Mirall::Folder(0x7ff44a6700f0)  with name  "ownCloud" 
06-25 21:37:19:481 owncloudgui.cpp:124 Sync state changed for folder  "ownCloud" :  "Sync Running" 
06-25 21:37:19:481 socketapi.cpp:131 SocketApi:  Broadcasting to 0 listeners:  "UPDATE_VIEW" 
06-25 21:37:19:484 networkjobs.cpp:65 void Mirall::AbstractNetworkJob::setTimeout(qint64) 300000 
06-25 21:37:19:485 networkjobs.cpp:191 !!! Mirall::PUTFileJob created for  QUrl( "https://cloud.kluthr.de" )  querying "/Public/Shared/Dragonball.zip-chunking-151131922-24-0" 
06-25 21:37:19:485 networkjobs.cpp:65 void Mirall::AbstractNetworkJob::setTimeout(qint64) 300000 
06-25 21:37:19:485 networkjobs.cpp:191 !!! Mirall::PUTFileJob created for  QUrl( "https://cloud.kluthr.de" )  querying "/Public/Shared/Music 1.zip-chunking-13271173-14-0" 
06-25 21:37:19:486 networkjobs.cpp:65 void Mirall::AbstractNetworkJob::setTimeout(qint64) 300000 
06-25 21:37:19:486 networkjobs.cpp:191 !!! Mirall::PUTFileJob created for  QUrl( "https://cloud.kluthr.de" )  querying "/Public/Shared/Music 2.zip-chunking-1976473324-20-0" 
06-25 21:37:20:051 sparkleupdater_mac.mm:107 virtual void Mirall::SparkleUpdater::backgroundCheckForUpdate() launching background check 
06-25 21:37:20:056 sparkleupdater_mac.mm:34 -[DelegateObject updaterMayCheckForUpdates:] may check: YES 
06-25 21:37:21:689 sparkleupdater_mac.mm:47 -[DelegateObject updaterDidNotFindUpdate:] 
06-25 21:37:48:962 networkjobs.cpp:191 !!! Mirall::CheckQuotaJob created for  QUrl( "https://cloud.kluthr.de" )  querying "/" 
06-25 21:39:08:548 propagator_qnam.cpp:236 void Mirall::PropagateUploadFileQNAM::slotPutFinished()  QUrl( "https://cloud.kluthr.de/remote.php/webdav/Public/Shared/Dragonball.zip-chunking-151131922-24-0" )  FINISHED WITH STATUS 0 "" QVariant(int, 201) QVariant(QString, "Created") 
06-25 21:39:08:550 syncjournaldb.cpp:672 "INSERT OR REPLACE INTO uploadinfo (path, chunk, transferid, errorcount, size, modtime) VALUES ( ? , ?, ? , ? ,  ? , ? )" "Public/Shared/Dragonball.zip" 1 161617682 0 
06-25 21:39:08:551 syncjournaldb.cpp:848 Transaction Start  "Upload info" 
06-25 21:39:08:552 networkjobs.cpp:65 void Mirall::AbstractNetworkJob::setTimeout(qint64) 300000 
06-25 21:39:08:553 networkjobs.cpp:191 !!! Mirall::PUTFileJob created for  QUrl( "https://cloud.kluthr.de" )  querying "/Public/Shared/Dragonball.zip-chunking-151131922-24-1" 
06-25 21:39:38:961 networkjobs.cpp:191 !!! Mirall::CheckQuotaJob created for  QUrl( "https://cloud.kluthr.de" )  querying "/" 
06-25 21:40:58:331 propagator_qnam.cpp:236 void Mirall::PropagateUploadFileQNAM::slotPutFinished()  QUrl( "https://cloud.kluthr.de/remote.php/webdav/Public/Shared/Dragonball.zip-chunking-151131922-24-1" )  FINISHED WITH STATUS 0 "" QVariant(int, 201) QVariant(QString, "Created") 
06-25 21:40:58:333 syncjournaldb.cpp:672 "INSERT OR REPLACE INTO uploadinfo (path, chunk, transferid, errorcount, size, modtime) VALUES ( ? , ?, ? , ? ,  ? , ? )" "Public/Shared/Dragonball.zip" 2 161617682 0 
06-25 21:40:58:334 syncjournaldb.cpp:848 Transaction Start  "Upload info" 
06-25 21:40:58:618 networkjobs.cpp:65 void Mirall::AbstractNetworkJob::setTimeout(qint64) 300000 
06-25 21:40:58:620 networkjobs.cpp:191 !!! Mirall::PUTFileJob created for  QUrl( "https://cloud.kluthr.de" )  querying "/Public/Shared/Dragonball.zip-chunking-151131922-24-2" 
06-25 21:42:48:270 propagator_qnam.cpp:236 void Mirall::PropagateUploadFileQNAM::slotPutFinished()  QUrl( "https://cloud.kluthr.de/remote.php/webdav/Public/Shared/Music 1.zip-chunking-13271173-14-0" )  FINISHED WITH STATUS 0 "" QVariant(int, 201) QVariant(QString, "Created") 
06-25 21:42:48:271 syncjournaldb.cpp:672 "INSERT OR REPLACE INTO uploadinfo (path, chunk, transferid, errorcount, size, modtime) VALUES ( ? , ?, ? , ? ,  ? , ? )" "Public/Shared/Music 1.zip" 1 6979717 0 
06-25 21:42:48:272 syncjournaldb.cpp:848 Transaction Start  "Upload info" 
06-25 21:42:48:391 networkjobs.cpp:65 void Mirall::AbstractNetworkJob::setTimeout(qint64) 300000 
06-25 21:42:48:393 networkjobs.cpp:191 !!! Mirall::PUTFileJob created for  QUrl( "https://cloud.kluthr.de" )  querying "/Public/Shared/Music 1.zip-chunking-13271173-14-1" 
06-25 21:42:48:394 networkjobs.cpp:139 void Mirall::AbstractNetworkJob::slotFinished() 2 "Connection closed" 
06-25 21:42:48:395 propagator_qnam.cpp:236 void Mirall::PropagateUploadFileQNAM::slotPutFinished()  QUrl( "https://cloud.kluthr.de/remote.php/webdav/Public/Shared/Music 2.zip-chunking-1976473324-20-0" )  FINISHED WITH STATUS 2 "Connection closed" QVariant(Invalid) QVariant(Invalid) 
06-25 21:42:48:396 propagator_qnam.cpp:254 "" 
06-25 21:42:48:397 syncengine.cpp:626 void Mirall::SyncEngine::slotJobCompleted(const Mirall::SyncFileItem &) "Public/Shared/Music 2.zip" 1 "Connection closed" 
06-25 21:42:48:416 propagator_qnam.cpp:354 virtual void Mirall::PropagateUploadFileQNAM::abort() "Public/Shared/Dragonball.zip" 
06-25 21:42:48:417 networkjobs.cpp:139 void Mirall::AbstractNetworkJob::slotFinished() 5 "Operation canceled" 
06-25 21:42:48:418 propagator_qnam.cpp:236 void Mirall::PropagateUploadFileQNAM::slotPutFinished()  QUrl( "https://cloud.kluthr.de/remote.php/webdav/Public/Shared/Dragonball.zip-chunking-151131922-24-2" )  FINISHED WITH STATUS 5 "Operation canceled" QVariant(Invalid) QVariant(Invalid) 
06-25 21:42:48:419 qiodevice.cpp:821 QIODevice::read: device not open
06-25 21:42:48:420 propagator_qnam.cpp:254 "" 
06-25 21:42:48:421 syncengine.cpp:626 void Mirall::SyncEngine::slotJobCompleted(const Mirall::SyncFileItem &) "Public/Shared/Dragonball.zip" 1 "Operation canceled" 
06-25 21:42:48:423 propagator_qnam.cpp:354 virtual void Mirall::PropagateUploadFileQNAM::abort() "Public/Shared/Music 1.zip" 
06-25 21:42:48:424 networkjobs.cpp:139 void Mirall::AbstractNetworkJob::slotFinished() 5 "Operation canceled" 
06-25 21:42:48:425 propagator_qnam.cpp:236 void Mirall::PropagateUploadFileQNAM::slotPutFinished()  QUrl( "https://cloud.kluthr.de/remote.php/webdav/Public/Shared/Music 1.zip-chunking-13271173-14-1" )  FINISHED WITH STATUS 5 "Operation canceled" QVariant(Invalid) QVariant(Invalid) 
06-25 21:42:48:426 qiodevice.cpp:821 QIODevice::read: device not open
06-25 21:42:48:427 propagator_qnam.cpp:254 "" 
06-25 21:42:48:427 syncengine.cpp:626 void Mirall::SyncEngine::slotJobCompleted(const Mirall::SyncFileItem &) "Public/Shared/Music 1.zip" 1 "Operation canceled" 
06-25 21:42:48:430 propagator_qnam.cpp:354 virtual void Mirall::PropagateUploadFileQNAM::abort() "Public/Shared/Music 2.zip" 
06-25 21:42:48:431 propagator_qnam.cpp:354 virtual void Mirall::PropagateUploadFileQNAM::abort() "Public/Shared/Dragonball.zip" 
06-25 21:42:48:432 propagator_qnam.cpp:354 virtual void Mirall::PropagateUploadFileQNAM::abort() "Public/Shared/Music 1.zip" 
06-25 21:42:48:423 qiodevice.cpp:1307 QIODevice::write: device not open
06-25 21:42:48:433 propagator_qnam.cpp:354 virtual void Mirall::PropagateUploadFileQNAM::abort() "Public/Shared/Music 1.zip" 
06-25 21:42:48:452 syncjournaldb.cpp:848 Transaction Start  "All Finished." 
06-25 21:42:48:454 syncengine.cpp:667 CSync run took  329835 
06-25 21:42:48:456 folder.cpp:633 -> CSync Finished slot with error  true warn count 0 
06-25 21:42:48:460 folder.cpp:374 Processing result list and logging took  3  Milliseconds. 
06-25 21:42:48:461 folder.cpp:392 OO folder slotSyncFinished: result:  3 
06-25 21:42:48:462 folder.cpp:645   ** error Strings:  ("Connection closed", "Operation canceled", "Operation canceled", "Public/Shared/Dragonball.zip: Operation canceled", "Public/Shared/Music 2.zip: Connection closed", "Public/Shared/Music 1.zip: Operation canceled") 
06-25 21:42:48:463 folder.cpp:647     * owncloud csync thread finished with error 
06-25 21:42:48:660 owncloudgui.cpp:209 Folder in overallStatus Message:  Mirall::Folder(0x7ff44a6700f0)  with name  "ownCloud" 
06-25 21:42:48:661 owncloudgui.cpp:124 Sync state changed for folder  "ownCloud" :  "Error" 
06-25 21:42:48:662 socketapi.cpp:131 SocketApi:  Broadcasting to 0 listeners:  "UPDATE_VIEW" 
06-25 21:42:48:864 folderman.cpp:478 <===================================== sync finished for  "ownCloud"

And on the other side:

62.227.112.201 - - [25/Jun/2014:21:37:17 +0200] "GET /status.php HTTP/1.1" 200 4933 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.112.201 - - [25/Jun/2014:21:37:17 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 1337 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.112.201 - - [25/Jun/2014:21:37:18 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 1304 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.112.201 - - [25/Jun/2014:21:37:18 +0200] "PROPFIND /remote.php/webdav HTTP/1.1" 401 5038 "-" "Mozilla/5.0 (Macintosh) csyncoC/0.91.5 neon/0.30.0"
62.227.112.201 - - [25/Jun/2014:21:37:18 +0200] "PROPFIND /remote.php/webdav HTTP/1.1" 207 2842 "-" "Mozilla/5.0 (Macintosh) csyncoC/0.91.5 neon/0.30.0"
62.227.112.201 - - [25/Jun/2014:21:37:19 +0200] "PUT /remote.php/webdav/Public/Shared/Dragonball.zip-chunking-151131922-24-0 HTTP/1.1" 201 987 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.112.201 - - [25/Jun/2014:21:37:19 +0200] "PUT /remote.php/webdav/Public/Shared/Music%201.zip-chunking-13271173-14-0 HTTP/1.1" 200 265 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.112.201 - - [25/Jun/2014:21:37:19 +0200] "PUT /remote.php/webdav/Public/Shared/Music%202.zip-chunking-1976473324-20-0 HTTP/1.1" 200 265 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.112.201 - - [25/Jun/2014:21:37:49 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 1438 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.112.201 - - [25/Jun/2014:21:39:08 +0200] "PUT /remote.php/webdav/Public/Shared/Dragonball.zip-chunking-151131922-24-1 HTTP/1.1" 201 987 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.112.201 - - [25/Jun/2014:21:39:10 +0200] "PUT /remote.php/webdav/Public/Shared/Music%201.zip-chunking-13271173-14-0 HTTP/1.1" 201 1121 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.112.201 - - [25/Jun/2014:21:39:11 +0200] "PUT /remote.php/webdav/Public/Shared/Music%202.zip-chunking-1976473324-20-0 HTTP/1.1" 200 265 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.112.201 - - [25/Jun/2014:21:42:48 +0200] "PUT /remote.php/webdav/Public/Shared/Music%201.zip-chunking-13271173-14-1 HTTP/1.1" 200 132 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.112.201 - - [25/Jun/2014:21:39:39 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 1438 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.112.201 - - [25/Jun/2014:21:40:58 +0200] "PUT /remote.php/webdav/Public/Shared/Dragonball.zip-chunking-151131922-24-2 HTTP/1.1" 200 132 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.112.201 - - [25/Jun/2014:21:43:19 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 5125 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.112.201 - - [25/Jun/2014:21:43:19 +0200] "PROPFIND /remote.php/webdav HTTP/1.1" 401 5038 "-" "Mozilla/5.0 (Macintosh) csyncoC/0.91.5 neon/0.30.0"
62.227.112.201 - - [25/Jun/2014:21:43:20 +0200] "PROPFIND /remote.php/webdav HTTP/1.1" 207 2842 "-" "Mozilla/5.0 (Macintosh) csyncoC/0.91.5 neon/0.30.0"
62.227.112.201 - - [25/Jun/2014:21:43:21 +0200] "PUT /remote.php/webdav/Public/Shared/Music%201.zip-chunking-13271173-14-1 HTTP/1.1" 201 1121 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.112.201 - - [25/Jun/2014:21:43:21 +0200] "PUT /remote.php/webdav/Public/Shared/Dragonball.zip-chunking-151131922-24-2 HTTP/1.1" 200 132 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"
62.227.112.201 - - [25/Jun/2014:21:43:21 +0200] "PUT /remote.php/webdav/Public/Shared/Music%202.zip-chunking-1909510517-20-0 HTTP/1.1" 200 265 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.0"

and:

{"app":"webdav","message":"Sabre_DAV_Exception_BadRequest: expected filesize 10485760 got 4718592","level":4,"time":"2014-06-25T19:36:27+00:00"}
{"app":"webdav","message":"Sabre_DAV_Exception_BadRequest: expected filesize 10485760 got 229376","level":4,"time":"2014-06-25T19:36:28+00:00"}
{"app":"webdav","message":"Sabre_DAV_Exception_BadRequest: expected filesize 10485760 got 245760","level":4,"time":"2014-06-25T19:36:30+00:00"}
{"app":"webdav","message":"Sabre_DAV_Exception_BadRequest: expected filesize 10485760 got 32768","level":4,"time":"2014-06-25T19:39:08+00:00"}
{"app":"webdav","message":"Sabre_DAV_Exception_BadRequest: expected filesize 10485760 got 32768","level":4,"time":"2014-06-25T19:39:08+00:00"}
{"app":"webdav","message":"Sabre_DAV_Exception_BadRequest: expected filesize 10485760 got 32768","level":4,"time":"2014-06-25T19:42:48+00:00"}
{"app":"webdav","message":"Sabre_DAV_Exception_BadRequest: expected filesize 10485760 got 32768","level":4,"time":"2014-06-25T19:42:48+00:00"}
{"app":"webdav","message":"Sabre_DAV_Exception_BadRequest: expected filesize 10485760 got 32768","level":4,"time":"2014-06-25T19:45:10+00:00"}
{"app":"webdav","message":"Sabre_DAV_Exception_BadRequest: expected filesize 10485760 got 32768","level":4,"time":"2014-06-25T19:45:10+00:00"}
{"app":"webdav","message":"Sabre_DAV_Exception_BadRequest: expected filesize 10485760 got 163840","level":4,"time":"2014-06-25T19:45:13+00:00"}

(Is that UTC time?)

FYI: My current, stable, upstream:
bildschirmfoto 2014-06-25 um 21 49 47

@tachyon-ops
Copy link

Yeah, I confirm I have this issue also. I'll point an url in my thread to this one.
(my experience here: #1906 )

@tachyon-ops tachyon-ops mentioned this issue Jun 26, 2014
Closed
@Commifreak Commifreak changed the title [1.6.0] No chunking anymore? Upload always failing [1.6.0/1.6.1] Upload is failing, when uploading multiple, big files Jul 4, 2014
@Commifreak
Copy link
Author

Updates:

  • Updated to mirall 1.6.1 for Mac
  • Updated oC to 6.0.4 [PHP 5.4.4-14]

I want, again, to upload 2 big files, but mirall is always failing. Always means:

  • mirall detects the change and starts uploading as expected. after 5-10 minutes, mirall fails. A short time, mirall wants to retry. Another 5.10 minutes: Fail.

If I upload the files one per one: No issue, even after 10+ minutes.

Serverside->Apache:

62.227.81.122 - - [04/Jul/2014:21:26:52 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 1337 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.1"
62.227.81.122 - - [04/Jul/2014:21:26:53 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 1304 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.1"
62.227.81.122 - - [04/Jul/2014:21:26:54 +0200] "PROPFIND /remote.php/webdav HTTP/1.1" 401 5038 "-" "Mozilla/5.0 (Macintosh) csyncoC/0.91.5 neon/0.30.0"
62.227.81.122 - - [04/Jul/2014:21:26:54 +0200] "PROPFIND /remote.php/webdav HTTP/1.1" 207 2921 "-" "Mozilla/5.0 (Macintosh) csyncoC/0.91.5 neon/0.30.0"
62.227.81.122 - - [04/Jul/2014:21:27:25 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 1438 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.1"
62.227.81.122 - - [04/Jul/2014:21:27:25 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 2017 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.1"
62.227.81.122 - - [04/Jul/2014:21:27:26 +0200] "PROPFIND /remote.php/webdav HTTP/1.1" 401 5038 "-" "Mozilla/5.0 (Macintosh) csyncoC/0.91.5 neon/0.30.0"
62.227.81.122 - - [04/Jul/2014:21:27:26 +0200] "PROPFIND /remote.php/webdav HTTP/1.1" 207 2921 "-" "Mozilla/5.0 (Macintosh) csyncoC/0.91.5 neon/0.30.0"
62.227.81.122 - - [04/Jul/2014:21:27:55 +0200] "GET /status.php HTTP/1.1" 200 4933 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.1"
62.227.81.122 - - [04/Jul/2014:21:27:55 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 1337 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.1"
62.227.81.122 - - [04/Jul/2014:21:27:56 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 1304 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.1"
62.227.81.122 - - [04/Jul/2014:21:27:56 +0200] "PROPFIND /remote.php/webdav HTTP/1.1" 401 5038 "-" "Mozilla/5.0 (Macintosh) csyncoC/0.91.5 neon/0.30.0"
62.227.81.122 - - [04/Jul/2014:21:27:56 +0200] "PROPFIND /remote.php/webdav HTTP/1.1" 207 2921 "-" "Mozilla/5.0 (Macintosh) csyncoC/0.91.5 neon/0.30.0"
62.227.81.122 - - [04/Jul/2014:21:27:57 +0200] "MKCOL /remote.php/webdav/Public/Neuer%20Ordner/ HTTP/1.1" 201 784 "-" "Mozilla/5.0 (Macintosh) csyncoC/0.91.5 neon/0.30.0"
62.227.81.122 - - [04/Jul/2014:21:27:58 +0200] "PUT /remote.php/webdav/Public/Neuer%20Ordner/Dragonball-Z.zip-chunking-164120460-24-0 HTTP/1.1" 201 987 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.1"
62.227.81.122 - - [04/Jul/2014:21:27:58 +0200] "PUT /remote.php/webdav/Public/Neuer%20Ordner/Skoda%2002%202013%20ElsWwin%205%200%20Compatible%20Patch.zip-chunking-869170001-17-0 HTTP/1.1" 200 265 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.1"
62.227.81.122 - - [04/Jul/2014:21:28:27 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 1438 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.1"
62.227.81.122 - - [04/Jul/2014:21:29:51 +0200] "PUT /remote.php/webdav/Public/Neuer%20Ordner/Dragonball-Z.zip-chunking-164120460-24-1 HTTP/1.1" 201 987 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.1"
62.227.81.122 - - [04/Jul/2014:21:29:53 +0200] "PUT /remote.php/webdav/Public/Neuer%20Ordner/Skoda%2002%202013%20ElsWwin%205%200%20Compatible%20Patch.zip-chunking-869170001-17-0 HTTP/1.1" 200 265 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.1"
62.227.81.122 - - [04/Jul/2014:21:30:22 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 1438 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.1"
62.227.81.122 - - [04/Jul/2014:21:31:45 +0200] "PUT /remote.php/webdav/Public/Neuer%20Ordner/Dragonball-Z.zip-chunking-164120460-24-2 HTTP/1.1" 201 987 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.1"
62.227.81.122 - - [04/Jul/2014:21:31:46 +0200] "PUT /remote.php/webdav/Public/Neuer%20Ordner/Skoda%2002%202013%20ElsWwin%205%200%20Compatible%20Patch.zip-chunking-869170001-17-0 HTTP/1.1" 200 265 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.1"
62.227.81.122 - - [04/Jul/2014:21:32:15 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 1438 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.1"
62.227.81.122 - - [04/Jul/2014:21:33:35 +0200] "PUT /remote.php/webdav/Public/Neuer%20Ordner/Dragonball-Z.zip-chunking-164120460-24-3 HTTP/1.1" 200 132 "-" "Mozilla/5.0 (Macintosh) mirall/1.6.1"

Serverside->owncloud.log:

{"reqId":"53b7003db23af","app":"OC\\Files\\Cache\\Scanner","message":"!!! Path 'files\/Public\/Neuer Ordner' is not readable !!!","level":0,"time":"2014-07-04T19:27:57+00:00","method":"MKCOL","url":"\/remote.php\/webdav\/Public\/Neuer%20Ordner\/"}
{"reqId":"53b700afd5959","app":"webdav","message":"Sabre_DAV_Exception_BadRequest: expected filesize 10485760 got 32768","level":4,"time":"2014-07-04T19:29:51+00:00","method":"PUT","url":"\/remote.php\/webdav\/Public\/Neuer%20Ordner\/Skoda%2002%202013%20ElsWwin%205%200%20Compatible%20Patch.zip-chunking-869170001-17-0"}
{"reqId":"53b7012127b1b","app":"webdav","message":"Sabre_DAV_Exception_BadRequest: expected filesize 10485760 got 32768","level":4,"time":"2014-07-04T19:31:45+00:00","method":"PUT","url":"\/remote.php\/webdav\/Public\/Neuer%20Ordner\/Skoda%2002%202013%20ElsWwin%205%200%20Compatible%20Patch.zip-chunking-869170001-17-0"}
{"reqId":"53b7019005606","app":"webdav","message":"Sabre_DAV_Exception_BadRequest: expected filesize 10485760 got 32768","level":4,"time":"2014-07-04T19:33:36+00:00","method":"PUT","url":"\/remote.php\/webdav\/Public\/Neuer%20Ordner\/Skoda%2002%202013%20ElsWwin%205%200%20Compatible%20Patch.zip-chunking-869170001-17-0"}
{"reqId":"53b7019317d4d","app":"webdav","message":"Sabre_DAV_Exception_BadRequest: expected filesize 10485760 got 163840","level":4,"time":"2014-07-04T19:33:39+00:00","method":"PUT","url":"\/remote.php\/webdav\/Public\/Neuer%20Ordner\/Dragonball-Z.zip-chunking-164120460-24-3"}

Client->mirall:

07-04 21:27:54:941 socketapi.cpp:55 SocketApi:  can't start server "" 
07-04 21:27:54:953 networkjobs.cpp:191 !!! Mirall::CheckServerJob created for  QUrl( "https://cloud.kluthr.de" )  querying "status.php" 
07-04 21:27:54:983 folderman.cpp:449 FolderMan: Syncing is disabled, no scheduling. 
07-04 21:27:55:145 networkjobs.cpp:417 status.php returns:  QMap(("edition", QVariant(QString, "") ) ( "installed" ,  QVariant(QString, "true") ) ( "version" ,  QVariant(QString, "6.0.4.1") ) ( "versionstring" ,  QVariant(QString, "6.0.4") ) )    0  Reply:  QNetworkReplyHttpImpl(0x7f902c0cc340) 
07-04 21:27:55:145 connectionvalidator.cpp:99 ** Application: ownCloud found:   QUrl( "https://cloud.kluthr.de/status.php" )   with version  "6.0.4" ( "6.0.4.1" ) 
07-04 21:27:55:162 networkjobs.cpp:191 !!! Mirall::PropfindJob created for  QUrl( "https://cloud.kluthr.de" )  querying "/" 
07-04 21:27:55:162 connectionvalidator.cpp:146 # checking for authentication settings. 
07-04 21:27:55:496 networkjobs.cpp:191 !!! Mirall::CheckQuotaJob created for  QUrl( "https://cloud.kluthr.de" )  querying "/" 
07-04 21:27:56:000 owncloudgui.cpp:209 Folder in overallStatus Message:  Mirall::Folder(0x7f902a456d90)  with name  "ownCloud" 
07-04 21:27:56:000 folderman.cpp:400 Schedule folder  "ownCloud"  to sync! 
07-04 21:27:56:000 folderman.cpp:415  II> Sync for folder  "ownCloud"  already scheduled, do not enqueue! 
07-04 21:27:56:000 application.cpp:292 Connection Validator Result:  "Connected" 
07-04 21:27:56:000 application.cpp:297 ######## Connection and Credentials are ok! 
07-04 21:27:56:000 folderman.cpp:400 Schedule folder  "ownCloud"  to sync! 
07-04 21:27:56:001 folderman.cpp:415  II> Sync for folder  "ownCloud"  already scheduled, do not enqueue! 
07-04 21:27:56:001 owncloudgui.cpp:157 ######## connected to ownCloud Server! 
07-04 21:27:56:253 folderman.cpp:453 XX slotScheduleFolderSync: folderQueue size:  1 
07-04 21:27:56:253 folder.cpp:537 ==== added system ignore list to csync: "/Applications/owncloud.app/Contents/Resources/sync-exclude.lst" 
[...]
07-04 21:27:56:502 folderman.cpp:469 >===================================== sync started for  "ownCloud" 
07-04 21:27:56:505 syncjournaldb.cpp:870 Transaction Start  "checkConnect" 
07-04 21:27:56:506 syncjournaldb.cpp:346 Columns in the current journal:  ("phash", "pathlen", "path", "inode", "uid", "gid", "mode", "modtime", "type", "md5", "fileid") 
07-04 21:27:56:506 syncengine.cpp:462 =====sync with existing DB 
07-04 21:27:56:506 syncengine.cpp:505 #### Update start #################################################### >> 
[...]
07-04 21:27:56:613 csync_ftw:  <= Closing walk for /Users/robin/ownCloud/Public/MK with read_from_db 0
07-04 21:27:56:613 csync_walker: directory: /Users/robin/ownCloud/Public/Neuer Ordner [file_id=]
07-04 21:27:56:613 _csync_detect_update: Checking for rename based on inode # 3845237
07-04 21:27:56:613 _csync_detect_update: file: Public/Neuer Ordner, instruction: INSTRUCTION_NEW <<=
07-04 21:27:56:613 csync_walker: file: /Users/robin/ownCloud/Public/Neuer Ordner/Dragonball-Z.zip [file_id=]
07-04 21:27:56:613 _csync_detect_update: Checking for rename based on inode # 3845241
07-04 21:27:56:613 _csync_detect_update: file: Public/Neuer Ordner/Dragonball-Z.zip, instruction: INSTRUCTION_NEW <<=
07-04 21:27:56:613 csync_walker: file: /Users/robin/ownCloud/Public/Neuer Ordner/Skoda 02 2013 ElsWwin 5 0 Compatible Patch.zip [file_id=]
07-04 21:27:56:613 _csync_detect_update: Checking for rename based on inode # 3845240
07-04 21:27:56:613 _csync_detect_update: file: Public/Neuer Ordner/Skoda 02 2013 ElsWwin 5 0 Compatible Patch.zip, instruction: INSTRUCTION_NEW <<=
07-04 21:27:56:613 csync_ftw:  <= Closing walk for /Users/robin/ownCloud/Public/Neuer Ordner with read_from_db 0
[...]
07-04 21:27:56:613 csync_ftw:  <= Closing walk for /Users/robin/ownCloud/Public with read_from_db 0
07-04 21:27:56:613 csync_ftw:  <= Closing walk for /Users/robin/ownCloud with read_from_db 0
07-04 21:27:56:613 csync_update: Update detection for local replica took 0,11 seconds walking 475 files.
07-04 21:27:56:614 oc_module: opendir method called on ownclouds://cloud.kluthr.de/remote.php/webdav
[...]
07-04 21:27:56:614 oc_module: Timeout set to 300 seconds
07-04 21:27:56:615 oc_module: No proxy configured.
07-04 21:27:56:740 oc_module: Call the csync callback for SSL problems
07-04 21:27:56:740 credentialscommon.cpp:58 SSL Fingerprint from neon:  "9a:14:23:33:a4:26:5f:d6:62:21:be:ff:6b:bd:54:80:dc:19:d8:53"  compared to verified:  "9a:14:23:33:a4:26:5f:d6:62:21:be:ff:6b:bd:54:80:dc:19:d8:53" 
07-04 21:27:56:740 oc_module: ## VERIFY_SSL CERT: 0
07-04 21:27:56:906 oc_module: Authentication required 
07-04 21:27:56:906 oc_module: Call the csync callback for ownCloud
07-04 21:27:57:141 oc_module: Simple propfind result code 207.
07-04 21:27:57:141 oc_module: opendir returning handle 0x7f902c67fe60 (count=4)
[...]
07-04 21:27:57:143 csync_update: Update detection for remote replica took 0,53 seconds walking 472 files.
07-04 21:27:57:143 syncengine.cpp:519 <<#### Update end ####################################################  637 
[...]
07-04 21:27:57:227 csync_reconcile: Reconciliation for remote replica took 0,04 seconds visiting 472 files.
07-04 21:27:57:228 syncjournaldb.cpp:870 Transaction Start  "checkConnect" 
07-04 21:27:57:229 syncjournaldb.cpp:346 Columns in the current journal:  ("phash", "pathlen", "path", "inode", "uid", "gid", "mode", "modtime", "type", "md5", "fileid") 
07-04 21:27:57:231 owncloudpropagator.cpp:279 Using QNAM/HTTP parallel code path 
07-04 21:27:57:235 folder.cpp:632     * csync thread started 
07-04 21:27:57:495 owncloudgui.cpp:209 Folder in overallStatus Message:  Mirall::Folder(0x7f902a456d90)  with name  "ownCloud" 
07-04 21:27:57:496 owncloudgui.cpp:124 Sync state changed for folder  "ownCloud" :  "Sync Running" 
07-04 21:27:57:496 socketapi.cpp:131 SocketApi:  Broadcasting to 0 listeners:  "UPDATE_VIEW" 
07-04 21:27:58:305 syncengine.cpp:631 void Mirall::SyncEngine::slotJobCompleted(const Mirall::SyncFileItem &) "Public/Neuer Ordner" 4 "" 
07-04 21:27:58:310 networkjobs.cpp:65 void Mirall::AbstractNetworkJob::setTimeout(qint64) 300000 
07-04 21:27:58:310 networkjobs.cpp:191 !!! Mirall::PUTFileJob created for  QUrl( "https://cloud.kluthr.de" )  querying "/Public/Neuer Ordner/Dragonball-Z.zip-chunking-164120460-24-0" 
07-04 21:27:58:310 networkjobs.cpp:65 void Mirall::AbstractNetworkJob::setTimeout(qint64) 300000 
07-04 21:27:58:311 networkjobs.cpp:191 !!! Mirall::PUTFileJob created for  QUrl( "https://cloud.kluthr.de" )  querying "/Public/Neuer Ordner/Skoda 02 2013 ElsWwin 5 0 Compatible Patch.zip-chunking-869170001-17-0" 
07-04 21:27:58:314 sparkleupdater_mac.mm:107 virtual void Mirall::SparkleUpdater::backgroundCheckForUpdate() launching background check 
07-04 21:27:58:317 sparkleupdater_mac.mm:34 -[DelegateObject updaterMayCheckForUpdates:] may check: YES 
07-04 21:27:59:555 sparkleupdater_mac.mm:47 -[DelegateObject updaterDidNotFindUpdate:] 
07-04 21:28:26:998 networkjobs.cpp:191 !!! Mirall::CheckQuotaJob created for  QUrl( "https://cloud.kluthr.de" )  querying "/" 
07-04 21:29:51:734 propagator_qnam.cpp:246 void Mirall::PropagateUploadFileQNAM::slotPutFinished()  QUrl( "https://cloud.kluthr.de/remote.php/webdav/Public/Neuer Ordner/Dragonball-Z.zip-chunking-164120460-24-0" )  FINISHED WITH STATUS 0 "" QVariant(int, 201) QVariant(QString, "Created") 
07-04 21:29:51:736 syncjournaldb.cpp:672 "INSERT OR REPLACE INTO uploadinfo (path, chunk, transferid, errorcount, size, modtime) VALUES ( ? , ?, ? , ? ,  ? , ? )" "Public/Neuer Ordner/Dragonball-Z.zip" 1 157829004 0 
07-04 21:29:51:737 syncjournaldb.cpp:870 Transaction Start  "Upload info" 
07-04 21:29:51:739 networkjobs.cpp:65 void Mirall::AbstractNetworkJob::setTimeout(qint64) 300000 
07-04 21:29:51:740 networkjobs.cpp:191 !!! Mirall::PUTFileJob created for  QUrl( "https://cloud.kluthr.de" )  querying "/Public/Neuer Ordner/Dragonball-Z.zip-chunking-164120460-24-1" 
07-04 21:30:21:995 networkjobs.cpp:191 !!! Mirall::CheckQuotaJob created for  QUrl( "https://cloud.kluthr.de" )  querying "/" 
07-04 21:31:45:048 propagator_qnam.cpp:246 void Mirall::PropagateUploadFileQNAM::slotPutFinished()  QUrl( "https://cloud.kluthr.de/remote.php/webdav/Public/Neuer Ordner/Dragonball-Z.zip-chunking-164120460-24-1" )  FINISHED WITH STATUS 0 "" QVariant(int, 201) QVariant(QString, "Created") 
07-04 21:31:45:050 syncjournaldb.cpp:672 "INSERT OR REPLACE INTO uploadinfo (path, chunk, transferid, errorcount, size, modtime) VALUES ( ? , ?, ? , ? ,  ? , ? )" "Public/Neuer Ordner/Dragonball-Z.zip" 2 157829004 0 
07-04 21:31:45:051 syncjournaldb.cpp:870 Transaction Start  "Upload info" 
07-04 21:31:45:052 networkjobs.cpp:65 void Mirall::AbstractNetworkJob::setTimeout(qint64) 300000 
07-04 21:31:45:053 networkjobs.cpp:191 !!! Mirall::PUTFileJob created for  QUrl( "https://cloud.kluthr.de" )  querying "/Public/Neuer Ordner/Dragonball-Z.zip-chunking-164120460-24-2" 
07-04 21:32:14:994 networkjobs.cpp:191 !!! Mirall::CheckQuotaJob created for  QUrl( "https://cloud.kluthr.de" )  querying "/" 
07-04 21:33:35:901 propagator_qnam.cpp:246 void Mirall::PropagateUploadFileQNAM::slotPutFinished()  QUrl( "https://cloud.kluthr.de/remote.php/webdav/Public/Neuer Ordner/Dragonball-Z.zip-chunking-164120460-24-2" )  FINISHED WITH STATUS 0 "" QVariant(int, 201) QVariant(QString, "Created") 
07-04 21:33:35:903 syncjournaldb.cpp:672 "INSERT OR REPLACE INTO uploadinfo (path, chunk, transferid, errorcount, size, modtime) VALUES ( ? , ?, ? , ? ,  ? , ? )" "Public/Neuer Ordner/Dragonball-Z.zip" 3 157829004 0 
07-04 21:33:35:904 syncjournaldb.cpp:870 Transaction Start  "Upload info" 
07-04 21:33:35:908 networkjobs.cpp:65 void Mirall::AbstractNetworkJob::setTimeout(qint64) 300000 
07-04 21:33:35:909 networkjobs.cpp:191 !!! Mirall::PUTFileJob created for  QUrl( "https://cloud.kluthr.de" )  querying "/Public/Neuer Ordner/Dragonball-Z.zip-chunking-164120460-24-3" 
07-04 21:33:36:030 networkjobs.cpp:139 void Mirall::AbstractNetworkJob::slotFinished() 2 "Connection closed" 
07-04 21:33:36:031 propagator_qnam.cpp:246 void Mirall::PropagateUploadFileQNAM::slotPutFinished()  QUrl( "https://cloud.kluthr.de/remote.php/webdav/Public/Neuer Ordner/Skoda 02 2013 ElsWwin 5 0 Compatible Patch.zip-chunking-869170001-17-0" )  FINISHED WITH STATUS 2 "Connection closed" QVariant(Invalid) QVariant(Invalid) 
07-04 21:33:36:032 propagator_qnam.cpp:264 "" 
07-04 21:33:36:032 syncengine.cpp:631 void Mirall::SyncEngine::slotJobCompleted(const Mirall::SyncFileItem &) "Public/Neuer Ordner/Skoda 02 2013 ElsWwin 5 0 Compatible Patch.zip" 1 "Connection closed" 
07-04 21:33:36:035 propagator_qnam.cpp:375 virtual void Mirall::PropagateUploadFileQNAM::abort() "Public/Neuer Ordner/Dragonball-Z.zip" 
07-04 21:33:36:036 networkjobs.cpp:139 void Mirall::AbstractNetworkJob::slotFinished() 5 "Operation canceled" 
07-04 21:33:36:037 propagator_qnam.cpp:246 void Mirall::PropagateUploadFileQNAM::slotPutFinished()  QUrl( "https://cloud.kluthr.de/remote.php/webdav/Public/Neuer Ordner/Dragonball-Z.zip-chunking-164120460-24-3" )  FINISHED WITH STATUS 5 "Operation canceled" QVariant(Invalid) QVariant(Invalid) 
07-04 21:33:36:038 qiodevice.cpp:821 QIODevice::read: device not open
07-04 21:33:36:038 propagator_qnam.cpp:264 "" 
07-04 21:33:36:039 syncengine.cpp:631 void Mirall::SyncEngine::slotJobCompleted(const Mirall::SyncFileItem &) "Public/Neuer Ordner/Dragonball-Z.zip" 1 "Operation canceled" 
07-04 21:33:36:041 propagator_qnam.cpp:375 virtual void Mirall::PropagateUploadFileQNAM::abort() "Public/Neuer Ordner/Skoda 02 2013 ElsWwin 5 0 Compatible Patch.zip" 
07-04 21:33:36:057 propagator_qnam.cpp:375 virtual void Mirall::PropagateUploadFileQNAM::abort() "Public/Neuer Ordner/Dragonball-Z.zip" 
07-04 21:33:36:041 qiodevice.cpp:1307 QIODevice::write: device not open
07-04 21:33:36:077 syncjournaldb.cpp:870 Transaction Start  "All Finished." 
07-04 21:33:36:079 syncengine.cpp:675 CSync run took  339580 
07-04 21:33:36:080 folder.cpp:644 -> CSync Finished slot with error  true warn count 0 
07-04 21:33:36:088 folder.cpp:385 Processing result list and logging took  4  Milliseconds. 
07-04 21:33:36:089 folder.cpp:403 OO folder slotSyncFinished: result:  3 
07-04 21:33:36:090 folder.cpp:656   ** error Strings:  ("Connection closed", "Operation canceled", "Public/Neuer Ordner/Skoda 02 2013 ElsWwin 5 0 Compatible Patch.zip: Connection closed", "Public/Neuer Ordner/Dragonball-Z.zip: Operation canceled") 
07-04 21:33:36:091 folder.cpp:658     * owncloud csync thread finished with error 
07-04 21:33:36:302 owncloudgui.cpp:209 Folder in overallStatus Message:  Mirall::Folder(0x7f902a456d90)  with name  "ownCloud" 
07-04 21:33:36:304 owncloudgui.cpp:124 Sync state changed for folder  "ownCloud" :  "Error" 
07-04 21:33:36:304 socketapi.cpp:131 SocketApi:  Broadcasting to 0 listeners:  "UPDATE_VIEW" 
07-04 21:33:36:507 folderman.cpp:478 <===================================== sync finished for  "ownCloud" 
07-04 21:33:36:709 folderman.cpp:453 XX slotScheduleFolderSync: folderQueue size:  0

Do you need more informations?

@Commifreak
Copy link
Author

Another update:

I've found the cause:

  • PHP-FPM -> FastCGIExternalServer's --idle-timeout is the problem: set to 900 (15 mins): after 15 mins: mirall fails. PHP-FPM did not reported that (I dont know why), but if I change the idle-timeout, the fail comes a bit later/earlier. In the last comment, the timeout was 360s
  • Another weird thing: shortly after the first fail, mirall fails every 2 minutes. It trries to re-sync the failed things. This fails, as said, after 2 minutes already.

Are some devs using fpm? How can this problem be avoided?

@tachyon-ops tachyon-ops mentioned this issue Jul 5, 2014
Closed
@tachyon-ops
Copy link

@Commifreak , do you have pm=ondemand ?

Check this:
owncloud/core#9324 (comment)

@Commifreak
Copy link
Author

Yep. pm=ondemand. But where should be the problem vs dynamic? It changes just the way, how fpm creates processes and how many...?

@tachyon-ops
Copy link

@Commifreak could have some problem in there... but I've tested and dynamic only seams to bring more stability to my connections. So, ondemand breaks almost 90% of transactions, dynamic about 10 - 20%, depending on quality of connection (values fluctuate). It doesn't seam connected to server load.
I'm a little lost here as well. Gonna try clunking size to see if it maintains connections below a 120s threshold.

@tachyon-ops
Copy link

@Commifreak What's you upload speed?

@Commifreak
Copy link
Author

bildschirmfoto 2014-06-25 um 21 49 47

@tachyon-ops
Copy link

That gives about 1000 seconds of duration for 10Mb chunks.
I also have that speed issue. Mine fluctuates from 33 to 250. Hence, the erratic behaviour of my client-server connection.

@guruz guruz added the bug label Aug 29, 2014
@guruz guruz added this to the 1.7. milestone Aug 29, 2014
@ckamm
Copy link
Contributor

ckamm commented Sep 5, 2014

@guruz Given that the issue seems to be related to php idle timeouts on the server, is there even something we can do in mirall? Reduce the chunk size?

@markoza
Copy link

markoza commented Sep 8, 2014

Hello,

I think I have the same problem.

I have installed ownCloud 7.0.0 on IIS 8.0 (Windows Server 2012). It Works great, but when I add some large test files to sync using Windows client, I get this error: Operation canceled.

Here is the output of client log file:

9-04 09:08:30:305 syncjournaldb.cpp:870 Transaction Start "checkConnect"
09-04 09:08:30:337 syncjournaldb.cpp:346 Columns in the current journal: ("phash", "pathlen", "path", "inode", "uid", "gid", "mode", "modtime", "type", "md5", "fileid")
09-04 09:08:30:344 owncloudpropagator.cpp:279 Using QNAM/HTTP parallel code path
09-04 09:08:30:361 folderwatcher.cpp:154 detected changes in folders: QSet("C:\Users\Adminaa\ownCloud/")
09-04 09:08:30:362 folderman.cpp:397 the current folder is currently syncing.
09-04 09:08:30:362 folder.cpp:632 * csync thread started
09-04 09:08:30:451 owncloudgui.cpp:209 Folder in overallStatus Message: Mirall::Folder(0x524ce88) with name "ownCloud"
09-04 09:08:30:453 owncloudgui.cpp:124 Sync state changed for folder "ownCloud" : "Sync Running"
09-04 09:08:30:453 socketapi.cpp:131 SocketApi: Broadcasting to 0 listeners: "UPDATE_VIEW"
09-04 09:08:30:456 propagator_qnam.cpp:108 virtual void Mirall::PropagateUploadFileQNAM::start() "documents/Marktn/__IPAN 2014/Dobarr-logotipi/Fexxs (11)/GW_Ranoji 2x.zip" : Resuming from chunk 11
09-04 09:08:30:456 networkjobs.cpp:65 void Mirall::AbstractNetworkJob::setTimeout(qint64) 300000
09-04 09:08:30:457 networkjobs.cpp:191 !!! Mirall::PUTFileJob created for QUrl( "https://ocloud.ennnnn.si/owncloud" ) querying "/documents/Marktn/__IPAN 2014/Dobarr-logotipi/Fexxs (11)/GW_Ranoji 2x.zip-chunking-3380711604-14-11"
09-04 09:08:30:457 propagator_qnam.cpp:460 virtual void Mirall::PropagateDownloadFileQNAM::start() "documents/Marktn/__IPAN 2014/Dobarr-logotipi/Fexxs (11)/werramsfer-42c4cs.zip" 1
09-04 09:08:30:457 owncloudpropagator.cpp:345 CaseClashCheck for "C:\Users\Adminaa\ownCloud/documents/Marktn/__IPAN 2014/Dobarr-logotipi/Fexxs (11)/werramsfer-42c4cs.zip"
09-04 09:08:30:458 owncloudpropagator.cpp:355 bool Mirall::OwncloudPropagator::localFileNameClash(const QString&) Real file name is "werramsfer-42c4cs.zip"
09-04 09:08:30:460 syncjournaldb.cpp:606 "INSERT OR REPLACE INTO downloadinfo (path, tmpfile, etag, errorcount) VALUES ( ? , ?, ? , ? )" "documents/Marktn/__IPAN 2014/Dobarr-logotipi/Fexxs (11)/werramsfer-42c4cs.zip" "documents/Marktn/__IPAN 2014/Dobarr-logotipi/Fexxs (11)/.werramsfer-42c4cs.zip.~7d3f" "54080da922e8a" 0
09-04 09:08:30:460 syncjournaldb.cpp:870 Transaction Start "download file start"
09-04 09:08:30:478 networkjobs.cpp:65 void Mirall::AbstractNetworkJob::setTimeout(qint64) 300000
09-04 09:08:30:479 networkjobs.cpp:191 !!! Mirall::GETFileJob created for QUrl( "https://ocloud.ennnnn.si/owncloud" ) querying "/documents/Marktn/__IPAN 2014/Dobarr-logotipi/Fexxs (11)/werramsfer-42c4cs.zip"
09-04 09:08:30:483 networkjobs.cpp:65 void Mirall::AbstractNetworkJob::setTimeout(qint64) 300000
09-04 09:08:30:483 networkjobs.cpp:191 !!! Mirall::PUTFileJob created for QUrl( "https://ocloud.ennnnn.si/owncloud" ) querying "/documents/Marktn/__IPAN 2014/Dobarr-logotipi/Ranketron-Bpt (36)/Rano Domovv+termal.jpg"
09-04 09:08:30:541 qiodevice.cpp:1307 QIODevice::write: device not open
09-04 09:08:30:541 qiodevice.cpp:1307 QIODevice::write: device not open
09-04 09:08:30:541 qiodevice.cpp:1307 QIODevice::write: device not open
09-04 09:08:30:542 networkjobs.cpp:139 void Mirall::AbstractNetworkJob::slotFinished() 99 "Neznana napaka"
09-04 09:08:30:543 propagator_qnam.cpp:246 void Mirall::PropagateUploadFileQNAM::slotPutFinished() QUrl( "https://ocloud.ennnnn.si/owncloud/remote.php/webdav/documents/Marktn/__IPAN 2014/Dobarr-logotipi/Ranketron-Bpt (36)/Rano Domovv+termal.jpg" ) FINISHED WITH STATUS 99 "Neznana napaka" QVariant(Invalid) QVariant(Invalid)
09-04 09:08:30:543 propagator_qnam.cpp:264 ""
09-04 09:08:30:543 syncengine.cpp:631 void Mirall::SyncEngine::slotJobCompleted(const Mirall::SyncFileItem&) "documents/Marktn/__IPAN 2014/Dobarr-logotipi/Ranketron-Bpt (36)/Rano Domovv+termal.jpg" 1 "Neznana napaka"
09-04 09:08:30:546 propagator_qnam.cpp:375 virtual void Mirall::PropagateUploadFileQNAM::abort() "documents/Marktn/__IPAN 2014/Dobarr-logotipi/Ranketron-Bpt (36)/Rano Domovv+termal.jpg"
09-04 09:08:30:547 propagator_qnam.cpp:375 virtual void Mirall::PropagateUploadFileQNAM::abort() "documents/Marktn/__IPAN 2014/Dobarr-logotipi/Fexxs (11)/GW_Ranoji 2x.zip"
09-04 09:08:30:547 networkjobs.cpp:139 void Mirall::AbstractNetworkJob::slotFinished() 5 "Operation canceled"
09-04 09:08:30:548 propagator_qnam.cpp:246 void Mirall::PropagateUploadFileQNAM::slotPutFinished() QUrl( "https://ocloud.ennnnn.si/owncloud/remote.php/webdav/documents/Marktn/__IPAN 2014/Dobarr-logotipi/Fexxs (11)/GW_Ranoji 2x.zip-chunking-3380711604-14-11" ) FINISHED WITH STATUS 5 "Operation canceled" QVariant(Invalid) QVariant(Invalid)
09-04 09:08:30:548 qiodevice.cpp:821 QIODevice::read: device not open
09-04 09:08:30:548 propagator_qnam.cpp:264 ""
09-04 09:08:30:548 syncengine.cpp:631 void Mirall::SyncEngine::slotJobCompleted(const Mirall::SyncFileItem&) "documents/Marktn/__IPAN 2014/Dobarr-logotipi/Fexxs (11)/GW_Ranoji 2x.zip" 1 "Operation canceled"
09-04 09:08:30:549 networkjobs.cpp:139 void Mirall::AbstractNetworkJob::slotFinished() 5 "Operation canceled"
09-04 09:08:30:549 propagator_qnam.cpp:548 void Mirall::PropagateDownloadFileQNAM::slotGetFinished() QUrl( "https://ocloud.ennnnn.si/owncloud/remote.php/webdav/documents/Marktn/__IPAN 2014/Dobarr-logotipi/Fexxs (11)/werramsfer-42c4cs.zip" ) FINISHED WITH STATUS 5 "Operation canceled"
09-04 09:08:30:551 syncjournaldb.cpp:616 "DELETE FROM downloadinfo WHERE path=?" "documents/Marktn/__IPAN 2014/Dobarr-logotipi/Fexxs (11)/werramsfer-42c4cs.zip"
09-04 09:08:30:551 syncengine.cpp:631 void Mirall::SyncEngine::slotJobCompleted(const Mirall::SyncFileItem&) "documents/Marktn/__IPAN 2014/Dobarr-logotipi/Fexxs (11)/werramsfer-42c4cs.zip" 1 "Operation canceled"
09-04 09:08:30:553 propagator_qnam.cpp:375 virtual void Mirall::PropagateUploadFileQNAM::abort() "documents/Marktn/__IPAN 2014/Dobarr-logotipi/Fexxs (11)/GW_Ranoji 2x.zip"
09-04 09:08:30:549 qiodevice.cpp:1307 QIODevice::write: device not open
09-04 09:08:30:556 syncjournaldb.cpp:870 Transaction Start "All Finished."
09-04 09:08:30:571 syncengine.cpp:675 CSync run took 4421
09-04 09:08:30:571 folder.cpp:644 -> CSync Finished slot with error true warn count 0
09-04 09:08:30:588 folder.cpp:385 Processing result list and logging took 15 Milliseconds.
09-04 09:08:30:588 folder.cpp:403 OO folder slotSyncFinished: result: 3
09-04 09:08:30:589 folder.cpp:656 ** error Strings: ("Neznana napaka", "Operation canceled", "Operation canceled", "documents/Marktn/__IPAN 2014/Dobarr-logotipi/Fexxs (11)/GW_Ranoji 2x.zip: Operation canceled", "documents/Marktn/__IPAN 2014/Dobarr-logotipi/Ranketron-Bpt (36)/Rano Domovv+termal.jpg: Neznana napaka", "documents/Marktn/__IPAN 2014/Dobarr-logotipi/Fexxs (11)/werramsfer-42c4cs.zip: Operation canceled")
09-04 09:08:30:589 folder.cpp:658 * owncloud csync thread finished with error
09-04 09:08:30:676 owncloudgui.cpp:209 Folder in overallStatus Message: Mirall::Folder(0x524ce88) with name "ownCloud"
09-04 09:08:30:678 owncloudgui.cpp:124 Sync state changed for folder "ownCloud" : "Error"
09-04 09:08:30:678 socketapi.cpp:131 SocketApi: Broadcasting to 0 listeners: "UPDATE_VIEW"
09-04 09:08:30:878 folderman.cpp:478 <===================================== sync finished for "ownCloud"
09-04 09:08:31:078 folderman.cpp:453 XX slotScheduleFolderSync: folderQueue size: 0

@Commifreak
Copy link
Author

@markoza Do you use the latest sync-client?

@markoza
Copy link

markoza commented Sep 8, 2014

Yes, I have the latest client. Now I see that even if I try to upload larger ZIP file over web site I get error "Not Found". If I check Windows\Temp folder I can see a lot of phpXXXX.tmp files but it is strange because they are all the same size 42221KB.

Thank you!

Best wishes,
Marko

@luciamaestro
Copy link

@markoza @Commifreak Is it still happening with 1.6.3?

@ghost ghost mentioned this issue Oct 27, 2014
Closed
@ochurlaud ochurlaud mentioned this issue Nov 2, 2014
Closed
@luciamaestro
Copy link

If it is still happening in the latest version please reopen it, thx.

@Happyfeet01 Happyfeet01 mentioned this issue Apr 29, 2016
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
type:bug
Projects
None yet
Milestone
1.7.1
Development

No branches or pull requests
6 participants
@Commifreak @tachyon-ops @ckamm @guruz @luciamaestro @markoza