Bug 1520580

Summary: Unable to log in on arm disk images
Product: [Fedora] Fedora Reporter: Paul Whalen <pwhalen>
Component: livecd-toolsAssignee: Patrick Uiterwijk <puiterwijk>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 28CC: adam.stokes, alciregi, awilliam, bcl, bruno, dhuff, dustymabe, dwalsh, gmarr, jreiser, katzj, lvrabec, metherid, mgrepl, mschmidt, ngompa13, pbrobinson, plautrba, pmoore, puiterwijk, robatino, roysjosh, sumukher, vanmeeuwen+fedora
Target Milestone: ---   
Target Release: ---   
Hardware: armhfp   
OS: Linux   
Whiteboard: AcceptedBlocker
Fixed In Version: livecd-tools-25.0-6.fc28 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2018-03-26 22:30:03 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:
Bug Depends On:    
Bug Blocks: 245418, 1469204    

Description Paul Whalen 2017-12-04 18:49:10 UTC
Description of problem:
After completing initial-setup, attempts to log in fail. Selinux in permissive allows successful log in.

Version-Release number of selected component (if applicable):
selinux-policy-3.13.1-304.fc28.noarch

How reproducible:
everytime

Actual results:

ausearch -ts recent -m avc

type=AVC msg=audit(1512413082.177:197): avc:  denied  { transition } for  pid=900 comm="login" path="/usr/bin/bash" dev="sda4" ino=7141 scontext=system_u:system_r:kernel_t:s0 tcontext=unconfined_u:unconfined_r:unconfined_t:s0 tclass=process permissive=1
----
time->Mon Dec  4 13:44:42 2017
type=AVC msg=audit(1512413082.177:198): avc:  denied  { entrypoint } for  pid=900 comm="login" path="/usr/bin/bash" dev="sda4" ino=7141 scontext=unconfined_u:unconfined_r:unconfined_t:s0 tcontext=system_u:object_r:unlabeled_t:s0 tclass=file permissive=1

Comment 1 Paul Whalen 2017-12-06 18:16:11 UTC
Proposing as a blocker for beta, this affects both release blocking images for arm.

Comment 2 sumantro 2017-12-11 07:05:56 UTC
This is reproducible so giving it a +1 for beta blocker

Comment 3 Geoffrey Marr 2017-12-11 18:18:35 UTC
Discussed during the 2017-12-11 blocker review meeting: [1]

The decision to classify this bug as an AcceptedBlocker was made as it violates the following blocker criteria:

"A system installed without a graphical package set must boot to a state where it is possible to log in through at least one of the default virtual consoles", for ARM disk images.

[1] https://meetbot.fedoraproject.org/fedora-blocker-review/2017-12-11/f28-blocker-review.2017-12-11-17.01.txt

Comment 4 Fedora End Of Life 2018-02-20 15:26:36 UTC
This bug appears to have been reported against 'rawhide' during the Fedora 28 development cycle.
Changing version to '28'.

Comment 5 John Reiser 2018-03-03 04:15:53 UTC
Login still fails when booting RaspberryPi-3B after writing uSDHC card from expanded Fedora-Xfce-armhfp-Rawhide-20180301.n.0-sda.raw.xz .

The anaconda graphical final configuration succeeded (timezone, network+hostname, root password, local user account).  The lightdm greeter appeared on the VGA console and accepted userID and password from keyboard, but within a couple seconds went back to the original greeter screen with no login.  Attempting to login via ssh from a different system failed with "Connection closed".  Both the local userID and 'root' failed from both the local console and remote login via ssh.  System shutdown via mouse clicks succeeded.

Removing the uSDHC card and mounting it on another box allowed inspection of files.  /var/log/secure is attached.  Various lines of interest seem to be:

=====
Mar  2 15:19:39 localhost useradd[1674]: new group: name=jreiser, GID=1000
Mar  2 15:19:39 localhost useradd[1674]: new user: name=jreiser, UID=1000, GID=1000, home=/home/jreiser, shell=/bin/bash
Mar  2 15:19:40 localhost useradd[1674]: add 'jreiser' to group 'wheel'
Mar  2 15:19:40 localhost useradd[1674]: add 'jreiser' to shadow group 'wheel'
Mar  2 15:19:46 localhost chage[1684]: changed password expiry for jreiser
Mar  2 15:19:46 localhost chage[1691]: changed password expiry for root
=====
     so passwords should be OK

=====
Mar  2 15:19:58 localhost lightdm[1754]: pam_unix(lightdm-greeter:session): session opened for user lightdm by (uid=0)
Mar  2 15:19:59 localhost systemd[1757]: pam_unix(systemd-user:session): session opened for user lightdm by (uid=0)
Mar  2 15:19:59 localhost systemd[1771]: pam_unix(systemd-user:session): session closed for user lightdm
Mar  2 15:19:59 localhost lightdm[1754]: pam_systemd(lightdm-greeter:session): Failed to create session: Start job for unit user failed with 'failed'
=====
     That is the first failure that I see in the file.

