Syncthing misbehaves after mass rename

ST went crazy on me today:

All was quiet and in complete sync, then after renaming and moving across sub-directories a bunch of files (~40GB, 6K files) on one PC, the following happened:

For every renamed_file.ext on the source PC, ~syncthing~renamed_file.ext.tmp is created (on the source PC itself), doubling the directory size, and constantly “syncing” without any network traffic, and SyncTrayzor’s “Recently Updated” tray view loops through all the files, infinitely listing every renamed_file.ext as updated “just now”.

ST’s log shows nothing abnormal. SyncTrayzor’s one is flooded with:

...
2017-09-19 14:40:31.3145 #14044 [Warn] SyncTrayzor.Syncthing.Folders.FolderStateTransformer: Unknown folder sync state . Defaulting to Idle 
2017-09-19 14:40:31.3145 #14044 [Warn] SyncTrayzor.Syncthing.Folders.FolderStateTransformer: Unknown folder sync state . Defaulting to Idle 
2017-09-19 14:40:31.3215 #14044 [Warn] SyncTrayzor.Syncthing.Folders.FolderStateTransformer: Unknown folder sync state . Defaulting to Idle 
...

With few:

...
2017-09-19 14:40:31.4150 #14044 [Warn] SyncTrayzor.Syncthing.Folders.FolderStateTransformer: Unknown folder sync state . Defaulting to Idle 
2017-09-19 14:41:08.4241 #14044 [Warn] SyncTrayzor.Syncthing.ApiClient.SyncthingHttpClientHandler: Non-successful status code. StatusCode: 500, ReasonPhrase: 'Internal Server Error', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:
{
  Access-Control-Allow-Origin: *
  Pragma: no-cache
  X-Content-Type-Options: nosniff
  X-Syncthing-Id: IDIDID_IDIDID_IDIDID
  X-Syncthing-Version: v0.14.37
  Cache-Control: no-store, no-cache, max-age=0
  Date: Tue, 19 Sep 2017 11:41:08 GMT
  Content-Length: 15
  Content-Type: text/plain; charset=utf-8
  Expires: Tue, 19 Sep 2017 11:41:08 GMT
} no such folder 
2017-09-19 14:41:10.5415 #14044 [Warn] SyncTrayzor.Syncthing.ApiClient.SyncthingHttpClientHandler: Non-successful status code. StatusCode: 500, ReasonPhrase: 'Internal Server Error', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:
{
  Access-Control-Allow-Origin: *
  Pragma: no-cache
  X-Content-Type-Options: nosniff
  X-Syncthing-Id: IDIDID_IDIDID_IDIDID
  X-Syncthing-Version: v0.14.37
  Cache-Control: no-store, no-cache, max-age=0
  Date: Tue, 19 Sep 2017 11:41:10 GMT
  Content-Length: 15
  Content-Type: text/plain; charset=utf-8
  Expires: Tue, 19 Sep 2017 11:41:10 GMT
} no such folder 
2017-09-19 14:42:16.0992 #14044 [Info] SyncTrayzor.Services.MemoryUsageLogger: Working Set: 176MiB. Private Memory Size: 126MiB. GC Total Memory: 21MiB 
2017-09-19 14:42:40.5121 #14044 [Warn] SyncTrayzor.Syncthing.ApiClient.SyncthingHttpClientHandler: Non-successful status code. StatusCode: 500, ReasonPhrase: 'Internal Server Error', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:
{
  Access-Control-Allow-Origin: *
  Pragma: no-cache
  X-Content-Type-Options: nosniff
  X-Syncthing-Id: IDIDID_IDIDID_IDIDID
  X-Syncthing-Version: v0.14.37
  Cache-Control: no-store, no-cache, max-age=0
  Date: Tue, 19 Sep 2017 11:42:40 GMT
  Content-Length: 15
  Content-Type: text/plain; charset=utf-8
  Expires: Tue, 19 Sep 2017 11:42:40 GMT
} no such folder 
2017-09-19 14:47:16.0896 #14044 [Info] SyncTrayzor.Services.MemoryUsageLogger: Working Set: 176MiB. Private Memory Size: 126MiB. GC Total Memory: 21MiB 
2017-09-19 14:52:16.0952 #14044 [Info] SyncTrayzor.Services.MemoryUsageLogger: Working Set: 176MiB. Private Memory Size: 126MiB. GC Total Memory: 20MiB 
2017-09-19 14:53:43.6061 #14044 [Warn] SyncTrayzor.Syncthing.Folders.FolderStateTransformer: Unknown folder sync state . Defaulting to Idle 
2017-09-19 14:53:43.8743 #14044 [Warn] SyncTrayzor.Syncthing.Folders.FolderStateTransformer: Unknown folder sync state . Defaulting to Idle 
2017-09-19 14:53:43.8743 #14044 [Warn] SyncTrayzor.Syncthing.Folders.FolderStateTransformer: Unknown folder sync state . Defaulting to Idle 
...

