[v1.6.1] SO>SR target misses 10 elements, not showing them

[Catfriend1]

Hi,

I’m currently on v1.6.1 with an SO>SR Duplicati “backup” cluster where SO sends to SR periodically while Duplicati is not running.

SO, device A:

SR, device B:

If I click 10 items on B, nothing shows up.

I’ve restarted Syncthing on both nodes, clicked “Rescan” and waited a while, but nothing else changes or happens.

Btw: I’ve already checked device A’s ignore patterns and don’t see any mistake. I’ve ignored one folder (months ago on v1.5.0 already) because I don’t want it to be synced over to the target and the target doesn’t have this folder.

Which logs should I grab next?

Thank you.

Kind regards Catfriend1

[imsodin (Simon)]

Ignores are likely not the culprit here, that’s been a consistent problem ages ago but I can’t actually remember any recent issues with ignores.

The numbers not matching the list of items in the modal points at a mistake in the new “need accounting”. That stores the numbers of needed files for efficiency, separate from the storage of the actual needed items (the latter hasn’t changed). Unfortunately that’s super hard to debug without a reproducer, as it’s just a few cumulative numbers that are wrong, no history or even just which files are involved is visible.

When you click on the 6 out of sync items on A, is the modal empty too?

[Catfriend1]

Hi @imsodin !

I’ve clicked on the 6 out of sync items on device A and it’s showing the following:

Should I now take a backup of the two databases for you or try STRECHECKDBEVERY=0 ?

[Catfriend1]

So what I did on device B:

1. service syncthing stop (took a copy of the ST DB of device B)
2. export STRECHECKDBEVERY=0
3. /usr/bin/syncthing --no-browser --no-restart (waited some time)
4. ctrl+c
5. /usr/bin/syncthing --no-browser --no-restart --reset-deltas (waited for index exchange to complete between device A + B)
6. ctrl+c
7. service syncthing start
8. After that, device B started, I went to the Web UI and saw it syncing the files in question.

device A:

device B:

device B log:

device_B
2020-06-15 13:21:39 My ID: device_B-D75OLQA
2020-06-15 13:21:40 Single thread SHA256 performance is 78 MB/s using minio/sha256-simd (57 MB/s using crypto/sha256).
2020-06-15 13:21:41 Hashing performance is 68.19 MB/s
2020-06-15 13:21:41 Device *-F7H3EQC send rate is unlimited, receive rate limit is 1250 KiB/s
2020-06-15 13:21:41 Overall send rate is unlimited, receive rate is unlimited
2020-06-15 13:21:41 Stored folder metadata for "banz2-7xtft" is 442283h21m41.200489647s old; recalculating
2020-06-15 13:21:41 TCP listener (0.0.0.0:20081) starting
2020-06-15 13:21:41 GUI and API listening on [::]:web_port
2020-06-15 13:21:41 Access the GUI via the following URL: http://127.0.0.1:web_port/
2020-06-15 13:21:41 My name is "device_B"
2020-06-15 13:21:41 ...
2020-06-15 13:21:41 Device *-F7H3EQC is "device_A" at [tcp4://DNS:port]
2020-06-15 13:21:41 Syncthing should not run as a privileged or system user. Please consider using a normal user account.
2020-06-15 13:21:41 Established secure connection to *-F7H3EQC at IP_B:48586-IP_A:port/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256
2020-06-15 13:21:41 Device *-F7H3EQC client is "syncthing v1.6.1" named "device_A" at IP_B:48586-IP_A:port/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256
2020-06-15 13:21:42 Index for nonexistent folder "banz2-7xtft"
2020-06-15 13:21:42 Connection to *-F7H3EQC at IP_B:48586-IP_A:port/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256 closed: receiver error: banz2-7xtft: no such folder
2020-06-15 13:21:44 Established secure connection to *-F7H3EQC at IP_B:48588-IP_A:port/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256
2020-06-15 13:21:44 Device *-F7H3EQC client is "syncthing v1.6.1" named "device_A" at IP_B:48588-IP_A:port/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256
2020-06-15 13:21:44 Index for nonexistent folder "banz2-7xtft"
2020-06-15 13:21:44 Connection to *-F7H3EQC at IP_B:48588-IP_A:port/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256 closed: receiver error: banz2-7xtft: no such folder
2020-06-15 13:21:46 Repaired 10 sequence entries in database
2020-06-15 13:21:46 Ready to synchronize "so_duplicati_target" (banz2-7xtft) (sendreceive)
2020-06-15 13:22:04 Completed initial scan of sendreceive folder "so_duplicati_target" (banz2-7xtft)
2020-06-15 13:22:44 Established secure connection to *-F7H3EQC at IP_B:48594-IP_A:port/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256
2020-06-15 13:22:44 Device *-F7H3EQC client is "syncthing v1.6.1" named "device_A" at IP_B:48594-IP_A:port/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256

I’ve waited some time again, but the two “unsynced” items remain. 8 seem to have resolved by the --reset-deltas command I’ve ran on device B.

[Catfriend1]

Very interesting. After Syncthing on device B was showing “behind 2 files” and nothing happened for a while, I’ve chosen to restart Syncthing on device A. Afterwards, I saw again an index retransmission between both nodes. Device B uploaded ca. 295 MByte to device A without syncing anything according to the UI. The restart of A must have triggered it?!

I looked into the log of device B and saw this:

2020-06-15 13:51:17 Device *-F7H3EQC client is "syncthing v1.6.1" named "device_A" at IP:PORT-IP:PORT/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256
2020-06-15 13:58:07 Non-increasing sequence detected: Checking and repairing the db...
2020-06-15 13:58:08 Repaired 2 sequence entries in database

Now device A and B both show “in sync” and “up2date”.

• Device A does not report any last synced file.

• Device B reports those files as “last synced”:

  

I’ve ignored one folder on A but not on B. B doesn’t have that folder. So I suspect the different global/local state file counts aren’t a problem.

If it’s required, I could send a backup of device B’s database to @imsodin . Please let me know if it makes sense.

[imsodin (Simon)]

Thanks for all the investigation. The db wouldn’t help me, as I don’t know what to look for. It’s clear that despite the fixes until v1.6.1 around sequences, there’s still ways for the db to get inconsistent - no clue how though.