=====
Mar  2 15:20:05 localhost polkitd[948]: /usr/share/polkit-1/rules.d/lightdm.rules:3: action=[Action id='org.freedesktop.DisplayManager.AccountsService.ReadAny']
Mar  2 15:20:05 localhost polkitd[948]: /usr/share/polkit-1/rules.d/lightdm.rules:4: subject=[Subject pid=1772 user='lightdm' groups=lightdm seat='seat0' session='c1' local=true active=false]
Mar  2 15:20:11 localhost polkitd[948]: /usr/share/polkit-1/rules.d/lightdm.rules:3: action=[Action id='org.freedesktop.DisplayManager.AccountsService.ReadAny']
Mar  2 15:20:11 localhost polkitd[948]: /usr/share/polkit-1/rules.d/lightdm.rules:4: subject=[Subject pid=1772 user='lightdm' groups=lightdm seat='seat0' session='c1' local=true active=false]
Mar  2 15:20:11 localhost polkitd[948]: /usr/share/polkit-1/rules.d/lightdm.rules:3: action=[Action id='org.freedesktop.DisplayManager.AccountsService.ReadAny']
Mar  2 15:20:11 localhost polkitd[948]: /usr/share/polkit-1/rules.d/lightdm.rules:4: subject=[Subject pid=1772 user='lightdm' groups=lightdm seat='seat0' session='c1' local=true active=false]
Mar  2 15:20:11 localhost lightdm[1754]: pam_unix(lightdm-greeter:session): session closed for user lightdm
Mar  2 15:20:12 localhost lightdm[1814]: gkr-pam: couldn't run gnome-keyring-daemon: Permission denied
Mar  2 15:20:12 localhost lightdm[1802]: gkr-pam: gnome-keyring-daemon didn't start properly
=====
     That is the second failure.

=====
Mar  2 15:20:13 localhost systemd[1815]: pam_unix(systemd-user:session): session opened for user jreiser by (uid=0)
Mar  2 15:20:13 localhost systemd[1829]: pam_unix(systemd-user:session): session closed for user jreiser
Mar  2 15:20:13 localhost lightdm[1802]: pam_systemd(lightdm:session): Failed to create session: Start job for unit user failed with 'failed'
Mar  2 15:20:13 localhost lightdm[1802]: pam_unix(lightdm:session): session opened for user jreiser by (uid=0)
Mar  2 15:20:13 localhost lightdm[1802]: pam_unix(lightdm:session): session closed for user jreiser
Mar  2 15:20:15 localhost lightdm[1836]: pam_unix(lightdm-greeter:session): session opened for user lightdm by (uid=0)
Mar  2 15:20:21 localhost polkitd[948]: /usr/share/polkit-1/rules.d/lightdm.rules:3: action=[Action id='org.freedesktop.DisplayManager.AccountsService.ReadAny']
Mar  2 15:20:21 localhost polkitd[948]: /usr/share/polkit-1/rules.d/lightdm.rules:4: subject=[Subject pid=1839 user='lightdm' groups=lightdm seat='seat0' session='c2' local=true active=true]
Mar  2 15:20:33 localhost lightdm[1836]: pam_unix(lightdm-greeter:session): session closed for user lightdm
Mar  2 15:20:34 localhost lightdm[1877]: gkr-pam: couldn't run gnome-keyring-daemon: Permission denied
Mar  2 15:20:34 localhost lightdm[1869]: gkr-pam: gnome-keyring-daemon didn't start properly
Mar  2 15:20:34 localhost systemd[1878]: pam_unix(systemd-user:session): session opened for user jreiser by (uid=0)
Mar  2 15:20:34 localhost systemd[1892]: pam_unix(systemd-user:session): session closed for user jreiser
Mar  2 15:20:34 localhost lightdm[1869]: pam_systemd(lightdm:session): Failed to create session: Start job for unit user failed with 'failed'
Mar  2 15:20:34 localhost lightdm[1869]: pam_unix(lightdm:session): session opened for user jreiser by (uid=0)
Mar  2 15:20:34 localhost lightdm[1869]: pam_unix(lightdm:session): session closed for user jreiser
=====
     a couple more failures, this time for my attempts to log in.

=====
Mar  2 15:21:04 localhost lightdm[1899]: pam_unix(lightdm-greeter:session): session closed for user lightdm
Mar  2 15:21:05 localhost lightdm[1962]: gkr-pam: couldn't run gnome-keyring-daemon: Permission denied
Mar  2 15:21:05 localhost lightdm[1954]: gkr-pam: gnome-keyring-daemon didn't start properly
Mar  2 15:21:05 localhost systemd[1963]: pam_unix(systemd-user:session): session opened for user root by (uid=0)
Mar  2 15:21:05 localhost lightdm[1954]: pam_systemd(lightdm:session): Failed to create session: Start job for unit user failed with 'failed'
Mar  2 15:21:05 localhost lightdm[1954]: pam_unix(lightdm:session): session opened for user root by (uid=0)
Mar  2 15:21:05 localhost lightdm[1954]: pam_unix(lightdm:session): session closed for user root
=====
     this time for 'root'.

