Can pull directories but not files

[enzo (Lorenzo Castoldi)]

I’m having a strange issue running Syncthing on my TrueNAS box. It can create new directories (top-level share folder, .stfolder, or regular sub-folders within the share), but it goes out of sync if a remote device pushes a file.

The exact error reported in the UI is “operation not permitted” / “syncing: finishing: opening temp file: open /path/to/share/.syncthing.foo.jpg.tmp: operation not permitted” for a given file named “foo.jpg”.

(I have tested with files called literally “foo.jpg”, so this is nothing to do with special chars in the filenames.)

Bizzarely, Syncthing does actually create the temp file on disk, despite the “not permitted” error. It shows up as an empty file. Permissions are managed with an ACL, so the files may be owned by root:root, but are still writeable when logged in as the “apps” user (same user that Syncthing runs as). For good measure, it’s possible to manipulate files with touch, mv, rm, etc as the same user in the share folder.

The main thing is that chmod can’t be used. This is a limitation of TrueNAS (the reasoning is a bit convoluted; Syncthing actually mounts the share folder as an NFS volume). The error doesn’t mention chmod or permissions, but if Syncthing is trying to set any particular permissions, that’s probably the issue. However, I see the same behavior even with “ignore permissions” set on both devices. Everything runs fine without the NFS layer in the middle.

Any suggestions are appreciated. I’m currently wondering if there’s a way to get more granularity from the “not permitted” error, or if there’s a hidden setting to really ignore permissions.

Running version v1.23.5 installed via TrueCharts on TrueNAS SCALE 22.12.3.1

Log (attempt to pull baz.jpg, all debug logging facilities ON)

