1.7.0 beta (3920) owncloud client never "rests"

[kaplandani]

It looks like the owncloud 1.7.0 never rests. It's consuming 25% CPU, even when finished all syncing.

once finished - it keeps syncing again and again (discovering stage) - owncloud never rests. after every "round" I get notification in the tray that 87 files were not sync and it goes over again....

my server is 7.0.2 on CentOS 7. my os is windows 8.1

The client logs each sync in the log dir: Here is the last lines from log.1 and then the first lines from log.2 - notice they are immediate - 6 ticks away and folder change detected and we go over again.....

-- first file: 10-03 13:42:39:348 networkjobs.cpp:201 !!! Mirall::CheckQuotaJob created for QUrl( "https://myserver.com/mycloud" ) querying "/" 10-03 13:42:48:005 folder.cpp:257 * Polling "Docs" for changes. (time since last sync: 299 s) 10-03 13:42:48:006 folder.cpp:275 \ Force Sync now, state is "Success, some files were ignored." 10-03 13:42:48:006 folderman.cpp:445 Schedule folder "Docs" to sync! 10-03 13:42:48:006 folderman.cpp:462 II> Sync for folder "Docs" already scheduled, do not enqueue! 10-03 13:42:49:350 networkjobs.cpp:206 Mirall::CheckQuotaJob(0xb5f7a78) Timeout 10-03 13:42:49:350 networkjobs.cpp:146 void Mirall::AbstractNetworkJob::slotFinished() 5 "Operation canceled" 10-03 13:42:49:355 folder.cpp:506 folder "Work" Terminating! 10-03 13:42:50:008 folderman.cpp:497 FolderMan: Syncing is disabled, no scheduling. 10-03 13:43:09:151 oc_module: Simple propfind result code 207. 10-03 13:43:09:151 oc_module: opendir returning handle 0c2b4178 (count=2) 10-03 13:43:09:151 csync_walker: Aborted! 10-03 13:43:09:152 syncengine.cpp:500 #### ERROR during csync_update : "Aborted by the user" 10-03 13:43:09:152 syncengine.cpp:503 Update phase was aborted by user! 10-03 13:43:09:281 syncengine.cpp:789 CSync run took 320825 10-03 13:43:09:281 folder.cpp:692 -> CSync Finished slot with error false warn count 0 10-03 13:43:09:284 folder.cpp:392 Processing result list and logging took 0 Milliseconds. 10-03 13:43:09:284 folder.cpp:412 OO folder slotSyncFinished: result: 4 10-03 13:43:09:295 owncloudgui.cpp:177 Sync state changed for folder "Work" : "Success"

---

----- new file:

---

10-03 13:43:09:301 folderwatcher.cpp:153 detected changes in folders: QSet("Y:\Work/") 10-03 13:43:09:301 folderman.cpp:445 Schedule folder "Work" to sync! 10-03 13:43:09:302 folderman.cpp:462 II> Sync for folder "Work" already scheduled, do not enqueue! 10-03 13:43:09:497 folderman.cpp:538 <===================================== sync finished for "" 10-03 13:43:09:697 folderman.cpp:497 FolderMan: Syncing is disabled, no scheduling. 10-03 13:43:11:300 folderman.cpp:497 FolderMan: Syncing is disabled, no scheduling. 10-03 13:43:18:004 folder.cpp:257 * Polling "Docs" for changes. (time since last sync: 329 s) 10-03 13:43:18:004 folder.cpp:268 Not syncing. : false 0 10-03 13:43:21:348 networkjobs.cpp:201 !!! Mirall::CheckServerJob created for QUrl( "https://myserver.com/mycloud" ) querying "status.php" 10-03 13:43:31:354 networkjobs.cpp:377 TIMEOUT virtual void Mirall::CheckServerJob::slotTimeout() 10-03 13:43:31:355 application.cpp:290 Connection Validator Result: "Status not found" 10-03 13:43:39:288 folder.cpp:257 * Polling "Work" for changes. (time since last sync: 29 s) 10-03 13:43:39:288 folder.cpp:268 Not syncing. : false 0 10-03 13:43:48:004 folder.cpp:257 * Polling "Docs" for changes. (time since last sync: 359 s) 10-03 13:43:48:004 folder.cpp:268 Not syncing. : false 0

[ckamm]

@kaplandani I've merged a fix to the 1.7 branch that prevents regular 'force'-syncing from happening. Could you test it?

[kaplandani]

If its in the nightly build I will test it today. Otherwise where can I get the binaries ?

[guruz]

http://download.owncloud.com/desktop/daily/ownCloud-1.7.0.3950-nightly20141008-setup.exe

[enoch85]

@guruz Still the same issue with build 3950.

[ckamm]

@kaplandani Since that doesn't seem to solve the issue completely yet, could I ask you for another log? If it's too big, show me only the lines with folder.cpp/folderman.cpp/syncengine.cpp/owncloudgui.cpp, that should be enough to figure out what is triggering these sync runs.

[kaplandani]

Just got home, downloading, installing, and generating logs. give me 60 min.

On Wed, Oct 8, 2014 at 3:39 PM, ckamm notifications@github.com wrote:

@kaplandani https://github.com/kaplandani Since that doesn't seem to solve the issue completely yet, could I ask you for another log? If it's too big, show me only the lines with folder.cpp/folderman.cpp/syncengine.cpp/owncloudgui.cpp, that should be enough to figure out what is triggering these sync runs.

— Reply to this email directly or view it on GitHub https://github.com/owncloud/mirall/issues/2268#issuecomment-58350787.

[kaplandani]

Is it possible that once a sync is finish with ERROR it's immediately starts over ? I'm still dealing with this error: https://github.com/owncloud/mirall/issues/2266

maybe b/c the sync is always ends with an error message about 87 files that were not sync it's immediately start over ?

Posting the new logs in 15 min.

[kaplandani]

Here is the end of log.2 and start of log.3:

End of log.2:

10-08 16:36:17:333 syncjournaldb.cpp:457 "INSERT OR REPLACE INTO metadata (phash, pathlen, path, inode, uid, gid, mode, modtime, type, md5, fileid, remotePerm) VALUES ( ? , ?, ? , ? , ? , ? , ?, ? , ? , ?, ?, ? )" 8497370526290683634 4 "yosi" 119590 0 "1393691887" "2" "542e033d86ccf" "00222388oc2833a28ce5" "RDNVCK" 10-08 16:36:18:062 syncjournaldb.cpp:1054 Transaction Start "All Finished." 10-08 16:36:21:592 syncengine.cpp:789 CSync run took 377315 10-08 16:36:21:625 folderman.cpp:492 Currently folder "Work" is running, wait for finish! 10-08 16:36:21:630 folderwatcher.cpp:153 detected changes in folders: QSet("Y:\Work/") 10-08 16:36:21:630 folderman.cpp:445 Schedule folder "Work" to sync! 10-08 16:36:21:630 folderman.cpp:462 II> Sync for folder "Work" already scheduled, do not enqueue! 10-08 16:36:21:646 folder.cpp:694 -> CSync Finished slot with error false warn count 1 10-08 16:36:21:653 folder.cpp:394 Processing result list and logging took 4 Milliseconds. 10-08 16:36:21:747 folder.cpp:414 OO folder slotSyncFinished: result: 3 10-08 16:36:21:829 folder.cpp:709 * error Strings: ("SomePathOfMine/EventManagerUI_Backup_2011.10.08_11.16.05/Content/2011.1.315/Vista/.svn/text-base/loading.gif.svn-base: Access is denied. ", "SomePathOfMine/EventManagerUI_Backup_2011.10.08_11.16.05/App_GlobalResources/.svn/text-base/GridLocalization.pt-PT.resx.svn-base: Access is denied.", "SomePathOfMine/EventManager/Dev/Sources/backup/EventManagerUI_Backup_2011.10.08_11.16.05/Views/Race/.svn/all-wcprops: Access is denied. ", "SomePathOfMine/tfs/a/_vti_cnf/editDynamicPages.aspx: Access is denied.", "SomePathOfMine/tfs/a/_vti_cnf/galleryInfoEdit.aspx: Access is denied." and here there is list of many more.....) 10-08 16:36:21:829 folder.cpp:711 \ owncloud csync thread finished with error 10-08 16:36:21:861 owncloudgui.cpp:260 Folder in overallStatus Message: Mirall::Folder(0x742d298) with name "Docs" 10-08 16:36:21:861 owncloudgui.cpp:260 Folder in overallStatus Message: Mirall::Folder(0x7435528) with name "Work" 10-08 16:36:21:864 owncloudgui.cpp:177 Sync state changed for folder "Work" : "Error"

Start of log.3:

10-08 16:36:22:066 folderman.cpp:538 <===================================== sync finished for "Work" 10-08 16:36:22:267 folderman.cpp:502 XX slotScheduleFolderSync: folderQueue size: 2 10-08 16:36:22:301 owncloudgui.cpp:260 Folder in overallStatus Message: Mirall::Folder(0x742d298) with name "Docs" 10-08 16:36:22:301 owncloudgui.cpp:260 Folder in overallStatus Message: Mirall::Folder(0x7435528) with name "Work" 10-08 16:36:22:303 owncloudgui.cpp:177 Sync state changed for folder "Docs" : "SyncPrepare" 10-08 16:36:22:303 folder.cpp:611 ** Start syncing - client version 1.7.0 10-08 16:36:22:303 folder.cpp:555 ==== added system ignore list to csync: "C:/Program Files (x86)/ownCloud/sync-exclude.lst" 10-08 16:36:22:304 csync_exclude_load: Adding entry: .filepart Truncated.... 10-08 16:36:22:306 folderman.cpp:529 >===================================== sync started for "Docs" 10-08 16:36:22:306 socketapi.cpp:306 ==== added system ignore list to socketapi: "C:/Program Files (x86)/ownCloud/sync-exclude.lst" 10-08 16:36:22:306 csync_exclude_load: Adding entry: *.filepart truncated.... 10-08 16:36:22:308 syncjournaldb.cpp:76 No database Transaction to commit 10-08 16:36:22:309 syncengine.cpp:549 =====sync with existing DB 10-08 16:36:22:309 syncengine.cpp:590 #### Discovery start #################################################### >> 10-08 16:36:22:310 csync_update: Journal: Y:\Docs/.csync_journal.db 10-08 16:36:22:331 csync_walker: file: Y:\Docs/.owncloudsync.log [inode=2942 size=57097] 10-08 16:36:22:331 _csync_detect_update: .owncloudsync.log excluded (1) 10-08 16:36:22:331 csync_walker: file: Y:\Docs/.owncloudsync.log.1 [inode=2995 size=1154720] 10-08 16:36:22:331 _csync_detect_update: .owncloudsync.log.1 excluded (1) 10-08 16:36:22:331 csync_ftw: Uniq ID from Database: 20110117121021198.pdf -> 5426b8a395350 10-08 16:36:22:331 csync_walker: file: Y:\Docs/20110117121021198.pdf [inode=67561 size=38364] 10-08 16:36:22:331 _csync_detect_update: Database entry found, compare: 1295211600 <-> 1295211600, etag: 5426b8a395350 <-> 5426b8a395350, inode: 67561 <-> 67561, size: 38364 <-> 0 10-08 16:36:22:331 _csync_detect_update: file: 20110117121021198.pdf, instruction: INSTRUCTION_NONE <<= 10-08 16:36:22:332 syncjournaldb.cpp:1054 Transaction Start "checkConnect"

