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

Quick change in folder hierarchy causes sync errors #6694

Closed
jnweiger opened this issue Aug 6, 2018 · 7 comments
Closed

Quick change in folder hierarchy causes sync errors #6694

jnweiger opened this issue Aug 6, 2018 · 7 comments
Assignees
@ogoffart
Labels
ReadyToTest QA, please validate the fix/enhancement
Milestone
2.6.0

Comments

@jnweiger
Copy link
Contributor

jnweiger commented Aug 6, 2018 •
edited
Loading

Revert the hierarchy of two enabled folders quickly

  • web interface: create an empty folder in Documents called Empty.
  • owncloud client: Enable only Documents/Empty
  • mv Documents/Empty . ; mv Documents Empty

BAD:
Error message in client log
6 Aug 2018 15:22:36, Documents/Empty, testpilotcloud2,Error transferring https://demo.owncloud.org/remote.php/dav/files/demo/Empty/Documents/Empty - server replied:

grafik

Error message in server log

{"reqId":"fd27578c-dd20-4954-a8b1-9cab2c8bb3cb","level":2,"time":"2018-08-06T13:14:29+00:00","remoteAddr":"192.168.48.16","user":"demo","app":"dav","method":"MOVE","url":"\/remote.php\/dav\/files\/demo\/Empty\/Documents\/Empty","message":"Could not get node for path: \"files\/demo\/Empty\/Documents\/Empty\" : File with name Empty\/Documents\/Empty could not be located"}
{"reqId":"27ac4e76-b8ea-47bf-b826-414a1a85b84f","level":2,"time":"2018-08-06T13:14:44+00:00","remoteAddr":"192.168.48.16","user":"demo","app":"dav","method":"MOVE","url":"\/remote.php\/dav\/files\/demo\/Empty\/Documents\/Empty","message":"Could not get node for path: \"files\/demo\/Empty\/Documents\/Empty\" : File with name Empty\/Documents\/Empty could not be located"}
{"reqId":"22e1bf9f-3922-47b6-a881-559904da1d8d","level":2,"time":"2018-08-06T13:14:58+00:00","remoteAddr":"192.168.48.16","user":"demo","app":"dav","method":"MOVE","url":"\/remote.php\/dav\/files\/demo\/Empty\/Documents\/Empty","message":"Could not get node for path: \"files\/demo\/Empty\/Documents\/Empty\" : File with name Empty\/Documents\/Empty could not be located"}

Almost good:
Do the same slowly

  • mv Documents/Empty . ; sleep 10; mv Documents Empty # sufficient sleep so that a sync run completes.
    Syncs without errors, but the new toplevel folder called "Empty" is reported with (0B), which is no longer correct, as the Empty/Documents folder contains ca. 35Kb
    grafik
@jnweiger jnweiger mentioned this issue Aug 6, 2018
Closed
@jnweiger jnweiger changed the title Quick change in hierarchy causes sync errors Quick change in folder hierarchy causes sync errors Aug 6, 2018
@jnweiger
Copy link
Contributor Author

jnweiger commented Aug 6, 2018

Moving the folders back into their original hierarchy, resolves the error state:
mv Empty/Documents .; mv Empty Documents

@ogoffart ogoffart self-assigned this Aug 7, 2018
@ogoffart ogoffart added this to the 2.5.0 milestone Aug 7, 2018
ogoffart added a commit that referenced this issue Aug 7, 2018
@ogoffart
SyncEngine: Fix renmaes making hierarchy inversion
edbaeb1 
Issue #6694
@ogoffart ogoffart mentioned this issue Aug 7, 2018
Merged
ogoffart added a commit that referenced this issue Aug 9, 2018
@ogoffart
SyncEngine: Fix renames making hierarchy inversion
ef285eb 
Issue #6694
@guruz guruz added the ReadyToTest QA, please validate the fix/enhancement label Aug 10, 2018
ckamm pushed a commit that referenced this issue Aug 16, 2018
@ogoffart @ckamm
SyncEngine: Fix renames making hierarchy inversion
776eb29 
Issue #6694
ckamm pushed a commit that referenced this issue Aug 16, 2018
@ogoffart @ckamm
SyncEngine: Fix renames making hierarchy inversion
4a3fce5 
Issue #6694
@ckamm
Copy link
Contributor