And few:

...
2017-09-19 20:05:58.4840 #24012 [Warn] SyncTrayzor.Syncthing.Folders.FolderStateTransformer: Unknown folder sync state . Defaulting to Idle 
2017-09-19 20:05:58.5291 #24012 [Error] SyncTrayzor.Services.Conflicts.ConflictFileManager: Failed to enumerate files in folder <PATH>: OperationCanceledException The operation was canceled. System.OperationCanceledException The operation was canceled. Void ThrowOperationCanceledException()    at System.Threading.CancellationToken.ThrowOperationCanceledException()
   at SyncTrayzor.Services.Conflicts.ConflictFileManager.<>c__DisplayClass13_0.<FindConflictsImpl>b__2() in C:\projects\synctrayzor\src\SyncTrayzor\Services\Conflicts\ConflictFileManager.cs:line 204
   at SyncTrayzor.Services.Conflicts.ConflictFileManager.TryFilesystemEnumeration(Action action, String path, String itemType) in C:\projects\synctrayzor\src\SyncTrayzor\Services\Conflicts\ConflictFileManager.cs:line 226 System.OperationCanceledException: The operation was canceled.
   at System.Threading.CancellationToken.ThrowOperationCanceledException()
   at SyncTrayzor.Services.Conflicts.ConflictFileManager.<>c__DisplayClass13_0.<FindConflictsImpl>b__2() in C:\projects\synctrayzor\src\SyncTrayzor\Services\Conflicts\ConflictFileManager.cs:line 204
   at SyncTrayzor.Services.Conflicts.ConflictFileManager.TryFilesystemEnumeration(Action action, String path, String itemType) in C:\projects\synctrayzor\src\SyncTrayzor\Services\Conflicts\ConflictFileManager.cs:line 226
2017-09-19 20:06:01.4390 #24012 [Warn] SyncTrayzor.Syncthing.Folders.FolderStateTransformer: Unknown folder sync state . Defaulting to Idle 
...

It’s going on like that for the whole day, and doesn’t look like it’s about to settle. Restarts has no effect, upgrade to 0.14.38 just happened, the behavior continues as before…

Any suggestions? I’m not even sure who to blame, is it ST? Is it SyncTrayzor not playing ball with the recent FS refactor? Maybe @canton7 has any wise words to add?

(ST v.0.14.37+38, SyncTrayzor v.1.1.18, Win10x64)

That means I got a folder state of ‘’ (emptystring) from Syncthing, probably from the FolderStateChanged event or from fetching the config. That shouldn’t affect much, but does mean that I won’t suppress change notifications while Syncthing is changing files as a result of synchronising.

That’s a bit more of a concern. It might make sense with the state stuff if Syncthing is giving me a weird entry in the config or some such. Mind fetching /rest/system/config, see what the folders entry says?