Comment 6 John Reiser 2018-03-03 04:26:57 UTC
3 attempts to Attach /var/log/secure each failed after more than one minute, displaying a page that said:
=====
Bad Request

Your browser sent a request that this server could not understand.
=====
Browser is firefox-57.0.1-1.fc25.x86_64
.

Comment 7 John Reiser 2018-03-05 04:08:06 UTC
I see the same problem using Fedora-Minimal-armhfp-28-20180301.n.1-sda.raw.xz.

After final configuration in text mode, neither the local user nor root can log in using keyboard and VGA console.  After accepting username and password, then there is a very brief message that seems to contain something like "no shell", then that line is erased and "login: " reappears.

After shutdown by power-off, and mounting the uSDHC card on another system, then "journalctl --file=/var/log/journal/<SHA1>/user-1000.journal" says:
=====
-- Logs begin at Sun 2018-03-04 15:01:15 PST, end at Sun 2018-03-04 15:02:03 PST. --
Mar 04 15:01:15 host.domain systemd[1611]: user: Failed to execute command: Permission denied
Mar 04 15:01:15 host.domain systemd[1611]: user: Failed at step EXEC spawning /usr/lib/systemd/systemd: Permission denied
Mar 04 15:01:15 host.domain systemd[1625]: pam_unix(systemd-user:session): session closed for user jreiser
Mar 04 15:01:23 host.domain systemd[1631]: user: Failed to execute command: Permission denied
Mar 04 15:01:23 host.domain systemd[1631]: user: Failed at step EXEC spawning /usr/lib/systemd/systemd: Permission denied
Mar 04 15:01:23 host.domain systemd[1645]: pam_unix(systemd-user:session): session closed for user jreiser
Mar 04 15:01:38 host.domain systemd[1671]: user: Failed to execute command: Permission denied
Mar 04 15:01:38 nost.domain systemd[1671]: user: Failed at step EXEC spawning /usr/lib/systemd/systemd: Permission denied
Mar 04 15:01:38 host.domain systemd[1685]: pam_unix(systemd-user:session): session closed for user jreiser
Mar 04 15:02:03 host.domain systemd[1694]: user: Failed to execute command: Permission denied
Mar 04 15:02:03 host.domain systemd[1694]: user: Failed at step EXEC spawning /usr/lib/systemd/systemd: Permission denied
Mar 04 15:02:03 nost.domain systemd[1708]: pam_unix(systemd-user:session): session closed for user jreiser
=====

