[Bug]: Files already synced, keep syncing

valdearg commented 2 years ago

⚠️ Before submitting, please verify the following: ⚠️

[X] This is a bug, not a question or a configuration issue.
[X] This issue is not already reported on Github (I've searched it).
[X] Nextcloud Server and Desktop Client are up to date. See Server Maintenance and Release Schedule and Desktop Releases for supported versions.
[X] I agree to follow Nextcloud's Code of Conduct

Bug description

I'm having an issue where some files I've renamed using PowerShell have been synced into the NextCloud server perfectly fine, however the system keeps re-syncing these items.

The files are usually named "info.json" but other files can be in there also. The only thing in common seems to be that they are all JSON files.

The files are perfectly on the server, there are no errors in the server log when this happens.

It's not all files which are renamed in this method, it's just... some... which I understand isn't particularly helpful.

It's a bit difficult to find the exact file(s) which are being synced this way because the Desktop client interface does not actually give you the path, just the filename.

I can however see one file. When I generate the Debug file which I created after the latest sync. I think it might be something relating to the following log:

2022-06-26 19:35:57:322 [ debug nextcloud.sync.propagator.download C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\libsync\propagatedownload.cpp:455 ] [ OCC::PropagateDownloadFile::start ]:  "<NextCloud Folder>/info.json" 0
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common/ownsql.h:145 ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 1 8544768958560429632
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common\ownsql.cpp:295 ]    [ OCC::SqlQuery::exec ]:    SQL exec "SELECT path, inode, modtime, type, md5, fileid, remotePerm, filesize,  ignoredChildrenRemote, contentchecksumtype.name || ':' || contentChecksum, e2eMangledName, isE2eEncrypted,   lock, lockOwnerDisplayName, lockOwnerId, lockType, lockOwnerEditor, lockTime, lockTimeout  FROM metadata  LEFT JOIN checksumtype as contentchecksumtype ON metadata.contentChecksumTypeId == contentchecksumtype.id WHERE phash=?1"
2022-06-26 19:35:57:322 [ debug nextcloud.sync.propagator.download C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\libsync\propagatedownload.cpp:499 ] [ OCC::PropagateDownloadFile::startAfterIsEncryptedIsChecked ]: dehydrating file "<NextCloud Folder>/info.json"
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common/ownsql.h:145 ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 1 2179061456218874304
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common\ownsql.cpp:295 ]    [ OCC::SqlQuery::exec ]:    SQL exec "DELETE FROM metadata WHERE phash=?1"
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common\ownsql.cpp:328 ]    [ OCC::SqlQuery::exec ]:    Last exec affected 1 rows.
2022-06-26 19:35:57:322 [ debug nextcloud.sync.fileitem C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\libsync\syncfileitem.cpp:59 ]  [ OCC::SyncFileItem::toSyncJournalFileRecordWithInode ]:    "G:/Scripts/gallery-dl/Coomer/<NextCloud Folder>/info.json" Retrieved inode  327021 (previous item inode:  327021 )
2022-06-26 19:35:57:322 [ info nextcloud.sync.database C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common\syncjournaldb.cpp:883 ]: Updating file record for path: "<NextCloud Folder>/info.json" inode: 327021 modtime: 1648843415 type: CSyncEnums::ItemTypeVirtualFile etag: "7fe6fa285bf9ebdb81672295c092e81a" fileId: "12442157ocqz3krd2bi6" remotePerm: "WDNVR" fileSize: 920 checksum: "SHA1:06d145f3a018b11c60f061fb1ad44856b7574979" e2eMangledName: "" isE2eEncrypted: false lock: false lock owner type: 0 lock owner: "" lock owner id: "" lock editor: ""
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common/ownsql.h:145 ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 1 2179061456218874304
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common/ownsql.h:145 ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 2 62
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common/ownsql.h:151 ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 3 "<NextCloud Folder>/info.json"
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common/ownsql.h:145 ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 4 327021
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common/ownsql.h:145 ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 5 0
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common/ownsql.h:145 ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 6 0
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common/ownsql.h:145 ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 7 0
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common/ownsql.h:145 ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 8 1648843415
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common/ownsql.h:138 ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 9 CSyncEnums::ItemTypeVirtualFile
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common/ownsql.h:151 ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 10 "7fe6fa285bf9ebdb81672295c092e81a"
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common/ownsql.h:151 ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 11 "12442157ocqz3krd2bi6"
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common/ownsql.h:151 ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 12 "WDNVR"
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common/ownsql.h:145 ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 13 920
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common/ownsql.h:145 ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 14 0
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common/ownsql.h:151 ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 15 "06d145f3a018b11c60f061fb1ad44856b7574979"
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common/ownsql.h:145 ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 16 1
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common/ownsql.h:151 ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 17 ""
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common/ownsql.h:145 ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 18 false
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common/ownsql.h:145 ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 19 0
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common/ownsql.h:145 ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 20 0
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common/ownsql.h:145 ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 21 ""
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common/ownsql.h:145 ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 22 ""
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common/ownsql.h:145 ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 23 ""
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common/ownsql.h:145 ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 24 0
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common/ownsql.h:145 ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 25 0
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common\ownsql.cpp:295 ]    [ OCC::SqlQuery::exec ]:    SQL exec "INSERT OR REPLACE INTO metadata (phash, pathlen, path, inode, uid, gid, mode, modtime, type, md5, fileid, remotePerm, filesize, ignoredChildrenRemote, contentChecksum, contentChecksumTypeId, e2eMangledName, isE2eEncrypted, lock, lockType, lockOwnerDisplayName, lockOwnerId, lockOwnerEditor, lockTime, lockTimeout) VALUES (?1 , ?2, ?3 , ?4 , ?5 , ?6 , ?7,  ?8 , ?9 , ?10, ?11, ?12, ?13, ?14, ?15, ?16, ?17, ?18, ?19, ?20, ?21, ?22, ?23, ?24, ?25);"
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common\ownsql.cpp:328 ]    [ OCC::SqlQuery::exec ]:    Last exec affected 1 rows.
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common/ownsql.h:145 ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 1 ""
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common\ownsql.cpp:295 ]    [ OCC::SqlQuery::exec ]:    SQL exec "DELETE FROM downloadinfo WHERE path=?1"
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common\ownsql.cpp:328 ]    [ OCC::SqlQuery::exec ]:    Last exec affected 0 rows.
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common\syncjournaldb.cpp:2418 ]    [ OCC::SyncJournalDb::commitInternal ]: Transaction commit "download file start2" and starting new transaction
2022-06-26 19:35:57:322 [ info nextcloud.sync.propagator C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\libsync\owncloudpropagator.cpp:283 ]: Completed propagation of "<NextCloud Folder>/info.json" by OCC::PropagateDownloadFile(0x1925c6a4fe0) with status OCC::SyncFileItem::Success
2022-06-26 19:35:57:322 [ debug nextcloud.sync.statustracker C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\libsync\syncfilestatustracker.cpp:274 ]   [ OCC::SyncFileStatusTracker::slotItemCompleted ]:  Item completed "<NextCloud Folder>/info.json" OCC::SyncFileItem::Success CSyncEnums::CSYNC_INSTRUCTION_SYNC
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common/ownsql.h:145 ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 1 8544768958560429632
2022-06-26 19:35:57:322 [ debug nextcloud.sync.database.sql C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\common\ownsql.cpp:295 ]    [ OCC::SqlQuery::exec ]:    SQL exec "SELECT path, inode, modtime, type, md5, fileid, remotePerm, filesize,  ignoredChildrenRemote, contentchecksumtype.name || ':' || contentChecksum, e2eMangledName, isE2eEncrypted,   lock, lockOwnerDisplayName, lockOwnerId, lockType, lockOwnerEditor, lockTime, lockTimeout  FROM metadata  LEFT JOIN checksumtype as contentchecksumtype ON metadata.contentChecksumTypeId == contentchecksumtype.id WHERE phash=?1"
2022-06-26 19:35:57:322 [ warning nextcloud.gui.activity C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\gui\tray\usermodel.cpp:638 ]: Item  "<NextCloud Folder>/info.json"  retrieved resulted in  ""
2022-06-26 19:35:57:322 [ warning nextcloud.gui.activity C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\gui\tray\usermodel.cpp:575 ]: Item  "<NextCloud Folder>/info.json"  retrieved successfully.
2022-06-26 19:35:57:322 [ info nextcloud.gui.activity C:\Users\sysadmin\AppData\Local\Temp\2\windows-10303\client-building\desktop\src\gui\tray\activitylistmodel.cpp:599 ]:    Successfully added to the activity list:  ""