2023-06-26 18:50:19 http: GET "https://172.16.0.90:8384/rest/noauth/health": status 307, 79 bytes in 0.03 ms
2023-06-26 18:50:19 http: GET "https://172.16.0.90:8384/rest/noauth/health": status 307, 79 bytes in 0.02 ms
2023-06-26 18:50:19 http: GET "/rest/noauth/health": status 200, 21 bytes in 0.06 ms
2023-06-26 18:50:19 http: GET "/rest/noauth/health": status 200, 21 bytes in 0.10 ms
2023-06-26 18:50:20 http: GET "/rest/system/log?since=2023-06-26T18%3A50%3A17.070659647-04%3A00": status 200, 965 bytes in 0.19 ms
2023-06-26 18:50:21 http: GET "/rest/system/discovery": status 200, 969 bytes in 0.65 ms
2023-06-26 18:50:21 http: GET "/rest/system/status": status 200, 4652 bytes in 1.67 ms
2023-06-26 18:50:21 http: GET "/rest/system/connections": status 200, 1411 bytes in 0.24 ms
2023-06-26 18:50:21 http: GET "/rest/system/error": status 200, 21 bytes in 0.10 ms
2023-06-26 18:50:22 handle index-update for 19fb9-veeue message
2023-06-26 18:50:22 queueing IndexUpdate(362XLTQ-J3DBHPM-WITU2L5-6D33IZW-YNYL64Y-GJL6FIW-G7O2NAX-GTTSTAV, 19fb9-veeue, 2 files)
2023-06-26 18:50:22 Index update (in): 362XLTQ-J3DBHPM-WITU2L5-6D33IZW-YNYL64Y-GJL6FIW-G7O2NAX-GTTSTAV / "19fb9-veeue": 2 files
2023-06-26 18:50:22 19fb9-veeue Update(362XLTQ-J3DBHPM-WITU2L5-6D33IZW-YNYL64Y-GJL6FIW-G7O2NAX-GTTSTAV, [2])
2023-06-26 18:50:22 insert (remote); folder="19fb9-veeue" device=362XLTQ-J3DBHPM-WITU2L5-6D33IZW-YNYL64Y-GJL6FIW-G7O2NAX-GTTSTAV File{Name:"baz.jpg", Sequence:14, Permissions:0660, ModTime:2023-06-26 17:43:03.003785472 -0400 EDT, Version:{[{362XLTQ 1687819821}]}, VersionHash:, Length:303196, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:131072, NumBlocks:3, BlocksHash:7f01c3aeb7c4a9a2495ccee24f799616130db2bbd32b4bb31c25a31f4b778fd4, Platform:{<nil> <nil> <nil> <nil> <nil> <nil>}, InodeChangeTime:1969-12-31 19:00:00 -0500 EST}
2023-06-26 18:50:22 update global; folder="19fb9-veeue" device=362XLTQ-J3DBHPM-WITU2L5-6D33IZW-YNYL64Y-GJL6FIW-G7O2NAX-GTTSTAV file="baz.jpg" version={[{362XLTQ 1687819821}]} invalid=false
2023-06-26 18:50:22 new global for "baz.jpg" after update: {{Version:{[{362XLTQ 1687819821}]}, Deleted:false, Devices:{362XLTQ}, Invalid:{}}}
2023-06-26 18:50:22 local need insert; folder="19fb9-veeue", name="baz.jpg"
2023-06-26 18:50:22 insert (remote); folder="19fb9-veeue" device=362XLTQ-J3DBHPM-WITU2L5-6D33IZW-YNYL64Y-GJL6FIW-G7O2NAX-GTTSTAV File{Name:"bar.jpg", Sequence:15, Permissions:0660, ModTime:2023-06-26 18:50:21.003785472 -0400 EDT, Version:{[{362XLTQ 1687819821}]}, VersionHash:, Length:0, Deleted:true, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:131072, NumBlocks:0, BlocksHash:, Platform:{<nil> <nil> <nil> <nil> <nil> <nil>}, InodeChangeTime:1969-12-31 19:00:00 -0500 EST}
2023-06-26 18:50:22 update global; folder="19fb9-veeue" device=362XLTQ-J3DBHPM-WITU2L5-6D33IZW-YNYL64Y-GJL6FIW-G7O2NAX-GTTSTAV file="bar.jpg" version={[{362XLTQ 1687819821}]} invalid=false
2023-06-26 18:50:22 new global for "bar.jpg" after update: {{Version:{[{362XLTQ 1687819821}]}, Deleted:true, Devices:{362XLTQ}, Invalid:{}}}
2023-06-26 18:50:22 local need delete; folder="19fb9-veeue", name="bar.jpg"
2023-06-26 18:50:22 19fb9-veeue Snapshot()
2023-06-26 18:50:22 19fb9-veeue WithNeed(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4)
2023-06-26 18:50:22 log 1154 RemoteIndexUpdated map[device:362XLTQ-J3DBHPM-WITU2L5-6D33IZW-YNYL64Y-GJL6FIW-G7O2NAX-GTTSTAV folder:19fb9-veeue items:2 sequence:15 version:15]
2023-06-26 18:50:22 http: GET "/rest/events?since=1110": status 200, 329 bytes in 42645.17 ms
2023-06-26 18:50:22 folderconfiguration.go:121 basic /mnt/Pictures/Test Stat . {0xc0014b2270} <nil>
2023-06-26 18:50:22 folderconfiguration.go:139 basic /mnt/Pictures/Test Stat .stfolder {0xc0014b2340} <nil>
2023-06-26 18:50:22 folder.go:334 basic /var/syncthing/config/index-v0.14.0.db Usage . {274753257472 274877906944} <nil>
2023-06-26 18:50:22 folderconfiguration.go:121 basic /mnt/Pictures/Test Stat . {0xc0014b2410} <nil>
2023-06-26 18:50:22 folderconfiguration.go:139 basic /mnt/Pictures/Test Stat .stfolder {0xc0014b24e0} <nil>
2023-06-26 18:50:22 folder.go:334 basic /var/syncthing/config/index-v0.14.0.db Usage . {274753257472 274877906944} <nil>
2023-06-26 18:50:22 receiveonly/19fb9-veeue@0xc000488800 pulling
2023-06-26 18:50:22 log 1155 StateChanged map[duration:389.545080322 folder:19fb9-veeue from:idle to:sync-waiting]
2023-06-26 18:50:22 log 1156 StateChanged map[duration:0.545251665 folder:19fb9-veeue from:sync-waiting to:sync-preparing]
2023-06-26 18:50:22 19fb9-veeue Snapshot()
2023-06-26 18:50:22 receiveonly/19fb9-veeue@0xc000488800 copiers: 2 pullerPendingKiB: 32768
2023-06-26 18:50:22 19fb9-veeue WithNeed(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4)
2023-06-26 18:50:22 19fb9-veeue Get(baz.jpg)
2023-06-26 18:50:22 19fb9-veeue GetGlobal(baz.jpg)
2023-06-26 18:50:22 receiveonly/19fb9-veeue@0xc000488800 parent not missing baz.jpg
2023-06-26 18:50:22 19fb9-veeue Availability(baz.jpg)
2023-06-26 18:50:22 stats.DeviceStatisticsReference.WasSeen: 362XLTQ-J3DBHPM-WITU2L5-6D33IZW-YNYL64Y-GJL6FIW-G7O2NAX-GTTSTAV
2023-06-26 18:50:22 19fb9-veeue Get(baz.jpg)
2023-06-26 18:50:22 open: open /mnt/Pictures/Test/.syncthing.baz.jpg.tmp: no such file or directory
2023-06-26 18:50:22 http: GET "/rest/system/log?since=2023-06-26T18%3A50%3A19.427554368-04%3A00": status 200, 8283 bytes in 13.35 ms
2023-06-26 18:50:22 receiveonly/19fb9-veeue@0xc000488800 need file baz.jpg; copy 3, reused 0
2023-06-26 18:50:22 log 1157 ItemStarted map[action:update folder:19fb9-veeue item:baz.jpg type:file]
2023-06-26 18:50:22 folderconfiguration.go:274 basic /mnt/Pictures/Test Usage . {54254756691968 54263936974848} <nil>
2023-06-26 18:50:22 http: GET "/rest/events?since=1111": status 200, 777 bytes in 0.41 ms
2023-06-26 18:50:22 receiveonly/19fb9-veeue@0xc000488800 closing baz.jpg
2023-06-26 18:50:22 receiveonly/19fb9-veeue@0xc000488800 new error for baz.jpg: finishing: opening temp file: open /mnt/Pictures/Test/.syncthing.baz.jpg.tmp: operation not permitted
2023-06-26 18:50:22 progress emitter: deregistering 19fb9-veeue baz.jpg
2023-06-26 18:50:22 receiveonly/19fb9-veeue@0xc000488800 changed 1 on try 1
2023-06-26 18:50:22 19fb9-veeue Snapshot()
2023-06-26 18:50:22 receiveonly/19fb9-veeue@0xc000488800 copiers: 2 pullerPendingKiB: 32768
2023-06-26 18:50:22 19fb9-veeue WithNeed(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4)
2023-06-26 18:50:22 log 1158 ItemFinished map[action:update error:0xc004584c20 folder:19fb9-veeue item:baz.jpg type:file]
2023-06-26 18:50:22 19fb9-veeue Get(baz.jpg)
2023-06-26 18:50:22 19fb9-veeue GetGlobal(baz.jpg)
2023-06-26 18:50:22 receiveonly/19fb9-veeue@0xc000488800 parent not missing baz.jpg
2023-06-26 18:50:22 19fb9-veeue Availability(baz.jpg)
2023-06-26 18:50:22 stats.DeviceStatisticsReference.WasSeen: 362XLTQ-J3DBHPM-WITU2L5-6D33IZW-YNYL64Y-GJL6FIW-G7O2NAX-GTTSTAV
2023-06-26 18:50:22 19fb9-veeue Get(baz.jpg)
2023-06-26 18:50:22 log 1159 ItemStarted map[action:update folder:19fb9-veeue item:baz.jpg type:file]
2023-06-26 18:50:22 receiveonly/19fb9-veeue@0xc000488800 need file baz.jpg; copy 3, reused 0
2023-06-26 18:50:22 basic /mnt/Pictures/Test Watch: Ignoring .syncthing.baz.jpg.tmp
2023-06-26 18:50:22 folderconfiguration.go:274 basic /mnt/Pictures/Test Usage . {54254756691968 54263936974848} <nil>
2023-06-26 18:50:22 http: GET "/rest/events?since=1114": status 200, 609 bytes in 0.37 ms
2023-06-26 18:50:22 receiveonly/19fb9-veeue@0xc000488800 closing baz.jpg
2023-06-26 18:50:22 receiveonly/19fb9-veeue@0xc000488800 new error for baz.jpg: finishing: opening temp file: open /mnt/Pictures/Test/.syncthing.baz.jpg.tmp: operation not permitted
2023-06-26 18:50:22 progress emitter: deregistering 19fb9-veeue baz.jpg
2023-06-26 18:50:22 receiveonly/19fb9-veeue@0xc000488800 changed 1 on try 2
2023-06-26 18:50:22 19fb9-veeue Snapshot()
2023-06-26 18:50:22 receiveonly/19fb9-veeue@0xc000488800 copiers: 2 pullerPendingKiB: 32768
2023-06-26 18:50:22 19fb9-veeue WithNeed(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4)
2023-06-26 18:50:22 log 1160 ItemFinished map[action:update error:0xc0012b2f60 folder:19fb9-veeue item:baz.jpg type:file]
2023-06-26 18:50:22 19fb9-veeue Get(baz.jpg)
2023-06-26 18:50:22 19fb9-veeue GetGlobal(baz.jpg)
2023-06-26 18:50:22 receiveonly/19fb9-veeue@0xc000488800 parent not missing baz.jpg
2023-06-26 18:50:22 19fb9-veeue Availability(baz.jpg)
2023-06-26 18:50:22 stats.DeviceStatisticsReference.WasSeen: 362XLTQ-J3DBHPM-WITU2L5-6D33IZW-YNYL64Y-GJL6FIW-G7O2NAX-GTTSTAV
2023-06-26 18:50:22 19fb9-veeue Get(baz.jpg)
2023-06-26 18:50:22 receiveonly/19fb9-veeue@0xc000488800 need file baz.jpg; copy 3, reused 0
2023-06-26 18:50:22 log 1161 ItemStarted map[action:update folder:19fb9-veeue item:baz.jpg type:file]
2023-06-26 18:50:22 basic /mnt/Pictures/Test Watch: Ignoring .syncthing.baz.jpg.tmp
2023-06-26 18:50:22 folderconfiguration.go:274 basic /mnt/Pictures/Test Usage . {54254756691968 54263936974848} <nil>
2023-06-26 18:50:22 http: GET "/rest/events?since=1116": status 200, 609 bytes in 0.19 ms
2023-06-26 18:50:22 receiveonly/19fb9-veeue@0xc000488800 closing baz.jpg
2023-06-26 18:50:22 receiveonly/19fb9-veeue@0xc000488800 new error for baz.jpg: finishing: opening temp file: open /mnt/Pictures/Test/.syncthing.baz.jpg.tmp: operation not permitted
2023-06-26 18:50:22 progress emitter: deregistering 19fb9-veeue baz.jpg
2023-06-26 18:50:22 receiveonly/19fb9-veeue@0xc000488800 changed 1 on try 3
2023-06-26 18:50:22 Puller (folder "Test" (19fb9-veeue), item "baz.jpg"): syncing: finishing: opening temp file: open /mnt/Pictures/Test/.syncthing.baz.jpg.tmp: operation not permitted
2023-06-26 18:50:22 "Test" (19fb9-veeue): Failed to sync 1 items
2023-06-26 18:50:22 log 1162 ItemFinished map[action:update error:0xc000a89290 folder:19fb9-veeue item:baz.jpg type:file]
2023-06-26 18:50:22 log 1163 FolderErrors map[errors:[{baz.jpg syncing: finishing: opening temp file: open /mnt/Pictures/Test/.syncthing.baz.jpg.tmp: operation not permitted}] folder:19fb9-veeue]
2023-06-26 18:50:22 Folder "Test" (19fb9-veeue) isn't making sync progress - retrying in 1h4m0s.
2023-06-26 18:50:22 log 1164 StateChanged map[duration:0.656175123 folder:19fb9-veeue from:sync-preparing to:idle]
2023-06-26 18:50:22 19fb9-veeue Snapshot()
2023-06-26 18:50:22 progress emitter: bytes completed for 19fb9-veeue: 0
2023-06-26 18:50:22 19fb9-veeue Snapshot()
2023-06-26 18:50:22 model@0xc001482340 Completion(362XLTQ-J3DBHPM-WITU2L5-6D33IZW-YNYL64Y-GJL6FIW-G7O2NAX-GTTSTAV, "19fb9-veeue"): map[completion:100 globalBytes:303196 globalItems:1 needBytes:0 needDeletes:0 needItems:0 remoteState:valid sequence:15]
2023-06-26 18:50:22 log 1165 FolderSummary {19fb9-veeue 0xc000d50dc0}
2023-06-26 18:50:22 log 1166 FolderCompletion map[completion:100 device:362XLTQ-J3DBHPM-WITU2L5-6D33IZW-YNYL64Y-GJL6FIW-G7O2NAX-GTTSTAV folder:19fb9-veeue globalBytes:303196 globalItems:1 needBytes:0 needDeletes:0 needItems:0 remoteState:valid sequence:15]
2023-06-26 18:50:22 http: GET "/rest/events?since=1118": status 200, 2738 bytes in 0.46 ms

