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 1769148 - Privatedevices broken on F31 s390x system
Summary: Privatedevices broken on F31 s390x system
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: systemd
Version: 31
Hardware: s390x
OS: Linux
unspecified
unspecified
Target Milestone: ---
Assignee: systemd-maint
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
: 1769294 (view as bug list)
Depends On:
Blocks: ZedoraTracker 1746413
TreeView+ depends on / blocked
 
Reported: 2019-11-06 00:08 UTC by Stephen John Smoogen
Modified: 2019-11-21 01:25 UTC (History)
9 users (show)

Fixed In Version: systemd-243.4-1.fc31
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2019-11-21 01:25:00 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
strace output for the reproducer (98.99 KB, text/plain)
2019-11-06 11:35 UTC, Dan Horák
no flags Details


Links
System ID Private Priority Status Summary Last Updated
IBM Linux Technology Center 182545 0 None None None 2019-11-20 14:18:53 UTC

Description Stephen John Smoogen 2019-11-06 00:08:42 UTC
Description of problem:

Fedora Infrastrucutre started updating builders to F31 and found that on the s390x builders postfix fails to run in a similar method listed as BZ#1412696. Postfix will fail on the line where it tries to send error to /dev/null

Nov 05 23:52:57 buildvm-s390x-01.stg.s390.fedoraproject.org postfix[1756]: /usr/libexec/postfix/postfix-script: line 127: /dev/null: Operation not permitted
Nov 05 23:52:57 buildvm-s390x-01.stg.s390.fedoraproject.org postfix/postfix-script[1763]: fatal: the Postfix mail system is already running

The difference is that the system is in Permissive mode so we dont' think this is a policy item. Also using the debug methods listed in BZ#1412696 everything looked to be labeled correctly. 

I then looked at /etc/systemd/system/multi-user.target.wants/postfix.service and changed PrivateDevices= to false. On a reload, the service was able to start up and work. This then seemed closer to https://lkml.org/lkml/2018/12/22/212 but the system is running 

Linux buildvm-s390x-01.stg.s390.fedoraproject.org 5.3.8-300.fc31.s390x #1 SMP Tue Oct 29 14:11:57 UTC 2019 s390x s390x s390x GNU/Linux

which should have the update. Not sure what the problem is yet so I decided to start with systemd to see if there are things we can debug better from that end.

[root@buildvm-s390x-01 ~]# rpm -q kernel-core systemd selinux-policy postfix
kernel-core-5.3.8-300.fc31.s390x
systemd-243-4.gitef67743.fc31.s390x
selinux-policy-3.14.4-39.fc31.noarch
postfix-3.4.7-1.fc31.s390x

Comment 1 Zbigniew Jędrzejewski-Szmek 2019-11-06 09:06:29 UTC
I think that there are differences between architectures which make this hard to debug.

To isolate the issue a bit can you run the following:
# /etc/systemd/system/private-devs2.service
[Service]
Type=oneshot
PrivateTmp=true
CapabilityBoundingSet=~ CAP_NET_ADMIN CAP_SYS_ADMIN CAP_SYS_BOOT CAP_SYS_MODULE
ProtectSystem=true
PrivateDevices=true
ExecStart=bash -c 'echo asdf >/dev/null'

If the device nodes are not set up properly, this should show the same issue.

Alternatively, is it possible to get access to an affected system?

Comment 2 Zbigniew Jędrzejewski-Szmek 2019-11-06 10:55:35 UTC
*** Bug 1769294 has been marked as a duplicate of this bug. ***

Comment 3 Dan Horák 2019-11-06 11:05:23 UTC
[Service]
Type=oneshot
PrivateDevices=true
ExecStart=bash -c 'echo asdf >/dev/null'

^^^ this is sufficient to reproduce the problem

