systemd-portabled fails to start service with "Failed to set up mount namespacing: Permission denied"

[calebccff]

systemd version the issue has been seen with

systemd-255.4-1.fc41.aarch64

Used distribution

Fedora rawhide

Linux kernel version used

6.9.0-rc6-sdm845-00141-g8a2a63badb24-dirty

CPU architectures issue was seen on

aarch64

Component

systemd-portabled

Expected behaviour you didn't see

attached services start

Unexpected behaviour you saw

services started via portabled fail with a namespace error (see below error log).

I'm booting Fedora Rawhide (a slightly older image from 23rd april) on a Qualcomm platform and attempting to run some system services which are in a postmarketOS rootfs image (adjusted to meet the portabled requirements). The pmOS image is installed in a sysext which also includes device specific firmware and kernel modules.

Below is the debug output from journalctl when starting one of the services.

sysext, portabled, and service info are below. The portabled image is attached using the "trusted" profile.

root@fedora:/home/user# systemd-sysext list
NAME      TYPE PATH                              TIME
otter-dal raw  /var/lib/extensions/otter-dal.raw Fri 2024-03-01 01:11:05 CET
root@fedora:/home/user# portablectl inspect otter-dal_0.1.0
(Matching unit files with prefix 'otter-dal'.)
Image:
        /etc/portables/otter-dal_0.1.0.raw
Portable Service:
        n/a
Operating System:
        Fedora Linux 41 (Workstation Edition Prerelease)
Unit files:
        otter-dal-pd-mapper.service
        otter-dal-rmtfs.service
        otter-dal-tqftpserv.service
root@fedora:/home/user# systemctl cat otter-dal-tqftpserv --no-pager
# /etc/systemd/system.attached/otter-dal-tqftpserv.service
[Unit]
Description=QRTR TFTP services
Before=rmtfs.service

[Service]
ExecStart=/usr/bin/tqftpserv
Restart=always
RestartSec=1

[Install]
WantedBy=multi-user.target

# /etc/systemd/system.attached/otter-dal-tqftpserv.service.d/10-profile.conf
# The "trusted" profile for services, i.e. no restrictions are applied apart from a private /tmp

[Service]
MountAPIVFS=yes
PrivateTmp=yes
BindPaths=/run
BindReadOnlyPaths=/etc/machine-id
BindReadOnlyPaths=/etc/resolv.conf

# /usr/lib/systemd/system/service.d/10-timeout-abort.conf
# This file is part of the systemd package.
# See https://fedoraproject.org/wiki/Changes/Shorter_Shutdown_Timer.
#
# To facilitate debugging when a service fails to stop cleanly,
# TimeoutStopFailureMode=abort is set to "crash" services that fail to stop in
# the time allotted. This will cause the service to be terminated with SIGABRT
# and a coredump to be generated.
#
# To undo this configuration change, create a mask file:
#   sudo mkdir -p /etc/systemd/system/service.d
#   sudo ln -sv /dev/null /etc/systemd/system/service.d/10-timeout-abort.conf

[Service]
TimeoutStopFailureMode=abort

# /etc/systemd/system.attached/otter-dal-tqftpserv.service.d/20-portable.conf
# Drop-in created for image '/usr/lib/portables/otter-dal_0.1.0.raw', do not edit.

[Service]
RootImage=/usr/lib/portables/otter-dal_0.1.0.raw
Environment=PORTABLE=otter-dal_0.1.0.raw
LogExtraFields=PORTABLE=otter-dal_0.1.0.raw
LogExtraFields=PORTABLE_NAME_AND_VERSION=fedora_41

Steps to reproduce the problem

No response

Additional program output to the terminal or log subsystem illustrating the issue