and "journalctl --file=.../system.journal" says [excerpt]:
=====
Mar 04 15:01:05 host.domain audit[1599]: USER_AUTH pid=1599 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:kernel_t:s0 msg='op=PAM:authentication grantors=pam_unix acct="jreiser" exe="/usr/bin/login" hostname=host.domain addr=? terminal=tty1 res=success'
Mar 04 15:01:05 host.domain audit[1599]: USER_ACCT pid=1599 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:kernel_t:s0 msg='op=PAM:accounting grantors=pam_unix,pam_localuser acct="jreiser" exe="/usr/bin/login" hostname=host.domain addr=? terminal=tty1 res=success'
Mar 04 15:01:07 host.domain audit[1599]: CRED_ACQ pid=1599 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:kernel_t:s0 msg='op=PAM:setcred grantors=pam_unix acct="jreiser" exe="/usr/bin/login" hostname=host.domain addr=? terminal=tty1 res=success'
Mar 04 15:01:14 host.domain audit[1599]: USER_ROLE_CHANGE pid=1599 uid=0 auid=1000 ses=1 subj=system_u:system_r:kernel_t:s0 msg='pam: default-context=unconfined_u:unconfined_r:unconfined_t:s0 selected-context=unconfined_u:unconfined_r:unconfined_t:s0 exe="/usr/bin/login" hostname=host.domain addr=? terminal=tty1 res=success'
Mar 04 15:01:14 host.domain systemd[1]: Created slice User Slice of jreiser.
Mar 04 15:01:14 host.domain systemd[1]: Starting User Manager for UID 1000...
Mar 04 15:01:14 host.domain systemd-logind[876]: New session 1 of user jreiser.
Mar 04 15:01:15 host.domain systemd[1]: Started Session 1 of user jreiser.
Mar 04 15:01:15 host.domain audit[1611]: USER_ACCT pid=1611 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:kernel_t:s0 msg='op=PAM:accounting grantors=pam_unix,pam_localuser acct="jreiser" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Mar 04 15:01:15 host.domain audit[1611]: USER_ROLE_CHANGE pid=1611 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:kernel_t:s0 msg='pam: default-context=unconfined_u:unconfined_r:unconfined_t:s0 selected-context=unconfined_u:unconfined_r:unconfined_t:s0 exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Mar 04 15:01:15 host.domain systemd[1611]: pam_unix(systemd-user:session): session opened for user jreiser by (uid=0)
Mar 04 15:01:15 host.domain audit[1611]: USER_START pid=1611 uid=0 auid=1000 ses=2 subj=system_u:system_r:kernel_t:s0 msg='op=PAM:session_open grantors=pam_selinux,pam_selinux,pam_loginuid,pam_keyinit,pam_limits,pam_systemd,pam_unix acct="jreiser" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Mar 04 15:01:15 host.domain audit[1611]: AVC avc:  denied  { transition } for  pid=1611 comm="(systemd)" path="/usr/lib/systemd/systemd" dev="mmcblk0p4" ino=19360 scontext=system_u:system_r:kernel_t:s0 tcontext=unconfined_u:unconfined_r:unconfined_t:s0 tclass=process permissive=0
Mar 04 15:01:15 host.domain audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:kernel_t:s0 msg='unit=user@1000 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
Mar 04 15:01:15 host.domain audit[1599]: USER_START pid=1599 uid=0 auid=1000 ses=1 subj=system_u:system_r:kernel_t:s0 msg='op=PAM:session_open grantors=pam_selinux,pam_loginuid,pam_selinux,pam_namespace,pam_keyinit,pam_keyinit,pam_limits,pam_unix,pam_lastlog acct="jreiser" exe="/usr/bin/login" hostname=host.domain addr=? terminal=tty1 res=success'
Mar 04 15:01:15 host.domain audit[1599]: CRED_REFR pid=1599 uid=0 auid=1000 ses=1 subj=system_u:system_r:kernel_t:s0 msg='op=PAM:setcred grantors=pam_unix acct="jreiser" exe="/usr/bin/login" hostname=host.domain addr=? terminal=tty1 res=success'
Mar 04 15:01:15 host.domain audit[1599]: USER_LOGIN pid=1599 uid=0 auid=1000 ses=1 subj=system_u:system_r:kernel_t:s0 msg='op=login id=1000 exe="/usr/bin/login" hostname=host.domain addr=? terminal=tty1 res=success'
Mar 04 15:01:15 host.domain audit[1626]: AVC avc:  denied  { transition } for  pid=1626 comm="login" path="/usr/bin/bash" dev="mmcblk0p4" ino=7216 scontext=system_u:system_r:kernel_t:s0 tcontext=unconfined_u:unconfined_r:unconfined_t:s0 tclass=process permissive=0
Mar 04 15:01:16 host.domain audit[1599]: CRED_DISP pid=1599 uid=0 auid=1000 ses=1 subj=system_u:system_r:kernel_t:s0 msg='op=PAM:setcred grantors=pam_unix acct="jreiser" exe="/usr/bin/login" hostname=host.domain addr=? terminal=tty1 res=success'
Mar 04 15:01:16 host.domain audit[1599]: USER_END pid=1599 uid=0 auid=1000 ses=1 subj=system_u:system_r:kernel_t:s0 msg='op=PAM:session_close grantors=pam_selinux,pam_loginuid,pam_selinux,pam_namespace,pam_keyinit,pam_keyinit,pam_limits,pam_unix,pam_lastlog acct="jreiser" exe="/usr/bin/login" hostname=host.domain addr=? terminal=tty1 res=success'
Mar 04 15:01:15 host.domain systemd[1]: user: Failed with result 'protocol'.
Mar 04 15:01:15 host.domain login[1599]: pam_systemd(login:session): Failed to create session: Start job for unit user failed with 'failed'
Mar 04 15:01:15 host.domain systemd[1]: Failed to start User Manager for UID 1000.
=====

Comment 8 Paul Whalen 2018-03-16 18:46:15 UTC
Using the latest nominated nightly (Fedora-28-20180314.n.2), it still
doesnt allow login but the avcs have changed:

time->Fri Mar 16 18:32:47 2018
type=AVC msg=audit(1521239567.589:170): avc:  denied  { transition } for  pid=1184 comm="(systemd)" path="/usr/lib/systemd/systemd" dev="sda4" ino=19350 scontext=system_u:system_r:kernel_t:s0 tcontext=unconfined_u:unconfined_r:unconfined_t:s0 tclass=process permissive=1
----
time->Fri Mar 16 18:32:47 2018
type=AVC msg=audit(1521239567.590:171): avc:  denied  { entrypoint } for  pid=1184 comm="(systemd)" path="/usr/lib/systemd/systemd" dev="sda4" ino=19350 scontext=unconfined_u:unconfined_r:unconfined_t:s0 tcontext=system_u:object_r:unlabeled_t:s0 tclass=file permissive=1

