[systemd-devel] Manual start of user@<uid>.service failed with permission denied

Fri Dec 8 16:53:50 UTC 2023

Hi Mantas,

I have from your suggestion done the following:

Putting the below in user at .service

[Service]
...
Environment=XDG_RUNTIME_DIR=/run/user/%i
Environment=SYSTEMD_LOG_LEVEL=debug

Putting the below in user-runtime-dir at .service

[Service]
...
Environment=SYSTEMD_LOG_LEVEL=debug

Then I have disabled the global set-log-level debug (if this is also required, please let me know). What I can see from the logs is that user-runtime-dir at 1001.service<mailto:user-runtime-dir at 1001.service> seems to be started and mount /run/user/1001, but addition creation of directory under this mount is getting permission denied.

Dec 08 17:33:29 host systemd[1]: Created slice User Slice of UID 1001.
Dec 08 17:33:29 host systemd[1]: Starting User Runtime Directory /run/user/1001...
Dec 08 17:33:29 host systemd-user-runtime-dir[36278]: Bus n/a: changing state UNSET -> OPENING
Dec 08 17:33:29 host systemd-user-runtime-dir[36278]: sd-bus: starting bus by connecting to /run/dbus/system_bus_socket...
Dec 08 17:33:29 host systemd-user-runtime-dir[36278]: Bus n/a: changing state OPENING -> AUTHENTICATING
Dec 08 17:33:29 host systemd-user-runtime-dir[36278]: Bus n/a: changing state AUTHENTICATING -> HELLO
Dec 08 17:33:29 host systemd-user-runtime-dir[36278]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=Hello cookie=1 reply_cookie=0 signature=n/a error-name=n/a error-message=n/a
Dec 08 17:33:29 host systemd-user-runtime-dir[36278]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.2536 path=n/a interface=n/a member=n/a  cookie=1 reply_cookie=1 signature=s error-name=n/a error-message=n/a
Dec 08 17:33:29 host systemd-user-runtime-dir[36278]: Bus n/a: changing state HELLO -> RUNNING
Dec 08 17:33:29 host systemd-user-runtime-dir[36278]: Sent message type=method_call sender=n/a destination=org.freedesktop.login1 path=/org/freedesktop/login1 interface=org.freedesktop.DBus.Properties member=Get cookie=2 reply_cookie=0 signature=ss error-name=n/a error-message=n/a
Dec 08 17:33:29 host systemd-user-runtime-dir[36278]: Got message type=method_return sender=:1.323 destination=:1.2536 path=n/a interface=n/a member=n/a  cookie=15 reply_cookie=2 signature=v error-name=n/a error-message=n/a
Dec 08 17:33:29 host systemd-user-runtime-dir[36278]: Sent message type=method_call sender=n/a destination=org.freedesktop.login1 path=/org/freedesktop/login1 interface=org.freedesktop.DBus.Properties member=Get cookie=3 reply_cookie=0 signature=ss error-name=n/a error-message=n/a
Dec 08 17:33:29 host systemd-user-runtime-dir[36278]: Got message type=method_return sender=:1.323 destination=:1.2536 path=n/a interface=n/a member=n/a  cookie=16 reply_cookie=3 signature=v error-name=n/a error-message=n/a
Dec 08 17:33:29 host systemd-user-runtime-dir[36278]: Bus n/a: changing state RUNNING -> CLOSED
Dec 08 17:33:29 host systemd-user-runtime-dir[36278]: Will mount /run/user/1001 owned by 1001:118
Dec 08 17:33:29 host systemd-user-runtime-dir[36278]: Mounting tmpfs (tmpfs) on /run/user/1001 (MS_NOSUID|MS_NODEV "mode=0700,uid=1001,gid=118,size=99426304,nr_inodes=24274")...
Dec 08 17:33:29 host systemd[1]: Finished User Runtime Directory /run/user/1001.
Dec 08 17:33:29 host systemd[1]: Starting User Manager for UID 1001...
Dec 08 17:33:29 host systemd[36280]: systemd 254.7-2-g9edc143 running in user mode for user 1001/ida. (-PAM -AUDIT -SELINUX -APPARMOR +IMA -SMACK +SECCOMP +GCRYPT +GNUTLS +OPENSSL -ACL +BLKID +CURL -ELFUTILS -FIDO2 -IDN2 -IDN -IPTC +KMOD -LIBCRYPTSETUP +LIBFDISK -PCRE2 -PWQUALITY -P11KIT -QRENCODE -TPM2 +BZIP2 -LZ4 +XZ +ZLIB +ZSTD -BPF_FRAMEWORK -XKBCOMMON -UTMP -SYSVINIT default-hierarchy=unified)
Dec 08 17:33:29 host systemd[36280]: Failed to create '/run/user/1001/systemd/inaccessible', ignoring: Permission denied
Dec 08 17:33:29 host systemd[36280]: Failed to create '/run/user/1001/systemd/inaccessible/reg', ignoring: Permission denied
Dec 08 17:33:29 host systemd[36280]: Failed to create '/run/user/1001/systemd/inaccessible/dir', ignoring: Permission denied
Dec 08 17:33:29 host systemd[36280]: Failed to create '/run/user/1001/systemd/inaccessible/fifo', ignoring: Permission denied
Dec 08 17:33:29 host systemd[36280]: Failed to create '/run/user/1001/systemd/inaccessible/sock', ignoring: Permission denied
Dec 08 17:33:29 host systemd[36280]: Failed to create '/run/user/1001/systemd/inaccessible/chr', ignoring: Permission denied
Dec 08 17:33:29 host systemd[36280]: Failed to create '/run/user/1001/systemd/inaccessible/blk', ignoring: Permission denied
Dec 08 17:33:29 host systemd[36280]: Failed to create parent directory of /run/user/1001/systemd/propagate/.os-release-stage/os-release, ignoring: Permission denied
Dec 08 17:33:29 host systemd[36280]: Failed to copy os-release for propagation, ignoring: Permission denied
Dec 08 17:33:29 host systemd[36280]: Failed at setting rlimit 1073741816 for resource RLIMIT_NOFILE. Will attempt setting value 524288 instead.
Dec 08 17:33:29 host systemd[36280]: Found cgroup2 on /sys/fs/cgroup/, full unified hierarchy
Dec 08 17:33:29 host systemd[36280]: Unified cgroup hierarchy is located at /sys/fs/cgroup/user.slice/user-1001.slice/user at 1001.service.
Dec 08 17:33:29 host systemd[36280]: bpf-firewall: Got EBADF when using BPF_F_ALLOW_MULTI, which indicates it is supported. Yay!
Dec 08 17:33:29 host systemd[36280]: Not enough privileges, BPF device control is not supported.
Dec 08 17:33:29 host systemd[36280]: Controller 'cpu' supported: yes
Dec 08 17:33:29 host systemd[36280]: Controller 'cpuacct' supported: no
Dec 08 17:33:29 host systemd[36280]: Controller 'cpuset' supported: no
Dec 08 17:33:29 host systemd[36280]: Controller 'io' supported: no
Dec 08 17:33:29 host systemd[36280]: Controller 'blkio' supported: no
Dec 08 17:33:29 host systemd[36280]: Controller 'memory' supported: yes
Dec 08 17:33:29 host systemd[36280]: Controller 'devices' supported: no
Dec 08 17:33:29 host systemd[36280]: Controller 'pids' supported: yes
Dec 08 17:33:29 host systemd[36280]: Controller 'bpf-firewall' supported: yes
Dec 08 17:33:29 host systemd[36280]: Controller 'bpf-devices' supported: no
Dec 08 17:33:29 host systemd[36280]: Controller 'bpf-foreign' supported: yes
Dec 08 17:33:29 host systemd[36280]: Controller 'bpf-socket-bind' supported: no
Dec 08 17:33:29 host systemd[36280]: Controller 'bpf-restrict-network-interfaces' supported: no
Dec 08 17:33:29 host systemd[36280]: Set up TFD_TIMER_CANCEL_ON_SET timerfd.
Dec 08 17:33:29 host systemd[36280]: Failed to establish memory pressure event source, ignoring: Operation not supported
Dec 08 17:33:29 host systemd[36280]: Failed to allocate manager object: Permission denied
Dec 08 17:33:29 host systemd[1]: user at 1001.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 17:33:29 host systemd[1]: user at 1001.service: Failed with result 'exit-code'.
Dec 08 17:33:29 host systemd[1]: Failed to start User Manager for UID 1001.
Dec 08 17:33:29 host systemd[1]: Stopping User Runtime Directory /run/user/1001...
Dec 08 17:33:29 host systemd-user-runtime-dir[36283]: Will remove /run/user/1001
Dec 08 17:33:29 host systemd[1]: user-runtime-dir at 1001.service: Deactivated successfully.
Dec 08 17:33:29 host systemd[1]: Stopped User Runtime Directory /run/user/1001.
Dec 08 17:33:29 host systemd[1]: Removed slice User Slice of UID 1001.