[gadget]

@enzo

Everything runs fine without the NFS layer in the middle.

I think that pretty much sums up where the issue is.

Any suggestions are appreciated. I’m currently wondering if there’s a way to get more granularity from the “not permitted”

When a program requests a file handle from the OS, all that’s often returned is a success/fail without any details. And it gets even more vague when network shares are involved.

There are a number of things that can cause an “operation not permitted” error, but the most common one on Linux is file/directory permissions.

error, or if there’s a hidden setting to really ignore permissions.

There’s ignoring permissions in terms of not replicating them, and then there’s ignoring permissions in terms of not abiding by them. The former is easy, while the latter isn’t something that any userland program can or is supposed to do (even setuid/setgid in Unix/Linux has its limits).

Running version v1.23.5 installed via TrueCharts on TrueNAS SCALE 22.12.3.1

Last time I checked, TrueNAS SCALE runs all add-on apps in containers, so your Syncthing instance is running inside what’s effectively another Linux system.

You’ll have to map the user:group that Syncthing is running under inside the container to whoever owns the target path via the NFS mount. (Note: For security reasons, by default, root:root has restricted access to NFS shares.)

So it’s a TrueNAS + NFS + Docker/Kubernetes problem rather than a Syncthing problem.

[calmh (Jakob Borg)]