[root@localhost ~]# rpm -q selinux-policy
selinux-policy-3.14.1-11.fc28.noarch

Comment 9 Paul Whalen 2018-03-16 19:06:30 UTC
gnome-initial-setup fails on the Workstation image (Fedora-28-20180314.n.2):

[root@localhost ~]# ausearch -ts recent -m avc,user_avc
----
time->Fri Mar 16 14:53:46 2018
type=AVC msg=audit(1521226426.489:139): avc:  denied  { transition } for  pid=1007 comm="(systemd)" path="/usr/lib/systemd/systemd" dev="sda4" ino=24906 scontext=system_u:system_r:kernel_t:s0 tcontext=unconfined_u:unconfined_r:unconfined_t:s0 tclass=process permissive=1
----
time->Fri Mar 16 14:53:46 2018
type=AVC msg=audit(1521226426.489:140): avc:  denied  { entrypoint } for  pid=1007 comm="(systemd)" path="/usr/lib/systemd/systemd" dev="sda4" ino=24906 scontext=unconfined_u:unconfined_r:unconfined_t:s0 tcontext=system_u:object_r:unlabeled_t:s0 tclass=file permissive=1
----
time->Fri Mar 16 14:55:08 2018
type=AVC msg=audit(1521226508.267:219): avc:  denied  { transition } for  pid=1626 comm="(systemd)" path="/usr/lib/systemd/systemd" dev="sda4" ino=24906 scontext=system_u:system_r:kernel_t:s0 tcontext=unconfined_u:unconfined_r:unconfined_t:s0 tclass=process permissive=1
----
time->Fri Mar 16 14:55:08 2018
type=AVC msg=audit(1521226508.267:220): avc:  denied  { entrypoint } for  pid=1626 comm="(systemd)" path="/usr/lib/systemd/systemd" dev="sda4" ino=24906 scontext=unconfined_u:unconfined_r:unconfined_t:s0 tcontext=system_u:object_r:unlabeled_t:s0 tclass=file permissive=1
----
time->Fri Mar 16 14:55:09 2018
type=AVC msg=audit(1521226509.681:231): avc:  denied  { transition } for  pid=1671 comm="(systemd)" path="/usr/lib/systemd/systemd" dev="sda4" ino=24906 scontext=system_u:system_r:kernel_t:s0 tcontext=unconfined_u:unconfined_r:unconfined_t:s0 tclass=process permissive=1
----
time->Fri Mar 16 14:55:09 2018
type=AVC msg=audit(1521226509.681:232): avc:  denied  { entrypoint } for  pid=1671 comm="(systemd)" path="/usr/lib/systemd/systemd" dev="sda4" ino=24906 scontext=unconfined_u:unconfined_r:unconfined_t:s0 tcontext=system_u:object_r:unlabeled_t:s0 tclass=file permissive=1
----
time->Fri Mar 16 14:55:57 2018
type=AVC msg=audit(1521226557.731:250): avc:  denied  { transition } for  pid=1931 comm="gdm-session-wor" path="/usr/bin/gnome-keyring-daemon" dev="sda4" ino=39169 scontext=system_u:system_r:kernel_t:s0 tcontext=unconfined_u:unconfined_r:unconfined_t:s0 tclass=process permissive=1
----
time->Fri Mar 16 14:55:57 2018
type=AVC msg=audit(1521226557.732:251): avc:  denied  { entrypoint } for  pid=1931 comm="gdm-session-wor" path="/usr/bin/gnome-keyring-daemon" dev="sda4" ino=39169 scontext=unconfined_u:unconfined_r:unconfined_t:s0 tcontext=system_u:object_r:unlabeled_t:s0 tclass=file permissive=1
----
time->Fri Mar 16 14:58:12 2018
type=AVC msg=audit(1521226692.864:274): avc:  denied  { transition } for  pid=2839 comm="login" path="/usr/bin/bash" dev="sda4" ino=18214 scontext=system_u:system_r:kernel_t:s0 tcontext=unconfined_u:unconfined_r:unconfined_t:s0 tclass=process permissive=1
----
time->Fri Mar 16 14:58:12 2018
type=AVC msg=audit(1521226692.864:275): avc:  denied  { entrypoint } for  pid=2839 comm="login" path="/usr/bin/bash" dev="sda4" ino=18214 scontext=unconfined_u:unconfined_r:unconfined_t:s0 tcontext=system_u:object_r:unlabeled_t:s0 tclass=file permissive=1
----
time->Fri Mar 16 14:59:09 2018
type=AVC msg=audit(1521226749.962:294): avc:  denied  { dyntransition } for  pid=3085 comm="sshd" scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:system_r:sshd_net_t:s0 tclass=process permissive=1
----
time->Fri Mar 16 14:59:09 2018
type=AVC msg=audit(1521226749.963:295): avc:  denied  { search } for  pid=3085 comm="sshd" name="empty" dev="sda4" ino=130320 scontext=system_u:system_r:sshd_net_t:s0 tcontext=system_u:object_r:unlabeled_t:s0 tclass=dir permissive=1
----
time->Fri Mar 16 14:59:17 2018
type=AVC msg=audit(1521226757.301:309): avc:  denied  { transition } for  pid=3089 comm="(systemd)" path="/usr/lib/systemd/systemd" dev="sda4" ino=24906 scontext=system_u:system_r:kernel_t:s0 tcontext=unconfined_u:unconfined_r:unconfined_t:s0 tclass=process permissive=1
----
time->Fri Mar 16 14:59:17 2018
type=AVC msg=audit(1521226757.301:310): avc:  denied  { entrypoint } for  pid=3089 comm="(systemd)" path="/usr/lib/systemd/systemd" dev="sda4" ino=24906 scontext=unconfined_u:unconfined_r:unconfined_t:s0 tcontext=system_u:object_r:unlabeled_t:s0 tclass=file permissive=1
----
time->Fri Mar 16 14:59:17 2018
type=AVC msg=audit(1521226757.538:317): avc:  denied  { dyntransition } for  pid=3125 comm="sshd" scontext=system_u:system_r:kernel_t:s0 tcontext=unconfined_u:unconfined_r:unconfined_t:s0 tclass=process permissive=1