Nov 06 06:04:47 devel7.s390.bos.redhat.com systemd[1]: Starting private-devs2.service...
Nov 06 06:04:47 devel7.s390.bos.redhat.com bash[14190]: /usr/bin/bash: /dev/null: Operation not permitted
Nov 06 06:04:47 devel7.s390.bos.redhat.com systemd[1]: private-devs2.service: Main process exited, code=exited, status=1/FAILURE
Nov 06 06:04:47 devel7.s390.bos.redhat.com systemd[1]: private-devs2.service: Failed with result 'exit-code'.
Nov 06 06:04:47 devel7.s390.bos.redhat.com systemd[1]: Failed to start private-devs2.service.

Comment 4 Zbigniew Jędrzejewski-Szmek 2019-11-06 11:26:58 UTC
Can you run strace: strace -o /tmp/log -p 1 -f ?
The interesting part is the strace of the child.

Comment 5 Dan Horák 2019-11-06 11:35:33 UTC
Created attachment 1633251 [details]
strace output for the reproducer

Comment 6 Stephen John Smoogen 2019-11-06 14:27:52 UTC
[root@buildvm-s390x-01 ~]# cat /run/systemd/system/lsdevnull.service
[Service]
PrivateDevices=true
PrivateTmp=true
CapabilityBoundingSet=~ CAP_NET_ADMIN CAP_SYS_ADMIN CAP_SYS_BOOT CAP_SYS_MODULE
ProtectSystem=true
Type=oneshot
ExecStart=/bin/ls -lZ --time-style=long-iso /dev/
ExecStart=bash -c 'echo asdf >/dev/null'
ExecStart=echo "foo" 2> /dev/null
ExecStart=/bin/sleep 1


[root@buildvm-s390x-01 ~]# systemctl status lsdevnull
● lsdevnull.service
   Loaded: loaded (/run/systemd/system/lsdevnull.service; static; vendor preset: disabled)
   Active: failed (Result: exit-code) since Wed 2019-11-06 14:25:17 UTC; 6s ago
  Process: 2040 ExecStart=/bin/ls -lZ --time-style=long-iso /dev/ (code=exited, status=0/SUCCESS)
  Process: 2041 ExecStart=/usr/bin/bash -c echo asdf >/dev/null (code=exited, status=1/FAILURE)
 Main PID: 2041 (code=exited, status=1/FAILURE)
      CPU: 18ms