Don’t worry about the conflict file manager stuff - it’s probably scanning for file conflicts, then aborting those scans as new changes are received. I’ll tidy up the logging there.

Try disabling the filesystem notifications in SyncTrayzor - that will take it out of the loop.

None of this explains why temporary files are created, right? To me that sounds like it concerns syncthing not synctrayzor.

Temporary files not becoming normal files would mean some errors in the log, so I suggest the user starts there.

Update:

So I managed to get out of the loop by the following: On the PC that had all the modifications and .tmp files, copy the whole thing aside to be safe, then I shut down syncthing, deleted all the .tmp files manually, then back in syncthing set the troubled folder as send-only (master) and hit “override changes”. After a while it seemingly settled.

However, 15 mins later it reappeared as “out of sync” again, showing local state 41GB (as it should) and global state as 1GB. I checked the other online PC, and it got all the renamed_files.ext deleted. I hit “override changes” on the source PC again, and now it is in the middle of re-uploading all 40GB from scratch.

Side note - I remember github issue about “case-only renames breaking stuff”, i had such renames to some of the subfolders, so it might be related.

As Audrius said above, logs from Syncthing would be very helpful (hopefully).

I went throuth the log bit more, seems like this is why temps remain:

 [IDIDID-9] 08:55:27 INFO: Puller (folder "FOLDER-12", file "FILE.EXT"): dst create: open \?e:\PATH\~syncthing~FILE.EXT.tmp: The file exists.
 [IDIDID-9] 08:55:27 INFO: Puller: final: open \?e:\PATH\~syncthing~FILE.EXT.tmp: The file exists.

full(er) log: https://gist.github.com/anonymous/8a3b9091e104d8b08c98def4e39f0d5c

Do you have two syncthings handling the same folder or something like that? Or did some funny pausing business before this happened?

Regardless it should have fixed itself shortly after this.

I think that error is a red herring, as it’s a one off and I suspect you have nested folders that caused it.

Anyways, everything looks fine from the logs. If you have nested folders it’s possible that they started stepping on each others toes.

Nope, only one instance exists on this PC. Nothing nested.

The funny pausing business you see: When i tried to set it as master, I paused all folders and resumed only the problematic one to make restarts more tolerable (this PC has few tens of shares, so each restart takes very long time with all enabled)

Unfortunately not a one-off either:

While making logs, i put them in a shared directory, and renamed and moved some old files there - and it just happened again - renamed files got their evil-twin ~syncthing~st.log.tmp copies created. Here’s what was logged at the same time:

 [IDIDID-9] 23:17:52 INFO: Established secure connection to IDIDIDID-13 at LOCAL-IPv4-1.2:63601-95.97.92.221:22067 (relay-server) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
 [IDIDID-9] 23:17:52 INFO: Device IDIDIDID-13 client is "syncthing v0.14.37" named "DEVICE-13"
 [IDIDID-9] 23:18:45 INFO: TLS handshake (BEP/tcp): read tcp LOCAL-IPv4-1.2:22000->IPv4-3:35870: wsarecv: An existing connection was forcibly closed by the remote host.
 [IDIDID-9] 23:19:05 INFO: Established secure connection to IDIDIDID-13 at LOCAL-IPv4-1.2:22000-IPv4-3:35873 (tcp-server) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
 [IDIDID-9] 23:19:05 INFO: Replacing old connection LOCAL-IPv4-1.2:63601-95.97.92.221:22067/relay-server with LOCAL-IPv4-1.2:22000-IPv4-3:35873/tcp-server for IDIDIDID-13
 [IDIDID-9] 23:19:05 INFO: Connection to IDIDIDID-13 closed: reading length: EOF
 [IDIDID-9] 23:19:05 INFO: Device IDIDIDID-13 client is "syncthing v0.14.37" named "DEVICE-13"
 [IDIDID-9] 23:21:32 INFO: Folder "FOLDER-86" isn't making progress. Pausing puller for 1m0s.
 [IDIDID-9] 23:22:33 INFO: Folder "FOLDER-86" isn't making progress. Pausing puller for 1m0s.
 [IDIDID-9] 23:22:41 INFO: Folder "FOLDER-86" isn't making progress. Pausing puller for 1m0s.
 [IDIDID-9] 23:25:24 INFO: Removing NAT port mapping: external TCP address IPv4-2:19578, NAT ab9ab775-15d9-b098-3832-5c39f252d9e8 is no longer available.
 [IDIDID-9] 23:25:24 INFO: New NAT port mapping: external TCP address IPv4-2:65077 to local address 0.0.0.0:22000.
 [IDIDID-9] 23:27:50 INFO: Folder "FOLDER-86" isn't making progress. Pausing puller for 1m0s.
 [IDIDID-9] 23:28:18 INFO: Connection to IDIDIDID-10 closed: reading length: read tcp LOCAL-IPv4-1.2:22000->LOCAL-IPv4-1.11:43460: wsarecv: An existing connection was forcibly closed by the remote host.
 [IDIDID-9] 23:29:05 INFO: Connection to IDIDIDID-13 closed: read timeout
 [IDIDID-9] 23:29:32 INFO: Established secure connection to IDIDIDID-10 at [IPv6-5%Ethernet 2]:22000-[IPv6-6%Ethernet 2]:43338 (tcp-server) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
 [IDIDID-9] 23:29:32 INFO: Device IDIDIDID-10 client is "syncthing v0.14.38" named "DEVICE-10"
 [IDIDID-9] 23:30:46 INFO: Connected to already connected device (IDIDIDID-10)
 [IDIDID-9] 23:35:44 INFO: Folder "FOLDER-86" isn't making progress. Pausing puller for 1m0s.
 [IDIDID-9] 23:37:12 INFO: Folder "FOLDER-86" isn't making progress. Pausing puller for 1m0s.
 [IDIDID-9] 23:37:40 INFO: Connection to IDIDIDID-7 closed: reading length: read tcp LOCAL-IPv4-1.2:22000->IPv4-3:43848: wsarecv: An existing connection was forcibly closed by the remote host.
 [IDIDID-9] 23:38:13 INFO: Established secure connection to IDIDIDID-7 at LOCAL-IPv4-1.2:64240-95.97.92.221:22067 (relay-server) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
 [IDIDID-9] 23:38:13 INFO: Device IDIDIDID-7 client is "syncthing v0.14.37" named "DEVICE-7"
 [IDIDID-9] 23:38:22 INFO: Connection to IDIDIDID-7 closed: reading length: EOF
 [IDIDID-9] 23:38:50 INFO: Established secure connection to IDIDIDID-7 at LOCAL-IPv4-1.2:22000-IPv4-3:44234 (tcp-server) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
 [IDIDID-9] 23:38:50 INFO: Device IDIDIDID-7 client is "syncthing v0.14.37" named "DEVICE-7"
 [IDIDID-9] 23:40:58 INFO: Established secure connection to IDIDIDID-13 at LOCAL-IPv4-1.2:64349-37.120.167.213:22067 (relay-client) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
 [IDIDID-9] 23:40:58 INFO: Device IDIDIDID-13 client is "syncthing v0.14.37" named "DEVICE-13"
 [IDIDID-9] 23:41:00 INFO: Connection to IDIDIDID-13 closed: reading length: EOF
 [IDIDID-9] 23:43:11 INFO: Established secure connection to IDIDIDID-13 at LOCAL-IPv4-1.2:64442-95.97.92.221:22067 (relay-server) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
 [IDIDID-9] 23:43:11 INFO: Device IDIDIDID-13 client is "syncthing v0.14.37" named "DEVICE-13"
 [IDIDID-9] 23:43:11 INFO: Connection to IDIDIDID-13 closed: reading length: EOF
 [IDIDID-9] 23:45:30 INFO: Folder "FOLDER-86" isn't making progress. Pausing puller for 1m0s.
 [IDIDID-9] 23:46:38 INFO: Connection to IDIDIDID-3 closed: reading length: read tcp LOCAL-IPv4-1.2:22000->77.127.7.244:32768: wsarecv: An existing connection was forcibly closed by the remote host.
 [IDIDID-9] 23:47:53 INFO: Folder "FOLDER-86" isn't making progress. Pausing puller for 1m0s.
 [IDIDID-9] 23:48:53 INFO: Folder "FOLDER-86" isn't making progress. Pausing puller for 1m0s.
 [IDIDID-9] 23:50:48 INFO: Folder "FOLDER-86" isn't making progress. Pausing puller for 1m0s.
 [IDIDID-9] 23:53:19 INFO: Folder "FOLDER-86" isn't making progress. Pausing puller for 1m0s.
 [IDIDID-9] 23:54:11 INFO: Folder "FOLDER-86" isn't making progress. Pausing puller for 1m0s.
 [IDIDID-9] 23:55:28 INFO: Folder "FOLDER-86" isn't making progress. Pausing puller for 1m0s.
 [IDIDID-9] 23:56:07 INFO: Folder "FOLDER-86" isn't making progress. Pausing puller for 1m0s.
 [IDIDID-9] 23:56:26 INFO: Folder "FOLDER-86" isn't making progress. Pausing puller for 1m0s.
 [IDIDID-9] 23:57:36 INFO: Folder "FOLDER-86" isn't making progress. Pausing puller for 1m0s.
 [IDIDID-9] 23:58:54 INFO: Folder "FOLDER-86" isn't making progress. Pausing puller for 1m0s.
 [IDIDID-9] 23:59:32 INFO: Folder "FOLDER-86" isn't making progress. Pausing puller for 1m0s.

