"Out Of Sync" - First use of Syncthing beween Synology and W10

vdeconinck · May 21, 2020, 12:54pm

I have to admit I find it a bit worrisome…

I have added a new folder to sync and the number has risen to 259 “out of sync” items

Do you know if that known issue only affects the first sync (in which case I can try to “fix” the out of sync items by hand, e.g. by moving them out and back in the folders), or do they come back randomly? The number of synced files now is about 50000 on 2 machines, but if I settle on Syncthing for all my sync needs, that will be around 10 times more, spread on 4 machines, and I’m afraid I’ll soon overlook those warnings and my family and I will end up having an wrong feeling of safety.

Can I help narrow down the issue ?

KR,

Vincent

Edit: Even more weird: the “Device” section mentions 259 “out of sync” files, but on the new “CDRom” folder alone, it says 656 items are “out of sync” (?):

If I click on the link on those 656 items in the “CDRom” folder, I’m getting this:

imsodin · May 21, 2020, 1:09pm

The folder and remote device out of sync displays are independent - it’s totally fine for them to show different numbers. The folder one shows how many files need updating for the local device to get up to date, the remote one shows how many files the remote device needs.

In your case the folder is “send-only”, so this means the remote changed those files and it refuses to accept those changes (because it’s send-only). They should go away when you click override changes, but beware that means the remote will get their changes overwritten by what the send-only device has.

vdeconinck · May 21, 2020, 5:47pm

Hi imsodin, thanks for your reply.

Makes much sense. I checked that the changes did not matter and chose to override them, and now the 656 “out of sync” items in the CDRom folder have disappeared. Great.

Regarding the 259 items on the right of the PC UI, if I understand correctly, it means that the remote (NAS) needs them.

But what’s strange is that on the NAS UI, it also says 259 items are out of sync (and yes, they’re the same):

Any idea how to solve this issue ?

Kind regards,

Vincent

imsodin · May 21, 2020, 6:12pm

Anything special about those items? Does the case of the filenames on disk differ (e.g. foobar vs fooBar)?

vdeconinck · May 21, 2020, 8:52pm

Hmmm, no, the files all originated from Windows, so two files with different case in the same folder is impossible. Could I find the reason for unsync’d files somewhere in the logs ?

Anyway, I performed two tests on two set of files to try and resync.

For the Audio folder, I moved the offending files out of the source (Win) dir, then forced a resync. Syncthing proposed to override (which I did), and remote files were deleted. I then brought back the files into the original Windows folder and a second sync uploaded the files fine (they disappeared from the “out of sync” list on both sides).
For the CDRom folder, I acted differently : I deleted a set of files listed as “out of sync” from the NAS. I then forced a resync and the files did reappear on the NAS, but they are still listed in the “out of sync” list on the NAS UI.

In this case, I don’t understnand how they could be “needed on the NAS”, because syncthing on the NAS just redownloaded them…

What is the recommended way to bring two folders back in sync ?

Plus, I still have plenty of unsync’d files. If I can grab logs or something that might help understand where the issue lies, I’d be glad to help.

Of course, it could also be yet another usage error on my part

KR,

Vincent

imsodin · May 22, 2020, 7:36am

If the local/global state in the expanded folders match, the folders are likely in sync and “just” the remote device accounting is incorrect.

For further analysis why, please post the output of https://docs.syncthing.net/rest/db-file-get.html for one of the out-of-sync-items (curl example: https://docs.syncthing.net/dev/rest.html#api-key, windows howto: [ How To ] call the REST API from Windows PowerShell).

vdeconinck · May 22, 2020, 7:58pm

Indeed, local=global, which is good

However, I just noticed that the numbers for the “Audio” folder (which shows no “out of sync” files on either side anymore) are different on Win (18 250) vs NAS (18 275). Mmmh 25 files more on the NAS ? Weird.

Thanks for the very helpful links. Here’s the JSON result for one such “out of sync” files:

From Windows:

{
  "availability": null,
  "global": {
    "deleted": false,
    "ignored": false,
    "invalid": false,
    "localFlags": 0,
    "modified": "2014-01-20T23:20:14+01:00",
    "modifiedBy": "HQMIU6O",
    "mustRescan": false,
    "name": "Raspberry Pi\\magPi-FR\\The-MagPi-issue-8-fr.pdf",
    "noPermissions": false,
    "numBlocks": 117,
    "permissions": "0644",
    "sequence": 32846,
    "size": 15229723,
    "type": "FILE",
    "version": [
      "HQMIU6O:1"
    ]
  },
  "local": {
    "deleted": false,
    "ignored": false,
    "invalid": false,
    "localFlags": 0,
    "modified": "2014-01-20T23:20:14+01:00",
    "modifiedBy": "HQMIU6O",
    "mustRescan": false,
    "name": "Raspberry Pi\\magPi-FR\\The-MagPi-issue-8-fr.pdf",
    "noPermissions": false,
    "numBlocks": 117,
    "permissions": "0644",
    "sequence": 32846,
    "size": 15229723,
    "type": "FILE",
    "version": [
      "HQMIU6O:1"
    ]
  }
}

Same request from the NAS:

{
  "availability": null,
  "global": {
    "deleted": false,
    "ignored": false,
    "invalid": false,
    "localFlags": 0,
    "modified": "2014-01-20T23:20:14.1065494+01:00",
    "modifiedBy": "7PUJGCV",
    "mustRescan": false,
    "name": "Raspberry Pi/magPi-FR/The-MagPi-issue-8-fr.pdf",
    "noPermissions": true,
    "numBlocks": 117,
    "sequence": 4179,
    "size": 15229723,
    "type": "FILE",
    "version": [
      "7PUJGCV:1"
    ]
  },
  "local": {
    "deleted": false,
    "ignored": false,
    "invalid": false,
    "localFlags": 0,
    "modified": "2014-01-20T23:20:14.1065494+01:00",
    "modifiedBy": "7PUJGCV",
    "mustRescan": false,
    "name": "Raspberry Pi/magPi-FR/The-MagPi-issue-8-fr.pdf",
    "noPermissions": true,
    "numBlocks": 117,
    "sequence": 4179,
    "size": 15229723,
    "type": "FILE",
    "version": [
      "7PUJGCV:1"
    ]
  }
}

I admit I don’t see much difference… Do you ?

KR,

Vincent

imsodin · May 22, 2020, 8:12pm

The versions are different. The NAS should show the file as out of sync on the folder. Can you get the stindex tool from https://build.syncthing.net/buildConfiguration/Syncthing_Tools/65961?buildTab=artifacts and run stindex -mode idxck /path/to/index-v0.14.0.db to check the db.

vdeconinck · May 22, 2020, 9:21pm

Hi,

I had to struggle a bit to find the .db location but I think I found it (please check below and tell me if it’s not the right path). I had shut down syncthing before to make sure not to mess with a live DB.

Here are the results on the NAS:

sudo /volume1/misc/stindex -mode idxck /var/packages/syncthing/target/var/index-v0.14.0.db

