Unexpected items on remote untrusted RPI3

[rustycanb (Russell)]

For years I have been able to share my Thunderbird profile between two laptops and my RPI3 using ST, no conflicts, always in sync. (I always allow time for the sync to finish and never have two laptops accessing the TB profile simultaneously.)

Recently I changed the PI to an untrusted device. After closing Thunderbird on a laptop, the PI shows unexpected items, although the global and local states usually remain equal. Deleting the unexpected items results in the folder being Out-of-Sync.

If on the Out-of-sync folder I go to edit/advanced and change the rescan time from say 30 secs to 31 secs and then save, the folder will immediately show Up-to-Date.

On the laptop, the folder is always shown as Up-to-Date, with local and global states equal.

This is 100% reproducible.

I’m wondering why I get unexpected items anyway (given that unencrypted folders sync flawlessly). And why, after deleting the unexpected items, changing the rescan time provokes Up-to-Date.

[tomasz86]

Could you post screenshots showing the full Web GUI from both devices?

If the problem is reproducible, you may also want to enable db and model debug logging on the receiving device, wait for the problem to happen, and then upload the logs here, so that people will be able to analyse them and possible find the culprit.

[rustycanb (Russell)]

Screenshot of laptop-E7270 Up-to-Date.

RPi3 with unexpected items.

RPi3 after deleting unexpected items.

RPi3 Up-to-Date after changing rescan by 1 second.

Log from RPi3 with model and db debugging enabled. RPI3-log (138.0 KB)

[tomasz86]

There is another ongoing issue, which I would say looks very similar to this one, i.e. https://forum.syncthing.net/t/v1-18-1-started-afresh-trusted-untrusted-unexpected-items/17206. Both here and there the problem happens on a Linux system, and specifically a Debian-based one.

We have the logs, so I would now wait for one of the maintainers to have a look at them and see whether there is anything suspicious there.

Edit:

I have noticed that you have some encrypted files marked as .sync-conflict-*. How is this possible? The only situation that I can think of would be if the encrypted folder was shared with yet another device, but this time as non-encrypted, so the files would be treated as regular rather than encrypted. This doesn’t seem to be case here though.

[rustycanb (Russell)]

Interestingly, the file count for the encrypted folder on the Pi is 1485 items. This does not change even when the folder is showing several unexpected items. After deleting these and returning the folder to fully sync’ed as described above, the folder count remains at 1485 items, but the byte count is reduced by 1 byte.

[rustycanb (Russell)]

Pause/Resume also triggers the encrypted folder to go from Out of Sync to Up to Date.

[imsodin (Simon)]

The issue of the out-of-sync items after a revert is likely just a missing trigger to sync after reverting: lib/model: Schedule pull after revert on recv-enc by imsodin · Pull Request #7892 · syncthing/syncthing · GitHub</title
That doesn’t explain why the locally changed items appear to begin with - no idea there yet.

[rustycanb (Russell)]

@imsodin Appreciate your PR #7892. Are there ST parameters I can adjust to reduce the number/incidents of Unexpected Items, rescan time etc? Is it possible to delete Unexpected items using CLI or API?

The folders that are now throwing Unexpected Items as encrypted folders have worked consistently well unencrypted over a long period.

Thanks to you and the others devs for amazing Syncthing!

[imsodin (Simon)]

I can’t advise you on what to do, as I don’t know how/why they happen. You can revert the folder through the /rest/db/revert endpoint.

Are multiple devices connected to the encrypted device? Any newly added devices?

[rustycanb (Russell)]

The setup is the same encrypted or unencrypted: two laptops and a RaspberryPi3B+ in a mesh configuration sharing the Thunderbird profile folder. No new or changed devices have been added.

Thunderbird creates about 8-10 additional files when running. I grabbed some of the unexpected items and decrypted them. They are JSON and sqlite files (session.json, cookies.sqlite etc) and .parentlock. I’m guessing these are file that are written late in the process of Thunderbird closing. There are no ‘syncthing-conflict’ files though.

I have tried pausing both, individually and together, then opening and closing Thunderbird, to no effect. Unexpected items still appear on the Pi while the laptop shows Up-to-Date with the correct number of files local and global.

Because I have plenty of time in Covid lockdown, as a trial I changed the folder back to unencrypted. It syncs perfectly again unencrypted.

I’ll change back to encrypted for further experiments.

BTW, my phone’s Whatsapp folder is shared to the Pi as an encrypted folder and then on to the laptops unencrypted to be included in a Borgbackup. There are no unexpected items for this folder on the Pi.

Thanks again for the support.

[rustycanb (Russell)]

Folder ‘Thunderbird’ remains unecrypted on the Pi and is syncing as mentioned earlier between laptops and Pi.

As an experiment, on the laptop I rsync’ed folder Thunderbird to a new folder TB. TB was then sync’ed encrypted to the Pi. Syncthing works as expected, folder TB is fully sync’ed and Up-to-Date.

