Incorrect local state when using ! negated ignore patterns combined with parent folder ignored

[tomasz1986]

I believe this is likely responsible for the long-term issue I've been experiencing since basically forever which leads to non-matching local and remote folder states despite using the exact same ignore patterns on both sides.

1. Share an empty folder between Device 1 (D1) and Device 2 (D2).
2. Set the folder to "Send & Receive" on both sides.
3. Add the following ignore patterns to the folder on both sides.

   !*.txt
   /
   

4. The folders on both sides should now look as follows.
   
   
5. Create the following hierarchy in the folder on D1.

   /folder
   /folder/file.txt
   

6. Scan the folder on D1. Wait for the changes to sync to D2.
7. The final state looks as follows.
   
   
8. As you can see, the folder state on D1 is incorrect. Because file.txt is present inside /folder, the folder should be included in the local state as well, however in reality only the file is. Once this happens, neither rescanning the folder nor restarting Syncthing repairs the broken local state.

There is a caveat though. The steps above aren't complete. I've just managed to reproduce this in my test environment and I'm attaching logs with model,db enabled below, however in my testing I was repeatedly creating and removing folders and files in order to find the culprit. While doing so, I eventually managed to reach the state as seen above, but I can't reproduce it at will directly yet.

The logs should contain the relevant information though. They aren't very large either, as the whole testing took less than 10 minutes or so.

syncthing1.log
syncthing2.log

For the record, I think the actual synchronisation still functions fine despite the incorrect local states. However, I've encountered problems with Receive Only folders being stuck in a permanent "Out of Sync" state which I believe is likely related to this very bug. I still haven't been able to reproduce that one in my test environment though.

[calmh]

I don't think this is incorrect; the folder is ignored and shouldn't be included. What happens on the other side is that the folder is created because it's required for the file to be able to exist, and then it's discovered locally on the next scan because it's not ignored on that side.

If the other side is receive only things will get confusing, I agree. The directory isn't supposed to exist, but it must, and this does not compute 🤖 ⁉️

What you're imagining is that unignoring a file should unignore all the parent dirs, and perhaps that's what should happen, but it's not (and would be tricky to implement).

The difference might not be visible for the most part, but things like permissions and extended attributes won't be the same on that parent directory, since it's in fact ignored and not synced.

[tomasz1986]

What you're imagining is that unignoring a file should unignore all the parent dirs, and perhaps that's what should happen, but it's not (and would be tricky to implement).

But I think this is exactly what is supposed to happen normally 🙃. In fact, I've just found my old issue about basically the same thing at #7740 which I forgot about and which was supposed to be fixed by @imsodin a long time ago. On top of that, the steps to reproduce are actually almost identical as in here. However, it seems that something still triggers the same issue… 😕.

The difference between the old issue and this one is that there the problem happened every time. Here, as mentioned above, one step is missing but I'm unable to figure out what it is exactly. It is recorded in the logs though.

[tomasz1986]

it's discovered locally on the next scan because it's not ignored on that side.

I'd just like to add a comment on this point. The thing is that the folder is ignored on that side too (see step 3. in the OP)! The ignore patterns are the same, yet the behaviour is different.

[calmh]

That's odd.

[tomasz1986]

I this this depends on the events going on inside the folder, e.g.

1. Folder empty -> folder ignored
2. Text files added -> text files unignored -> folder unignored too
3. Text files deleted -> folder ignored again
4. Text files re-added -> text files unignored -> folder unignored again

and so on, and at some point we end up with the state as in the last screenshot 🙁.

[tomasz1986]

More testing, and I've managed to trigger the issue almost immediately this time. I'm attaching new logs below, as they're super short compared to the original ones, so they should be much easier to analyse.

syncthing1.log
syncthing2.log

I think this may be the exact moment the folder was ignored and removed from the local state.

[DHK2G] 2022/12/31 21:54:29.272262 folder_sendrecv.go:343: DEBUG: sendreceive/z2wgi-hdz5a@0xc001481400 Handling ignored file Directory{Name:"folder", Sequence:3, Permissions:0755, ModTime:2022-12-31 21:54:28.9127352 +0100 CET, Version:{[{IDWWV34 1672520069}]}, VersionHash:, Deleted:false, Invalid:false, LocalFlags:0x2, NoPermissions:false, Platform:{<nil> <nil> <nil> <nil> <nil> <nil>}, InodeChangeTime:1970-01-01 01:00:00 +0100 CET}
[DHK2G] 2022/12/31 21:54:29.272262 set.go:116: DEBUG: z2wgi-hdz5a Update(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4, [1])
[DHK2G] 2022/12/31 21:54:29.272262 lowlevel.go:378: DEBUG: removing sequence; folder="z2wgi-hdz5a" sequence=1 folder
[DHK2G] 2022/12/31 21:54:29.272262 lowlevel.go:239: DEBUG: insert (local); folder="z2wgi-hdz5a" Directory{Name:"folder", Sequence:3, Permissions:0755, ModTime:2022-12-31 21:54:28.9127352 +0100 CET, Version:{[{IDWWV34 1672520069}]}, VersionHash:, Deleted:false, Invalid:false, LocalFlags:0x2, NoPermissions:false, Platform:{<nil> <nil> <nil> <nil> <nil> <nil>}, InodeChangeTime:1970-01-01 01:00:00 +0100 CET}
[DHK2G] 2022/12/31 21:54:29.272262 transactions.go:635: DEBUG: update global; folder="z2wgi-hdz5a" device=7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4 file="folder" version={[{IDWWV34 1672520069}]} invalid=true
[DHK2G] 2022/12/31 21:54:29.272262 transactions.go:649: DEBUG: new global for "folder" after update: {{Version:{[{IDWWV34 1672520069}]}, Deleted:false, Devices:{IDWWV34}, Invalid:{7777777}}}
[DHK2G] 2022/12/31 21:54:29.272262 transactions.go:775: DEBUG: local need delete; folder="z2wgi-hdz5a", name="folder"
[DHK2G] 2022/12/31 21:54:29.272262 lowlevel.go:260: DEBUG: adding sequence; folder="z2wgi-hdz5a" sequence=3 folder
[DHK2G] 2022/12/31 21:54:29.272262 folder_sendrecv.go:194: DEBUG: sendreceive/z2wgi-hdz5a@0xc001481400 changed 1 on try 1

[tomasz1986]

I became somewhat fed up with the folders being constantly stuck in this "fake" Local Additions state, so I've managed to find a clunky workaround for this issue.

Basically, if instead of

!/folder1/folder2/*.txt
*

you do

!/folder1/folder2/*.txt
/folder1/folder2/
!/folder1/folder2
/folder1/
!/folder1
*

and so on, then the parent folders will be unignored and "synced". Of course, this is only viable if the folder structure is known and fixed.