Nov 06 14:25:17 buildvm-s390x-01.stg.s390.fedoraproject.org systemd[1]: Starting lsdevnull.service...
Nov 06 14:25:17 buildvm-s390x-01.stg.s390.fedoraproject.org ls[2040]: total 0
Nov 06 14:25:17 buildvm-s390x-01.stg.s390.fedoraproject.org ls[2040]: drwxr-xr-x. 2 root root system_u:object_r:tmpfs_t:s0           180 2019-11-06 14:25 char
Nov 06 14:25:17 buildvm-s390x-01.stg.s390.fedoraproject.org ls[2040]: lrwxrwxrwx. 1 root root system_u:object_r:tmpfs_t:s0            11 2019-11-06 14:25 core -> /proc/kcore
Nov 06 14:25:17 buildvm-s390x-01.stg.s390.fedoraproject.org ls[2040]: lrwxrwxrwx. 1 root root system_u:object_r:tmpfs_t:s0            13 2019-11-06 14:25 fd -> /proc/self/fd
Nov 06 14:25:17 buildvm-s390x-01.stg.s390.fedoraproject.org ls[2040]: crw-rw-rw-. 1 root root system_u:object_r:null_device_t:s0    1, 7 2019-11-05 22:49 full
Nov 06 14:25:17 buildvm-s390x-01.stg.s390.fedoraproject.org ls[2040]: drwxr-xr-x. 2 root root system_u:object_r:hugetlbfs_t:s0         0 2019-11-05 22:49 hugepages
Nov 06 14:25:17 buildvm-s390x-01.stg.s390.fedoraproject.org ls[2040]: lrwxrwxrwx. 1 root root system_u:object_r:devlog_t:s0           28 2019-11-06 14:25 log -> /run/systemd/journal/dev-log
Nov 06 14:25:17 buildvm-s390x-01.stg.s390.fedoraproject.org ls[2040]: drwxrwxrwt. 2 root root system_u:object_r:tmpfs_t:s0            40 2019-11-05 22:49 mqueue
Nov 06 14:25:17 buildvm-s390x-01.stg.s390.fedoraproject.org ls[2040]: crw-rw-rw-. 1 root root system_u:object_r:null_device_t:s0    1, 3 2019-11-05 22:49 null
Nov 06 14:25:17 buildvm-s390x-01.stg.s390.fedoraproject.org ls[2040]: crw-rw-rw-. 1 root tty  system_u:object_r:ptmx_t:s0           5, 2 2019-11-06 14:25 ptmx
Nov 06 14:25:17 buildvm-s390x-01.stg.s390.fedoraproject.org ls[2040]: drwxr-xr-x. 2 root root system_u:object_r:devpts_t:s0            0 2019-11-05 22:49 pts
Nov 06 14:25:17 buildvm-s390x-01.stg.s390.fedoraproject.org ls[2040]: crw-rw-rw-. 1 root root system_u:object_r:random_device_t:s0  1, 8 2019-11-05 22:49 random
Nov 06 14:25:17 buildvm-s390x-01.stg.s390.fedoraproject.org ls[2040]: drwxrwxrwt. 2 root root system_u:object_r:tmpfs_t:s0            40 2019-11-05 22:49 shm
Nov 06 14:25:17 buildvm-s390x-01.stg.s390.fedoraproject.org ls[2040]: lrwxrwxrwx. 1 root root system_u:object_r:tmpfs_t:s0            15 2019-11-06 14:25 stderr -> /proc/self/fd/2
Nov 06 14:25:17 buildvm-s390x-01.stg.s390.fedoraproject.org ls[2040]: lrwxrwxrwx. 1 root root system_u:object_r:tmpfs_t:s0            15 2019-11-06 14:25 stdin -> /proc/self/fd/0
Nov 06 14:25:17 buildvm-s390x-01.stg.s390.fedoraproject.org ls[2040]: lrwxrwxrwx. 1 root root system_u:object_r:tmpfs_t:s0            15 2019-11-06 14:25 stdout -> /proc/self/fd/1
Nov 06 14:25:17 buildvm-s390x-01.stg.s390.fedoraproject.org ls[2040]: crw-rw-rw-. 1 root tty  system_u:object_r:devtty_t:s0         5, 0 2019-11-05 22:49 tty
Nov 06 14:25:17 buildvm-s390x-01.stg.s390.fedoraproject.org ls[2040]: crw-rw-rw-. 1 root root system_u:object_r:urandom_device_t:s0 1, 9 2019-11-05 22:49 urandom
Nov 06 14:25:17 buildvm-s390x-01.stg.s390.fedoraproject.org ls[2040]: crw-rw-rw-. 1 root root system_u:object_r:zero_device_t:s0    1, 5 2019-11-05 22:49 zero
Nov 06 14:25:17 buildvm-s390x-01.stg.s390.fedoraproject.org bash[2041]: /usr/bin/bash: /dev/null: Operation not permitted
Nov 06 14:25:17 buildvm-s390x-01.stg.s390.fedoraproject.org systemd[1]: lsdevnull.service: Main process exited, code=exited, status=1/FAILURE
Nov 06 14:25:17 buildvm-s390x-01.stg.s390.fedoraproject.org systemd[1]: lsdevnull.service: Failed with result 'exit-code'.
Nov 06 14:25:17 buildvm-s390x-01.stg.s390.fedoraproject.org systemd[1]: Failed to start lsdevnull.service.
Nov 06 14:25:17 buildvm-s390x-01.stg.s390.fedoraproject.org audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=lsdevnull comm="sys>
Nov 06 14:25:45 buildvm-s390x-01.stg.s390.fedoraproject.org rsyslogd[507]: cannot connect to log01:514: Connection timed out [v8.1910.0 try https://www.rsyslog.com/e/2027 ]
Nov 06 14:25:54 buildvm-s390x-01.stg.s390.fedoraproject.org audit[507]: AVC avc:  denied  { getattr } for  pid=507 comm="in:imfile" path="/var/log/audit" dev="vda3" ino=2623263 scontext=sys>
Nov 06 14:25:54 buildvm-s390x-01.stg.s390.fedoraproject.org audit[507]: AVC avc:  denied  { search } for  pid=507 comm="in:imfile" name="audit" dev="vda3" ino=2623263 scontext=system_u:syst>

Comment 7 Dan Horák 2019-11-06 14:36:03 UTC
Is there a way to disable/by-pass seccomp in systemd? Because it is the causing pretty odd bugs in other projects, when not done correctly (eg. due different order of syscall parameters on s390x).

Comment 8 Dan Horák 2019-11-06 15:42:20 UTC
no change when run under systemd with disabled seccomp

Comment 9 Zbigniew Jędrzejewski-Szmek 2019-11-07 15:25:03 UTC
I don't think seccomp is related here at all. It seems that the general support for a PrivateDevices= is broken,
and access is denied to any node created in this way. This is implemented through a mount namespace,
a tmpfs mount, and bind mount for the device nodes.

[root@devel7 ~]# systemd-run -p PrivateDevices=true -t echo asdf; echo $?
Running as unit: run-u69.service
Press ^] three times within 1s to disconnect TTY.
208
[root@devel7 ~]# journalctl -u run-u69 --no-pager
-- Logs begin at Wed 2019-11-06 03:43:02 EST, end at Thu 2019-11-07 10:23:23 EST. --
systemd[1]: Started /usr/bin/echo asdf.
systemd[18797]: run-u69.service: Failed to set up standard input: Operation not permitted
systemd[18797]: run-u69.service: Failed at step STDIN spawning /usr/bin/echo: Operation not permitted
systemd[1]: run-u69.service: Main process exited, code=exited, status=208/STDIN
systemd[1]: run-u69.service: Failed with result 'exit-code'.

