I’m sorry for making the debugging process harder 
. 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.
@Catfriend1 The file names are encrypted, but you can see from the experiment I reported on earlier (I ran parallel encrypted and unencrypted folders) I deduced that the incorrect/not updated modtime was causing the Unexpected Items to appear. Rescanning at short interval (60 secs) on the encrypted folder and then regularly running the revert command suggested by Simon resolves them. Global and local items match and everything is Up to Date.
The mystery is why the modtime is correct when the folder is unencrypted, and syncs perfectly, but incorrect when the same folder and files are encrypted and cause Unexpected Items.
1 Like
I also have the same (or, maybe, just a very similar) problem with untrusted Thunderbird directory syncing. Unexpected items appear after a little while, but I can also confirm that I get sync-conflict files on the untrusted side, which shouldn’t be happening at all. The configuration is very simple: laptop → untrusted NAS.
Here’s a debug result from one of the conflict files: { “availability”: [], “global”: { “deleted”: false, “ignored”: false, “invalid”: true, “localFlags”: 8, “modified”: “2009-02-13T23:31:30Z”, “modifiedBy”: “HTW36X3”, “mustRescan”: false, “name”: “3.syncthing-enc/S2/H0LE73DK5LI5FQMJ41LFMQDLRMFIAA1T0F79JPQ1LCR1GM9A9PK8QPDUVQJFG20G0IBEJB9PEM3S6H5SEJ1R0JQKBJB74CUBQU.sync-conflict-20210928-175513-”, “noPermissions”: true, “numBlocks”: 0, “sequence”: 79907, “size”: 5402, “type”: “FILE_INFO_TYPE_FILE”, “version”: [ “HTW36X3:1632848113” ] }, “globalVersions”: “{{Version:{[{HTW36X3 1632848113}]}, Deleted:false, Devices: {}, Invalid:{7777777}}}”, “local”: { “deleted”: false, “ignored”: false, “invalid”: true, “localFlags”: 8, “modified”: “2009-02-13T23:31:30Z”, “modifiedBy”: “HTW36X3”, “mustRescan”: false, “name”: “3.syncthing-enc/S2/H0LE73DK5LI5FQMJ41LFMQDLRMFIAA1T0F79JPQ1LCR1GM9A9PK8QPDUVQJFG20G0IBEJB9PEM3S6H5SEJ1R0JQKBJB74CUBQU.sync-conflict-20210928-175513-”, “noPermissions”: true, “numBlocks”: 0, “sequence”: 79907, “size”: 5402, “type”: “FILE_INFO_TYPE_FILE”, “version”: [ “HTW36X3:1632848113” ] }, “mtime”: { “err”: null, “value”: { “real”: “0001-01-01T00:00:00Z”, “virtual”: “0001-01-01T00:00:00Z” } } }
Actually never mind, false alarm.
[YZZY6] 2021/09/28 20:36:36.782699 set.go:254: DEBUG: xxxxx-nnqhx Get(9.syncthing-enc/2M/VA0TOP630CP52N0AOJQKJSNUERPCKH0U7MU6MDVOSEMS3D9SSSAPFJT70NAI43E
6R0G07DQ6FEOFU3DTEHRUTP8JJC4N2OVQF1K0RGIVOE4NNQQ9H6DC9E5R68FTEATO9HA13QVN0A0VR2D7BCJ6KNLBG37G6F684Q41SA8PSAHNO3F5EFS337FN1NB9686S6V0S17RT)
[YZZY6] 2021/09/28 20:36:36.783196 walk.go:438: DEBUG: walker/xxxxx-nnqhx@0x2cdc660 dir: 9.syncthing-enc/2M/VA0TOP630CP52N0AOJQKJSNUERPCKH0U7MU6MDVOSEMS
3D9SSSAPFJT70NAI43E6R0G07DQ6FEOFU3DTEHRUTP8JJC4N2OVQF1K0RGIVOE4NNQQ9H6DC9E5R68FTEATO9HA13QVN0A0VR2D7BCJ6KNLBG37G6F684Q41SA8PSAHNO3F5EFS337FN1NB9686S6V0S
17RT Directory{Name:"9.syncthing-enc/2M/VA0TOP630CP52N0AOJQKJSNUERPCKH0U7MU6MDVOSEMS3D9SSSAPFJT70NAI43E6R0G07DQ6FEOFU3DTEHRUTP8JJC4N2OVQF1K0RGIVOE4NNQQ9
H6DC9E5R68FTEATO9HA13QVN0A0VR2D7BCJ6KNLBG37G6F684Q41SA8PSAHNO3F5EFS337FN1NB9686S6V0S17RT", Sequence:0, Permissions:0755, ModTime:2021-09-25 07:43:35.173
070932 +1000 AEST, Version:{[{YZZY6NC 1632825396}]}, VersionHash:, Deleted:false, Invalid:false, LocalFlags:0x8, NoPermissions:true}
[YZZY6] 2021/09/28 20:36:36.783771 set.go:254: DEBUG: xxxxx-nnqhx Get(9.syncthing-enc/2M/VA0TOP630CP52N0AOJQKJSNUERPCKH0U7MU6MDVOSEMS3D9SSSAPFJT70NAI43E6R0G07DQ6FEOFU3DTEHRUTP8JJC4N2OVQF1K0RGIVOE4NNQQ9H6DC9E5R68FTEATO9HA13QVN0A0VR2D7BCJ6KNLBG37G6F684Q41SA8PSAHNO3F5EFS337FN1NB9686S6V0S17RT/RQ6254UP0)
[YZZY6] 2021/09/28 20:36:36.784260 walk.go:391: DEBUG: walker/xxxxx-nnqhx@0x2cdc660 unchanged: File{Name:"9.syncthing-enc/2M/VA0TOP630CP52N0AOJQKJSNUERPCKH0U7MU6MDVOSEMS3D9SSSAPFJT70NAI43E6R0G07DQ6FEOFU3DTEHRUTP8JJC4N2OVQF1K0RGIVOE4NNQQ9H6DC9E5R68FTEATO9HA13QVN0A0VR2D7BCJ6KNLBG37G6F684Q41SA8PSAHNO3F5EFS337FN1NB9686S6V0S17RT/RQ6254UP0", Sequence:416, Permissions:0644, ModTime:2009-02-14 10:31:30 +1100 AEDT, Version:{[{AAAAAAA 1620954337}]}, VersionHash:, Length:59483, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:false, BlockSize:131112, Blocks:[Block{0/58821/0/e90e40d0d1be7243a14373d39a3d8b4a46b585ac099095e6484420328fc06875cf4247f4d6a44beb1fdbd62b65472633}], BlocksHash:367fcec076ce3c13ac38a6771f26467ba04792892288f0ef4a38f19b9f70dfb7} 1234567890 -rw-r--r--
What is it? Long paths, as in very long ones. Where we add path separators on the encrypted filenames, and thus introduce “virtual” directories (virtual as in they don’t represent anything). And we don’t properly ignore them, so they show up as locally changed.
2 Likes
A Unexpected Item on the encrypted folder has a path like this: /media/pi/Data/Thunderbird/F.syncthing-enc/L0/3NOLNGSOUKREH827UPOESCKQM45FTSI2SBTQB233SE4C4CEV11B9888I9BEMFV0HJGRHQOVEEK6KT1EMBR4G9MAQQMV0S27KRSJO
The path to this same file on the unencrypted side is /media/sda3/Thunderbird/xulstore.json
1 Like
Btw, I’ve been trying to decrypt the filenames in Python and it’s not working… Am I doing something wrong or is there a bug in one of the modules?
I pass the folder password to stdin, the folder ID is in folder_id and the base32hex decoded filename is in bin.
The error that it returns is “ciphertext verification failure!”
base32hex decoding was done via basenc.
#!/usr/local/bin/python3
import sys
import hashlib
from miscreant.aes.siv import SIV
with open("/dev/stdin","rb") as stdin:
folder_pass = stdin.read().rstrip()
with open("folder_id","rb") as file:
folder_id = file.read().rstrip()
folder_key = hashlib.scrypt(folder_pass,salt=(b"syncthing"+folder_id),n=32768,r=8,p=1,maxmem=1000000000,dklen=32)
siv = SIV(folder_key)
with open("bin","rb") as file:
bin_val = file.read().rstrip()
decrypted_val = siv.open(bin_val)
print(decrypted_val)
You could try initializing an AEAD object instead of the SIV object directly, even though that just calls SIV under the hood.
Otherwise, there might be something wrong with your filenames? Based on the source code, you need to remove file extensions and slashes before base32hex decoding.
Also make sure that there are no special control characters anywhere (especially newlines), not sure how python handles this.
Oddly enough, according to the log it’s never unexpected. However it still shows a bug, which this time is related to modification only changes. The puller takes a shortcut for that, which is expected, but not ok for receive-encrypted: They need to write the encryption trailer. https://github.com/syncthing/syncthing/issues/7991
1 Like
Updated to 1.18.4-rc.1 just now (it includes fixes for issues 7991 and 7994) on RPi3 and laptop.
Unexpected items still appearing on RPi3 encrypted side. Revert commands resolves these as before.
Maybe open issue 7987 is needed.
Thanks to devs (Simon) for working on this.
1 Like
The (encrypted) filenames of unexpected items could show if it is indeed that issue. Could you post some please.
There are six unexpected items on the remote encrypted device, paths are preceded from root by /media/pi/Data/
|3.syncthing-enc/AR/6N7JOK2RI2KOTSBRTQT055L05SKIVVIS5NSQC1UL0|1.421875 KiB| |4.syncthing-enc/F7/BR767Q3I0HBHSPSKLGQ5S6IAT9U4GL8A3LHCF7U47IG0JLVGH3V8|1.451171875 KiB| |5.syncthing-enc/QP/J3GCVRBT9855911MCDSBOH5AOKOPNPTNEAEAVJ4BMT2RU0C|10.37109375 KiB| |6.syncthing-enc/AC/G2A0J2CN5J9VAHHBDITU6GE89FT1QRATH1I1N53V72O8TSQCOTEJ6|1.453125 KiB| |J.syncthing-enc/JP/F9P6FM2FIDNU6612TTCT1UOH5H8IQ12BH0TL0GAGME6E7DSLQP90|3.66015625 KiB| |L.syncthing-enc/QS/TSVF6OFL8688075HL9NDKLAMIL52COPLJOSBI043CI|1.435546875 KiB|
These don’t look exceedingly long. My earlier experiments (mentioned above) confirm that modtimes are not updated on the encrypted device, but retain the time of one version earlier.
Edit: there’s an addition level after /Data/Thunderbird/
It’s not issue 7987 then. You could gather logs again like before with 1.18.4-rc.1 and I’ll have another look.
Hold off on those logs, just realized a mistake with the logs from that other thread: Failed items and "access is denied" in a Receive Encrypted folder - #17 by imsodin
Actually, the changed file here is a mistake in a change I made for 1.18.4-rc.1: https://github.com/syncthing/syncthing/pull/7992.
1 Like
Maybe #7987 is not out of play just yet. Here are four Unexpected Items with path names (>203 characters) preceded by /media/pi/Data/Techie/
L.syncthing-enc/0O/UFCPMD4GJ9F20VN1SMLUVCCPUGCSIBEQ1DRVKHINQSJ8FK4KABOQECUJEQST4JV6R34KHGNN97SISHTFM93INVQ4V70R5O3H2CNELDPUKOUO4QU7RJN4J1AD0MV2V199S1FF4EV3U4I2AQ22A7LG2TS8377V134OQB0CUP8E0CEPLSF3JD8RJV37G
N.syncthing-enc/3A/6V3N430SK1D2967EU3E015V1HBB7V7KAVPBUBTKUAV8JTQO0Q77VE6A02F3JUODCCFKML5E541QV1L2SEMD7JLJIC0AJ70QO1VM5E7B7A843K0NECCFHR4M9JE8R7G362250U7LAA8SNFIPAQ3IUQ4DKKR7INVUDRRQ52I4VEHHOBMO4E2E55DCAG
N.syncthing-enc/4R/PU6C7Q3NKGQH8KK6RPN0Q6799LHUHE41R9JIQK0V2S93UDEUSTP25RBAMC0RKKVJR1ULQISJ166QH01MJF6LE56PANKSKEL3J7K8OD1BAJ2QF28KMIA6UEBQ732KI7VD0B6BIHAFMVG6DAQOKVH5GF7I2KSOB48GH7HS3AU9O92DUDIL0R21BT50
V.syncthing-enc/26/UPUKIVT7CP81NPNDN4PHT85RCI5UCDBBJKOOF3VUE431BFIFLDN68TISF8EQ85C0JMTCTP3G5PA1BUPLQG5KCA846B5S7N7LAPH3MBHH7OCFIJB6TEJPQSS91SH67BRQDG5I20L4874PJUNOKLC2SJK2CI7EJSNFCMSBR2586N7R4GT13HSDN42Q0
I don’t have Syncthing with the fix committed to #7992 as yet.
I’ve just updated to v1.18.4-rc.2 and the Unexpected Items have disappeared without my intervention.
Yay, thanks and great job @imsodin and to @tomasz86 for help as well.
3 Likes
This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.