Comment 10 Paul Whalen 2018-03-16 19:14:56 UTC
Xfce(Fedora-28-20180314.n.2), fails on login:

----
time->Fri Mar 16 15:07:44 2018
type=AVC msg=audit(1521227264.943:218): avc:  denied  { transition } for  pid=1852 comm="(systemd)" path="/usr/lib/systemd/systemd" dev="sda4" ino=30228 scontext=system_u:system_r:kernel_t:s0 tcontext=unconfined_u:unconfined_r:unconfined_t:s0 tclass=process permissive=0
----
time->Fri Mar 16 15:07:55 2018
type=AVC msg=audit(1521227275.808:228): avc:  denied  { transition } for  pid=1910 comm="lightdm" path="/usr/bin/gnome-keyring-daemon" dev="sda4" ino=53551 scontext=system_u:system_r:kernel_t:s0 tcontext=unconfined_u:unconfined_r:unconfined_t:s0 tclass=process permissive=0
----
time->Fri Mar 16 15:07:56 2018
type=AVC msg=audit(1521227276.145:233): avc:  denied  { transition } for  pid=1911 comm="(systemd)" path="/usr/lib/systemd/systemd" dev="sda4" ino=30228 scontext=system_u:system_r:kernel_t:s0 tcontext=unconfined_u:unconfined_r:unconfined_t:s0 tclass=process permissive=0
----
time->Fri Mar 16 15:07:56 2018
type=AVC msg=audit(1521227276.178:237): avc:  denied  { transition } for  pid=1926 comm="lightdm" path="/etc/X11/xinit/Xsession" dev="sda4" ino=151809 scontext=system_u:system_r:kernel_t:s0 tcontext=unconfined_u:unconfined_r:unconfined_t:s0 tclass=process permissive=0
----
time->Fri Mar 16 19:08:56 2018
type=AVC msg=audit(1521241736.484:143): avc:  denied  { transition } for  pid=1072 comm="(systemd)" path="/usr/lib/systemd/systemd" dev="sda4" ino=30228 scontext=system_u:system_r:kernel_t:s0 tcontext=unconfined_u:unconfined_r:unconfined_t:s0 tclass=process permissive=1
----
time->Fri Mar 16 19:08:56 2018
type=AVC msg=audit(1521241736.484:144): avc:  denied  { entrypoint } for  pid=1072 comm="(systemd)" path="/usr/lib/systemd/systemd" dev="sda4" ino=30228 scontext=unconfined_u:unconfined_r:unconfined_t:s0 tcontext=system_u:object_r:unlabeled_t:s0 tclass=file permissive=1
----
time->Fri Mar 16 15:09:11 2018
type=AVC msg=audit(1521227351.920:199): avc:  denied  { transition } for  pid=1359 comm="lightdm" path="/usr/bin/gnome-keyring-daemon" dev="sda4" ino=53551 scontext=system_u:system_r:kernel_t:s0 tcontext=unconfined_u:unconfined_r:unconfined_t:s0 tclass=process permissive=1
----
time->Fri Mar 16 15:09:11 2018
type=AVC msg=audit(1521227351.920:200): avc:  denied  { entrypoint } for  pid=1359 comm="lightdm" path="/usr/bin/gnome-keyring-daemon" dev="sda4" ino=53551 scontext=unconfined_u:unconfined_r:unconfined_t:s0 tcontext=system_u:object_r:unlabeled_t:s0 tclass=file permissive=1
----
time->Fri Mar 16 15:09:12 2018
type=AVC msg=audit(1521227352.557:205): avc:  denied  { transition } for  pid=1364 comm="(systemd)" path="/usr/lib/systemd/systemd" dev="sda4" ino=30228 scontext=system_u:system_r:kernel_t:s0 tcontext=unconfined_u:unconfined_r:unconfined_t:s0 tclass=process permissive=1
----
time->Fri Mar 16 15:09:12 2018
type=AVC msg=audit(1521227352.557:206): avc:  denied  { entrypoint } for  pid=1364 comm="(systemd)" path="/usr/lib/systemd/systemd" dev="sda4" ino=30228 scontext=unconfined_u:unconfined_r:unconfined_t:s0 tcontext=system_u:object_r:unlabeled_t:s0 tclass=file permissive=1
----
time->Fri Mar 16 15:10:43 2018
type=AVC msg=audit(1521227443.545:217): avc:  denied  { dyntransition } for  pid=1852 comm="sshd" scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:system_r:sshd_net_t:s0 tclass=process permissive=1
----
time->Fri Mar 16 15:10:43 2018
type=AVC msg=audit(1521227443.546:218): avc:  denied  { search } for  pid=1852 comm="sshd" name="empty" dev="sda4" ino=132530 scontext=system_u:system_r:sshd_net_t:s0 tcontext=system_u:object_r:unlabeled_t:s0 tclass=dir permissive=1
----
time->Fri Mar 16 15:10:48 2018
type=AVC msg=audit(1521227448.640:232): avc:  denied  { transition } for  pid=1857 comm="(systemd)" path="/usr/lib/systemd/systemd" dev="sda4" ino=30228 scontext=system_u:system_r:kernel_t:s0 tcontext=unconfined_u:unconfined_r:unconfined_t:s0 tclass=process permissive=1
----
time->Fri Mar 16 15:10:48 2018
type=AVC msg=audit(1521227448.640:233): avc:  denied  { entrypoint } for  pid=1857 comm="(systemd)" path="/usr/lib/systemd/systemd" dev="sda4" ino=30228 scontext=unconfined_u:unconfined_r:unconfined_t:s0 tcontext=system_u:object_r:unlabeled_t:s0 tclass=file permissive=1
----
time->Fri Mar 16 15:10:49 2018
type=AVC msg=audit(1521227449.059:240): avc:  denied  { dyntransition } for  pid=1883 comm="sshd" scontext=system_u:system_r:kernel_t:s0 tcontext=unconfined_u:unconfined_r:unconfined_t:s0 tclass=process permissive=1