Open the application Thunderbird on the laptop and browse emails etc, close the application and it syncs folder Thunderbird (the profile) as expected to the unencrypted folder on the Pi. This is normal and expected unencrypted.

On the laptop, again rsync folder Thunderbird to folder TB. (About 10 files are deleted or modified as expected when the application is opened and then closed.) Laptop folder TB syncs to Pi folder TB but with one unexpected items out of 646 files in the Pi’s GUI.

Using Pi GUI, delete unexpected items (folder is now out of sync), pause/unpause folder and three more unexpected items appear. Same routine, delete, pause/unpause and the Pi folder TB is Up-to-Date. Local and global states match with 646 files.

[rustycanb (Russell)]

PR #7892 in the latest -rc.3 solves the need for pause/resume, but I’m still getting several unexpected item using a mirror folder of my Thunderbird profile folder, as described earlier.

I would appreciate any suggestions on how to debug this issue.

[imsodin (Simon)]

The logs you showed had conflict files in them. As @tomasz86 already wrote, that’s entirely unexpected: An untrusted device should never see any conflicts. When you reproduce the issue, do conflicts still occur? You can check the same logs or just search the filesystem for files containing sync-conflict.

If there are conflicts, please enable debugging in the web UI and then call syncthing cli debug file *folder-id* *relative-path-to-conflict-file* on the untrusted device and post the output. If you don’t have our config in the default location, add --home *path-to-config after cli.

[rustycanb (Russell)]

@imsodin Thanks for your response. There are no sync-conflict files in the file system. (I think that was confusing and coincidental in my log at the time.)

This is a screenshot of the RPi3 with Unexpected (6 Locally Changed Items) Note that the Local and Global states are the same at 646 files.

After running ssh pi@192.168.1.xx curl -X POST -H X-API-Key:xxxxx... http://127.0.0.1:8384/rest/db/revert?folder=xxxxx-xxxxx this screenshot results:

The encrypted folder TB is a mirror of Thunderbird created and updated after the application Thunderbird is closed using rsync on my laptop. The folder Thunderbird is now unencrypted and syncing flawlessly to the RPi3.

Should I re-run the logs on RPi3?

[rustycanb (Russell)]

A little more information that might help track down the cause of Unexpected Items. By comparing these items in the encrypted folder, TB, and unencrypted folder, Thunderbird, I have found that the byte sizes match on both but the mtime is not update on the encrypted folder on the Pi. Mtimes remain as they were on the last full up to date.

Running /rest/db/revert updates the mtime, ‘Unexpected Items’ disappear and rsync --dry-run and Syncthing show all files are synced and up to date.

[rustycanb (Russell)]

Another experiment conducted on Unexpected Items today. See attached file. Bottom line is Syncthing and rsync agree after db/revert command is executed. RPi-modtimes (949 Bytes)

Filesystems are XFS on all partitions, noatime in fstab.

[imsodin (Simon)]

Actually, we should first check what it is that is different between those locally changed items and expectations: Can you query /rest/debug/file?folder=*folder-id*&file=*relative-path* on the untrusted device for one of those files.

Different question: When you say the mtime isn’t updated on the encrypted folder: Did you decrypt the encrypted directory with syncthing decrypt and then compare? The modtime of the encrypted files is something entirely different (on purpose).

[rustycanb (Russell)]

Thanks again for the support. I tried curl -X POST -H X-API-Key:xxxxx... http://127.0.0.1:8384/rest/debug/file?folder=xxxxx-xxxxx result was ‘Method Not Allowed’ and curl -X POST -H X-API-Key:xxxxx http://127.0.0.1:8384/rest/debug/file=/media/pi/Data/TB/ with the same result, ‘Method Not Allowed’.

Maybe I got that wrong!

Blockquote Different question: When you say the mtime isn’t updated on the encrypted folder: Did you decrypt the encrypted directory with syncthing decrypt and then compare? The modtime of the encrypted files is something entirely different (on purpose).

I didn’t use syncthing decrypt. I used rsync on laptop 1 to sync folders TB and Thunderbird, which created Unexpected Items in TB on the RPi, I then used Syncthing on a second laptop connected to the RPi to sync both encrypted and unencrypted folders, then on laptop2 used rsync --dry-run to determine the files that were different between folders TB and Thunderbird. Examining these files in the file manager of laptop 2 gave me the different mtimes. Using the ‘revert’ command on the RPi immediately corrected the mtimes in the file manager and Unexpected Items were deleted on the RPi. Syncthing shows the folders as Up-to-Date. Checking again with rsync --dry-run confirmed folders were identical.

Unencrypted folder Thunderbird was Up-to-Date throughout.

[imsodin (Simon)]

Lets use syncthing cli, less changes for mishaps. 1. I forgot about enabling debugging: syncthing cli config gui debugging set true. Then to equivalent of the previous curl command: syncthing cli debug file *folder-id* *relative-path*. You previously used /media/pi/Data/TB/ as the path, which is an absolute path. It looks like it’s the path to you folder. So if one of the unexpected items were /media/pi/Data/TB/foo/bar, you need to provide foo/bar for *relative-path*.

