Note: This is a public test instance of Red Hat Bugzilla. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback at bugzilla.redhat.com.

Bug 1708991

Summary: Failed to set up mount namespacing: Permission denied
Product: [Fedora] Fedora Reporter: a.klindt
Component: snapdAssignee: Zygmunt Krynicki <me>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 30CC: bberg, christian.morales.vega, ckellner, dwalsh, federico.chia, go-sig, jgrulich, kde-sig, lvrabec, maciek.borzecki, mclayton, me, me, mgrepl, mkyral, nathan.guerin, ngompa13, plautrba, rdieter, rhughes, stealthcipher, taaem, than, zpytela
Target Milestone: ---   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: snapd-2.39.1-1.fc30 snapd-2.39.1-1.el7 snapd-2.39.1-1.fc29 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2019-06-06 01:06:39 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description a.klindt 2019-05-12 10:00:55 UTC
Description of problem: Several KDE-components take very long to start: KInfocenter, Dolphin, startup of Plasma after login on my system used to be instantaneous (under 2sec) now takes 1 min.


Version-Release number of selected component (if applicable):

Operating System: Fedora 30
KDE Plasma Version: 5.15.4
KDE Frameworks Version: 5.57.0
Qt Version: 5.12.1
Kernel Version: 5.0.14-300.fc30.x86_64
OS Type: 64-bit
Processors: 4 × Intel® Core™ i5-3320M CPU @ 2.60GHz
Memory: 7,5 GiB of RAM

How reproducible:
Logout, Reboot: same


Steps to Reproduce:
1.Upgrade to Kernels >5.0.13
2.reboot
3.

Actual results: startup of several components takes very long


Expected results:startup should be instantaneous


Additional info:

Comment 1 Martin Kyral 2019-05-15 07:51:09 UTC
I am also hit by this issue. Affects dolphin, sddm, plasmashell, krunner and perheaps some other components as well.

For me, the problem is there with kernel 5.0.11-300.fc30.x86_64 so the kernel update to 5.0.13+ is not the culprit.

Comment 2 a.klindt 2019-05-15 08:11:51 UTC
I think the issue is connected to both my upowerd and hostnamed not starting. The log says namespace error/226, but I have not been able to find any further helpful information. hostnamed is not really a problem, but upowerd presents a problem to some processes and the system will try to start the service several times, which leads to the stalling issue. I've had time to downgrade upower to version 0.99.8.3.fc30 with no better results. Alas I am a noob.

Comment 3 Rex Dieter 2019-05-15 17:55:43 UTC
What evidence do you have that upowerd isn't starting properly?  Logs?  crashes?

Comment 4 Rex Dieter 2019-05-15 17:56:32 UTC
nevermind, you mentioned log (namespace error), I'll triage this to upower for now.

Comment 5 a.klindt 2019-05-15 18:51:27 UTC
From journalctl -b:
May 15 17:41:44 F30-T430 systemd[1]: Starting Daemon for power management...
May 15 17:41:44 F30-T430 audit[3923]: AVC avc:  denied  { remount } for  pid=3923 comm="(upowerd)" scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:snappy_>
May 15 17:41:44 F30-T430 systemd[3923]: upower.service: Failed to set up mount namespacing: Permission denied
May 15 17:41:44 F30-T430 systemd[3923]: upower.service: Failed at step NAMESPACE spawning /usr/libexec/upowerd: Permission denied
May 15 17:41:44 F30-T430 systemd[1]: upower.service: Main process exited, code=exited, status=226/NAMESPACE
May 15 17:41:44 F30-T430 systemd[1]: upower.service: Failed with result 'exit-code'.
May 15 17:41:44 F30-T430 systemd[1]: Failed to start Daemon for power management.

