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 see.
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.
Hmm, yes, I can reproduce, as this happens any time a case renamed file is being synced from one device to another.
One thing I must say though is that I did apply your newest commit (https://github.com/syncthing/syncthing/commit/b628ec5054a9ac68d84ef7559017b9c217961f20) on top of v1.9.0 and recompiled Syncthing with it, so I have not been testing the other “slow” case sensitivity detection method used in Windows in v1.9.0 normally.
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.
Below is a full log file.
[SWPW3] 2020/09/10 02:25:15.950306 model.go:937: DEBUG: Index update (in): D4DZUGP-XXXXXXX / "acwp2-snogx": 2 files
[SWPW3] 2020/09/10 02:25:15.967884 folder_sendrecv.go:168: DEBUG: sendreceive/acwp2-snogx@0x12d14000 pulling
[SWPW3] 2020/09/10 02:25:15.969838 folder_sendrecv.go:249: DEBUG: sendreceive/acwp2-snogx@0x12d14000 copiers: 2 pullerPendingKiB: 32768
[SWPW3] 2020/09/10 02:25:15.973744 folder_sendrecv.go:684: DEBUG: sendreceive/acwp2-snogx@0x12d14000 parent not missing TES.m4a
[SWPW3] 2020/09/10 02:25:15.974720 folder_sendrecv.go:939: DEBUG: sendreceive/acwp2-snogx@0x12d14000 taking rename shortcut teS.m4a -> TES.m4a
[SWPW3] 2020/09/10 02:25:15.975697 folder_sendrecv.go:480: DEBUG: rename shortcut for TES.m4a failed: given name "TES.m4a" differs from name in filesystem "teS.m4a"
[SWPW3] 2020/09/10 02:25:15.976673 folder_sendrecv.go:1108: DEBUG: sendreceive/acwp2-snogx@0x12d14000 need file TES.m4a; copy 758, reused 0
[SWPW3] 2020/09/10 02:25:15.982533 progressemitter.go:264: DEBUG: progress emitter: registering acwp2-snogx TES.m4a
[SWPW3] 2020/09/10 02:25:16.828236 progressemitter.go:296: DEBUG: progress emitter: bytes completed for acwp2-snogx: 65536
[SWPW3] 2020/09/10 02:25:16.828236 model.go:829: DEBUG: model@0x12c7c0d0 Completion(D4DZUGP-XXXXXX, "acwp2-snogx"): map[completion:100 globalBytes:99258847 globalItems:3 needBytes:0 needDeletes:0 needItems:0]
[SWPW3] 2020/09/10 02:25:17.414368 sharedpullerstate.go:249: DEBUG: sharedPullerState acwp2-snogx TES.m4a copyNeeded -> 757
[SWPW3] 2020/09/10 02:25:17.414368 sharedpullerstate.go:249: DEBUG: sharedPullerState acwp2-snogx TES.m4a copyNeeded -> 756
[SWPW3] 2020/09/10 02:25:17.415247 sharedpullerstate.go:249: DEBUG: sharedPullerState acwp2-snogx TES.m4a copyNeeded -> 755
--- SKIPPED SIMILAR LINES HERE ---
[SWPW3] 2020/09/10 02:25:20.483487 sharedpullerstate.go:249: DEBUG: sharedPullerState acwp2-snogx TES.m4a copyNeeded -> 2
[SWPW3] 2020/09/10 02:25:20.486124 sharedpullerstate.go:249: DEBUG: sharedPullerState acwp2-snogx TES.m4a copyNeeded -> 1
[SWPW3] 2020/09/10 02:25:20.487882 sharedpullerstate.go:249: DEBUG: sharedPullerState acwp2-snogx TES.m4a copyNeeded -> 0
[SWPW3] 2020/09/10 02:25:20.603018 progressemitter.go:85: DEBUG: progress emitter: timer - looking after 1
[SWPW3] 2020/09/10 02:25:23.342569 folder_sendrecv.go:1554: DEBUG: sendreceive/acwp2-snogx@0x12d14000 closing TES.m4a
[SWPW3] 2020/09/10 02:25:23.342569 folder_sendrecv.go:1790: DEBUG: sendreceive/acwp2-snogx@0x12d14000 new error for TES.m4a: given name "TES.m4a" differs from name in filesystem "teS.m4a"
[SWPW3] 2020/09/10 02:25:23.342569 progressemitter.go:138: DEBUG: progress emitter: emitting map[string]map[string]*model.pullerProgress{"acwp2-snogx":map[string]*model.pullerProgress{"TES.m4a":(*model.pullerProgress)(0x131aede0)}}
[SWPW3] 2020/09/10 02:25:23.342569 progressemitter.go:284: DEBUG: progress emitter: deregistering acwp2-snogx TES.m4a
[SWPW3] 2020/09/10 02:25:23.342569 folder_sendrecv.go:835: DEBUG: sendreceive/acwp2-snogx@0x12d14000 Deleting file teS.m4a
[SWPW3] 2020/09/10 02:25:23.352237 folder_sendrecv.go:197: DEBUG: sendreceive/acwp2-snogx@0x12d14000 changed 2 on try 1
[SWPW3] 2020/09/10 02:25:23.352237 folder_sendrecv.go:249: DEBUG: sendreceive/acwp2-snogx@0x12d14000 copiers: 2 pullerPendingKiB: 32768
[SWPW3] 2020/09/10 02:25:23.353994 folder_sendrecv.go:684: DEBUG: sendreceive/acwp2-snogx@0x12d14000 parent not missing TES.m4a
[SWPW3] 2020/09/10 02:25:23.413760 model.go:1980: DEBUG: indexSender@0x13384400 for acwp2-snogx to at 10.0.2.15:54500-160.16.133.73:22067/relay-client/TLS1.3-TLS_AES_128_GCM_SHA256: Sending 1 files (<76 bytes)
[SWPW3] 2020/09/10 02:25:24.065024 progressemitter.go:296: DEBUG: progress emitter: bytes completed for acwp2-snogx: 0
[SWPW3] 2020/09/10 02:25:24.065903 model.go:829: DEBUG: model@0x12c7c0d0 Completion(D4DZUGP-XXXXXX, "acwp2-snogx"): map[completion:100 globalBytes:99258847 globalItems:3 needBytes:0 needDeletes:0 needItems:0]
[SWPW3] 2020/09/10 02:25:24.839335 folder_sendrecv.go:1108: DEBUG: sendreceive/acwp2-snogx@0x12d14000 need file TES.m4a; copy 0, reused 758
[SWPW3] 2020/09/10 02:25:24.840214 progressemitter.go:264: DEBUG: progress emitter: registering acwp2-snogx TES.m4a
[SWPW3] 2020/09/10 02:25:24.840214 folder_sendrecv.go:1256: DEBUG: not weak hashing TES.m4a. file did not contain any weak hashes
[SWPW3] 2020/09/10 02:25:24.884159 folder_sendrecv.go:1554: DEBUG: sendreceive/acwp2-snogx@0x12d14000 closing TES.m4a
[SWPW3] 2020/09/10 02:25:24.885038 progressemitter.go:284: DEBUG: progress emitter: deregistering acwp2-snogx TES.m4a
[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.
[SWPW3] 2020/09/10 02:25:24.888554 folder_sendrecv.go:197: DEBUG: sendreceive/acwp2-snogx@0x12d14000 changed 1 on try 2
[SWPW3] 2020/09/10 02:25:24.889433 folder_sendrecv.go:249: DEBUG: sendreceive/acwp2-snogx@0x12d14000 copiers: 2 pullerPendingKiB: 32768
[SWPW3] 2020/09/10 02:25:24.890312 folder_sendrecv.go:197: DEBUG: sendreceive/acwp2-snogx@0x12d14000 changed 0 on try 3
[SWPW3] 2020/09/10 02:25:24.891190 progressemitter.go:296: DEBUG: progress emitter: bytes completed for acwp2-snogx: 0
[SWPW3] 2020/09/10 02:25:24.892948 model.go:829: DEBUG: model@0x12c7c0d0 Completion(D4DZUGP-XXXXXX, "acwp2-snogx"): map[completion:100 globalBytes:99258847 globalItems:3 needBytes:0 needDeletes:0 needItems:0]
[SWPW3] 2020/09/10 02:25:24.893827 model.go:1980: DEBUG: indexSender@0x13384400 for acwp2-snogx to at 10.0.2.15:54500-160.16.133.73:22067/relay-client/TLS1.3-TLS_AES_128_GCM_SHA256: Sending 1 files (<39449 bytes)
[SWPW3] 2020/09/10 02:25:29.703102 progressemitter.go:85: DEBUG: progress emitter: timer - looking after 1
[SWPW3] 2020/09/10 02:25:29.703102 progressemitter.go:138: DEBUG: progress emitter: emitting map[string]map[string]*model.pullerProgress{}
[SWPW3] 2020/09/10 02:25:33.038541 folder.go:195: DEBUG: sendreceive/acwp2-snogx@0x12d14000 Scan due to watcher
[SWPW3] 2020/09/10 02:25:33.038541 folder.go:195: DEBUG: sendreceive/acwp2-snogx@0x12d14000 Scan due to watcher
[SWPW3] 2020/09/10 02:25:38.627085 model.go:1948: DEBUG: Exiting indexSender for acwp2-snogx to at 10.0.2.15:54500-160.16.133.73:22067/relay-client/TLS1.3-TLS_AES_128_GCM_SHA256: <nil>
[SWPW3] 2020/09/10 02:25:38.627085 progressemitter.go:81: DEBUG: progress emitter: stopping
[SWPW3] 2020/09/10 02:25:38.629212 quic_listen.go:124: INFO: QUIC listener (0.0.0.0:22000) shutting down
[SWPW3] 2020/09/10 02:25:38.629212 folder.go:163: DEBUG: sendreceive/acwp2-snogx@0x12d14000 exiting
[SWPW3] 2020/09/10 02:25:38.632403 relay_listen.go:123: INFO: Relay listener (dynamic+https://relays.syncthing.net/endpoint) shutting down
[SWPW3] 2020/09/10 02:25:38.636657 static.go:114: INFO: Disconnected from relay relay://172.104.111.251:22067
[SWPW3] 2020/09/10 02:25:38.636657 model.go:1393: INFO: Connection to D4DZUGP-XXXXXX at 10.0.2.15:54500-160.16.133.73:22067/relay-client/TLS1.3-TLS_AES_128_GCM_SHA256 closed: Syncthing is being stopped
[SWPW3] 2020/09/10 02:25:39.266241 tcp_listen.go:100: INFO: TCP listener ([::]:22000) shutting down
[SWPW3] 2020/09/10 02:25:39.268368 syncthing.go:366: INFO: Exiting
Please let me know whether there is anything useful there.
Also, just out of my curiosity, what is exactly the deal with this fsync error that keeps popping up? Can I just ignore it?
Again, the pull works just fine, this line indicates it ended successfully:
[SWPW3] 2020/09/10 02:25:24.890312 folder_sendrecv.go:197: DEBUG: sendreceive/acwp2-snogx@0x12d14000 changed 0 on try 3
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).
Thank you for the fsync explanation. Here is another try with model and events enabled.
[NISVV] 2020/09/11 17:54:49.605766 api.go:649: INFO: Enabled debug data for "model"
[NISVV] 2020/09/11 17:54:52.136729 api.go:649: INFO: Enabled debug data for "events"
[NISVV] 2020/09/11 17:55:12.638986 model.go:932: DEBUG: Index update (in): SWPW3LH-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX / "uqzch-bwmvk": 2 files
[NISVV] 2020/09/11 17:55:12.638986 events.go:313: DEBUG: log 99 RemoteIndexUpdated map[device:SWPW3LH-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX folder:uqzch-bwmvk items:2 sequence:11 version:11]
[NISVV] 2020/09/11 17:55:12.641916 events.go:313: DEBUG: log 100 StateChanged map[duration:33.1524701 folder:uqzch-bwmvk from:idle to:sync-waiting]
[NISVV] 2020/09/11 17:55:12.641916 folder_sendrecv.go:168: DEBUG: sendreceive/uqzch-bwmvk@0x13e18000 pulling
[NISVV] 2020/09/11 17:55:12.641916 folder_sendrecv.go:249: DEBUG: sendreceive/uqzch-bwmvk@0x13e18000 copiers: 2 pullerPendingKiB: 32768
[NISVV] 2020/09/11 17:55:12.643868 events.go:313: DEBUG: log 101 StateChanged map[duration:0.0009763 folder:uqzch-bwmvk from:sync-waiting to:sync-preparing]
[NISVV] 2020/09/11 17:55:12.644844 folder_sendrecv.go:684: DEBUG: sendreceive/uqzch-bwmvk@0x13e18000 parent not missing TES.m4a
[NISVV] 2020/09/11 17:55:12.644844 folder_sendrecv.go:939: DEBUG: sendreceive/uqzch-bwmvk@0x13e18000 taking rename shortcut tes.m4a -> TES.m4a
[NISVV] 2020/09/11 17:55:12.644844 folder_sendrecv.go:480: DEBUG: rename shortcut for TES.m4a failed: given name "TES.m4a" differs from name in filesystem "tes.m4a"
[NISVV] 2020/09/11 17:55:12.646798 folder_sendrecv.go:1108: DEBUG: sendreceive/uqzch-bwmvk@0x13e18000 need file TES.m4a; copy 758, reused 0
[NISVV] 2020/09/11 17:55:12.646798 events.go:313: DEBUG: log 102 ItemStarted map[action:delete folder:uqzch-bwmvk item:tes.m4a type:file]
[NISVV] 2020/09/11 17:55:12.646798 events.go:313: DEBUG: log 103 ItemStarted map[action:update folder:uqzch-bwmvk item:TES.m4a type:file]
[NISVV] 2020/09/11 17:55:12.646798 events.go:313: DEBUG: log 104 ItemFinished map[action:delete error:0x13fc82a8 folder:uqzch-bwmvk item:tes.m4a type:file]
[NISVV] 2020/09/11 17:55:12.646798 events.go:313: DEBUG: log 105 ItemFinished map[action:update error:0x13fc82d0 folder:uqzch-bwmvk item:TES.m4a type:file]
[NISVV] 2020/09/11 17:55:12.646798 events.go:313: DEBUG: log 106 ItemStarted map[action:update folder:uqzch-bwmvk item:TES.m4a type:file]
[NISVV] 2020/09/11 17:55:12.652659 progressemitter.go:264: DEBUG: progress emitter: registering uqzch-bwmvk TES.m4a
[NISVV] 2020/09/11 17:55:12.656118 sharedpullerstate.go:249: DEBUG: sharedPullerState uqzch-bwmvk TES.m4a copyNeeded -> 757
--- SKIPPED SIMILAR LINES HERE ---
[NISVV] 2020/09/11 17:55:14.053475 sharedpullerstate.go:249: DEBUG: sharedPullerState uqzch-bwmvk TES.m4a copyNeeded -> 100
[NISVV] 2020/09/11 17:55:14.054452 progressemitter.go:296: DEBUG: progress emitter: bytes completed for uqzch-bwmvk: 86179840
[NISVV] 2020/09/11 17:55:14.054452 sharedpullerstate.go:249: DEBUG: sharedPullerState uqzch-bwmvk TES.m4a copyNeeded -> 99
[NISVV] 2020/09/11 17:55:14.055430 model.go:824: DEBUG: model@0x129981a0 Completion(SWPW3LH-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX, "uqzch-bwmvk"): map[completion:100 globalBytes:99258848 globalItems:3 needBytes:0 needDeletes:0 needItems:0 sequence:11]
[NISVV] 2020/09/11 17:55:14.055430 events.go:313: DEBUG: log 107 FolderSummary map[folder:uqzch-bwmvk summary:map[errors:0 globalBytes:99258848 globalDeleted:10002 globalDirectories:0 globalFiles:3 globalSymlinks:0 globalTotalItems:10005 ignorePatterns:false inSyncBytes:86180157 inSyncFiles:2 invalid: localBytes:99258848 localDeleted:10002 localDirectories:0 localFiles:3 localSymlinks:0 localTotalItems:10005 needBytes:13078691 needDeletes:1 needDirectories:0 needFiles:1 needSymlinks:0 needTotalItems:2 pullErrors:0 sequence:143123 state:sync-preparing stateChanged:2020-09-11 17:55:12.6419161 +0900 KST m=+881.646222801 version:143123]]
[NISVV] 2020/09/11 17:55:14.055430 events.go:313: DEBUG: log 108 FolderCompletion map[completion:100 device:SWPW3LH-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX folder:uqzch-bwmvk globalBytes:99258848 globalItems:3 needBytes:0 needDeletes:0 needItems:0 sequence:11]
[NISVV] 2020/09/11 17:55:14.056409 sharedpullerstate.go:249: DEBUG: sharedPullerState uqzch-bwmvk TES.m4a copyNeeded -> 98
--- SKIPPED SIMILAR LINES HERE ---
[NISVV] 2020/09/11 17:55:14.576030 sharedpullerstate.go:249: DEBUG: sharedPullerState uqzch-bwmvk TES.m4a copyNeeded -> 0
[NISVV] 2020/09/11 17:55:17.225589 folder_sendrecv.go:1554: DEBUG: sendreceive/uqzch-bwmvk@0x13e18000 closing TES.m4a
[NISVV] 2020/09/11 17:55:17.226565 folder_sendrecv.go:1790: DEBUG: sendreceive/uqzch-bwmvk@0x13e18000 new error for TES.m4a: given name "TES.m4a" differs from name in filesystem "tes.m4a"
[NISVV] 2020/09/11 17:55:17.226565 progressemitter.go:284: DEBUG: progress emitter: deregistering uqzch-bwmvk TES.m4a
[NISVV] 2020/09/11 17:55:17.226565 events.go:313: DEBUG: log 109 ItemFinished map[action:update error:0x1421e9d0 folder:uqzch-bwmvk item:TES.m4a type:file]
[NISVV] 2020/09/11 17:55:17.226565 folder_sendrecv.go:835: DEBUG: sendreceive/uqzch-bwmvk@0x13e18000 Deleting file tes.m4a
[NISVV] 2020/09/11 17:55:17.227550 events.go:313: DEBUG: log 110 ItemStarted map[action:delete folder:uqzch-bwmvk item:tes.m4a type:file]
[NISVV] 2020/09/11 17:55:17.271483 events.go:313: DEBUG: log 111 ItemFinished map[action:delete error:<nil> folder:uqzch-bwmvk item:tes.m4a type:file]
[NISVV] 2020/09/11 17:55:17.286133 events.go:313: DEBUG: log 112 LocalIndexUpdated map[filenames:[tes.m4a] folder:uqzch-bwmvk items:1 sequence:143124 version:143124]
[NISVV] 2020/09/11 17:55:17.288084 events.go:313: DEBUG: log 113 RemoteChangeDetected map[action:deleted folder:uqzch-bwmvk folderID:uqzch-bwmvk label:TEST modifiedBy:SWPW3LH path:tes.m4a type:file]
[NISVV] 2020/09/11 17:55:17.291012 model.go:1982: DEBUG: indexSender@0x1321bf40 for uqzch-bwmvk to at 10.0.0.2:60118-10.0.0.2:12204/tcp-server/TLS1.3-TLS_AES_128_GCM_SHA256: Sending 1 files (<60 bytes)
[NISVV] 2020/09/11 17:55:17.293945 folder_sendrecv.go:197: DEBUG: sendreceive/uqzch-bwmvk@0x13e18000 changed 2 on try 1
[NISVV] 2020/09/11 17:55:17.304687 folder_sendrecv.go:249: DEBUG: sendreceive/uqzch-bwmvk@0x13e18000 copiers: 2 pullerPendingKiB: 32768
[NISVV] 2020/09/11 17:55:17.307617 folder_sendrecv.go:684: DEBUG: sendreceive/uqzch-bwmvk@0x13e18000 parent not missing TES.m4a
[NISVV] 2020/09/11 17:55:17.654252 progressemitter.go:85: DEBUG: progress emitter: timer - looking after 1
[NISVV] 2020/09/11 17:55:17.654252 progressemitter.go:104: DEBUG: progress emitter: nothing new
[NISVV] 2020/09/11 17:55:18.058050 progressemitter.go:296: DEBUG: progress emitter: bytes completed for uqzch-bwmvk: 0
[NISVV] 2020/09/11 17:55:18.058050 events.go:313: DEBUG: log 114 FolderSummary map[folder:uqzch-bwmvk summary:map[errors:0 globalBytes:99258848 globalDeleted:10002 globalDirectories:0 globalFiles:3 globalSymlinks:0 globalTotalItems:10005 ignorePatterns:false inSyncBytes:317 inSyncFiles:2 invalid: localBytes:317 localDeleted:10003 localDirectories:0 localFiles:2 localSymlinks:0 localTotalItems:10005 needBytes:99258531 needDeletes:0 needDirectories:0 needFiles:1 needSymlinks:0 needTotalItems:1 pullErrors:0 sequence:143124 state:sync-preparing stateChanged:2020-09-11 17:55:12.6419161 +0900 KST m=+881.646222801 version:143124]]
[NISVV] 2020/09/11 17:55:18.061960 model.go:824: DEBUG: model@0x129981a0 Completion(SWPW3LH-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX, "uqzch-bwmvk"): map[completion:100 globalBytes:99258848 globalItems:3 needBytes:0 needDeletes:0 needItems:0 sequence:11]
[NISVV] 2020/09/11 17:55:18.061960 events.go:313: DEBUG: log 115 FolderCompletion map[completion:100 device:SWPW3LH-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX folder:uqzch-bwmvk globalBytes:99258848 globalItems:3 needBytes:0 needDeletes:0 needItems:0 sequence:11]
[NISVV] 2020/09/11 17:55:18.227953 folder_sendrecv.go:1108: DEBUG: sendreceive/uqzch-bwmvk@0x13e18000 need file TES.m4a; copy 0, reused 758
[NISVV] 2020/09/11 17:55:18.227953 events.go:313: DEBUG: log 116 ItemStarted map[action:update folder:uqzch-bwmvk item:TES.m4a type:file]
[NISVV] 2020/09/11 17:55:18.232839 progressemitter.go:264: DEBUG: progress emitter: registering uqzch-bwmvk TES.m4a
[NISVV] 2020/09/11 17:55:18.234791 folder_sendrecv.go:1256: DEBUG: not weak hashing TES.m4a. file did not contain any weak hashes
[NISVV] 2020/09/11 17:55:18.243580 folder_sendrecv.go:1554: DEBUG: sendreceive/uqzch-bwmvk@0x13e18000 closing TES.m4a
[NISVV] 2020/09/11 17:55:18.246507 progressemitter.go:284: DEBUG: progress emitter: deregistering uqzch-bwmvk TES.m4a
[NISVV] 2020/09/11 17:55:18.246507 events.go:313: DEBUG: log 117 ItemFinished map[action:update error:<nil> folder:uqzch-bwmvk item:TES.m4a type:file]
[NISVV] 2020/09/11 17:55:18.246507 folder_sendrecv.go:1624: DEBUG: fsync "." failed: sync \\?\D:\Programy\Syncthing\test1\test: The handle is invalid.
[NISVV] 2020/09/11 17:55:18.256275 events.go:313: DEBUG: log 118 LocalIndexUpdated map[filenames:[TES.m4a] folder:uqzch-bwmvk items:1 sequence:143125 version:143125]
[NISVV] 2020/09/11 17:55:18.256275 events.go:313: DEBUG: log 119 RemoteChangeDetected map[action:modified folder:uqzch-bwmvk folderID:uqzch-bwmvk label:TEST modifiedBy:SWPW3LH path:TES.m4a type:file]
[NISVV] 2020/09/11 17:55:18.258225 model.go:1982: DEBUG: indexSender@0x1321bf40 for uqzch-bwmvk to at 10.0.0.2:60118-10.0.0.2:12204/tcp-server/TLS1.3-TLS_AES_128_GCM_SHA256: Sending 1 files (<39452 bytes)
[NISVV] 2020/09/11 17:55:18.269945 folder_sendrecv.go:197: DEBUG: sendreceive/uqzch-bwmvk@0x13e18000 changed 1 on try 2
[NISVV] 2020/09/11 17:55:18.269945 folder_sendrecv.go:249: DEBUG: sendreceive/uqzch-bwmvk@0x13e18000 copiers: 2 pullerPendingKiB: 32768
[NISVV] 2020/09/11 17:55:18.271897 folder_sendrecv.go:197: DEBUG: sendreceive/uqzch-bwmvk@0x13e18000 changed 0 on try 3
[NISVV] 2020/09/11 17:55:18.271897 events.go:313: DEBUG: log 120 StateChanged map[duration:5.6302451 folder:uqzch-bwmvk from:sync-preparing to:idle]
[NISVV] 2020/09/11 17:55:18.271897 progressemitter.go:296: DEBUG: progress emitter: bytes completed for uqzch-bwmvk: 0
[NISVV] 2020/09/11 17:55:18.290450 events.go:313: DEBUG: log 121 FolderSummary map[folder:uqzch-bwmvk summary:map[errors:0 globalBytes:99258848 globalDeleted:10002 globalDirectories:0 globalFiles:3 globalSymlinks:0 globalTotalItems:10005 ignorePatterns:false inSyncBytes:99258848 inSyncFiles:3 invalid: localBytes:99258848 localDeleted:10002 localDirectories:0 localFiles:3 localSymlinks:0 localTotalItems:10005 needBytes:0 needDeletes:0 needDirectories:0 needFiles:0 needSymlinks:0 needTotalItems:0 pullErrors:0 sequence:143125 state:idle stateChanged:2020-09-11 17:55:18.2718974 +0900 KST m=+887.276467901 version:143125]]
[NISVV] 2020/09/11 17:55:18.303143 model.go:824: DEBUG: model@0x129981a0 Completion(SWPW3LH-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX, "uqzch-bwmvk"): map[completion:100 globalBytes:99258848 globalItems:3 needBytes:0 needDeletes:0 needItems:0 sequence:11]
[NISVV] 2020/09/11 17:55:18.306071 events.go:313: DEBUG: log 122 FolderCompletion map[completion:100 device:SWPW3LH-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX folder:uqzch-bwmvk globalBytes:99258848 globalItems:3 needBytes:0 needDeletes:0 needItems:0 sequence:11]
[NISVV] 2020/09/11 17:55:23.234909 progressemitter.go:85: DEBUG: progress emitter: timer - looking after 1
[NISVV] 2020/09/11 17:55:23.234909 progressemitter.go:104: DEBUG: progress emitter: nothing new
Looks like the UI is just too fast. The relevant events are:
[NISVV] 2020/09/11 17:55:18.271897 events.go:313: DEBUG: log 120 StateChanged map[duration:5.6302451 folder:uqzch-bwmvk from:sync-preparing to:idle]
[NISVV] 2020/09/11 17:55:18.290450 events.go:313: DEBUG: log 121 FolderSummary map[folder:uqzch-bwmvk summary:map[errors:0 globalBytes:99258848 globalDeleted:10002 globalDirectories:0 globalFiles:3 globalSymlinks:0 globalTotalItems:10005 ignorePatterns:false inSyncBytes:99258848 inSyncFiles:3 invalid: localBytes:99258848 localDeleted:10002 localDirectories:0 localFiles:3 localSymlinks:0 localTotalItems:10005 needBytes:0 needDeletes:0 needDirectories:0 needFiles:0 needSymlinks:0 needTotalItems:0 pullErrors:0 sequence:143125 state:idle stateChanged:2020-09-11 17:55:18.2718974 +0900 KST m=+887.276467901 version:143125]]
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 
.
This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.