Unexpected items on remote untrusted RPI3

Thanks!
The file sizes are different between local and global, which is expected due to the trailer with the encrypted file info we add when syncing. We might not appropriately reflect that change in the file info. That should however lead to wide-spread issues, not the rare ones you see. Anyway, that’s something that can be investigated - I set a reminder for me to the end of the week, right now I unfortunately have zero time for that.

1 Like

An ugly but effective workaround is to run a cron job every 10 minutes on the RPi which uses the /rest/db/revert command to delete the locally changed items on the encrypted folder TB.

Of course, this does not explain why they are created in the first place, when the parallel unencrypted folder syncs perfectly.

Update: I’ve converted my Thunderbird profile to encrypted on the RPi3 and deleted the parallel folder TB. With the workaround mentioned above, the folder is syncing as expected and I’m able to use it across two laptops (never simultaneously, of course).

However, when the application Thunderbird is closed, there are about 15 files that are modified or deleted each cycle. Of those, between 1 and 7 (usually 1-2) are shown as local changed items on the RPi3. The 10 minute cron job (‘revert’ command) deletes these and the local and global file counts match. The laptop reports the folder is Up to Date at all times.

As mentioned earlier, the difference seems to be that the modtime is not correctly updated for these few files on the encrypted side. The ‘revert’ command corrects this.

Is there anything I can add that might help track down this issue? I’d love to eliminate my crude workaround.

1 Like

The size difference is not an issue: It is the encryption trailer that exists locally only, that’s expected and exactly prevents a local change due to that. There’s no other difference that would point at why it’s considered changed.

I fiddled around with a setup like yours (3 devices, untrusted in the middle) and created a few conflicts, mod. time only changes, … in the hopes of reproducing, but was unable to do so.

If it happens so consistently, you could enable scanner,db,model logging on the encrypted device for the time before to after the locally modified items come up.

Simon, thanks again for following up on this issue.

The issue is consistently happening, but I have discovered that if the encrypted folder is set to scan by the default settings for Receive Encrypted (1d, no watcher) the Locally Changed Items do not appear in the GUI but are apparently hidden. If I rescan the folder, the Unexpected Items appear.

The log RPi3-log-db-model-scanner.txt (57.8 KB) is attached. After it was captured, I used the revert command mentioned above and the eight items were deleted.

1 Like

That log is very short and truncated (second line is ...).

Here is another log RPi3-db-model-scanner.log (35.6 KB) captured with model, db, scanner activated. Line 11 appears truncated but is not. Towards the end of the log, you can see that the revert command is used.

There are five encrypted folders on RPi3, only ‘Thunderbird’ was changed during the period the log was taken. Each time ‘Thunderbird’ is used on my laptop, Unexpected Items appear after a scan on the RPi3. Other folders occasionally have this too, but Unexpected Items only appear in the GUI after a rescan. All encrypted folders are set to the default rescan of 1d, no watcher.

1 Like

Now some locally changed items appear, but the context that should show why is still missing (e.g. nothing from the scan). What I’d hope to get is the logs from when the changes from the two remotes arrive, then the scan and the revert. Then there’s a good chance to see what the (probably temporary) difference is that makes it locally changed.

1 Like

I have discovered that if the scan on the encrypted side is set to the default (1d, no watcher) and if the revert command is then used and the apparent Unexpected Items are deleted, others will appear after a subsequent forced scan. So, a scan seems necessary to trigger the effect.

If I set the rescan to 60 secs on the encrypted folder, and then force ‘revert’, no later Unexpected Items appear on the encrypted folder. The Unexpected items do not resolve (ie are not temporary) unless reverted.

I have tried to keep the system as stable as possible by just using one laptop to access Thunderbird, close it, and then let ST sync and settle. Both sides show correct global and local states and the laptop shows Up to Date, but the Unexpected Items still appear on the RPi3 after a rescan.

As mentioned earlier, I think the modtime is the offending factor.

I will try and capture the log in a similar way, but force a scan and revert. Would that help?

1 Like

I have a feeling you’ve been capturing the logs using the Web GUI. Is this correct? The logs there are not complete, as they only include the most recent part. You likely need to save the log to a file and then copy and paste it from there (or directly from stdout).

1 Like

@tomasz86 Correct, earlier logs were from the RPi3 web gui.

Here is a log from stdout. RPi3-stdout.log (9.4 KB) But I am not sure how to activate db, scanner and model from the command line, so I might not have captured all the necessary details.

BTW, the Pi crashed with no space on disk because syslog and daemon.log were several GB each. I had to hack around and delete them to restart it, I’m guess that occurs because of ST logging, nothing else had changed.

1 Like

Do you mean that the Syncthing’s stdout is written to those logfiles? Normally, if you want to save Syncthing logs to the disk but still make sure they won’t take too much space, you could simply do syncthing -logfile=default, which will then keep rotating 5 log files saving them in your Syncthing home folder.

If you want to capture everything though, I’d suggest something more like STTRACE=db,model syncthing -logfile=<path-to-file>.

1 Like

No, sorry, that was noise, something else was spamming the logs.

I’ll capture the logs as you suggest and come back soon. Thanks…

1 Like

The logs were captured with STTRACE=db,model,scanner syncthing -logfile=/path/to/rpi3.log They are humongous: 2 x 10MB and 650KB after only 15 minutes. They are not anonymised. How can I safely post them?

The logs traverse a cycle from restart of ST through use of Thunderbird and shutdown on my laptop, sync, to scan and revert of the folder with Unexpected Items to shutdown of ST on the RPi3.

1 Like

I’ve used sed to anonymise mine. If you want to give it a try, copy and paste the following into a text file, e.g. sed.txt

/"[^"]*"/ s//"xxx"/g
/(open|remove).*:/ s//\1 xxx:/g
/(([A-Z]|[0-9])+)-([A-Z]|[0-9])+-([A-Z]|[0-9])+-([A-Z]|[0-9])+-([A-Z]|[0-9])+-([A-Z]|[0-9])+-([A-Z]|[0-9])+-([A-Z]|[0-9])+/ s//\1/g

and then run

sed -f sed.txt -i syncthing.log

The logs shouldn’t take very much space if you pack them with zip or similar before uploading.

1 Like

@tomasz86 Thanks for your help. RPi3.logs.zip (6.7 MB)

It’s unfortunately pointless like this - I’d need to know the filename of one of the locally changed files to weed through the logs. And we are talking about the logs of an untrusted device, that hardly needs anonymizing. Full device IDs sure, but filenames hardly. That means only the last line from tomasz sed instructions.

1 Like

I’m sorry for making the debugging process harder :astonished:. The funny thing is that the last line actually didn’t seem to work, because the full device IDs are there in the logs for some reason (but they’re not if I process the files myself here).

1 Like

@tomasz86 I discovered that as well, so I manually anonymised part of the device names and part of the folder names.

@imsodin Simon, I hope these logs are more useful to you. I appreciate your time and effort in tracking this issue. RPi3-anon-log.zip (6.8 MB)

1 Like

@rustycanb I seem also being affected by the issue mentioned here. Could you please give a filename from the locally unexpected items? Unfortunately I didn’t have the time yet to debug any further to fulfill my set reminder on the ticket.