FOLDER-86 is the one where evil-twins just got born.

The errors don’t explain much. Perhaps there is a better explanations for failures in the out of sync dialog in the UI?

Also devices are coming on and off, which could be that we are informed of files we need to pull, but the device that has them disconnects, so we end up with the temp files until the device reappears.

I’d fix connection flakyness issues and then see if you can get a clear concise repeatable reproducer.

I don’t think connections have any relevance, since all the temp files created are copies of local modifications. Remote PC did not perform any file renames/modifications whatsoever that’s the whole issue - local changes create tmp files as they are remote.

I’ll try to find a clean reproducible scenario.

I am having the same problem.

If you have a case insensitive Mac, try creating something like this with two systems:

  1. mkdir foo
  2. Add many things to foo
  3. Decide foo should be split into multiple projects. At this point both systems should be fully synced. Disconnect one system.
  4. mv foo foo-tmp
  5. mkdir Foo
  6. mv foo-tmp Foo
  7. Reconnect the disconnected system
  8. Reconnected system should have foo/foo not Foo/foo

I believe this is what has got me into this state where my two devices cannot synchronize.

OK, so I played with it for a while:

Definitely not a one-off, but not an easy-reproduce either.

It happened 4 more times.

What happened? - Local filename modifications trigger creation of .tmp duplicates of themselves locally by Syncthing.

What I was doing? - Batch renames of files and moving them across sub-directories, but sometimes only renames triggered it as well.

the only thing that reflected by logs is a bunch of

[IDIDID] 09:22:41 INFO: Folder "FOLDER-TEST" isn't making progress. Pausing puller for 1m0s.

appear, as in the logs above, but that’s it. Later I tried enabling extra logging, but then failed to reproduce it :frowning:

Also, a scary side note:

Case-only renames (Case-only renames break stuff · Issue #1787 · syncthing/syncthing · GitHub) can cause some serious troubles. In one occurrence, just renaming TEST directory to test caused deletion (locally!) of all the files inside this directory, and propagated it to all other nodes.

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.