Comment 10 Zbigniew Jędrzejewski-Szmek 2019-11-10 22:40:03 UTC
Stupid bug. See https://github.com/systemd/systemd/pull/13994/commits/9b5d02d44e3f6c491c60f99887684b478fab9783.
The full PR is https://github.com/systemd/systemd/pull/13994. Reviews are welcome...

Comment 11 Stephen John Smoogen 2019-11-11 13:03:03 UTC
My only review of the code would be that the patch does not change the comment above to explain why those items need to be chosen. In my experience that has led to problems where the _H is brought back again as someone thinks it will fix something else. However I also do not know the coding style of systemd and not sure if that kind of commentary works.

Comment 12 Zbigniew Jędrzejewski-Szmek 2019-11-11 13:40:07 UTC
Do you mean the comment "/* load device type to r2 */" ?
That comment is OK. After the move and and in the text line, r2 should contain the device type.

Comment 13 Stephen John Smoogen 2019-11-11 14:04:22 UTC
Yes. I didn't know if the additional items added needed to be detailed why they were that so someone in the future didn't revert etc. However again, it is a coding style comment versus a 'hey that will cause problems with some other code' comment.

Comment 14 Fedora Update System 2019-11-19 15:28:33 UTC
FEDORA-2019-4c3ce3aa5c has been submitted as an update to Fedora 31. https://bodhi.fedoraproject.org/updates/FEDORA-2019-4c3ce3aa5c

Comment 15 Fedora Update System 2019-11-20 01:28:01 UTC
systemd-243.4-1.fc31 has been pushed to the Fedora 31 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-4c3ce3aa5c

Comment 16 Fedora Update System 2019-11-21 01:25:00 UTC
systemd-243.4-1.fc31 has been pushed to the Fedora 31 stable repository. If problems still persist, please make note of it in this bug report.


Note You need to log in before you can comment on or make changes to this bug.