The files have been synced into the NC instance and the desktop client says that the file has been successfully renamed.

I'm slightly worried that the constant reads/writes on the DB/filesystem may not be helping performance etc.

I'm aware that we previously had this issue: https://github.com/nextcloud/desktop/issues/4016 though this is related to resetting the metadata.

Happy to provide desktop Debug archive logs privately!

Steps to reproduce

I apologise, but I'm not entirely sure how to replicate this issue reliably. This seems to affect files differently, however this is the PowerShell line that I'm using which seems to cause the most of the issues.

Move-Item -LiteralPath $filename -Destination $info_filename -Force

$filename here is a full path to a JSON file. $info_filename is then the full path just with the filename changed to info.json.

Expected behavior

Synced files should not be re-synced over and over again.

Which files are affected by this bug

info.json

Operating system

Windows

Which version of the operating system you are running.

Windows 10

Package

Other

Nextcloud Server version

24.0.2

Nextcloud Desktop Client version

3.5.1

Is this bug present after an update or on a fresh install?

Updated from a minor version (ex. 3.4.2 to 3.4.4)

Are you using the Nextcloud Server Encryption module?

Encryption is Disabled

Are you using an external user-backend?

[ ] Default internal user-backend
[ ] LDAP/ Active Directory
[ ] SSO - SAML
[ ] Other