Comment 11 John Reiser 2018-03-16 19:17:52 UTC
Why is this specific to ARM-32 (armhfp)?  What is it about armhfp that causes failure while x86_64 succeeds?

Comment 12 Peter Robinson 2018-03-17 00:44:03 UTC
(In reply to John Reiser from comment #11)
> Why is this specific to ARM-32 (armhfp)?  What is it about armhfp that
> causes failure while x86_64 succeeds?

We don't generate disk images (yet) for x86 as they're generally not consumed like that, x86 tends to use Live images instead.

Comment 13 Daniel Walsh 2018-03-18 11:40:16 UTC
The problem is the init program did not transition out of kernel_t.  When systemd runs it is supposed to transition to init_t.  Figuring out why this is happening should fix the rest of the issues.

Does 
restorecon -R -v /

Change lots of labels?

Comment 14 Paul Whalen 2018-03-19 16:57:09 UTC
Y(In reply to Daniel Walsh from comment #13)
> The problem is the init program did not transition out of kernel_t.  When
> systemd runs it is supposed to transition to init_t.  Figuring out why this
> is happening should fix the rest of the issues.
> 
> Does 
> restorecon -R -v /
> 
> Change lots of labels?

Yes, looks like just about everything.

Comment 15 Adam Williamson 2018-03-19 18:11:07 UTC
peter: well, we do generate disk images for x86_64, don't we? The cloud images. They're not exactly the same, but we do build them. Do we know if those are hitting this too?

Comment 16 Adam Williamson 2018-03-20 20:18:47 UTC
Ping? We are two days from Go/No-Go for Beta, and this is the only accepted blocker not showing obvious progress.

I'll try and look into this myself, though it's not my area of expertise.

I can at least see this, in mock_output.log from a recent F28 compose task - https://koji.fedoraproject.org/koji/taskinfo?taskID=25835616 :

mount: /var/tmp/imgcreate-ScvDnf/install_root/sys/fs/selinux/load: mount point does not exist.
/etc/selinux/targeted/contexts/files/file_contexts: No such file or directory

I think this is coming from python-imgcreate (which is part of https://github.com/livecd-tools/livecd-tools ), imgcreate/creator.py , __create_selinuxfs() . No idea if it's actually related to the problem yet, though. Unfortunately I don't have any 'success case' logs to compare against; all f27 createAppliance tests are too old and have had their logs garbage collected.

Comment 17 Lukas Vrabec 2018-03-20 20:31:30 UTC
Dan identified issue correctly, that's the reason why I asked about some changes on armhfp. There is a transition when kernel is executing systemd: 

#sesearch -T -s kernel_t -t init_exec_t -c process
type_transition kernel_t init_exec_t:process init_t;

I don't see this bug on x86_64, but here for some reason systemd is running under kernel_t which means there is no SELinux transition. Did anybody testes disk iamages for x86_64 from comment#15? 

Lukas.

Comment 18 Adam Williamson 2018-03-20 20:49:37 UTC
Lukas: I'm trying to establish if someone's actually taken responsibility for figuring out *why* the labels seem to be wrong in the ARM disk images.

Re #c15, the disk images we do build for x86_64 are actually built with a different toolchain (ImageFactory on x86_64, appliance-creator on armhfp), so they're not really comparable. I don't believe there are known SELinux issues with the x86_64 disk images, the Cloud ones are reported to be passing most tests.

Comment 19 Patrick Uiterwijk 2018-03-22 01:45:18 UTC
Okay, I think I've just fixed this: there was not selinux-policy-targeted dragged into the mock, which meant livecd-tools did not have an selinux policy to tag things with (resulting in the "/etc/selinux/targeted/contexts/files/file_contexts: No such file or directory
" error).
I have added selinux-policy-targeted to the appliance-build group in koji, and am building a new livecd-tools that adds a dep on it, which would hopefully resolve this.

Comment 20 Fedora Update System 2018-03-22 01:59:30 UTC
livecd-tools-25.0-5.fc28 has been submitted as an update to Fedora 28. https://bodhi.fedoraproject.org/updates/FEDORA-2018-58502a629f

Comment 21 Peter Robinson 2018-03-22 02:23:02 UTC
> I have added selinux-policy-targeted to the appliance-build group in koji,
> and am building a new livecd-tools that adds a dep on it, which would
> hopefully resolve this.

This seems sane, except that appliance-tools is used for the armv7 image creation so it makes sense to do the same with that package too.

Comment 22 Patrick Uiterwijk 2018-03-22 02:28:56 UTC
appliance-tools depends on livecd-tools, so it will drag it in recursively.
But as said, it's also added to the koji package group, so it's already dragged in without package updates.
I am now building a test image, when that finishes I'll post the link for people to test.

Comment 23 Lukas Vrabec 2018-03-22 10:05:12 UTC
Hi Patrick, 

Thank you for help on this. I'll change component for this ticket to livecd-tools. 

Lukas.

Comment 24 Patrick Uiterwijk 2018-03-22 12:07:46 UTC
I'm currently looking into this (it looks like my initial fix wasn't enough), so will take this bug.

Comment 25 Patrick Uiterwijk 2018-03-22 13:53:41 UTC
Okay, I've found the real problem and have a build now that fixes it.
Basically, in 25.0, livecd-tools switched from a setfiles to a restorecon, but there is no selinux policy loaded in the chroot yet at this point (https://pagure.io/livecd-tools/c/1c2307ce8b5150265f60afd7cf8a5749a1d26f9e?branch=master).
I am waiting for my fork to get created to submit the patch upstream, but I have made livecd-tools builds for rawhide and f28 that revert this patch, and my dry testing does confirm that it breaks with restorecon and works with the setfiles revert patch.

livecd-tools-25.0-6.fc28 should fix this problem.

Comment 26 Fedora Update System 2018-03-22 14:13:53 UTC
livecd-tools-25.0-5.fc28 has been pushed to the Fedora 28 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-2018-58502a629f

Comment 27 Fedora Update System 2018-03-22 14:18:27 UTC
livecd-tools-25.0-6.fc28 has been submitted as an update to Fedora 28. https://bodhi.fedoraproject.org/updates/FEDORA-2018-58502a629f

Comment 28 Fedora Update System 2018-03-22 15:06:35 UTC
livecd-tools-25.0-6.fc28 has been pushed to the Fedora 28 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-2018-58502a629f

Comment 29 Alessio 2018-03-23 16:30:38 UTC
Today compose (Fedora-Minimal-armhfp-28-20180323.n.0) on the Raspberry Pi 3 works like a charm.

Comment 30 sumantro 2018-03-25 15:27:17 UTC
Works fine on a Rpi 3

Comment 31 Fedora Update System 2018-03-26 22:30:03 UTC
livecd-tools-25.0-6.fc28 has been pushed to the Fedora 28 stable repository. If problems still persist, please make note of it in this bug report.