Ooops, this one's new: 
May 15 17:42:06 F30-T430 audit[4198]: AVC avc:  denied  { remount } for  pid=4198 comm="(resolved)" scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:snappy>
May 15 17:42:06 F30-T430 systemd[4198]: systemd-resolved.service: Failed to set up mount namespacing: Permission denied
May 15 17:42:06 F30-T430 systemd[4198]: systemd-resolved.service: Failed at step NAMESPACE spawning /usr/lib/systemd/systemd-resolved: Permission denied
May 15 17:42:06 F30-T430 systemd[1]: systemd-resolved.service: Main process exited, code=exited, status=226/NAMESPACE
May 15 17:42:06 F30-T430 systemd[1]: systemd-resolved.service: Failed with result 'exit-code'.
May 15 17:42:06 F30-T430 systemd[1]: Failed to start Network Name Resolution.

Good grief another one I haven't seen before:
May 15 19:15:13 F30-T430 systemd[1]: Starting Fingerprint Authentication Daemon...
May 15 19:15:13 F30-T430 audit[1869]: AVC avc:  denied  { remount } for  pid=1869 comm="(fprintd)" scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:snappy_>
May 15 19:15:13 F30-T430 systemd[1869]: fprintd.service: Failed to set up mount namespacing: Permission denied
May 15 19:15:13 F30-T430 systemd[1869]: fprintd.service: Failed at step NAMESPACE spawning /usr/libexec/fprintd: Permission denied
May 15 19:15:13 F30-T430 systemd[1]: fprintd.service: Main process exited, code=exited, status=226/NAMESPACE
May 15 19:15:13 F30-T430 systemd[1]: fprintd.service: Failed with result 'exit-code'.
May 15 19:15:13 F30-T430 systemd[1]: Failed to start Fingerprint Authentication Daemon.


So obviously that cannot be a problem of upower alone. What's with the namespace: permission denied? Sorry, just a noob trying to find my way around.

Comment 6 a.klindt 2019-05-15 19:33:26 UTC
set Selinux to permissive. Reboot

Same problem. See above.

Relabeled via restorecon -Rv /   Reboot

No change

Comment 7 Martin Kyral 2019-05-15 19:35:29 UTC
Few minutes ago, I found out that smplayer is affected by the issue as well. It hang for a minute before showing file dialog when I wanted to load subtitles in it.

Comment 8 Martin Kyral 2019-05-15 19:45:23 UTC
It happens when an application runs under common user. I tried to run it as root - no hang.

Comment 9 Martin Kyral 2019-05-15 19:46:45 UTC
I wouldn't blame upowerd though. I see way it can affect showing a file dialog. More precisely: qt file dialog. gedit does not have the problem.

Comment 10 Martin Kyral 2019-05-15 19:59:09 UTC
I meant: I see no way it can affect showing a file dialog.

Comment 11 Martin Kyral 2019-05-16 07:25:29 UTC
You're correct. upowerd is not staring because it is forbidden to start by SELinux:

May 16 09:16:48 dhcp-24-139 systemd[12760]: upower.service: Failed at step NAMESPACE spawning /usr/libexec/upowerd: Permission denied
May 16 09:16:48 dhcp-24-139 audit[12765]: AVC avc:  denied  { remount } for  pid=12765 comm="(upowerd)" scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:snappy_snap_t:s0 tclass=filesystem permissive=0

I have loads of these AVCs ion syslog, starting May 14th.

If I put SELinux into permissive mode and start upower service, this problem disappears.

If I put SELinux into enforcing mode and restart upower service (which fails), the problem is back.