Sequence entry missing for FileInfo "Compilation/VLC-build/_05.06.J-coreutils/libiconv-1.13.1-2-msys-1.0.13-dll-2.tar.lzma", folder "dhftj-klqfe", seq 4191
Sequence entry missing for FileInfo "Compilation/VLC-build/_05.06.J-coreutils/coreutils-5.97-3-msys-1.0.13-ext.tar.lzma", folder "dhftj-klqfe", seq 4193
Sequence entry missing for FileInfo "Raspberry Pi/magPi-FR/The-MagPi-issue-7-fr.pdf", folder "dhftj-klqfe", seq 4181
Sequence entry missing for FileInfo "Compilation/VLC-build/_05.06.J-coreutils/libintl-0.17-2-msys-dll-8.tar.lzma", folder "dhftj-klqfe", seq 4192
Sequence entry missing for FileInfo "Compilation/VLC-build/_03.B-02-msys/MSYS-1.0.11.exe", folder "dhftj-klqfe", seq 4198
Sequence entry missing for FileInfo "Raspberry Pi/magPi-FR/The-MagPi-issue-5-fr.pdf", folder "dhftj-klqfe", seq 4180
Sequence entry missing for FileInfo "Compilation/VLC-build/_08.H-09.2-msys-pkg-config/glib_2.18.2-1_win32.zip", folder "dhftj-klqfe", seq 4196
Sequence entry missing for FileInfo "Compilation/VLC-build/_02.F-04-mingw-utils/mingw-utils-0.3.tar.gz", folder "dhftj-klqfe", seq 4197
Sequence entry missing for FileInfo "Compilation/VLC-build/_08.H-09.2-msys-pkg-config/pkg-config_0.23-3_win32.zip", folder "dhftj-klqfe", seq 4195
Sequence entry missing for FileInfo "Raspberry Pi/magPi-FR/The-MagPi-issue-8-fr.pdf", folder "dhftj-klqfe", seq 4179
Sequence entry missing for FileInfo "Compilation/VLC-build/_08.H-09.2-msys-pkg-config/pkg-config-dev_0.23-3_win32.zip", folder "dhftj-klqfe", seq 4194
Folder 2 missing 3 sequence entries: #4179 - #4181
Folder 2 missing 8 sequence entries: #4191 - #4198
Missing need entry for needed file ".sync", folder "dhftj-klqfe"
Missing need entry for needed file ".sync/ID", folder "dhftj-klqfe"
Missing need entry for needed file ".sync/IgnoreList", folder "dhftj-klqfe"
Missing need entry for needed file ".sync/Archive", folder "dhftj-klqfe"
Missing need entry for needed file ".sync/StreamsList", folder "dhftj-klqfe"

Note that it’s the whole file. The “out of sync” file I checked via REST above (The-MagPi-issue-8-fr.pdf) is included with a “Sequence entry missing” but there are only 10 other files listed while the UI says there are 115 “out of sync”… Also note that the missing “.sync” (5 last lines) relate to a previous evaluation of Resilio Sync (which of course does not synchronize those folders anymore). The list of excluded patterns does include “.sync” on both sides though…

For reference, running stindex on the Win PC lists 223 “Sequence entry missing” although the UI says there are 234 “out of sync” files, so we’re much closer.

Does this help ?

KR,

Vincent

Andy · May 23, 2020, 8:42am

Do you still use Resilio in parallel? If so, some ignore patterns are needed, otherwise you will have problems when folder overlaps.

Regarding ignore patterns, Syncthing has no standard ignore patterns that are defined in principle or globally. In any case, I don’t know anything about it. The problem may be that Windows files are synchronized that Syncthing may not be able to delete from the NAS later if you delete them on Windows. Then you have to intervene manually, otherwise differences can occur.

I have also Synology for myself, DS412+, 415+, 1815+ and Synology is known to be something special with the ACLs. For example, the file Thumbs.db, which is a typical Windows file, had proven to be a “classic problem” for me. Without ignore patterns, this is of course synced and is also on the NAS. Therefore I use an entry in the Ignore list (?D)(?I)Thumbs.db, which means that no distinction is made between upper and lower case and the file is not transferred, because is ignored, but can be deleted if the process needs. There are other files that I have defined for all peers, since then it runs well, for example I define

(?d)(?i)Thumbs.db
(?d)(?i).thumbnails
(?d)(?i)ehthumbs.db
(?d)(?i)desktop.ini

The only thing that helps is to examine such things and make tests.

vdeconinck · May 24, 2020, 7:27am

Hi Andy, and thanks for replying.

As I said Resilio does not synchronize those folders anymore (it’s still running for other folders until I decide to switch to Syncthing) but they don’t overlap.

I currently exclude the patterns in the screenshot below, in each folder and on each side: 2020-05-24_0925

I will add your patterns. That could explain the difference in numbers, but not the list of “out of sync” files I guess…

KR,

Vincent