[ckamm]

@kaplandani Thanks for the new log files. To me this looks like the issue:

10-08 16:36:21:864 owncloudgui.cpp:177 Sync state changed for folder "Work" : "Error"

If a sync ends in an Error state it will be synced again 30s later. The "Access is denied" errors make the whole sync fail and thus trigger an early retry. And since the files aren't blacklisted, that will happen again and again.

[kaplandani]

@ckamm - a. I have a 2nd installation which is error-free. it actually never finish the first round (I have a 14 GB log file after 4 hours run). sync never ends there as well (maybe a different bug) b. You can see it's not 30s, but actually less than 250ms between the end and start of new sync. c. I am going to resolve this error and see what happens (bye bye access denied bug, but this is more important)

[kaplandani]

@ckamm Just a very wild guess, how does discovery handles circular directory references ?

[ckamm]

@kaplandani But in you latest logs, it finishes to sync Work and then immediately starts to sync Doc. That is expected. The 30s interval applies per synced folder. I assume that after Doc is done, Work is starting again?

Could you look for messages like "Schedule folder ... to sync" and look at why 'Work' and 'Doc' are scheduled repeatedly? Your first log file had: 'folderwatcher.cpp:153 detected changes in folders: QSet("Y:\Work/")' - is it always the folder watcher triggering these syncs?

[kaplandani]

You are correct. there are 2 folders, so it can happen as you said. I'm working on resolving all errors to see what happens.

[ckamm]

Just a very wild guess, how does discovery handles circular directory references ?

@kaplandani Are you saying you have set up symlinks or junction points between Work and Doc? The client should ignore it but maybe that's contributing to the issue.

[kaplandani]

@ckamm I was referring to my 2nd installation - which the first sync didn't end after 4 hours. it was just an idea...

[kaplandani]

@ckamm, @dragotin - once the errors removed the first installation works just like the 2nd one - once finishing the first folder sync it goes to the 2nd one and vice verse forever. Instead of using the folder watcher it does this in the middle of the work folder sync:

10-09 11:45:16:456 folder.cpp:258 * Polling "Docs" for changes. (time since last sync: 359 s) 10-09 11:45:16:457 folder.cpp:276 \ Force Sync now, state is "Success, some files were ignored." 10-09 11:45:16:457 folderman.cpp:445 Schedule folder "Docs" to sync! 10-09 11:45:16:458 folderman.cpp:462 II> Sync for folder "Docs" already scheduled, do not enqueue!

and then again:

10-09 11:47:22:501 csync_reconcile: Reconciliation for remote replica took 0.51 seconds visiting 7997 files. 10-09 11:47:22:504 socketapi.cpp:478 SocketApi: Broadcasting to 0 listeners: "STATUS:SYNC:Y:\Docs~WRL0991.tmp" 10-09 11:47:22:519 socketapi.cpp:478 SocketApi: Broadcasting to 0 listeners: "STATUS:SYNC:Y:\Docs~$brit.xlsx" 10-09 11:47:22:520 socketapi.cpp:478 SocketApi: Broadcasting to 0 listeners: "STATUS:SYNC:Y:\Docs\mada\Paramedic\Course Material\Protocols~$otocols.docx" 10-09 11:47:22:560 socketapi.cpp:478 SocketApi: Broadcasting to 0 listeners: "STATUS:SYNC:Y:\Docs~$brit.docx" 10-09 11:47:22:727 syncjournaldb.cpp:1054 Transaction Start "post treewalk" 10-09 11:47:22:727 syncjournaldb.cpp:1054 Transaction Start "post stale entry removal" 10-09 11:47:22:730 owncloudpropagator.cpp:306 Using QNAM/HTTP parallel code path 10-09 11:47:22:731 folder.cpp:682 * csync thread started 10-09 11:47:22:828 owncloudgui.cpp:260 Folder in overallStatus Message: Mirall::Folder(0x50e7cd8) with name "Work" 10-09 11:47:22:828 owncloudgui.cpp:260 Folder in overallStatus Message: Mirall::Folder(0x50e7c00) with name "Docs" 10-09 11:47:22:832 owncloudgui.cpp:177 Sync state changed for folder "Docs" : "Sync Running" 10-09 11:47:22:834 syncjournalfilerecord.cpp:80 Mirall::SyncJournalFileRecord::SyncJournalFileRecord(const Mirall::SyncFileItem&, const QString&) "Y:\Docs/BOA" Retrieved inode 9058 (previous item inode: 9058 ) 10-09 11:47:22:836 syncjournaldb.cpp:457 "INSERT OR REPLACE INTO metadata (phash, pathlen, path, inode, uid, gid, mode, modtime, type, md5, fileid, remotePerm) VALUES ( ? , ?, ? , ? , ? , ? , ?, ? , ? , ?, ?, ? )" -8543097882541646052 3 "BOA" 9058 0 "1411823782" "2" "5426b8a6708e7" "00000016oc2833a28ce5" "RDNVCK" 10-09 11:47:22:845 syncjournalfilerecord.cpp:80 Mirall::SyncJournalFileRecord::SyncJournalFileRecord(const Mirall::SyncFileItem&, const QString&) "Y:\Docs/BackUp" Retrieved inode 7925 (previous item inode: 7925 ) 10-09 11:47:22:846 syncjournaldb.cpp:457 "INSERT OR REPLACE INTO metadata (phash, pathlen, path, inode, uid, gid, mode, modtime, type, md5, fileid, remotePerm) VALUES ( ? , ?, ? , ? , ? , ? , ?, ? , ? , ?, ?, ? )" 800207035614717576 6 "BackUp" 7925 0 "1411823782" "2" "5426b8a6a0ad3" "00000021oc2833a28ce5" "RDNVCK" 10-09 11:47:22:860 folderwatcher.cpp:153 detected changes in folders: QSet("Y:\Docs/") 10-09 11:47:22:860 folderman.cpp:445 Schedule folder "Docs" to sync! 10-09 11:47:22:860 folderman.cpp:462 II> Sync for folder "Docs" already scheduled, do not enqueue!

Let me know what to look for and I'll try to post it here.

[ckamm]

@kaplandani Thanks for checking, that means what happens is:

0. You have two sync folders, Work and Doc
1. Work is synced (takes > 5 min)
2. In the middle of the Work sync, the Doc force-sync timeout expires and Doc is scheduled
3. Once Work finishes syncing, Doc is started (takes > 5 min)
4. In the middle of the Doc sync, the Work force-sync timeout expires and Work is scheduled
5. Once Doc finishes, goto 1.

The main issue shouldn't be that we're triggering a sync every 5 minutes per folder, but rather that it takes more than a couple of seconds when there shouldn't be anything that needs to be done.

Does the message 'owncloudgui.cpp:177 Sync state changed for folder "Work" ...' now report success instead of error? Can you give us a hint about what the client is doing during the syncs?

[kaplandani]

The client does nothing... I'm reading a pdf :-) or even if it left alone, it still does it. (and in more than one computer) Instead of being triggered by a changes it does a full scan every time. (I removed the errors by deleting the problem folders)

[ckamm]

@kaplandani I don't understand what you're saying. :)

1. Do the syncs of Work and Doc finish with success or error?
2. Is the client doing uploads/downloads during the sync phase? Why is it taking > 5 minutes?

[kaplandani]

@ckamm I have 2 computers I'm using to try the 1.7.0 client. Current situation - both "sync" forever.

the first client has 2 folder syncing. it used to have an error in one of them. the error triggered full discovery again and again - it took more than 4 min. meanwhile - the time for the 2nd folder to be sync arrived thus it was working all the time.

the 2nd client has 1 folder with no errors. It also remains in discovery forever.

While the 1st client had an error - I can see using --logdir flag, that a new sync was triggered every 4 min- generating a new log file.

once I removed the errors, it remains in discovery mode the entire time. it never finish and the log just gets bigger and bigger every round.

The expected behavior would have - full discovery once, than waiting for a change and dealing only with the change.

[ckamm]

@kaplandani

Current situation - both "sync" forever.

So you have two computers syncing against the same oC server? Does this happen if only one client is running at a time?

the 2nd client has 1 folder with no errors. It also remains in discovery forever.

Are you saying that the sync never finishes or that it finishes and starts again immediately afterwards?

To summarize: One of your clients has only 1 sync folder. It runs a sync and that takes several minutes. When the sync finishes, it's restarted immediately.

Is that correct? Is the client actually doing uploads/downloads during the sync phase?

[kaplandani]

@ckamm I have 2 clients syncing against the same server - with different accounts.

currently there are no errors, and all the client do is run through the "ignored" files again and again and again.

Both client are running discovery all the time now, and there is nothing to sync. so no file gets uploaded or downloaded. just constant discovery. If I change a file it would be uploaded, but then we're back to discovering.....

(btw - I do turn them off now, as they consume too much of the cpu forever).

[ckamm]

@kaplandani Okay! So there's no delay between two sync runs even though there were no errors. That is odd!

Here are some more questions (thanks for persisting): 1) We don't understand why your sync run takes so long when there's nothing to do. Could you get me the logfile lines starting with "CSync run took", "Update detection for local replica took" and "Update detection for remote replica took"?