Mar 01 01:26:18 fedora systemd[1]: Bus private-bus-connection: changing state UNSET → OPENING
Mar 01 01:26:18 fedora systemd[1]: sd-bus: starting bus private-bus-connection on fds 20/20 (socket:[26025], socket:[26025])...
Mar 01 01:26:18 fedora systemd[1]: Bus private-bus-connection: changing state OPENING → AUTHENTICATING
Mar 01 01:26:18 fedora systemd[1]: Accepting direct incoming connection from 2168 (systemctl) [n/a]
Mar 01 01:26:18 fedora systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1 iface=org.freedesktop.systemd1.Manager
Mar 01 01:26:18 fedora systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/job iface=org.freedesktop.systemd1.Job
Mar 01 01:26:18 fedora systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/unit iface=org.freedesktop.systemd1.Unit
Mar 01 01:26:18 fedora systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/unit iface=org.freedesktop.systemd1.Automount
Mar 01 01:26:18 fedora systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/unit iface=org.freedesktop.systemd1.Device
Mar 01 01:26:18 fedora systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/unit iface=org.freedesktop.systemd1.Mount
Mar 01 01:26:18 fedora systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/unit iface=org.freedesktop.systemd1.Path
Mar 01 01:26:18 fedora systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/unit iface=org.freedesktop.systemd1.Scope
Mar 01 01:26:18 fedora systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/unit iface=org.freedesktop.systemd1.Service
Mar 01 01:26:18 fedora systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/unit iface=org.freedesktop.systemd1.Slice
Mar 01 01:26:18 fedora systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/unit iface=org.freedesktop.systemd1.Socket
Mar 01 01:26:18 fedora systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/unit iface=org.freedesktop.systemd1.Swap
Mar 01 01:26:18 fedora systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/unit iface=org.freedesktop.systemd1.Target
Mar 01 01:26:18 fedora systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/unit iface=org.freedesktop.systemd1.Timer
Mar 01 01:26:18 fedora systemd[1]: Registering bus object implementation for path=/org/freedesktop/LogControl1 iface=org.freedesktop.LogControl1
Mar 01 01:26:18 fedora systemd[1]: Accepted new private connection.
Mar 01 01:26:18 fedora systemd[1]: Bus private-bus-connection: changing state AUTHENTICATING → RUNNING
Mar 01 01:26:18 fedora systemd[1]: Got message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=StartUnit  cookie=1 reply_cookie=0 signature=ss error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd[1]: otter-dal-tqftpserv.service: Trying to enqueue job otter-dal-tqftpserv.service/start/replace
Mar 01 01:26:18 fedora systemd[1]: otter-dal-tqftpserv.service: Installed new job otter-dal-tqftpserv.service/start as 4691
Mar 01 01:26:18 fedora systemd[1]: otter-dal-tqftpserv.service: Enqueued job otter-dal-tqftpserv.service/start as 4691
Mar 01 01:26:18 fedora systemd[1]: Sent message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=1 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd[1]: Sent message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=2 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=7602 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=7603 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd[1]: Sent message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=JobNew cookie=3 reply_cookie=0 signature=uos error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=JobNew cookie=7604 reply_cookie=0 signature=uos error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd[1]: Sent message type=method_return sender=org.freedesktop.systemd1 destination=n/a path=n/a interface=n/a member=n/a cookie=4 reply_cookie=1 signature=o error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd[1]: otter-dal-tqftpserv.service: Will spawn child (service_enter_start): /usr/bin/tqftpserv
Mar 01 01:26:18 fedora systemd-machined[718]: Got message type=signal sender=:1.2 destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged  cookie=7602 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd-machined[718]: Got message type=signal sender=:1.2 destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged  cookie=7603 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd-logind[717]: Got message type=signal sender=:1.2 destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged  cookie=7602 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd-logind[717]: Got message type=signal sender=:1.2 destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged  cookie=7603 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd[1]: Failed to enable controller cpu for  (/sys/fs/cgroup/cgroup.subtree_control): Invalid argument
Mar 01 01:26:18 fedora systemd[1]: otter-dal-tqftpserv.service: Failed to set 'memory.zswap.max' attribute on '/system.slice/otter-dal-tqftpserv.service' to 'max': No such file or directory
Mar 01 01:26:18 fedora systemd[1]: otter-dal-tqftpserv.service: Passing 0 fds to service
Mar 01 01:26:18 fedora systemd[1]: otter-dal-tqftpserv.service: About to execute: /usr/bin/tqftpserv
Mar 01 01:26:18 fedora systemd[1]: Serializing sd-executor-state to memfd.
Mar 01 01:26:18 fedora systemd[1]: otter-dal-tqftpserv.service: Forked /usr/bin/tqftpserv as 2170
Mar 01 01:26:18 fedora (qftpserv)[2170]: Found cgroup2 on /sys/fs/cgroup/, full unified hierarchy
Mar 01 01:26:18 fedora (qftpserv)[2170]: Found cgroup2 on /sys/fs/cgroup/, full unified hierarchy
Mar 01 01:26:18 fedora systemd[1]: Closing set fd 89 (socket:[12369])
Mar 01 01:26:18 fedora (qftpserv)[2170]: Opened '/usr/lib/portables/otter-dal_0.1.0.raw' in O_RDONLY access mode (O_RDWR was requested but not allowed), with O_DIRECT enabled.
Mar 01 01:26:18 fedora systemd-journald[445]: Successfully sent stream file descriptor to service manager.
Mar 01 01:26:18 fedora kernel: loop0: detected capacity change from 0 to 788480
Mar 01 01:26:18 fedora (qftpserv)[2170]: Couldn't find any partition table to derive sector size of.
Mar 01 01:26:18 fedora systemd[1]: Sent message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=5 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd[1]: Sent message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=6 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora (qftpserv)[2170]: loop0: Acquired exclusive lock.
Mar 01 01:26:18 fedora systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=7605 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=7606 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd-udevd[492]: 7:0: Device is queued (SEQNUM=5045, ACTION=add)
Mar 01 01:26:18 fedora audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=otter-dal-tqftpserv comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Mar 01 01:26:18 fedora systemd[1]: otter-dal-tqftpserv.service: Changed failed -> running
Mar 01 01:26:18 fedora systemd[1]: varlink-77: Sending message: {"parameters":{"cgroups":[{"mode":"auto","path":"/system.slice/otter-dal-tqftpserv.service","property":"ManagedOOMSwap"},{"mode":"auto","path":"/system.slice/otter-dal-tqftpserv.service","property":"ManagedOOMMemoryPressure","limit":0}]},"continues":true}
Mar 01 01:26:18 fedora systemd[1]: Sent message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=7 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=7607 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd[1]: otter-dal-tqftpserv.service: Job 4691 otter-dal-tqftpserv.service/start finished, result=done
Mar 01 01:26:18 fedora systemd[1]: Started otter-dal-tqftpserv.service - QRTR TFTP services.
Mar 01 01:26:18 fedora systemd[1]: Sent message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=8 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd[1]: Sent message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=9 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=7608 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd-logind[717]: Got message type=signal sender=:1.2 destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged  cookie=7605 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd-logind[717]: Got message type=signal sender=:1.2 destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged  cookie=7606 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=7609 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd-logind[717]: Got message type=signal sender=:1.2 destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged  cookie=7607 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd[1]: Sent message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=JobRemoved cookie=10 reply_cookie=0 signature=uoss error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=JobRemoved cookie=7610 reply_cookie=0 signature=uoss error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd-machined[718]: Got message type=signal sender=:1.2 destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged  cookie=7605 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd-machined[718]: Got message type=signal sender=:1.2 destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged  cookie=7606 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd[1]: Failed to communicate with plymouth: Connection refused
Mar 01 01:26:18 fedora systemd-machined[718]: Got message type=signal sender=:1.2 destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged  cookie=7607 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd-machined[718]: Got message type=signal sender=:1.2 destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged  cookie=7608 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd-machined[718]: Got message type=signal sender=:1.2 destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged  cookie=7609 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd[1]: user-1001.slice: Failed to set 'cpu.weight' attribute on '/user.slice/user-1001.slice' to '100': No such file or directory
Mar 01 01:26:18 fedora systemd-machined[718]: Got message type=signal sender=:1.2 destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=JobRemoved  cookie=7610 reply_cookie=0 signature=uoss error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd[1]: user-1001.slice: Failed to set 'cpu.max' attribute on '/user.slice/user-1001.slice' to 'max 100000': No such file or directory
Mar 01 01:26:18 fedora systemd[1]: user-1001.slice: Failed to set 'io.weight' attribute on '/user.slice/user-1001.slice' to 'default 100': No such file or directory
Mar 01 01:26:18 fedora systemd-logind[717]: Got message type=signal sender=:1.2 destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged  cookie=7608 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd-logind[717]: Got message type=signal sender=:1.2 destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged  cookie=7609 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd[1]: user-1001.slice: Failed to set 'memory.zswap.max' attribute on '/user.slice/user-1001.slice' to 'max': No such file or directory
Mar 01 01:26:18 fedora systemd-logind[717]: Got message type=signal sender=:1.2 destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=JobRemoved  cookie=7610 reply_cookie=0 signature=uoss error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd[1]: Failed to enable controller cpu for  (/sys/fs/cgroup/cgroup.subtree_control): Invalid argument
Mar 01 01:26:18 fedora (qftpserv)[2170]: Successfully acquired /dev/loop0, devno=7:0, nr=0, diskseq=117
Mar 01 01:26:18 fedora (qftpserv)[2170]: Opened /dev/loop0 (fd=3, whole_block_devnum=7:0, diskseq=117).
Mar 01 01:26:18 fedora (qftpserv)[2170]: /run/systemd/mount-rootfs/run (run) is duplicate.
Mar 01 01:26:18 fedora (qftpserv)[2170]: Successfully forked off '(fsck)' as PID 2171.
Mar 01 01:26:18 fedora systemd-udevd[492]: 7:0: Device ready for processing (SEQNUM=5045, ACTION=add)
Mar 01 01:26:18 fedora (qftpserv)[2170]: fsck failed with exit status 8.
Mar 01 01:26:18 fedora (qftpserv)[2170]: fsck failed with exit status 8.
Mar 01 01:26:18 fedora (qftpserv)[2170]: Ignoring fsck error.
Mar 01 01:26:18 fedora (qftpserv)[2170]: Mounting /proc/self/fd/3 (ext4) on /run/systemd/mount-rootfs (MS_NODEV "")...
Mar 01 01:26:18 fedora (qftpserv)[2170]: Failed to mount /proc/self/fd/3 (type ext4) on /run/systemd/mount-rootfs (MS_NODEV ""): Permission denied
Mar 01 01:26:18 fedora (qftpserv)[2170]: Failed to mount root image: Permission denied
Mar 01 01:26:18 fedora systemd[1]: Failed to enable controller cpu for /user.slice (/sys/fs/cgroup/user.slice/cgroup.subtree_control): No such file or directory
Mar 01 01:26:18 fedora systemd-udevd[492]: Successfully forked off '(udev-worker)' as PID 2173.
Mar 01 01:26:18 fedora systemd[1]: user.slice: Failed to set 'cpu.weight' attribute on '/user.slice' to '100': No such file or directory
Mar 01 01:26:18 fedora systemd[1]: user.slice: Failed to set 'cpu.max' attribute on '/user.slice' to 'max 100000': No such file or directory
Mar 01 01:26:18 fedora systemd[1]: user.slice: Failed to set 'io.weight' attribute on '/user.slice' to 'default 100': No such file or directory
Mar 01 01:26:18 fedora systemd-udevd[492]: 7:0: Worker [2173] is forked for processing SEQNUM=5045.
Mar 01 01:26:18 fedora systemd[1]: user.slice: Failed to set 'memory.zswap.max' attribute on '/user.slice' to 'max': No such file or directory
Mar 01 01:26:18 fedora systemd[1]: user-1001.slice: Failed to set 'cpu.weight' attribute on '/user.slice/user-1001.slice' to '100': No such file or directory
Mar 01 01:26:18 fedora systemd[1]: user-1001.slice: Failed to set 'cpu.max' attribute on '/user.slice/user-1001.slice' to 'max 100000': No such file or directory
Mar 01 01:26:18 fedora systemd-udevd[492]: loop0: Device is queued (SEQNUM=5046, ACTION=add)
Mar 01 01:26:18 fedora systemd[1]: user-1001.slice: Failed to set 'io.weight' attribute on '/user.slice/user-1001.slice' to 'default 100': No such file or directory
Mar 01 01:26:18 fedora (udev-worker)[2173]: 7:0: Processing device (SEQNUM=5045, ACTION=add)
Mar 01 01:26:18 fedora systemd-udevd[492]: loop0: Device ready for processing (SEQNUM=5046, ACTION=add)
Mar 01 01:26:18 fedora systemd[1]: user-1001.slice: Failed to set 'memory.zswap.max' attribute on '/user.slice/user-1001.slice' to 'max': No such file or directory
Mar 01 01:26:18 fedora systemd[1]: user.slice: Failed to set 'cpu.weight' attribute on '/user.slice' to '100': No such file or directory
Mar 01 01:26:18 fedora systemd[1]: user.slice: Failed to set 'cpu.max' attribute on '/user.slice' to 'max 100000': No such file or directory
Mar 01 01:26:18 fedora systemd[1]: user.slice: Failed to set 'io.weight' attribute on '/user.slice' to 'default 100': No such file or directory
Mar 01 01:26:18 fedora systemd[1]: user.slice: Failed to set 'memory.zswap.max' attribute on '/user.slice' to 'max': No such file or directory
Mar 01 01:26:18 fedora systemd-udevd[492]: Successfully forked off '(udev-worker)' as PID 2174.
Mar 01 01:26:18 fedora systemd-udevd[492]: loop0: Worker [2174] is forked for processing SEQNUM=5046.
Mar 01 01:26:18 fedora (udev-worker)[2173]: 7:0: /usr/lib/udev/rules.d/99-nfs.rules:1 Running PROGRAM '/usr/libexec/nfsrahead 7:0'
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Processing device (SEQNUM=5046, ACTION=add)
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Failed to flock(/dev/loop0): Resource temporarily unavailable
Mar 01 01:26:18 fedora (udev-worker)[2173]: 7:0: Starting '/usr/libexec/nfsrahead 7:0'
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Block device is currently locked, requeueing the event.
Mar 01 01:26:18 fedora systemd[1]: Failed to enable controller cpu for  (/sys/fs/cgroup/cgroup.subtree_control): Invalid argument
Mar 01 01:26:18 fedora (udev-worker)[2173]: Successfully forked off '(spawn)' as PID 2175.
Mar 01 01:26:18 fedora systemd-udevd[492]: loop0: Device is queued (SEQNUM=5047, ACTION=change)
Mar 01 01:26:18 fedora systemd-udevd[492]: loop0: Device ready for processing (SEQNUM=5046, ACTION=add)
Mar 01 01:26:18 fedora systemd-udevd[492]: loop0: sd-device-monitor(manager): Passed 228 byte to netlink monitor.
Mar 01 01:26:18 fedora systemd-udevd[492]: loop0: SEQNUM=5047 blocked by SEQNUM=5046
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Processing device (SEQNUM=5046, ACTION=add)
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Failed to open '/dev/loop0', ignoring: No such file or directory
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Removing watch handle -1.
Mar 01 01:26:18 fedora systemd-udevd[492]: loop0: Device is queued (SEQNUM=5048, ACTION=change)
Mar 01 01:26:18 fedora systemd-udevd[492]: loop0: SEQNUM=5048 blocked by SEQNUM=5046
Mar 01 01:26:18 fedora systemd-udevd[492]: 7:0: Device is queued (SEQNUM=5049, ACTION=remove)
Mar 01 01:26:18 fedora systemd-udevd[492]: 7:0: SEQNUM=5049 blocked by SEQNUM=5045
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: /usr/lib/udev/rules.d/50-udev-default.rules:88 GROUP 6
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: /usr/lib/udev/rules.d/60-persistent-storage.rules:133 Importing properties from results of builtin command 'blkid'
Mar 01 01:26:18 fedora systemd-udevd[492]: loop0: Device is queued (SEQNUM=5050, ACTION=remove)
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Failed to open block device /dev/loop0, ignoring: No such file or directory
Mar 01 01:26:18 fedora systemd-udevd[492]: loop0: SEQNUM=5050 blocked by SEQNUM=5046
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: /usr/lib/udev/rules.d/60-persistent-storage.rules:151 Added SYMLINK 'disk/by-diskseq/116'
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Device node /dev/loop0 is missing, skipping handling.
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Successfully created symlink '/dev/disk/by-diskseq/116' to '/dev/loop0'
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Successfully created symlink '/dev/block/7:0' to '/dev/loop0'
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: sd-device: Created db file '/run/udev/data/b7:0' for '/devices/virtual/block/loop0'
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Adding watch on '/dev/loop0'
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Failed to watch device node '/dev/loop0': No such file or directory
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Device processed (SEQNUM=5046, ACTION=add)
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: sd-device-monitor(worker): Passed 316 byte to netlink monitor.
Mar 01 01:26:18 fedora systemd-udevd[492]: loop0: Device ready for processing (SEQNUM=5047, ACTION=change)
Mar 01 01:26:18 fedora systemd[978]: loop0: Processing udev action (SEQNUM=5046, ACTION=add)
Mar 01 01:26:18 fedora systemd[978]: loop0: Got 'add' action on syspath '/sys/devices/virtual/block/loop0'.
Mar 01 01:26:18 fedora systemd[978]: loop0: Device busy: SYSTEMD_READY property from device is false
Mar 01 01:26:18 fedora systemd-udevd[492]: loop0: sd-device-monitor(manager): Passed 231 byte to netlink monitor.
Mar 01 01:26:18 fedora systemd[978]: loop0: Device busy: SYSTEMD_READY property from device is false
Mar 01 01:26:18 fedora systemd-udevd[492]: loop0: SEQNUM=5048 blocked by SEQNUM=5047
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Processing device (SEQNUM=5047, ACTION=change)
Mar 01 01:26:18 fedora systemd-udevd[492]: loop0: SEQNUM=5050 blocked by SEQNUM=5047
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Failed to open '/dev/loop0', ignoring: No such file or directory
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Removing watch handle -1.
Mar 01 01:26:18 fedora systemd[978]: loop0: Device busy: SYSTEMD_READY property from device is false
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: /usr/lib/udev/rules.d/60-persistent-storage.rules:133 Importing properties from results of builtin command 'blkid'
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Failed to open block device /dev/loop0, ignoring: No such file or directory
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: /usr/lib/udev/rules.d/60-persistent-storage.rules:151 Added SYMLINK 'disk/by-diskseq/117'
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Device node /dev/loop0 is missing, skipping handling.
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Removing/updating old device symlink '/dev/disk/by-diskseq/116', which is no longer belonging to this device.
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: No reference left for '/dev/disk/by-diskseq/116', removing
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Successfully created symlink '/dev/disk/by-diskseq/117' to '/dev/loop0'
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Successfully created symlink '/dev/block/7:0' to '/dev/loop0'
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: sd-device: Created db file '/run/udev/data/b7:0' for '/devices/virtual/block/loop0'
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Adding watch on '/dev/loop0'
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Failed to watch device node '/dev/loop0': No such file or directory
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Device processed (SEQNUM=5047, ACTION=change)
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: sd-device-monitor(worker): Passed 319 byte to netlink monitor.
Mar 01 01:26:18 fedora systemd-udevd[492]: loop0: Device ready for processing (SEQNUM=5048, ACTION=change)
Mar 01 01:26:18 fedora systemd-udevd[492]: loop0: sd-device-monitor(manager): Passed 251 byte to netlink monitor.
Mar 01 01:26:18 fedora systemd[978]: loop0: Processing udev action (SEQNUM=5047, ACTION=change)
Mar 01 01:26:18 fedora systemd[978]: loop0: Got 'change' action on syspath '/sys/devices/virtual/block/loop0'.
Mar 01 01:26:18 fedora systemd-udevd[492]: loop0: SEQNUM=5050 blocked by SEQNUM=5048
Mar 01 01:26:18 fedora systemd[978]: loop0: Device busy: SYSTEMD_READY property from device is false
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Processing device (SEQNUM=5048, ACTION=change)
Mar 01 01:26:18 fedora systemd[978]: loop0: Device busy: SYSTEMD_READY property from device is false
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Failed to open '/dev/loop0', ignoring: No such file or directory
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Removing watch handle -1.
Mar 01 01:26:18 fedora systemd[978]: loop0: Device busy: SYSTEMD_READY property from device is false
Mar 01 01:26:18 fedora audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=otter-dal-tqftpserv comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: /usr/lib/udev/rules.d/60-persistent-storage.rules:133 Importing properties from results of builtin command 'blkid'
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Failed to open block device /dev/loop0, ignoring: No such file or directory
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: /usr/lib/udev/rules.d/60-persistent-storage.rules:151 Added SYMLINK 'disk/by-diskseq/117'
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Device node /dev/loop0 is missing, skipping handling.
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Successfully created symlink '/dev/disk/by-diskseq/117' to '/dev/loop0'
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Successfully created symlink '/dev/block/7:0' to '/dev/loop0'
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: sd-device: Created db file '/run/udev/data/b7:0' for '/devices/virtual/block/loop0'
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Adding watch on '/dev/loop0'
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Failed to watch device node '/dev/loop0': No such file or directory
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Device processed (SEQNUM=5048, ACTION=change)
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: sd-device-monitor(worker): Passed 339 byte to netlink monitor.
Mar 01 01:26:18 fedora systemd-udevd[492]: loop0: Device ready for processing (SEQNUM=5050, ACTION=remove)
Mar 01 01:26:18 fedora systemd-udevd[492]: loop0: sd-device-monitor(manager): Passed 231 byte to netlink monitor.
Mar 01 01:26:18 fedora systemd[978]: loop0: Processing udev action (SEQNUM=5048, ACTION=change)
Mar 01 01:26:18 fedora systemd[978]: loop0: Got 'change' action on syspath '/sys/devices/virtual/block/loop0'.
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Processing device (SEQNUM=5050, ACTION=remove)
Mar 01 01:26:18 fedora systemd[978]: loop0: Device busy: SYSTEMD_READY property from device is false
Mar 01 01:26:18 fedora systemd[978]: loop0: Device busy: SYSTEMD_READY property from device is false
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Removing watch handle -1.
Mar 01 01:26:18 fedora systemd[978]: loop0: Device busy: SYSTEMD_READY property from device is false
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: No reference left for '/dev/disk/by-diskseq/117', removing
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: Device processed (SEQNUM=5050, ACTION=remove)
Mar 01 01:26:18 fedora (udev-worker)[2174]: loop0: sd-device-monitor(worker): Passed 319 byte to netlink monitor.
Mar 01 01:26:18 fedora systemd[978]: loop0: Processing udev action (SEQNUM=5050, ACTION=remove)
Mar 01 01:26:18 fedora systemd[978]: loop0: Got 'remove' action on syspath '/sys/devices/virtual/block/loop0'.
Mar 01 01:26:18 fedora systemd[1]: Sent message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=11 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd[1]: Sent message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=12 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=7611 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=7612 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd-logind[717]: Got message type=signal sender=:1.2 destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged  cookie=7611 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd-machined[718]: Got message type=signal sender=:1.2 destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged  cookie=7611 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd[1]: systemd-journald.service: Got notification message from PID 445 (FDSTORE=1)
Mar 01 01:26:18 fedora systemd[1]: systemd-journald.service: Trying to stash fd for dev=0:9/inode=29793
Mar 01 01:26:18 fedora (udev-worker)[2173]: 7:0: Process '/usr/libexec/nfsrahead 7:0' failed with exit code 2.
Mar 01 01:26:18 fedora systemd[1]: systemd-journald.service: Added fd 59 (stored) to fd store.
Mar 01 01:26:18 fedora (udev-worker)[2173]: 7:0: /usr/lib/udev/rules.d/99-nfs.rules:1 Command "/usr/libexec/nfsrahead 7:0" returned 2 (error)
Mar 01 01:26:18 fedora systemd[1]: loop0: Processing udev action (SEQNUM=5046, ACTION=add)
Mar 01 01:26:18 fedora systemd[1]: loop0: Got 'add' action on syspath '/sys/devices/virtual/block/loop0'.
Mar 01 01:26:18 fedora (udev-worker)[2173]: 7:0: Device processed (SEQNUM=5045, ACTION=add)
Mar 01 01:26:18 fedora systemd[1]: loop0: Device busy: SYSTEMD_READY property from device is false
Mar 01 01:26:18 fedora systemd[1]: loop0: Device busy: SYSTEMD_READY property from device is false
Mar 01 01:26:18 fedora systemd[1]: loop0: Device busy: SYSTEMD_READY property from device is false
Mar 01 01:26:18 fedora systemd[1]: Got message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=GetUnit  cookie=2 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd[1]: Sent message type=method_return sender=org.freedesktop.systemd1 destination=n/a path=n/a interface=n/a member=n/a cookie=13 reply_cookie=2 signature=o error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd-logind[717]: Got message type=signal sender=:1.2 destination=n/a path=/org/freedesktop/systemd1/unit/otter_2ddal_2dtqftpserv_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged  cookie=7612 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Mar 01 01:26:18 fedora systemd[1]: loop0: Processing udev action (SEQNUM=5047, ACTION=change)
Mar 01 01:26:18 fedora systemd[1]: loop0: Got 'change' action on syspath '/sys/devices/virtual/block/loop0'.
Mar 01 01:26:18 fedora systemd-oomd[643]: oomd: New incoming message: {"parameters":{"cgroups":[{"mode":"auto","path":"/system.slice/otter-dal-tqftpserv.service","property":"ManagedOOMSwap"},{"mode":"auto","path":"/system.slice/otter-dal-tqftpserv.service","property":"ManagedOOMMemoryPressure","limit":0}]},"continues":true}
Mar 01 01:26:18 fedora systemd[1]: loop0: Device busy: SYSTEMD_READY property from device is false
Mar 01 01:26:18 fedora systemd[1]: loop0: Device busy: SYSTEMD_READY property from device is false
Mar 01 01:26:18 fedora (udev-worker)[2173]: 7:0: sd-device-monitor(worker): Passed 162 byte to netlink monitor.
Mar 01 01:26:18 fedora systemd[1]: loop0: Device busy: SYSTEMD_READY property from device is false
Mar 01 01:26:18 fedora systemd-oomd[643]: oomd: Changing state awaiting-reply-more → processing-reply
Mar 01 01:26:18 fedora systemd-oomd[643]: oomd: Changing state processing-reply → awaiting-reply-more
Mar 01 01:26:18 fedora systemd-udevd[492]: 7:0: Device ready for processing (SEQNUM=5049, ACTION=remove)
Mar 01 01:26:18 fedora systemd-udevd[492]: 7:0: sd-device-monitor(manager): Passed 165 byte to netlink monitor.
Mar 01 01:26:18 fedora systemd[1]: loop0: Processing udev action (SEQNUM=5048, ACTION=change)
Mar 01 01:26:1

[bluca]

Failed to mount /proc/self/fd/3 (type ext4) on /run/systemd/mount-rootfs (MS_NODEV ""): Permission denied

your kernel is refusing your image

[calebccff]

Hi @bluca , thanks for taking a look. That definitely makes sense, but I'm at a bit of a loss for where to start looking into this, could it be because the portabled image is inside a sysext?

I'd appreciate any pointers if you have some ideas.

[poettering]

did you turn off selinux?