Looks to me like it can’t open the file for reading after having created it and written to it. ACL permissions may be odd/incorrect.

What’s the reason for the NFS bit? My impression of current TrueNAS is just that everything is a container and access is via Docker volumes.

[enzo (Lorenzo Castoldi)]

Thanks both for the replies.

@gadget

Last time I checked, TrueNAS SCALE runs all add-on apps in containers, so your Syncthing instance is running inside what’s effectively another Linux system.

@calmh

What’s the reason for the NFS bit? My impression of current TrueNAS is just that everything is a container and access is via Docker volumes.

You are right that Syncthing runs as a Docker container. A recent version of TrueNAS introduced “Host Path Validation”, which makes it impossible for Docker containers to mount a host path (ordinary filesystem path) which is also shared over SMB.

https://www.truenas.com/docs/scale/scaletutorials/apps/appadvancedsettings/configuring-host-path-safety-checks/

The official rationale is that host paths are “not secure” – I’m unsure if that’s infosec “secure” or data-integrity “secure”. It’s also very flaky, since the SMB service can just be started after the apps are running. It’s possible to just turn the validation off, but of course not recommended.

Non-official sources state that the root cause is apps which change file permissions, and/or “don’t work with ACLs”:

https://truecharts.org/news/hostpath-validation/

