When syncing a case changed file, Syncthing briefly shows an “Out of Sync” error for the folder, and only a second later marks it “Up to Date”. Is the error showing up like that expected?
It is difficult to take a screenshot, as the state changes very quickly, but for that brief moment the file is are listed under the “Out of Sync Items” twice, each with a different case (i.e. before and after the change).
I think this is expected. Renames are handled as create + delete with some optimizations, and in the case-only case the create might fail until we’ve processed the delete and then be retried.
I do think that it would be nicer to have all this happen somewhat in the background though. With a single file, it is no big deal. However, when doing some kind of mass renaming operations, I have a feeling that the Web GUI will go crazy during the synchronisation.
I can’t reproduce and there shouldn’t be any out-of-sync status/failed items in this scenario: We only display pull errors/failed items after all sync iterations/attempts are through, so it shouldn’t appear even intermittently. If you can reproduce, please do so with model debug logging enabled to see what’s going on.
Also, what is strange is that I do not notice these errors when doing mass case renaming operations, but when renaming and syncing just a single file, it always happens. Anyhow, below is the model log from the receiving side, i.e. the one where the errors show up. For the record, I renamed 1test.txt to 1tesT.txt.
2020-09-09 08:55:36 sendreceive/acwp2-snogx@0xc001b54000 pulling
2020-09-09 08:55:36 sendreceive/acwp2-snogx@0xc001b54000 copiers: 2 pullerPendingKiB: 32768
2020-09-09 08:55:36 sendreceive/acwp2-snogx@0xc001b54000 parent not missing 1tesT.txt
2020-09-09 08:55:36 sendreceive/acwp2-snogx@0xc001b54000 taking rename shortcut 1test.txt -> 1tesT.txt
2020-09-09 08:55:36 rename shortcut for 1tesT.txt failed: given name "1tesT.txt" differs from name in filesystem "1test.txt"
2020-09-09 08:55:36 sendreceive/acwp2-snogx@0xc001b54000 need file 1tesT.txt; copy 0, reused 1
2020-09-09 08:55:36 progress emitter: registering acwp2-snogx 1tesT.txt
2020-09-09 08:55:36 not weak hashing 1tesT.txt. file did not contain any weak hashes
2020-09-09 08:55:36 sendreceive/acwp2-snogx@0xc001b54000 closing 1tesT.txt
2020-09-09 08:55:36 sendreceive/acwp2-snogx@0xc001b54000 new error for 1tesT.txt: given name "1tesT.txt" differs from name in filesystem "1test.txt"
2020-09-09 08:55:36 progress emitter: deregistering acwp2-snogx 1tesT.txt
2020-09-09 08:55:36 sendreceive/acwp2-snogx@0xc001b54000 Deleting file 1test.txt
2020-09-09 08:55:36 indexSender@0xc0156b4000 for acwp2-snogx to at 10.0.0.2:5504-160.16.133.73:22067/relay-server/TLS1.3-TLS_AES_128_GCM_SHA256: Sending 1 files (<84 bytes)
2020-09-09 08:55:36 sendreceive/acwp2-snogx@0xc001b54000 changed 2 on try 1
2020-09-09 08:55:36 sendreceive/acwp2-snogx@0xc001b54000 copiers: 2 pullerPendingKiB: 32768
2020-09-09 08:55:36 sendreceive/acwp2-snogx@0xc001b54000 parent not missing 1tesT.txt
2020-09-09 08:55:36 sendreceive/acwp2-snogx@0xc001b54000 need file 1tesT.txt; copy 0, reused 1
2020-09-09 08:55:36 progress emitter: registering acwp2-snogx 1tesT.txt
2020-09-09 08:55:36 not weak hashing 1tesT.txt. file did not contain any weak hashes
2020-09-09 08:55:36 sendreceive/acwp2-snogx@0xc001b54000 closing 1tesT.txt
2020-09-09 08:55:36 progress emitter: deregistering acwp2-snogx 1tesT.txt
2020-09-09 08:55:36 fsync "." failed: sync \\?\D:\TEST: The handle is invalid.
2020-09-09 08:55:36 sendreceive/acwp2-snogx@0xc001b54000 changed 1 on try 2
2020-09-09 08:55:36 sendreceive/acwp2-snogx@0xc001b54000 copiers: 2 pullerPendingKiB: 32768
2020-09-09 08:55:36 sendreceive/acwp2-snogx@0xc001b54000 changed 0 on try 3
2020-09-09 08:55:36 progress emitter: bytes completed for acwp2-snogx: 0
2020-09-09 08:55:36 model@0xc000084600 Completion(XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX, "acwp2-snogx"): map[completion:100 globalBytes:316 globalItems:1002 needBytes:0 needDeletes:0 needItems:0]
2020-09-09 08:55:37 indexSender@0xc0156b4000 for acwp2-snogx to at 10.0.0.2:5504-160.16.133.73:22067/relay-server/TLS1.3-TLS_AES_128_GCM_SHA256: Sending 1 files (<136 bytes)
There is also an fsync error in there, although I am not sure whether it has any significance.
Edit: I have managed to grab a screenshot of the “Out of Sync” state. It only flashes for less than a second, so I used a screen recording software to do it. In this case, tes.m4a was renamed to teS.m4a.
The logs don’t show any moment where the folder should show as out-of-sync. It manages to get fully in sync during a single pull. That’s also consistent with your screenshot, where there are no failed items. It looks like this happens in between the index update and before actual syncing happens. That should be near instantaneous though and I have never seen this before.
There’s one problem though in your logs, that need looking at but should not be connected to the out-of-sync another thing to be improved, but that shouldn’t cause any problems:
2020-09-09 08:55:36 rename shortcut for 1tesT.txt failed: given name "1tesT.txt" differs from name in filesystem "1test.txt"
Renaming between two names just differing by name should work, but apparently doesn’t.
This is really strange to hear, as I can see the “Out of Sync” error flashing on the screen literally every time after the rename . Let me try one more time, just to be sure.
I have recorded this 15s long video clip showing what is going on the receiving side. You can see the “Out of Sync” error near the very end of the video. It does change very quickly, so I suggest just to keep looking at the folder status.
Maybe the folder summaries are sent in some funky order causing the brief out-of-sync status. Could you also enable events debug logging to see those.
The fsync error
[SWPW3] 2020/09/10 02:25:24.885917 folder_sendrecv.go:1624: DEBUG: fsync "." failed: sync \\?\C:\Users\TW86\Desktop\TEST: The handle is invalid.
is not connected or problematic. I assume that means directories cannot be fsynced on windows (i.e. it expects a file handle, but we pass it a directory, thus invalid).
Before those events it was syncing and the folder isn’t up to date. The event about the folder going idle is emitted before the summary which makes it up-to-date. In the 18ms (o.O) between those events, the UI is actually right to consider it out-of-sync.
However that is unrelated to case-only renames and/or any recent changes as far as I see. I’d expect this to happen on any sync, though possibly be racy (as in might occur or not depending on timing of events and what angularjs is up to at the time, which is more or less random).
Not sure what’s the best way to mitigate this. We could ignore folder state events when transiting from syncing to idle, to wait for the incoming folder summary and let that change the folder to idle and up-to-date at the same time. That might introduce some artificial delay though as folder summaries might not always be emitted immediately.
Hmm, this sounds quite tricky then. I mean, it is really not a big deal, more a cosmetic issue than anything else. I just do not remember seeing this kind of behaviour before, hence the question.
Most users will probably not even notice this anyhow, unless one literally sits in front of the Web GUI and observes it closely looking for potential issues .