Nextcloud Server logs

No response

Additional info

No response

pzwahlen commented 2 years ago

Hi,

Are you using Virtual File and if yes, are your json files smaller than 4KB. If yes and yes, then you might be hitting #4226 which so far has no solution AFAIK.

Cheers

valdearg commented 2 years ago

Interesting, the JSON files are all below 4KB and I use the VFS, so you could definitely be onto a winner there.

Shame there's been absolutely no response on that one though as it looks like there's several bug reports with the same issue.

I suppose this is typical of the Nextcloud developers though with issues receiving no response for weeks at a time.

AndyXheli commented 1 year ago

This should be fixed in 3.7.4. Please test and confirm

czinehuba commented 4 months ago

I have a similar issue going on for a few months now. I have a hosted server with multiple pc syncing, but it only does this on one of my computers. On my laptop, I have Ubuntu 23.10 with BTRFS and have no issues. But on my workstation it happens mainly with Blender files, but sometimes other files as well, although not consistent enough.

The only fix I found for these is to remove the file, wait until it syncs, then copy the files back and let it sync again. Then problem solved. I've tried regular arch package, flatpak and snap version. All have the same issue.

Config Arch with regular kernel, and BTRFS file system. Nextcloud client 3.12.3.

joshtrichards commented 2 weeks ago

@valdearg As previously stated, likely fixed. Are you still experiencing this?

valdearg commented 2 weeks ago

Apologies! Completely forgot about this one.

I'm afraid I've long since stopped using the Nextcloud Desktop client due to the stability issues.

Sounds like it was fixed about a year later so I'll go ahead and close it

czinehuba commented 1 week ago

Yes. I haven't experienced it lately.

nextcloud / desktop