2) I don't know why your sync runs are running back-to-back. Could you check for lines with "detected changes in folders"? And the "Force Sync" lines too, if you're using the latest nightly.

[kaplandani]

First occurrence:

10-09 16:31:40:173 syncjournaldb.cpp:1054 Transaction Start "All Finished." 10-09 16:31:40:692 syncengine.cpp:789 CSync run took 10889 10-09 16:31:40:695 folder.cpp:694 -> CSync Finished slot with error false warn count 1 10-09 16:31:40:697 folder.cpp:394 Processing result list and logging took 0 Milliseconds. 10-09 16:31:40:697 folder.cpp:414 OO folder slotSyncFinished: result: 3 10-09 16:31:40:756 owncloudgui.cpp:260 Folder in overallStatus Message: Mirall::Folder(0x4fe7c00) with name "Work" 10-09 16:31:40:756 owncloudgui.cpp:260 Folder in overallStatus Message: Mirall::Folder(0x7425550) with name "Docs" 10-09 16:31:40:757 owncloudgui.cpp:177 Sync state changed for folder "Docs" : "Success, some files were ignored." 10-09 16:31:40:958 folderman.cpp:538 <===================================== sync finished for "Docs" 10-09 16:31:41:158 folderman.cpp:502 XX slotScheduleFolderSync: folderQueue size: 2 10-09 16:31:41:158 clientproxy.cpp:106 Passing NO proxy to csync for "https://myserver.com/cloud" 10-09 16:31:41:208 owncloudgui.cpp:260 Folder in overallStatus Message: Mirall::Folder(0x4fe7c00) with name "Work" 10-09 16:31:41:208 owncloudgui.cpp:260 Folder in overallStatus Message: Mirall::Folder(0x7425550) with name "Docs" 10-09 16:31:41:210 owncloudgui.cpp:177 Sync state changed for folder "Work" : "SyncPrepare" 10-09 16:31:41:210 folder.cpp:611 ** Start syncing - client version 1.7.0 10-09 16:31:41:210 folder.cpp:555 ==== added system ignore list to csync: "C:/Program Files (x86)/ownCloud/sync-exclude.lst" 10-09 16:31:41:210 csync_exclude_load: Adding entry: .filepart

Next one (there was one file upload from work which is correct)

10-09 16:33:55:720 folderman.cpp:462 II> Sync for folder "Work" already scheduled, do not enqueue! 10-09 16:33:56:350 syncjournaldb.cpp:1054 Transaction Start "All Finished." 10-09 16:33:56:445 syncengine.cpp:789 CSync run took 135225 10-09 16:33:56:478 folder.cpp:694 -> CSync Finished slot with error false warn count 0 10-09 16:33:56:480 folder.cpp:394 Processing result list and logging took 0 Milliseconds. 10-09 16:33:56:480 folder.cpp:414 OO folder slotSyncFinished: result: 3 10-09 16:33:56:585 owncloudgui.cpp:260 Folder in overallStatus Message: Mirall::Folder(0x4fe7c00) with name "Work" 10-09 16:33:56:585 owncloudgui.cpp:260 Folder in overallStatus Message: Mirall::Folder(0x7425550) with name "Docs" 10-09 16:33:56:586 owncloudgui.cpp:177 Sync state changed for folder "Work" : "Success, some files were ignored." 10-09 16:33:56:788 folderman.cpp:538 <===================================== sync finished for "Work" 10-09 16:33:56:988 folderman.cpp:502 XX slotScheduleFolderSync: folderQueue size: 2 10-09 16:33:56:988 clientproxy.cpp:106 Passing NO proxy to csync for "https://myserver.com/cloud" 10-09 16:33:57:019 owncloudgui.cpp:260 Folder in overallStatus Message: Mirall::Folder(0x4fe7c00) with name "Work" 10-09 16:33:57:019 owncloudgui.cpp:260 Folder in overallStatus Message: Mirall::Folder(0x7425550) with name "Docs" 10-09 16:33:57:021 owncloudgui.cpp:177 Sync state changed for folder "Docs" : "SyncPrepare" 10-09 16:33:57:021 folder.cpp:611 ** Start syncing - client version 1.7.0 10-09 16:33:57:021 folder.cpp:555 ==== added system ignore list to csync: "C:/Program Files (x86)/ownCloud/sync-exclude.lst" 10-09 16:33:57:021 csync_exclude_load: Adding entry: .filepart

Next one:

10-09 16:34:06:169 syncjournaldb.cpp:1054 Transaction Start "All Finished." 10-09 16:34:06:750 syncengine.cpp:789 CSync run took 9724 10-09 16:34:06:755 folder.cpp:694 -> CSync Finished slot with error false warn count 1 10-09 16:34:06:758 folder.cpp:394 Processing result list and logging took 0 Milliseconds. 10-09 16:34:06:758 folder.cpp:414 OO folder slotSyncFinished: result: 3 10-09 16:34:06:804 owncloudgui.cpp:260 Folder in overallStatus Message: Mirall::Folder(0x4fe7c00) with name "Work" 10-09 16:34:06:804 owncloudgui.cpp:260 Folder in overallStatus Message: Mirall::Folder(0x7425550) with name "Docs" 10-09 16:34:06:806 owncloudgui.cpp:177 Sync state changed for folder "Docs" : "Success, some files were ignored." 10-09 16:34:07:006 folderman.cpp:538 <===================================== sync finished for "Docs" 10-09 16:34:07:206 folderman.cpp:502 XX slotScheduleFolderSync: folderQueue size: 2 10-09 16:34:07:206 clientproxy.cpp:106 Passing NO proxy to csync for "https://myserver.com/cloud" 10-09 16:34:07:242 owncloudgui.cpp:260 Folder in overallStatus Message: Mirall::Folder(0x4fe7c00) with name "Work" 10-09 16:34:07:242 owncloudgui.cpp:260 Folder in overallStatus Message: Mirall::Folder(0x7425550) with name "Docs" 10-09 16:34:07:243 owncloudgui.cpp:177 Sync state changed for folder "Work" : "SyncPrepare" 10-09 16:34:07:243 folder.cpp:611 ** Start syncing - client version 1.7.0 10-09 16:34:07:243 folder.cpp:555 ==== added system ignore list to csync: "C:/Program Files (x86)/ownCloud/sync-exclude.lst" 10-09 16:34:07:244 csync_exclude_load: Adding entry: .filepart

Next one:

10-09 16:36:14:245 syncjournaldb.cpp:1054 Transaction Start "All Finished." 10-09 16:36:20:185 syncengine.cpp:789 CSync run took 132930 10-09 16:36:20:215 folderman.cpp:492 Currently folder "Work" is running, wait for finish! 10-09 16:36:20:220 folderwatcher.cpp:153 detected changes in folders: QSet("Y:\Work/") 10-09 16:36:20:220 folderman.cpp:445 Schedule folder "Work" to sync! 10-09 16:36:20:220 folderman.cpp:462 II> Sync for folder "Work" already scheduled, do not enqueue! 10-09 16:36:20:237 folder.cpp:694 -> CSync Finished slot with error false warn count 1 10-09 16:36:20:240 folder.cpp:394 Processing result list and logging took 0 Milliseconds. 10-09 16:36:20:240 folder.cpp:414 OO folder slotSyncFinished: result: 3 10-09 16:36:20:350 owncloudgui.cpp:260 Folder in overallStatus Message: Mirall::Folder(0x4fe7c00) with name "Work" 10-09 16:36:20:350 owncloudgui.cpp:260 Folder in overallStatus Message: Mirall::Folder(0x7425550) with name "Docs" 10-09 16:36:20:352 owncloudgui.cpp:177 Sync state changed for folder "Work" : "Success, some files were ignored." 10-09 16:36:20:553 folderman.cpp:538 <===================================== sync finished for "Work" 10-09 16:36:20:753 folderman.cpp:502 XX slotScheduleFolderSync: folderQueue size: 2 10-09 16:36:20:811 owncloudgui.cpp:260 Folder in overallStatus Message: Mirall::Folder(0x4fe7c00) with name "Work" 10-09 16:36:20:811 owncloudgui.cpp:260 Folder in overallStatus Message: Mirall::Folder(0x7425550) with name "Docs" 10-09 16:36:20:813 owncloudgui.cpp:177 Sync state changed for folder "Docs" : "SyncPrepare" 10-09 16:36:20:813 folder.cpp:611 ** Start syncing - client version 1.7.0 10-09 16:36:20:813 folder.cpp:555 ==== added system ignore list to csync: "C:/Program Files (x86)/ownCloud/sync-exclude.lst" 10-09 16:36:20:813 csync_exclude_load: Adding entry: .filepart

Update Detection: 10-09 16:31:37:537 csync_ftw: <= Closing walk for Y:\Docs with read_from_db 0 10-09 16:31:37:538 csync_update: Update detection for local replica took 7.71 seconds walking 8001 files.

10-09 16:31:39:525 csync_update: Update detection for remote replica took 1.99 seconds walking 7997 files.

10-09 16:33:21:028 csync_ftw: <= Closing walk for Y:\Work with read_from_db 0 10-09 16:33:21:028 csync_update: Update detection for local replica took 99.51 seconds walking 105435 files. 10-09 16:33:37:682 csync_update: Update detection for remote replica took 16.65 seconds walking 105270 files.

10-09 16:34:04:454 csync_ftw: <= Closing walk for Y:\Docs with read_from_db 0 10-09 16:34:04:454 csync_update: Update detection for local replica took 7.41 seconds walking 8001 files. 10-09 16:34:05:535 csync_update: Update detection for remote replica took 1.08 seconds walking 7997 files.

10-09 16:35:45:914 csync_ftw: <= Closing walk for Y:\Work with read_from_db 0 10-09 16:35:45:914 csync_update: Update detection for local replica took 98.36 seconds walking 105435 files. 0-09 16:36:02:519 csync_update: Update detection for remote replica took 16.61 seconds walking 105270 files.

10-09 16:36:28:274 csync_ftw: <= Closing walk for Y:\Docs with read_from_db 0 10-09 16:36:28:274 csync_update: Update detection for local replica took 7.43 seconds walking 8001 files. 10-09 16:36:31:809 csync_update: Update detection for remote replica took 3.54 seconds walking 7997 files.

Detected Changes:

10-09 16:31:29:802 syncengine.cpp:590 #### Discovery start #################################################### >> 10-09 16:31:29:802 csync_update: Journal: Y:\Docs/.csync_journal.db 10-09 16:31:29:807 folderwatcher.cpp:153 detected changes in folders: QSet("Y:\Docs/") 10-09 16:31:29:807 folderman.cpp:445 Schedule folder "Docs" to sync! 10-09 16:31:29:826 csync_walker: file: Y:\Docs/.owncloudsync.log [inode=2942 size=58609] 10-09 16:31:29:826 _csync_detect_update: .owncloudsync.log excluded (1) 10-09 16:31:29:826 csync_walker: file: Y:\Docs/.owncloudsync.log.1 [inode=2995 size=1154720] 10-09 16:31:29:826 _csync_detect_update: .owncloudsync.log.1 excluded (1)

10-09 16:31:29:856 folderwatcher.cpp:153 detected changes in folders: QSet("Y:\Work/") 10-09 16:31:29:856 _csync_detect_update: file: Beer Sheva/Bank/20140120_113508.jpg, instruction: INSTRUCTION_NONE <<= 10-09 16:31:29:856 folderman.cpp:445 Schedule folder "Work" to sync! 10-09 16:31:29:856 folderman.cpp:462 II> Sync for folder "Work" already scheduled, do not enqueue!

10-09 16:31:39:932 syncjournaldb.cpp:457 "INSERT OR REPLACE INTO metadata (phash, pathlen, path, inode, uid, gid, mode, modtime, type, md5, fileid, remotePerm) VALUES ( ? , ?, ? , ? , ? , ? , ?, ? , ? , ?, ?, ? )" 800207035614717576 6 "BackUp" 7925 0 "1411823782" "2" "5426b8a6a0ad3" "00000021oc2833a28ce5" "RDNVCK" 10-09 16:31:39:937 folderwatcher.cpp:153 detected changes in folders: QSet("Y:\Docs/") 10-09 16:31:39:937 folderman.cpp:445 Schedule folder "Docs" to sync! 10-09 16:31:39:937 folderman.cpp:462 II> Sync for folder "Docs" already scheduled, do not enqueue!

10-09 16:31:41:536 _csync_detect_update: file: MyPAth/2010.xls, instruction: INSTRUCTION_NONE <<= 10-09 16:31:41:536 folderwatcher.cpp:153 detected changes in folders: QSet("Y:\Work/") 10-09 16:31:41:536 folderman.cpp:445 Schedule folder "Work" to sync!

10-09 16:33:44:520 syncjournaldb.cpp:457 "INSERT OR REPLACE INTO metadata (phash, pathlen, path, inode, uid, gid, mode, modtime, type, md5, fileid, remotePerm) VALUES ( ? , ?, ? , ? , ? , ? , ?, ? , ? , ?, ?, ? )" -3357646258756843905 78 "MYPATH/Android/AuthDemo/.metadata/.plugins/org.eclipse.core.resources/.history/ce" 135016 0 "1412113592" "2" "542b24b88acd7" "00068964oc2833a28ce5" "RDNVCK" 10-09 16:33:44:533 folderwatcher.cpp:153 detected changes in folders: QSet("Y:\Work/") 10-09 16:33:44:534 folderman.cpp:445 Schedule folder "Work" to sync! 10-09 16:33:44:534 folderman.cpp:462 II> Sync for folder "Work" already scheduled, do not enqueue!

10-09 16:33:45:894 syncjournaldb.cpp:457 "INSERT OR REPLACE INTO metadata (phash, pathlen, path, inode, uid, gid, mode, modtime, type, md5, fileid, remotePerm) VALUES ( ? , ?, ? , ? , ? , ? , ?, ? , ? , ?, ?, ? )" 1142055833011848510 40 "MyPath2/ResellerMgr.Web" 195835 0 "1412210301" "2" "542c9e7e2dddb" "00166582oc2833a28ce5" "RDNVCK" 10-09 16:33:45:908 folderwatcher.cpp:153 detected changes in folders: QSet("Y:\Work/") 10-09 16:33:45:908 folderman.cpp:445 Schedule folder "Work" to sync! 10-09 16:33:45:908 folderman.cpp:462 II> Sync for folder "Work" already scheduled, do not enqueue!

10-09 16:33:48:091 syncjournaldb.cpp:457 "INSERT OR REPLACE INTO metadata (phash, pathlen, path, inode, uid, gid, mode, modtime, type, md5, fileid, remotePerm) VALUES ( ? , ?, ? , ? , ? , ? , ?, ? , ? , ?, ?, ? )" 5701023862082636381 66 "Old Projects/Project/website - Copy/tmpChen/tvgSite/tvgSite/Scripts" 57895 0 "1412283890" "2" "542dbdf2c9821" "00212319oc2833a28ce5" "RDNVCK" 10-09 16:33:48:100 folderwatcher.cpp:153 detected changes in folders: QSet("Y:\Work/") 10-09 16:33:48:100 folderman.cpp:445 Schedule folder "Work" to sync! 10-09 16:33:48:100 folderman.cpp:462 II> Sync for folder "Work" already scheduled, do not enqueue!

and so on... No Force sync.

[ckamm]

@kaplandani Awesome! There was a bugfix in 1.7 that should stop the discovery phase triggering itself.