ckamm commented Aug 16, 2018

@ogoffart Should there be a ticket to track the larger underlying problem?

@jnweiger
Copy link
Contributor Author

jnweiger commented Aug 16, 2018 •
edited
Loading

Linux Mint tara; testpilotcloud-client-2.5.0daily20181016

@ckamm is your fix merged in the 2.5 branch already?
grafik

BAD
Looks still the same here. -> Not ready. Removing ReadytoTest Label.

Debug window says

08-16 16:40:13:298 [ info gui.folderwatcher ]:	Detected changes in paths: QSet("/home/testy/testpilotcloud/Documents/Empty")
08-16 16:40:13:299 [ warning sync.filesystem ]:	Could not get modification time for "/home/testy/testpilotcloud/Documents/Empty" with csync, using QFileInfo
08-16 16:40:13:299 [ info gui.folderwatcher ]:	Detected changes in paths: QSet("/home/testy/testpilotcloud/Empty")
08-16 16:40:13:302 [ info gui.folderwatcher ]:	Detected changes in paths: QSet("/home/testy/testpilotcloud/Documents")
08-16 16:40:13:302 [ warning sync.filesystem ]:	Could not get modification time for "/home/testy/testpilotcloud/Documents" with csync, using QFileInfo
08-16 16:40:13:302 [ info gui.folderwatcher ]:	Detected changes in paths: QSet("/home/testy/testpilotcloud/Documents/Empty/Documents")
08-16 16:40:15:348 [ info gui.folder.manager ]:	Schedule folder  "2"  to sync!
08-16 16:40:15:348 [ info gui.application ]:	Sync state changed for folder  "https://demo.owncloud.org/remote.php/dav/files/demo/" :  "Not yet Started"
08-16 16:40:15:349 [ info sync.accessmanager ]:	2 "" "https://demo.owncloud.org/ocs/v2.php/apps/notifications/api/v1/notifications?format=json" has X-Request-ID "86d4d3a8-aea3-4435-b92e-934f7790f24a"
08-16 16:40:15:351 [ info sync.networkjob ]:	OCC::JsonApiJob created for "https://demo.owncloud.org" + "ocs/v2.php/apps/notifications/api/v1/notifications" "OCC::ServerNotificationHandler"
08-16 16:40:15:352 [ info gui.folder.manager ]:	Starting the next scheduled sync in 0 seconds
08-16 16:40:15:359 [ info gui.application ]:	Sync state changed for folder  "https://demo.owncloud.org/remote.php/dav/files/demo/" :  "SyncPrepare"
08-16 16:40:15:359 [ info gui.folder ]:	*** Start syncing  "https://demo.owncloud.org/remote.php/dav/files/demo/"  - client version 2.5.0daily20180816 (build 10075)
08-16 16:40:15:363 [ info gui.folder ]:	Allowing local discovery to read from the database
08-16 16:40:15:364 [ info gui.folder.manager ]:	>========== Sync started for folder [testpilotcloud] of account [[email protected]] with remote [https://demo.owncloud.org/remote.php/dav/files/demo/]
08-16 16:40:15:364 [ info sync.engine ]:	There are 492690837504 bytes available at "/home/testy/testpilotcloud/"
08-16 16:40:15:364 [ info sync.engine ]:	Sync with existing sync journal
08-16 16:40:15:366 [ info sync.engine ]:	"Using Qt 5.10.1 SSL library OpenSSL 1.0.2n  7 Dec 2017 on Linux Mint 19"
08-16 16:40:15:367 [ info sync.engine ]:	Using Selective Sync
08-16 16:40:15:368 [ info sync.engine ]:	#### Discovery start ####################################################
08-16 16:40:15:369 [ info sync.engine ]:	Server "10.0.9.5" Using HTTP/2
08-16 16:40:15:370 [ info sync.csync.utils ]:	Memory: 959536K total size, 74228K resident, 51232K shared
08-16 16:40:15:370 [ info sync.csync.csync ]:	## Starting local discovery ##
08-16 16:40:15:370 [ info sync.csync.updater ]:	Checking for rename based on inode # 8257636
08-16 16:40:15:370 [ info sync.csync.updater ]:	pot rename detected based on inode # 8257636
08-16 16:40:15:370 [ info sync.csync.updater ]:	file: Empty, instruction: INSTRUCTION_EVAL_RENAME <<=
08-16 16:40:15:371 [ info sync.csync.updater ]:	Checking for rename based on inode # 8257557
08-16 16:40:15:371 [ info sync.csync.updater ]:	pot rename detected based on inode # 8257557
08-16 16:40:15:371 [ info sync.csync.updater ]:	file: Empty/Documents, instruction: INSTRUCTION_EVAL_RENAME <<=
08-16 16:40:15:371 [ info sync.csync.updater ]:	0 entries read below path Empty/Documents from db.
08-16 16:40:15:371 [ info sync.csync.updater ]:	 <= Closing walk for /home/testy/testpilotcloud/Empty with read_from_db 0
08-16 16:40:15:371 [ info sync.csync.updater ]:	.owncloudsync.log excluded  (1)
08-16 16:40:15:371 [ info sync.csync.updater ]:	._sync_f3502dd50375.db-wal excluded  (1)
08-16 16:40:15:371 [ info sync.csync.updater ]:	._sync_f3502dd50375.db excluded  (1)
08-16 16:40:15:371 [ info sync.csync.updater ]:	Database entry found, compare: 1534428143 <-> 1534428143, etag:  <-> c0faf852cf7b33ca92a25f256265a945, inode: 41028281 <-> 41028281, size: 4917168 <-> 4917168, perms: 0 <-> 9f, type: 0 <-> 0, checksum:  <-> SHA1:43956b5b12d8a7bb14463c672ee2e3ec5110fd75, ignore: 0
08-16 16:40:15:371 [ info sync.csync.updater ]:	file: ownCloud Manual.pdf, instruction: INSTRUCTION_NONE <<=
08-16 16:40:15:372 [ info sync.csync.updater ]:	._sync_f3502dd50375.db-shm excluded  (1)
08-16 16:40:15:372 [ info sync.csync.updater ]:	 <= Closing walk for /home/testy/testpilotcloud with read_from_db 0
08-16 16:40:15:372 [ info sync.csync.csync ]:	Update detection for local replica took 0.001 seconds walking 3 files
08-16 16:40:15:372 [ info sync.csync.utils ]:	Memory: 959536K total size, 74228K resident, 51232K shared
08-16 16:40:15:372 [ info sync.csync.csync ]:	## Starting remote discovery ##
08-16 16:40:15:377 [ info sync.accessmanager ]:	6 "PROPFIND" "https://demo.owncloud.org/remote.php/dav/files/demo/" has X-Request-ID "71a184bf-fdbd-4a2c-8187-b7aa6eb27fec"
08-16 16:40:15:377 [ info sync.networkjob ]:	OCC::LsColJob created for "https://demo.owncloud.org" + "" "OCC::DiscoverySingleDirectoryJob"
08-16 16:40:15:487 [ info sync.networkjob.jsonapi ]:	JsonApiJob of QUrl("https://demo.owncloud.org/ocs/v2.php/apps/notifications/api/v1/notifications?format=json") FINISHED WITH STATUS "OK"
08-16 16:40:15:523 [ info sync.networkjob.lscol ]:	LSCOL of QUrl("https://demo.owncloud.org/remote.php/dav/files/demo/") FINISHED WITH STATUS "OK"
08-16 16:40:15:524 [ info sync.csync.updater ]:	Database entry found, compare: 1534429756 <-> 1534429756, etag: 5b758a3d05e88 <-> 5b758a3d05e88, inode: 0 <-> 8257557, size: 0 <-> 0, perms: fd <-> fd, type: 2 <-> 2, checksum:  <-> , ignore: 0
08-16 16:40:15:524 [ info sync.csync.updater ]:	Reading from database: Documents
08-16 16:40:15:524 [ info sync.csync.updater ]:	file: Documents, instruction: INSTRUCTION_NONE <<=
08-16 16:40:15:524 [ info sync.csync.updater ]:	2 entries read below path Documents from db.
08-16 16:40:15:525 [ info sync.csync.updater ]:	Database entry found, compare: 1534428143 <-> 1534428143, etag: c0faf852cf7b33ca92a25f256265a945 <-> c0faf852cf7b33ca92a25f256265a945, inode: 0 <-> 41028281, size: 4917168 <-> 4917168, perms: 9f <-> 9f, type: 0 <-> 0, checksum: SHA1:43956b5b12d8a7bb14463c672ee2e3ec5110fd75 <-> SHA1:43956b5b12d8a7bb14463c672ee2e3ec5110fd75, ignore: 0
08-16 16:40:15:525 [ info sync.csync.updater ]:	file: ownCloud Manual.pdf, instruction: INSTRUCTION_NONE <<=
08-16 16:40:15:525 [ info sync.csync.updater ]:	 <= Closing walk for  with read_from_db 0
08-16 16:40:15:525 [ info sync.csync.csync ]:	Update detection for remote replica took 0.152 seconds walking 4 files
08-16 16:40:15:525 [ info sync.csync.utils ]:	Memory: 959536K total size, 74228K resident, 51232K shared
08-16 16:40:15:531 [ info sync.engine ]:	#### Discovery end ####################################################  163 ms
08-16 16:40:15:532 [ info sync.csync.reconciler ]:	Finding rename origin through inode 8257636
08-16 16:40:15:532 [ info sync.csync.reconciler ]:	Rename origin in other tree (Documents/Empty) found
08-16 16:40:15:533 [ info sync.csync.reconciler ]:	Switching Documents/Empty to RENAME to Empty
08-16 16:40:15:533 [ info sync.csync.reconciler ]:	Finding rename origin through inode 8257557
08-16 16:40:15:534 [ info sync.csync.reconciler ]:	Rename origin in other tree (Documents) found
08-16 16:40:15:534 [ info sync.csync.reconciler ]:	Switching Documents to RENAME to Empty/Documents
08-16 16:40:15:535 [ info sync.csync.csync ]:	Reconciliation for local replica took  0.003 seconds visiting  3  files.
08-16 16:40:15:535 [ info sync.csync.reconciler ]:	INSTRUCTION_REMOVE             server file: Documents/Example.odt
08-16 16:40:15:535 [ info sync.csync.reconciler ]:	INSTRUCTION_RENAME             server dir:  Documents/Empty
08-16 16:40:15:536 [ info sync.csync.reconciler ]:	INSTRUCTION_RENAME             server dir:  Documents
08-16 16:40:15:536 [ info sync.csync.csync ]:	Reconciliation for remote replica took  0 seconds visiting  4  files.
08-16 16:40:15:536 [ info sync.engine ]:	#### Reconcile end ####################################################  168 ms
08-16 16:40:15:536 [ info sync.engine ]:	Permissions of the root folder:  "DNVCKR"
08-16 16:40:15:537 [ info sync.engine ]:	#### Post-Reconcile end ####################################################  169 ms
08-16 16:40:15:537 [ info gui.folder ]:	#### Propagation start ####################################################
08-16 16:40:15:538 [ info gui.application ]:	Sync state changed for folder  "https://demo.owncloud.org/remote.php/dav/files/demo/" :  "Sync Running"
08-16 16:40:15:542 [ info sync.propagator ]:	Starting INSTRUCTION_RENAME propagation of "Empty/Documents/Empty" by OCC::PropagateRemoteMove(0x558c888f02c0)
08-16 16:40:15:542 [ info sync.accessmanager ]:	6 "MOVE" "https://demo.owncloud.org/remote.php/dav/files/demo/Empty/Documents/Empty" has X-Request-ID "ba99ceee-be14-4418-8718-219dd4eb7cea"
08-16 16:40:15:543 [ info sync.networkjob ]:	OCC::MoveJob created for "https://demo.owncloud.org" + "/Empty/Documents/Empty" "OCC::PropagateRemoteMove"
08-16 16:40:15:638 [ warning sync.networkjob ]:	QNetworkReply::NetworkError(ContentNotFoundError) "Error transferring https://demo.owncloud.org/remote.php/dav/files/demo/Empty/Documents/Empty - server replied: " QVariant(int, 404)
08-16 16:40:15:639 [ info sync.networkjob.move ]:	MOVE of QUrl("https://demo.owncloud.org/remote.php/dav/files/demo/Empty/Documents/Empty") FINISHED WITH STATUS "ContentNotFoundError Error transferring https://demo.owncloud.org/remote.php/dav/files/demo/Empty/Documents/Empty - server replied: "
08-16 16:40:15:640 [ info sync.database ]:	Setting blacklist entry for  "Empty/Documents/Empty" 1 "Error transferring https://demo.owncloud.org/remote.php/dav/files/demo/Empty/Documents/Empty - server replied: " 1534430415 25 1534430413 "5b758a3cc6b9f" "Empty" 0
08-16 16:40:15:640 [ warning sync.propagator ]:	Could not complete propagation of "Empty" by OCC::PropagateRemoteMove(0x558c888f02c0) with status 2 and error: "Error transferring https://demo.owncloud.org/remote.php/dav/files/demo/Empty/Documents/Empty - server replied: "
08-16 16:40:15:642 [ info sync.database ]:	Closing DB "/home/testy/testpilotcloud/._sync_f3502dd50375.db"
08-16 16:40:15:651 [ info sync.engine ]:	CSync run took  283 ms
08-16 16:40:15:652 [ info sync.database ]:	sqlite3 version "3.22.0"
08-16 16:40:15:653 [ info sync.database ]:	sqlite3 journal_mode= "wal"
08-16 16:40:15:658 [ info gui.folder ]:	Client version 2.5.0daily20180816 (build 10075)  Qt 5.10.1  SSL  OpenSSL 1.0.2n  7 Dec 2017
08-16 16:40:15:659 [ warning gui.folder ]:	SyncEngine finished with ERROR
08-16 16:40:15:660 [ info gui.folder ]:	Folder sync result:  3
08-16 16:40:15:660 [ info gui.folder ]:	the last 1 syncs failed
08-16 16:40:15:660 [ info gui.application ]:	Sync state changed for folder  "https://demo.owncloud.org/remote.php/dav/files/demo/" :  "Error"
08-16 16:40:15:862 [ info gui.folder.manager ]:	<========== Sync finished for folder [testpilotcloud] of account [[email protected]] with remote [https://demo.owncloud.org/remote.php/dav/files/demo/]
08-16 16:40:30:348 [ info gui.folder.manager ]:	Scheduling folder "2" , the last 1 syncs failed , anotherSyncNeeded 0 , last status: "Error" , time since last sync: 14687
08-16 16:40:30:349 [ info gui.folder.manager ]:	Schedule folder  "2"  to sync!
08-16 16:40:30:349 [ info gui.application ]:	Sync state changed for folder  "https://demo.owncloud.org/remote.php/dav/files/demo/" :  "Not yet Started"
08-16 16:40:30:350 [ info gui.folder.manager ]:	Starting the next scheduled sync in 0 seconds
08-16 16:40:30:356 [ info gui.application ]:	Sync state changed for folder  "https://demo.owncloud.org/remote.php/dav/files/demo/" :  "SyncPrepare"
08-16 16:40:30:357 [ info gui.folder ]:	*** Start syncing  "https://demo.owncloud.org/remote.php/dav/files/demo/"  - client version 2.5.0daily20180816 (build 10075)
08-16 16:40:30:361 [ info gui.folder ]:	Allowing local discovery to read from the database
08-16 16:40:30:361 [ info gui.folder.manager ]:	>========== Sync started for folder [testpilotcloud] of account [[email protected]] with remote [https://demo.owncloud.org/remote.php/dav/files/demo/]
08-16 16:40:30:362 [ info sync.engine ]:	There are 492690776064 bytes available at "/home/testy/testpilotcloud/"
08-16 16:40:30:362 [ info sync.engine ]:	Sync with existing sync journal
08-16 16:40:30:362 [ info sync.engine ]:	"Using Qt 5.10.1 SSL library OpenSSL 1.0.2n  7 Dec 2017 on Linux Mint 19"
08-16 16:40:30:362 [ info sync.engine ]:	Using Selective Sync
08-16 16:40:30:362 [ info sync.engine ]:	#### Discovery start ####################################################

@jnweiger jnweiger removed the ReadyToTest QA, please validate the fix/enhancement label Aug 16, 2018
@jnweiger
Copy link
Contributor Author

Linux build done from unmerged branch filerename-to-virtual-6718 (build 10079) does not show the issue!

@ogoffart
Copy link
Contributor

ogoffart commented Aug 17, 2018 •
edited by ckamm
Loading

@jnweiger it was merged at 11:00 yesterday

But as the discussion on the PR states, this is only a partial fix. More complicated changes such as this one:

You have folders Documents/Empty and Photos/Empty2 and do something like:
mv Documents/Empty ./ && mv Photos/Empty2 ./ && mv Documents Empty2/ && mv Photos Empty/ and the sync is still confused.

Other complicated scenario that involve 3 level directory where each of them is moved will also not work.

Edit: Changed milestone to 2.6 as this is a too complex problem to be fixed in 2.5 and is not a regression.

@ogoffart ogoffart modified the milestones: 2.5.0, 2.6.0 Aug 17, 2018
@camilasan camilasan mentioned this issue Sep 11, 2018
Closed
ogoffart added a commit that referenced this issue Dec 23, 2018
@ogoffart
Rename: fix renamed folder moved into renamed folder issue
aaaeaab 
Issue #6694
@ogoffart ogoffart mentioned this issue Dec 23, 2018
Merged
ogoffart added a commit that referenced this issue Jan 18, 2019
@ogoffart
Rename: fix renamed folder moved into renamed folder issue
d4845f6 
Issue #6694
ogoffart added a commit that referenced this issue Jan 22, 2019
@ogoffart
Rename: fix renamed folder moved into renamed folder issue
a4990c0 
Issue #6694
@guruz guruz modified the milestones: 2.6.0, 2.6.1 Apr 15, 2019
@ogoffart ogoffart added the ReadyToTest QA, please validate the fix/enhancement label Jun 4, 2019
@ogoffart
Copy link
Contributor

ogoffart commented Jun 4, 2019

The discovery in 2.6 should fix the problem.

The step to reproduce are in the description.
Also the operations in #6694 (comment) works for me.

@ogoffart ogoffart modified the milestones: 2.6.1, 2.6.0 Jun 4, 2019
@HanaGemela
Copy link
Contributor

Works as expected in 2.6.0alpha2 (build 12128), macOS 10.14.5

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@ogoffart ogoffart

Labels
ReadyToTest QA, please validate the fix/enhancement
Projects
None yet
Milestone
2.6.0
Development

No branches or pull requests
5 participants
@ckamm @ogoffart @guruz @jnweiger @HanaGemela