Best regards,
Christopher Wong

From: Mantas Mikulėnas <grawity at gmail.com>
Date: Friday, 8 December 2023 at 12:11
To: Christopher Wong <Christopher.Wong at axis.com>
Cc: Luca Boccassi <luca.boccassi at gmail.com>, Systemd <systemd-devel at lists.freedesktop.org>
Subject: Re: [systemd-devel] Manual start of user@<uid>.service failed with permission denied
On Fri, Dec 8, 2023, 12:22 Christopher Wong <Christopher.Wong at axis.com<mailto:Christopher.Wong at axis.com>> wrote:
Hi Luca,

Sorry, for late reply, below is a log with debug. This time I run with a user with higher UID, but the result is the same.

root at host:~# systemd-analyze set-log-level debug
root at host:~# systemctl set-environment XDG_RUNTIME_DIR="/run/user/1001"

I'd avoid doing that globally. If you really want to have a PAM-less system, then edit the unit to set this through its Environment= instead.

root at host:~# systemctl start user at 1001.service
Job for user at 1001.service failed because the control process exited with error code.
See "systemctl status user at 1001.service" and "journalctl -xeu user at 1001.service" for details.
root at host:~# journalctl -xeu user at 1001.service
Dec 08 09:35:53 host systemd[1]: /usr/lib/systemd/system/user at .service:19: Support for option PAMName= has been disabled at compile time and it is ignored
Dec 08 09:35:53 host systemd[1]: user at 1001.service: Trying to enqueue job user at 1001.service/start/replace
Dec 08 09:35:53 host systemd[1]: user at 1001.service: Installed new job user at 1001.service/start as 6724
Dec 08 09:35:53 host systemd[1]: user at 1001.service: Enqueued job user at 1001.service/start as 6724
Dec 08 09:35:53 host systemd[1]: user at 1001.service: starting held back, waiting for: user-runtime-dir at 1001.service
Dec 08 09:35:54 host systemd[1]: user at 1001.service: Will spawn child (service_enter_start): /usr/lib/systemd/systemd
Dec 08 09:35:54 host systemd[1]: user at 1001.service: Failed to set 'memory.zswap.max' attribute on '/user.slice/user-1001.slice/user at 1001.service' to 'max': No such file or directory
Dec 08 09:35:54 host systemd[1]: user at 1001.service: Passing 0 fds to service
Dec 08 09:35:54 host systemd[1]: user at 1001.service: About to execute: /usr/lib/systemd/systemd --user
Dec 08 09:35:54 host systemd[1]: user at 1001.service: Forked /usr/lib/systemd/systemd as 6899
Dec 08 09:35:54 host (systemd)[6899]: Found cgroup2 on /sys/fs/cgroup/, full unified hierarchy
Dec 08 09:35:54 host systemd[1]: user at 1001.service: Changed dead -> start
Dec 08 09:35:54 host systemd[1]: Starting User Manager for UID 1001...
Dec 08 09:35:54 host (systemd)[6899]: Bind-mounting / on /run/systemd/mount-rootfs (MS_BIND|MS_REC "")...
Dec 08 09:35:54 host systemd[1]: user at 1001.service: User lookup succeeded: uid=1001 gid=118
Dec 08 09:35:54 host (systemd)[6899]: Applying namespace mount on /run/systemd/mount-rootfs/run/credentials
Dec 08 09:35:54 host (systemd)[6899]: Bind-mounting /run/systemd/inaccessible/dir on /run/systemd/mount-rootfs/run/credentials (MS_BIND|MS_REC "")...
Dec 08 09:35:54 host (systemd)[6899]: Successfully mounted /run/systemd/inaccessible/dir to /run/systemd/mount-rootfs/run/credentials
Dec 08 09:35:54 host (systemd)[6899]: Applying namespace mount on /run/systemd/mount-rootfs/run/systemd/incoming
Dec 08 09:35:54 host (systemd)[6899]: Followed source symlinks /run/systemd/propagate/user at 1001.service → /run/systemd/propagate/user at 1001.service.
Dec 08 09:35:54 host (systemd)[6899]: Bind-mounting /run/systemd/propagate/user at 1001.service on /run/systemd/mount-rootfs/run/systemd/incoming (MS_BIND "")...
Dec 08 09:35:54 host (systemd)[6899]: Successfully mounted /run/systemd/propagate/user at 1001.service to /run/systemd/mount-rootfs/run/systemd/incoming
Dec 08 09:35:54 host (systemd)[6899]: Applying namespace mount on /run/systemd/mount-rootfs/sys
Dec 08 09:35:54 host (systemd)[6899]: Failed to umount /run/systemd/mount-rootfs/sys, ignoring: Device or resource busy
Dec 08 09:35:54 host (systemd)[6899]: Failed to umount /run/systemd/mount-rootfs/sys, ignoring: Device or resource busy
Dec 08 09:35:54 host (systemd)[6899]: Failed to umount /run/systemd/mount-rootfs/sys, ignoring: Device or resource busy
Dec 08 09:35:54 host (systemd)[6899]: Failed to umount /run/systemd/mount-rootfs/sys, ignoring: Device or resource busy
Dec 08 09:35:54 host (systemd)[6899]: Failed to umount /run/systemd/mount-rootfs/sys, ignoring: Device or resource busy
Dec 08 09:35:54 host (systemd)[6899]: Failed to umount /run/systemd/mount-rootfs/sys, ignoring: Device or resource busy
Dec 08 09:35:54 host (systemd)[6899]: Failed to umount /run/systemd/mount-rootfs/sys, ignoring: Device or resource busy
Dec 08 09:35:54 host (systemd)[6899]: Failed to umount /run/systemd/mount-rootfs/sys, ignoring: Device or resource busy
Dec 08 09:35:54 host (systemd)[6899]: Mounting sysfs (sysfs) on /run/systemd/mount-rootfs/sys (MS_NOSUID|MS_NODEV|MS_NOEXEC "")...
Dec 08 09:35:54 host (systemd)[6899]: user at 1001.service: Executing: /usr/lib/systemd/systemd --user
Dec 08 09:35:54 host systemd[6899]: Failed to copy os-release for propagation, ignoring: Permission denied
Dec 08 09:35:54 host systemd[6899]: Failed to allocate manager object: Permission denied
Try setting SYSTEMD_LOG_LEVEL=debug for the user@ service unit to see what happens here. (This is a separate instance so it doesn't inherit the debug level that pid1 has...)

Also, I might've missed this, but does anything *create* /run/user/1001 here? Normally user-user-runtime-dir at 1001.service would be the one to do so, and I see "waiting for: user-runtime-dir at 1001.service" in the logs, but I don't see anything else – did that service actually succeed? is the path owned by UID 1001?
Dec 08 09:35:54 host systemd[1]: user at 1001.service: Got notification message from PID 6899 (ERRNO=13)
Dec 08 09:35:54 host systemd[1]: user at 1001.service: Got notification message from PID 6899 (EXIT_STATUS=1)
Dec 08 09:35:54 host systemd[1]: user at 1001.service: Child 6899 belongs to user at 1001.service.
Dec 08 09:35:54 host systemd[1]: user at 1001.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:35:54 host systemd[1]: user at 1001.service: Failed with result 'exit-code'.
Dec 08 09:35:54 host systemd[1]: user at 1001.service: Service will not restart (restart setting)
Dec 08 09:35:54 host systemd[1]: user at 1001.service: Changed start -> failed
Dec 08 09:35:54 host systemd[1]: user at 1001.service: Job 6724 user at 1001.service/start finished, result=failed
Dec 08 09:35:54 host systemd[1]: Failed to start User Manager for UID 1001.
Dec 08 09:35:54 host systemd[1]: user at 1001.service: Unit entered failed state.
Dec 08 09:35:54 host systemd[1]: user at 1001.service: Consumed 63ms CPU time.
Dec 08 09:35:54 host systemd[1]: user at 1001.service: Releasing resources...

Best regards,
Christopher Wong

From: Luca Boccassi <luca.boccassi at gmail.com<mailto:luca.boccassi at gmail.com>>
Date: Wednesday, 6 December 2023 at 17:46
To: Christopher Wong <Christopher.Wong at axis.com<mailto:Christopher.Wong at axis.com>>
Cc: systemd-devel at lists.freedesktop.org<mailto:systemd-devel at lists.freedesktop.org> <systemd-devel at lists.freedesktop.org<mailto:systemd-devel at lists.freedesktop.org>>
Subject: Re: [systemd-devel] Manual start of user@<uid>.service failed with permission denied
On Wed, 6 Dec 2023 at 16:00, Christopher Wong <Christopher.Wong at axis.com<mailto:Christopher.Wong at axis.com>> wrote:
> Hi,
>
> I’m trying to do the following:
>
> root at host:~# systemctl set-environment XDG_RUNTIME_DIR="/run/user/503"

Why are you setting this?
Anyway, enable debug level log and attach the output, otherwise it's hard to say
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/systemd-devel/attachments/20231208/2a6f2ad7/attachment-0001.htm>