And about your discovery phase taking long: it looks like we need about 100s to go through 100k local files, i.e. about 1 ms per file. That sounds slow and there may be room for optimization, see #880.

[kaplandani]

@ckamm and I'm running SSD, on regular HDD It will be worse.... When will the bugfix you've mentioned will be addressed ?

[MU7L3Y]

I've also just installed 1.7.0 beta 3 yesterday and find that it constantly is in discovery mode and just says "Preparing to Sync." It's constantly using 13% CPU as well but sometimes jumping. No files are being downloaded or uploaded. If there's anything I can do to help I will try. Let me know.

OC server is 7.0.2. Sync folder is about 2.3GB. I have 2 clients running with the same account. One client is on Win7 x64, the other Win Server 2003. The Server 2003 client seems to sync it's folders as they are all set up as separate folders to sync, whereas the Win7 PC is just syncing the whole ownCloud folder.

[ckamm]

@kaplandani @MU7L3Y Could I ask you to test again with the latest nightly, i.e. http://download.owncloud.com/desktop/daily/ownCloud-1.7.0.3963-nightly20141010-setup.exe ? We think the issue was related to file change notifications during the sync triggering a new sync.

[MU7L3Y]

@ckamm I have installed that version and now it completes and says "Sync Success". CPU usage also drops to 0 at that time which is good. Seems much better, thanks.

[enoch85]

@ckamm Confirmed. Now it works as close to expected as possible. Only thing is high CPU load when discovering, or right before a sync starts. And by "high CPU load" I mean high like in "not responding" anymore. That should really be addressed properly. CPU is down to between 0-5% between syncjobs.

It also have high CPU load when browsing the files in Windows, but that´s another issue. :)

Otherwise OK. :+1: The constant loop is gone

[ckamm]

Thanks for testing!

[kaplandani]

3963 does look better, discovering occurred 3 times (strange) but then stopped.. :-) will monitor it for a while.

[kaplandani]

@ckamm Should the client go into full discovery every few minutes ? 3963 does that. it's much better than before as the client "rests" between them, but still, a full 1 min discovery happens every few minutes.

[ckamm]

@kaplandani Yes, unfortunately there are a couple of corner cases (related to the file watcher as far as I know) that can make the client not know that there are files that need to be synced. I agree that in an ideal world we'd only need one full discovery run.

[moscicki]

Hi,

How frequent these corner cases are and under which conditions they appear for the file watcher?

AFAIK the inotify may miss some events if it's buffer gets full due to high spikes of events at high rates. But that's rather rare and that possibly could be detected by the client (if you see too many events in a unit of time you may suspect that some have been lost and trigger a full scan). Can something like that be done for the cases with file watcher missing events?

I think a plausible option in the interim is to have a lower scan rate and possibly make the "Retry sync" button to be available to the user all the time. Like that if something is missed a user may trigger the sync.

kuba

On Oct 10, 2014, at 10:28 AM, ckamm notifications@github.com wrote:

@kaplandani Yes, unfortunately there are a couple of corner cases (related to the file watcher as far as I know) that can make the client not know that there are files that need to be synced. I agree that in an ideal world we'd only need one full discovery run.

— Reply to this email directly or view it on GitHub.

[ckamm]

I agree that it would be excellent to improve on this. The case that @dragotin mentioned was related to file change notifications we get during a sync:

We're performing write operations on sync folders during the sync phase. That triggers file watcher notifications. But we want to ignore these because they don't mean another sync is needed. Right now, we ignore all file watcher notifications for a folder while it is synced. That can make us miss files that were added while the sync was running until the next full discovery phase comes up.

This particular case can maybe be solved by looking at the file change notifications we get in detail and ignoring the ones we know we caused ourselves. I'm not sure whether there are other reasons to run the discovery phase this often. @guruz @ogoffart ?

[dragotin]

The problem with the filewatcher is that we can not distinguish between changes that the client did because of sync activity (we don't wanna react on) and events that were triggered due to external events, which would be important. That is because cross platform the file system notifications are very different, and in this case, linux is the worst... Yes, that is a technical debt, and we will revisit that.

[moscicki]

Another idea (which may have some other implications, though):

What about keeping temporary download files in a separate folder (one level down from the sync journal?). It is then confided to a single tree and notifications may be easier to filter out.

A bonus of this approach is that a user would never see this partial download crap in their directories. Of course you'd need to uniquify the tmp download file names but you can do whatever you want since you keep the download state in the sync journal…

One would have to see what to do in case of directory move or rename - your partially downloaded files would not correspond to the original directory anymore. But if you can detect this then you may simply trigger a full redownload. These are rare corner cases (interrupted download, directory manipulation, resumed download)….

kuba

On Oct 10, 2014, at 12:04 PM, Klaas Freitag notifications@github.com wrote:

The problem with the filewatcher is that we can not distinguish between changes that the client did because of sync activity (we don't wanna react on) and events that were triggered due to external events, which would be important. That is because cross platform the file system notifications are very different, and in this case, linux is the worst... Yes, that is a technical debt, and we will revisit that.

— Reply to this email directly or view it on GitHub.

[enoch85]

How does other cloud-services solve the problem?

[ckamm]

I suggest we move the discussion to the enhancement ticket #2297.