So, the workaround is for the app to mount the folder in question as a share, instead of using a host filesystem path. And sure enough, this prevents chmod from working, which I guess is the whole point? Clear as mud, honestly. But it’s a very difficult constraint to work around – I want to use Syncthing to backup the photos off my phone, for example, but now I can only access their non-shared directory with rsync or scp.

Another workaround…I could just run Syncthing on my desktop instead of the NAS

@gadget

You’ll have to map the user:group that Syncthing is running under inside the container to whoever owns the target path via the NFS mount. (Note: For security reasons, by default, root:root has restricted access to NFS shares.)

@calmh

Looks to me like it can’t open the file for reading after having created it and written to it. ACL permissions may be odd/incorrect.

I did try giving the apps user “full access” permissions, as well as chowning the folder as apps:apps, neither of which had any effect. I also messed with the NFS “mapall user” setting, no luck. But maybe the ACL is getting lost in the NFS layer somehow. I’ll create a test directory without an ACL and see if there’s any difference.

To elaborate on something I mentioned in the OP, it’s possible to open a shell within an application container. This is how I tested out the permissions manually; nosing around within the Syncthing container (really its mounted volumes). I had no problem creating or modifying files this way, less chmod. So if there’s some NFS-related permissions glitch, coreutils is immune.

Anyway – if this turns into a permissions troubleshooting thread, I’ll take it to the FreeNAS forums