vdeconinck · May 24, 2020, 8:58am

I just did another test to check if those alerts are real: compare Win and NAS folders using FreeFileSync.

The result shows that the file reported as “out of sync” and analyzed above (“Raspberry Pi/magPi-FR/The-MagPi-issue-8-fr.pdf”) is, in fact, in sync.

However, some others are not, and they are not reported anymore!

Remember there were first 259 “out of sync” files on the NAS, and trying to force a resync, I deleted a part of them (one folder) from the NAS and forced a resync on both sides. They disappeared from the “out of sync” list, bringing the number down to 115 files… but they were not actually copied :

I think this is the worst scenario: having a file sync system in place advertising green “Up to date” messages while there are actually missing files, as it gives a false feeling of security.

This clearly looks like a bug to me (if there is a permission or other issue, it should show up as an error I guess).

What do you think ? How can I help track down this bug ?

KR,

Vincent

Andy · May 24, 2020, 9:37am

I doesnt see anythink in your discussions here. My experience and is also discussed in the forum several times, to set in each peer “Ignore permissions” checked. So best is to test it.

Maybe read in the linked thread the discussion about.

imsodin · May 24, 2020, 11:19am

The sequence entry missing errors are the/a problem. While we don’t know the underlying cause of that problem, there is a fix in v1.6.0 that prevents one way how it can occur. I hope it’s the only way, but given I don’t know the root cause, I can’t be sure.

Now for the files that aren’t synced: Are any of those mentioned in the stindex output? If not, can you get the output of the /rest/db/file endpoint for one of those files?

To fix your current sequence related issues without upgrading, you could run Syncthing once with the STRECHECKDBEVERY=1s environment variable set. However lets first investigate the second, more serious issue, and then go on to this step.

vdeconinck · May 25, 2020, 4:51pm

Hi Andy,

Thanks for the suggestion. I had followed instructions on the kastelo.net page linked above so had already checked “Ignore permissions” on folders on the NAS, but I had left it by default (unchecked) on the Windows PC. I now just checked the option on Windows too…

Let’s see what it brings.

Edit: No change…

Vincent

PS: And, agreed, Synology’s take on ACL is really nasty.

vdeconinck · May 25, 2020, 5:20pm

Hi imsodin,

The missing files are not listed in the stindex output on the NAS, but they are listed in the stindex output from the Win PC, as Sequence entry missing.

So basically, that’s the issue to focus on, and I guess the first thing to do would be to upgrade to the test 1.6 version ? (Or can I still help understand what caused those “Sequence entry missing” ?)

If I go for the upgrade, a few questions then:

On Windows, I’m currently using Synctrayzor 1.1.24. What staging version would you suggest to install ?
Do you also suggest upgrading on the NAS ? And if so, is there a “staging” synology community package ?

Kind regards,

Vincent

imsodin · May 25, 2020, 5:45pm

Synctrayzor uses auto-upgrading, i.e. you can select release candidates in the settings menu of the web UI. Try the same for synology, maybe the use that too - I have no clue about that package.

If you don’t want to use release candidates, you can use this suggestion to fix the current problem:

If you can make the problem reappear, logs with db,walkfs enabled might help find the root cause. But beware those logs will be huge, you shouldn’t do that without redirecting your logs and monitoring their. Aka really only do this if you want to invest time.

vdeconinck · May 25, 2020, 7:19pm

Hi imsodin,

First let me thank you again for your help. It’s much appreciated!

Makes sense.

I just tried that route first indeed. I guessed the environment variable should be on the Windows side only, right ?

Here is the log:

[monitor] 20:25:25 INFO: Log output saved to file "C:\Users\Vincent\AppData\Local\Syncthing\syncthing.log"
[start] 20:25:25 INFO: syncthing v1.5.0 "Fermium Flea" (go1.13.10 windows-amd64) teamcity@build.syncthing.net 2020-04-21 20:45:03 UTC
[start] 20:25:25 INFO: Using large-database tuning
[HQMIU] 20:25:25 INFO: My ID: HQMIU6O
[HQMIU] 20:25:26 INFO: Single thread SHA256 performance is 204 MB/s using minio/sha256-simd (156 MB/s using crypto/sha256).
[HQMIU] 20:25:27 INFO: Hashing performance is 173.87 MB/s
[HQMIU] 20:25:27 INFO: Overall send rate is unlimited, receive rate is unlimited
[HQMIU] 20:25:27 INFO: Using discovery server https://discovery.syncthing.net/v2/?noannounce&id=LYXKCHX
[HQMIU] 20:25:27 INFO: Using discovery server https://discovery-v4.syncthing.net/v2/?nolookup&id=LYXKCHX
[HQMIU] 20:25:27 INFO: Using discovery server https://discovery-v6.syncthing.net/v2/?nolookup&id=LYXKCHX
[HQMIU] 20:25:27 INFO: Stored folder metadata for "dhftj-klqfe" is 105h14m45.5423799s old; recalculating
[HQMIU] 20:25:27 INFO: Relay listener (dynamic+https://relays.syncthing.net/endpoint) starting
[HQMIU] 20:25:27 INFO: QUIC listener ([::]:22000) starting
[HQMIU] 20:25:27 INFO: TCP listener ([::]:22000) starting
[HQMIU] 20:25:27 INFO: GUI and API listening on 127.0.0.1:8384
[HQMIU] 20:25:27 INFO: Access the GUI via the following URL: http://localhost:8384/
[HQMIU] 20:25:27 INFO: My name is "PC Vincent"
[HQMIU] 20:25:27 INFO: Device 7PUJGCV is "NAS1812+" at [dynamic]
[HQMIU] 20:25:27 INFO: Established secure connection to 7PUJGCV at [2a02:1811:507d:2d00:88fb:8444:3750:88c]:58699-[2a02:1811:507d:2d00:211:32ff:fe13:c31b]:22000/tcp-client/TLS1.3-TLS_CHACHA20_POLY1305_SHA256
[HQMIU] 20:25:27 INFO: Device 7PUJGCV client is "syncthing v1.5.0" named "NAS1812+" at [2a02:1811:507d:2d00:88fb:8444:3750:88c]:58699-[2a02:1811:507d:2d00:211:32ff:fe13:c31b]:22000/tcp-client/TLS1.3-TLS_CHACHA20_POLY1305_SHA256
[HQMIU] 20:25:29 INFO: Repaired 223 sequence entries in database
[HQMIU] 20:25:29 INFO: Connection to 7PUJGCV at [2a02:1811:507d:2d00:88fb:8444:3750:88c]:58699-[2a02:1811:507d:2d00:211:32ff:fe13:c31b]:22000/tcp-client/TLS1.3-TLS_CHACHA20_POLY1305_SHA256 closed: started folder "CDRom" (dhftj-klqfe)
[HQMIU] 20:25:29 INFO: Ready to synchronize "CDRom" (dhftj-klqfe) (sendonly)
[HQMIU] 20:25:29 INFO: Stored folder metadata for "nq7qk-mczvt" is 140h28m36.5190667s old; recalculating
[HQMIU] 20:25:30 INFO: Ready to synchronize "Audio" (nq7qk-mczvt) (sendonly)
[HQMIU] 20:25:31 INFO: Established secure connection to 7PUJGCV at [2a02:1811:507d:2d00:88fb:8444:3750:88c]:58759-[2a02:1811:507d:2d00:211:32ff:fe13:c31b]:22000/tcp-client/TLS1.3-TLS_CHACHA20_POLY1305_SHA256
[HQMIU] 20:25:31 INFO: Device 7PUJGCV client is "syncthing v1.5.0" named "NAS1812+" at [2a02:1811:507d:2d00:88fb:8444:3750:88c]:58759-[2a02:1811:507d:2d00:211:32ff:fe13:c31b]:22000/tcp-client/TLS1.3-TLS_CHACHA20_POLY1305_SHA256
[HQMIU] 20:25:31 INFO: Connection to 7PUJGCV at [2a02:1811:507d:2d00:88fb:8444:3750:88c]:58759-[2a02:1811:507d:2d00:211:32ff:fe13:c31b]:22000/tcp-client/TLS1.3-TLS_CHACHA20_POLY1305_SHA256 closed: reading length: read tcp [2a02:1811:507d:2d00:88fb:8444:3750:88c]:58759->[2a02:1811:507d:2d00:211:32ff:fe13:c31b]:22000: wsarecv: Une connexion existante a dû être fermée par l’hôte distant.
[HQMIU] 20:25:37 INFO: Completed initial scan of sendonly folder "Audio" (nq7qk-mczvt)
[HQMIU] 20:25:38 INFO: Detected 0 NAT services
[HQMIU] 20:25:46 INFO: quic://0.0.0.0:22000 detected NAT type: Port restricted NAT
[HQMIU] 20:25:46 INFO: quic://0.0.0.0:22000 resolved external address quic://195.16.0.126:22000 (via stun.syncthing.net:3478)
[HQMIU] 20:25:48 INFO: Completed initial scan of sendonly folder "CDRom" (dhftj-klqfe)
[HQMIU] 20:26:05 INFO: Joined relay relay://163.172.60.25:22067
[HQMIU] 20:26:25 INFO: Established secure connection to 7PUJGCV at [fe80::a8be:8658:f1b2:ed41%Ethernet]:22000-[fe80::211:32ff:fe13:c31b%Ethernet]:46649/tcp-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256
[HQMIU] 20:26:25 INFO: Device 7PUJGCV client is "syncthing v1.5.0" named "NAS1812+" at [fe80::a8be:8658:f1b2:ed41%Ethernet]:22000-[fe80::211:32ff:fe13:c31b%Ethernet]:46649/tcp-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256
[HQMIU] 20:26:35 INFO: Failed to exchange Hello messages with 7PUJGCV at [2a02:1811:507d:2d00:88fb:8444:3750:88c]:22000-[2a02:1811:507d:2d00:211:32ff:fe13:c31b]:48531/tcp-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256: EOF
[HQMIU] 20:26:35 INFO: Failed to exchange Hello messages with 7PUJGCV at [2a02:1811:507d:2d00:4086:4afe:153f:6768]:22000-[2a02:1811:507d:2d00:211:32ff:fe13:c31b]:56316/tcp-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256: write tcp [2a02:1811:507d:2d00:4086:4afe:153f:6768]:22000->[2a02:1811:507d:2d00:211:32ff:fe13:c31b]:56316: wsasend: Une connexion existante a dû être fermée par l’hôte distant.
[HQMIU] 20:26:38 WARNING: Non-increasing sequence detected: Checking and repairing the db...
[HQMIU] 20:26:39 INFO: Repaired %v sequence entries in database 174

So it seems the “Non-increasing sequence detected: Checking and repairing the db…” did the trick.

By the way, you said to run Syncthing once with the env. variable, but why not leave it so that DB is checked at every startup ? Or is it “risky” or does it use system resources during the whole time the program is running ?

Anyway, now the UI reports only 11 “out of sync” items on both sides (the same set, and by the way, the “Raspberry Pi\magPi-FR\The-MagPi-issue-8-fr.pdf” is still part of it ) although they are, in fact, in sync (just checked with a bit-by-bit comparison)

What would be your suggestion to fix these false “out of sync” ?

Kind regards,

Vincent

imsodin · May 25, 2020, 8:36pm

With an interval of 1s it doesn’t only do it on startup, but every time a folder is “opened in the db”, which is e.g. also when you pause and unpause a folder. And it can be costly depending on folder size. Otherwise it’s not risky, just shouldn’t be necessary.

vdeconinck · May 28, 2020, 8:04pm

Hi,

I tried moving the 11 “out of sync” items out of the Windows folder, let a sync complete, then bring those files back in, but the result is the same.

Could you advise the recommended way to get rid of those “false out of sync” files ?

Kind regards,

Vicent