Comment 12 Martin Kyral 2019-05-16 10:55:54 UTC
(In reply to a.klindt from comment #6)
> set Selinux to permissive. Reboot
> 
> Same problem. See above.
> 
> Relabeled via restorecon -Rv /   Reboot
> 
> No change

setenforce does not survive reboot. In order to set selinux into permissive permanently, you need to set it in /etc/selinux/config

Comment 13 Rex Dieter 2019-05-16 13:30:32 UTC
Triaging to selinux-policy for denials logged:
May 16 09:16:48 dhcp-24-139 systemd[12760]: upower.service: Failed at step NAMESPACE spawning /usr/libexec/upowerd: Permission denied
May 16 09:16:48 dhcp-24-139 audit[12765]: AVC avc:  denied  { remount } for  pid=12765 comm="(upowerd)" scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:snappy_snap_t:s0 tclass=filesystem permissive=0

Comment 14 Kevin Kofler 2019-05-16 14:06:11 UTC
The problem is probably the labeling of the mountpoint directories on the / volume, which are normally mounted over. restorecon or even the autorelabel process will not fix it because they run with the directories already mounted, but it is the SELinux label of the underlying (and normally hidden) directory on the / volume that is the problem here.

Try:
su -
mount --bind / /mnt
ls -Z /mnt
and you will see which of the directories has that strange snappy_snap_t label. Then you can use chcon to fix it.

See also bug #1703083 (where /dev is mislabeled), an issue that also happens if the system was installed with Calamares < 3.2.7-10 (which is how I found out about it).

Comment 15 a.klindt 2019-05-16 18:29:50 UTC
That didn't give me any clues regarding snappy_snap_t labels. But setting selinux to permissive removed the stalling problems for me. upower is alive again:
[arne@F30-T430 ~]$ upower -e
/org/freedesktop/UPower/devices/line_power_AC
/org/freedesktop/UPower/devices/battery_BAT0
/org/freedesktop/UPower/devices/DisplayDevice

Comment 16 Federico Chiacchiaretta 2019-06-03 12:36:01 UTC
Hi,
today I upgraded snapd-* to version 2.39, this made my system unstable (to be nice).

Services couldn't start with the same error message as above, eg.:

giu 03 14:05:49 vc0001.int.valuecore.it systemd[1]: Starting Network Name Resolution...
giu 03 14:05:49 vc0001.int.valuecore.it systemd[1733]: systemd-resolved.service: Failed to set up mount namespacing: Permission denied
giu 03 14:05:49 vc0001.int.valuecore.it systemd[1733]: systemd-resolved.service: Failed at step NAMESPACE spawning /usr/lib/systemd/systemd-resolved: Permission denied
giu 03 14:05:49 vc0001.int.valuecore.it systemd[1]: systemd-resolved.service: Main process exited, code=exited, status=226/NAMESPACE
giu 03 14:05:49 vc0001.int.valuecore.it systemd[1]: systemd-resolved.service: Failed with result 'exit-code'.


/var/log/audit/audit.log reported a lot of denials

type=AVC msg=audit(1559563522.899:82): avc:  denied  { remount } for  pid=1158 comm="(or-proxy)" scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:snappy_snap_t:s0 tclass=filesystem permissive=0
type=AVC msg=audit(1559563523.286:102): avc:  denied  { remount } for  pid=1267 comm="(ostnamed)" scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:snappy_snap_t:s0 tclass=filesystem permissive=0
type=AVC msg=audit(1559563528.476:221): avc:  denied  { remount } for  pid=1584 comm="(-localed)" scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:snappy_snap_t:s0 tclass=filesystem permissive=0
type=AVC msg=audit(1559563529.110:223): avc:  denied  { remount } for  pid=1607 comm="(upowerd)" scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:snappy_snap_t:s0 tclass=filesystem permissive=0
type=AVC msg=audit(1559563529.199:225): avc:  denied  { remount } for  pid=1612 comm="(geoclue)" scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:snappy_snap_t:s0 tclass=filesystem permissive=0
type=AVC msg=audit(1559563529.226:229): avc:  denied  { remount } for  pid=1617 comm="(upowerd)" scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:snappy_snap_t:s0 tclass=filesystem permissive=0
type=AVC msg=audit(1559563529.358:233): avc:  denied  { remount } for  pid=1648 comm="(upowerd)" scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:snappy_snap_t:s0 tclass=filesystem permissive=0
type=AVC msg=audit(1559563529.469:238): avc:  denied  { remount } for  pid=1669 comm="(upowerd)" scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:snappy_snap_t:s0 tclass=filesystem permissive=0
type=AVC msg=audit(1559563529.674:242): avc:  denied  { remount } for  pid=1698 comm="(upowerd)" scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:snappy_snap_t:s0 tclass=filesystem permissive=0
type=AVC msg=audit(1559563529.679:244): avc:  denied  { remount } for  pid=1699 comm="(fprintd)" scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:snappy_snap_t:s0 tclass=filesystem permissive=0
type=AVC msg=audit(1559563549.271:251): avc:  denied  { remount } for  pid=1724 comm="(resolved)" scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:snappy_snap_t:s0 tclass=filesystem permissive=0
type=AVC msg=audit(1559563549.285:255): avc:  denied  { remount } for  pid=1727 comm="(resolved)" scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:snappy_snap_t:s0 tclass=filesystem permissive=0
type=AVC msg=audit(1559563549.299:259): avc:  denied  { remount } for  pid=1730 comm="(resolved)" scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:snappy_snap_t:s0 tclass=filesystem permissive=0
type=AVC msg=audit(1559563549.312:263): avc:  denied  { remount } for  pid=1733 comm="(resolved)" scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:snappy_snap_t:s0 tclass=filesystem permissive=0
type=AVC msg=audit(1559563549.327:267): avc:  denied  { remount } for  pid=1736 comm="(resolved)" scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:snappy_snap_t:s0 tclass=filesystem permissive=0

I tried a filesystem relabel, but it didn't work, so I removed snapd-* packages and rebooted, system is working properly now.

How did those packages get out of testing into the stable repo?

Comment 17 Neal Gompa 2019-06-04 02:16:23 UTC
Maciek, can you please look into this?

Comment 18 Maciek Borzecki 2019-06-04 06:21:08 UTC
*** Bug 1716397 has been marked as a duplicate of this bug. ***

Comment 19 Maciek Borzecki 2019-06-04 08:11:40 UTC
Sorry for the trouble. 2.39 is the first version with revamped SELinux support.

Upstream has proposed a fix at https://github.com/snapcore/snapd/pull/6946

Comment 20 Zygmunt Krynicki 2019-06-04 08:14:28 UTC
*** Bug 1716736 has been marked as a duplicate of this bug. ***

Comment 21 Nate Guerin 2019-06-04 15:40:31 UTC
Is it possible that this is related to https://bugzilla.redhat.com/show_bug.cgi?id=1697667

Comment 22 Fedora Update System 2019-06-04 18:18:02 UTC
FEDORA-2019-3c4eec8250 has been submitted as an update to Fedora 30. https://bodhi.fedoraproject.org/updates/FEDORA-2019-3c4eec8250

Comment 23 Fedora Update System 2019-06-04 18:18:07 UTC
FEDORA-2019-02e160af16 has been submitted as an update to Fedora 29. https://bodhi.fedoraproject.org/updates/FEDORA-2019-02e160af16

Comment 24 taaem 2019-06-04 18:33:59 UTC
The update fixes the issue for me.

Comment 25 Fedora Update System 2019-06-05 00:07:02 UTC
snapd-2.39.1-1.el7 has been pushed to the Fedora EPEL 7 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-EPEL-2019-91a080fd55

Comment 26 Fedora Update System 2019-06-05 00:32:51 UTC
snapd-2.39.1-1.fc30 has been pushed to the Fedora 30 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2019-3c4eec8250

Comment 27 Fedora Update System 2019-06-05 03:05:40 UTC
snapd-2.39.1-1.fc29 has been pushed to the Fedora 29 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2019-02e160af16

Comment 28 Michael Clayton 2019-06-05 16:54:28 UTC
FEDORA-2019-3c4eec8250 fixed the issue for me on Fedora 30.

Comment 29 Fedora Update System 2019-06-06 01:06:39 UTC
snapd-2.39.1-1.fc30 has been pushed to the Fedora 30 stable repository. If problems still persist, please make note of it in this bug report.

Comment 30 Fedora Update System 2019-06-07 01:00:59 UTC
snapd-2.39.1-1.el7 has been pushed to the Fedora EPEL 7 stable repository. If problems still persist, please make note of it in this bug report.

Comment 31 Fedora Update System 2019-06-07 16:33:47 UTC
snapd-2.39.1-1.fc29 has been pushed to the Fedora 29 stable repository. If problems still persist, please make note of it in this bug report.