@gadget

When a program requests a file handle from the OS, all that’s often returned is a success/fail without any details. And it gets even more vague when network shares are involved.

Understood. I am basically just suspicious that Syncthing is still trying to chmod the files, even though that’s not what the log messages say. After all, if the OS really denied permission to open the file, then the temp file wouldn’t get created. If Syncthing were to create an empty file, chmod it, then modify it, then it would explain the behavior – maybe there just isn’t a Syncthing log message for each micro step along the way. (Just my pet theory)

[enzo (Lorenzo Castoldi)]

I think I figured it out.

The issue reproduces 100% on my system if the sync folder has an NFSv4 ACL. POSIX ACLs are fine, and if a folder further up the filesystem tree has an NFSv4 ACL, that’s also no problem. But if the existing folder /mnt/myStuff/sync/ has an NFSv4 ACL, and I try to set up Syncthing like /mnt/myStuff/sync/.stfolder/, it’ll crap out.

POSIX ACLs work fine. If it lacks permissions, Syncthing won’t create any files or folders at all (as expected). And if it has permissions, the ACL doesn’t get in the way. Restrictive NFSv4 ACLs worked the same, but even the most permissive possible NFSv4 ACL (777 apps:apps) triggers this folders-only behavior.

The “solution” is to strip the ACL (I had applied mine recursively), make sure any folders to sync are created, then apply the ACL non-recursively. This way, none of the sync folders pick up the ACL, and Syncthing works as expected. This is a pretty crappy solution, since any new folders will inherit the ACL (maybe there’s a way to turn this off), and the ACL permissions aren’t effective in the sub-folders. At least it can control access to the share as a whole.

I have no idea if this issue originates from within Syncthing itself, the Docker package I’m using, or something else entirely. Thanks for the support either way, this really had me pulling my hair out.

[calmh (Jakob Borg)]

I would take the escape hatch in the last paragraph on the linked page about host path validation;

Disabling host path safety checks might be helpful if you intend to have an app running in a shared dataset. For example, if you have apps that perform virus detection or media management and want them to work on files in your shared dataset.

But, I think Syncthing should work as well over NFS if it gets appropriate permissions and you check ignore permissions.

If it doesn’t, I wonder if the ACL is still too strict somehow. Syncthing creates temp files with 0600, if the ownership gets switcherood by some mapping, perhaps it then can’t open the file again afterwards. Actually no, when ignore permissions is set we create files with 0666 (minus whatever umask is in effect) and then just leave that as-is. Perhaps it’s running with a restrictive umask?

This is all magic to me as I don’t have such as system yet (though will soon, likely), but I don’t see why Syncthing over NFS would act any different than any other “normal user” over NFS. It’s just normal file access.