Nice procedure to compare the outcomes - thanks for explaining! Hopefully that info together with the output of the above command will help understand/reproduce the issue on my side, and lead to a solution.

[rustycanb (Russell)]

Simon, thanks again. Output from your instructions follow for two files locally changed on the Pi. Hope this helps…

pi@raspberrypi:~ $ syncthing cli debug file xxxxx-xxxxx G.syncthing-enc/SO/GVR7KF79TQ8A1GH08SU3RIS2362TC6Q0515OIB4JEH98 { “availability”: [ “YSUH66K-laptop 1, where mirror folder TB is located” ], “global”: { “deleted”: false, “ignored”: false, “invalid”: false, “localFlags”: 0, “modified”: “2009-02-14T10:31:30+11:00”, “modifiedBy”: “”, “mustRescan”: false, “name”: “G.syncthing-enc/SO/GVR7KF79TQ8A1GH08SU3RIS2362TC6Q0515OIB4JEH98”, “noPermissions”: false, “numBlocks”: 1, “permissions”: “0644”, “sequence”: 2746, “size”: 38144, “type”: “FILE_INFO_TYPE_FILE”, “version”: [ “AAAAAAA:1630310040” ] }, “globalVersions”: “{{Version:{[{AAAAAAA 1630310040} {YZZY6NC 1630310045}]}, Deleted:false, Devices:{}, Invalid:{7777777}}, {Version:{[{AAAAAAA 1630310040}]}, Deleted:false, Devices:{YSUH66K}, Invalid:{}}, {Version:{[{AAAAAAA 1630305029}]}, Deleted:false, Devices:{UOEAMCF}, Invalid:{}}}”, “local”: { “deleted”: false, “ignored”: false, “invalid”: true, “localFlags”: 8, “modified”: “2009-02-14T10:31:30+11:00”, “modifiedBy”: “YZZY6NC”, “mustRescan”: false, “name”: “G.syncthing-enc/SO/GVR7KF79TQ8A1GH08SU3RIS2362TC6Q0515OIB4JEH98”, “noPermissions”: true, “numBlocks”: 0, “sequence”: 3360, “size”: 38534, “type”: “FILE_INFO_TYPE_FILE”, “version”: [ “AAAAAAA:1630310040”, “YZZY6NC:1630310045” ] }, “mtime”: { “err”: null, “value”: { “real”: “0001-01-01T00:00:00Z”, “virtual”: “0001-01-01T00:00:00Z” } } } pi@raspberrypi:~ $ syncthing cli debug file ry5ju-tmqub K.syncthing-enc/SU/QA6TPPMGJLJNMLGTDJ98MV5NM5CFR29HUNDN02LS30DO3QKEGIA7N418CBAMHI8 { “availability”: [ “YSUH66K-laptop 1, where mirror folder TB is located” ], “global”: { “deleted”: false, “ignored”: false, “invalid”: false, “localFlags”: 0, “modified”: “2009-02-14T10:31:30+11:00”, “modifiedBy”: “”, “mustRescan”: false, “name”: “K.syncthing-enc/SU/QA6TPPMGJLJNMLGTDJ98MV5NM5CFR29HUNDN02LS30DO3QKEGIA7N418CBAMHI8”, “noPermissions”: false, “numBlocks”: 1, “permissions”: “0644”, “sequence”: 2729, “size”: 4493, “type”: “FILE_INFO_TYPE_FILE”, “version”: [ “AAAAAAA:3260356256” ] }, “globalVersions”: “{{Version:{[{AAAAAAA 3260356256} {YZZY6NC 1630310045}]}, Deleted:false, Devices:{}, Invalid:{7777777}}, {Version:{[{AAAAAAA 3260356256}]}, Deleted:false, Devices:{YSUH66K}, Invalid:{}}, {Version:{[{AAAAAAA 3260351245}]}, Deleted:false, Devices:{UOEAMCF}, Invalid:{}}}”, “local”: { “deleted”: false, “ignored”: false, “invalid”: true, “localFlags”: 8, “modified”: “2009-02-14T10:31:30+11:00”, “modifiedBy”: “YZZY6NC”, “mustRescan”: false, “name”: “K.syncthing-enc/SU/QA6TPPMGJLJNMLGTDJ98MV5NM5CFR29HUNDN02LS30DO3QKEGIA7N418CBAMHI8”, “noPermissions”: true, “numBlocks”: 0, “sequence”: 3361, “size”: 4931, “type”: “FILE_INFO_TYPE_FILE”, “version”: [ “AAAAAAA:3260356256”, “YZZY6NC:1630310045” ] }, “mtime”: { “err”: null, “value”: { “real”: “0001-01-01T00:00:00Z”, “virtual”: “0001-01-01T00:00:00Z” } } } pi@raspberrypi:~ $

Here is a file with equivalent. RPi-cli-output (3.2 KB)