Bug 1333106

Summary: Server deployment fails due to SELinux policy changes on current Fedora Rawhide and F24 (2016-05-21)
Product: [Fedora] Fedora Reporter: Adam Williamson <awilliam>
Component: selinux-policyAssignee: Lukas Vrabec <lvrabec>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: urgent Docs Contact:
Priority: urgent    
Version: 24CC: abokovoy, awilliam, dominick.grift, dwalsh, gmarr, ipa-maint, jhrozek, jpazdziora, lslebodn, lvrabec, mbasti, mgrepl, mkosek, plautrba, pspacek, pviktori, pvoborni, rcritten, robatino, ssorce
Target Milestone: ---   
Target Release: ---   
Hardware: All   
OS: All   
Whiteboard: AcceptedBlocker
Fixed In Version: selinux-policy-3.13.1-190.fc24 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2016-06-01 19:53:42 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: 1230435, 1277284    
Attachments:
Description Flags
ausearch output from audit.log (all the selinux denials)
none
DNSSEC audit.log none

Description Adam Williamson 2016-05-04 16:32:35 UTC
Now we have a FreeIPA deployment test running in openQA, I noticed right away it seems to fail on current Rawhide:

https://openqa.stg.fedoraproject.org/tests/16460

you can find the whole /var/log in the 'Logs & Assets' tab - https://openqa.stg.fedoraproject.org/tests/16460/file/role_deploy_domain_controller-var_log.tar.gz . Please don't download the disk image or ISO from that tab, openQA is not set up as a download server, if you want to get a current Rawhide nightly to see if you can reproduce, check https://www.happyassassin.net/nightlies.html .

The deployment goes through rolekit but I think it's a FreeIPA problem, it seems like (at least from a quick glance) the deployment mostly runs OK, then fails when it tries to do '/bin/systemctl restart ipa.service' right at the end, I couldn't quite see why that fails yet. The failure shows up both in the journal and in ipaserver-install.log .

Proposing as an F25 Alpha blocker, violation of "Release-blocking roles and the supported role configuration interfaces must meet the core functional Role Definition Requirements to the extent that supported roles can be successfully deployed, started, stopped, brought to a working configuration, and queried." - https://fedoraproject.org/wiki/Fedora_24_Alpha_Release_Criteria#Role_definition_requirements

Comment 1 Martin Bašti 2016-05-04 16:47:45 UTC
named-pkcs11 error from log:

May  4 08:23:07 localhost named-pkcs11[9090]: starting BIND 9.10.3-P4-RedHat-9.10.3-12.P4.fc25 <id:ebd72b3> -u named
May  4 08:23:07 localhost named-pkcs11[9090]: built with '--build=x86_64-redhat-linux-gnu' '--host=x86_64-redhat-linux-gnu' '--program-prefix=' '--disable-dependency-tracking' '--prefix=/usr' '--exec-prefix=/usr' '--bindir=/usr/bin' '--sbindir=/usr/sbin' '--sysconfdir=/etc' '--datadir=/usr/share' '--includedir=/usr/include' '--libdir=/usr/lib64' '--libexecdir=/usr/libexec' '--sharedstatedir=/var/lib' '--mandir=/usr/share/man' '--infodir=/usr/share/info' '--with-python=/usr/bin/python3' '--with-libtool' '--localstatedir=/var' '--enable-threads' '--enable-ipv6' '--enable-filter-aaaa' '--with-pic' '--disable-static' '--disable-openssl-version-check' '--includedir=/usr/include/bind9' '--with-tuning=large' '--with-geoip' '--enable-native-pkcs11' '--with-pkcs11=/usr/lib64/pkcs11/libsofthsm2.so' '--with-dlopen=yes' '--with-dlz-ldap=yes' '--with-dlz-postgres=yes' '--with-dlz-mysql=yes' '--with-dlz-filesystem=yes' '--with-dlz-bdb=yes' '--with-gssapi=yes' '--disable-isc-spnego' '--enable-fixed-rrset' '--with-docbook-xsl=/usr/share/sgml/docbook/xsl-stylesheets' '--enable-full-report' 'build_alias=x86_64-redhat-linux-gnu' 'host_alias=x86_64-redhat-linux-gnu' 'CFLAGS= -O2 -g -pipe -Wall -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector-strong --param=ssp-buffer-size=4 -grecord-gcc-switches -specs=/usr/lib/rpm/redhat/redhat-hardened-cc1 -m64 -mtune=generic' 'LDFLAGS=-Wl,-z,relro -specs=/usr/lib/rpm/redhat/redhat-hardened-ld' 'CPPFLAGS= -DDIG_SIGCHASE'
May  4 08:23:07 localhost named-pkcs11[9090]: ----------------------------------------------------
May  4 08:23:07 localhost named-pkcs11[9090]: BIND 9 is maintained by Internet Systems Consortium,
May  4 08:23:07 localhost named-pkcs11[9090]: Inc. (ISC), a non-profit 501(c)(3) public-benefit
May  4 08:23:07 localhost named-pkcs11[9090]: corporation.  Support and training for BIND 9 are
May  4 08:23:07 localhost named-pkcs11[9090]: available at https://www.isc.org/support
May  4 08:23:07 localhost named-pkcs11[9090]: ----------------------------------------------------
May  4 08:23:07 localhost named-pkcs11[9090]: adjusted limit on open files from 4096 to 1048576
May  4 08:23:07 localhost named-pkcs11[9090]: found 2 CPUs, using 2 worker threads
May  4 08:23:07 localhost named-pkcs11[9090]: using 2 UDP listeners per interface
May  4 08:23:07 localhost named-pkcs11[9090]: using up to 21000 sockets
May  4 08:23:07 localhost named-pkcs11[9090]: ObjectStore.cpp(59): Failed to enumerate object store in /var/lib/ipa/dnssec/tokens
May  4 08:23:07 localhost named-pkcs11[9090]: SoftHSM.cpp(456): Could not load the object store
May  4 08:23:07 localhost named-pkcs11[9090]: initializing DST: PKCS#11 initialization failed
May  4 08:23:07 localhost named-pkcs11[9090]: exiting (due to fatal error)
May  4 08:23:07 localhost systemd: named-pkcs11.service: Control process exited, code=exited status=1

Comment 2 Adam Williamson 2016-05-04 16:48:24 UTC
So we have a couple of suspects here:

<mbasti> adamw: May  4 08:23:07 localhost named-pkcs11[9090]: ObjectStore.cpp(59): Failed to enumerate object store in /var/lib/ipa/dnssec/tokens this is why it failed

but I also note that there are a ton of SELinux denials logged in /var/log/audit/audit.log . I'll attach them all, but I particularly note these two:

time->Wed May  4 05:24:23 2016
type=AVC msg=audit(1462364663.696:466): avc:  denied  { unlink } for  pid=9489 comm="systemd" name="ipa-dnskeysync-replica.ccache" dev="tmpfs" ino=66751 scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:tmp_t:s0 tclass=file permissive=0
----
time->Wed May  4 05:24:23 2016
type=AVC msg=audit(1462364663.696:467): avc:  denied  { unlink } for  pid=9489 comm="systemd" name="ipa-dnskeysyncd.ccache" dev="tmpfs" ino=66720 scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:tmp_t:s0 tclass=file permissive=0

which happen right around the time the systemctl restart command fails - per journalctl, that fails at 05:24:25 , two seconds after the denials are logged.

Comment 3 Adam Williamson 2016-05-04 16:49:15 UTC
Created attachment 1153936 [details]
ausearch output from audit.log (all the selinux denials)

Comment 4 Adam Williamson 2016-05-04 16:49:51 UTC
CCing lvrabec for SELinux denials.

Comment 5 Lukas Vrabec 2016-05-09 08:44:31 UTC
Hi Adam,

Which process is creating "ipa-dnskeysyncd.ccache"? What is SELinux domain of this process? ($ps -efZ | grep PROCESS_NAME)

Thank you.

Comment 6 Martin Bašti 2016-05-11 14:46:15 UTC
Process is 'ipa-dnskeysyncd'

ps -efZ | grep ipa-dnskeysyncd
system_u:system_r:unconfined_service_t:s0 ods 78891  1 94 16:44 ?        00:00:02 /usr/bin/python2 /usr/libexec/ipa/ipa-dnskeysyncd


tested on F24 alpha

selinux-policy-targeted-3.13.1-184.fc24.noarch
selinux-policy-3.13.1-184.fc24.noarch

Comment 7 Lukas Slebodnik 2016-05-11 15:01:11 UTC
If you can see the same problem on fedora 24 then you might reconsider
changing F25AlphaBlocker -> F24 Release Blocker

Comment 8 Martin Bašti 2016-05-11 15:05:35 UTC
I'm experiencing the same issue on F24, with 'setenforce 1' named cannot access keystore.

Probably same issue with following IPA ticket: https://fedorahosted.org/freeipa/ticket/5870

Comment 9 Lukas Vrabec 2016-05-11 15:43:36 UTC
Thank you for info. 

We need to label /usr/libexec/ipa/ipa-dnskeysyncd to run it in ipa SELinux domain.

Comment 10 Petr Vobornik 2016-05-12 10:14:01 UTC
Changing component according to the findings above.

Comment 11 Miroslav Grepl 2016-05-12 13:10:27 UTC
Lukas, 
do you think about a new type?

Comment 12 Lukas Vrabec 2016-05-12 13:16:20 UTC
We need to investigate it more, if we can use some existing type or create new one. But it looks like we need new type called e.g "ipa_dns_t".

Comment 13 Adam Williamson 2016-05-13 04:50:00 UTC
(In reply to Lukas Slebodnik from comment #7)
> If you can see the same problem on fedora 24 then you might reconsider
> changing F25AlphaBlocker -> F24 Release Blocker

It was not happening on F24 at the time, or else I would have done. F24 in openQA is failing now too, though, so I'll assume it's the same bug (I'm on vacation on a slow wifi connection and CBA downloading the logs to check) and adjust the nomination. It was probably still working earlier because F24 was frozen for Beta, so whatever change triggered this hadn't landed yet.

Comment 14 Geoffrey Marr 2016-05-16 18:07:17 UTC
Discussed during the 2016-05-16 blocker review meeting: [1]

Accepted as a blocker for F24 final as it violates the following Alpha-release criteria: [2]


[1] https://meetbot-raw.fedoraproject.org/fedora-blocker-review/2016-05-16/f24-blocker-review.2016-05-16-16.00.txt

[2] https://fedoraproject.org/wiki/Fedora_24_Alpha_Release_Criteria#Role_definition_requirements

Comment 15 Lukas Vrabec 2016-05-17 15:21:39 UTC
Hi, 

I sent selinux-policy scratch builds with new SELinux type: ipa_dnskey_t to Martin for testing. 

Scratch builds: https://copr.fedorainfracloud.org/coprs/lvrabec/selinux-policy/build/272005/

Comment 16 Lukas Vrabec 2016-05-25 10:51:34 UTC
Created new SELinux module for opendnssec service. Added new type ipa_dnskey_t with proper rules.

Build in koji: http://koji.fedoraproject.org/koji/buildinfo?buildID=768295

Could somebody from ipa team test it? 

Thank you.

Comment 17 Martin Bašti 2016-05-25 12:59:04 UTC
DNSSEC does not work, I see many denied lines in audit.log for ipa-dnskeysyncd

# rpm -q selinux-policy
selinux-policy-3.13.1-189.fc24.noarch


..............snip................
type=AVC msg=audit(1464180274.817:7324): avc:  denied  { search } for  pid=5430 comm="ipa-dnskeysyncd" name="httpd" dev="dm-0" ino=26687697 scontext=system_u:system_r:ipa_dnskey_t:s0 tcontext=system_u:object_r:httpd_config_t:s0 tclass=dir permissive=0
type=AVC msg=audit(1464180274.818:7325): avc:  denied  { search } for  pid=5430 comm="ipa-dnskeysyncd" name="httpd" dev="dm-0" ino=26687697 scontext=system_u:system_r:ipa_dnskey_t:s0 tcontext=system_u:object_r:httpd_config_t:s0 tclass=dir permissive=0
type=AVC msg=audit(1464180277.125:7326): avc:  denied  { search } for  pid=5440 comm="ods-ksmutil" name="opendnssec" dev="dm-0" ino=26688527 scontext=system_u:system_r:ipa_dnskey_t:s0 tcontext=system_u:object_r:opendnssec_conf_t:s0 tclass=dir permissive=0
type=AVC msg=audit(1464180277.125:7327): avc:  denied  { search } for  pid=5440 comm="ods-ksmutil" name="opendnssec" dev="dm-0" ino=26688527 scontext=system_u:system_r:ipa_dnskey_t:s0 tcontext=system_u:object_r:opendnssec_conf_t:s0 tclass=dir permissive=0
type=AVC msg=audit(1464180277.125:7328): avc:  denied  { search } for  pid=5440 comm="ods-ksmutil" name="opendnssec" dev="dm-0" ino=26688527 scontext=system_u:system_r:ipa_dnskey_t:s0 tcontext=system_u:object_r:opendnssec_conf_t:s0 tclass=dir permissive=0
type=AVC msg=audit(1464180277.125:7329): avc:  denied  { search } for  pid=5440 comm="ods-ksmutil" name="opendnssec" dev="dm-0" ino=26688527 scontext=system_u:system_r:ipa_dnskey_t:s0 tcontext=system_u:object_r:opendnssec_conf_t:s0 tclass=dir permissive=0
type=AVC msg=audit(1464180277.125:7330): avc:  denied  { search } for  pid=5440 comm="ods-ksmutil" name="opendnssec" dev="dm-0" ino=26688527 scontext=system_u:system_r:ipa_dnskey_t:s0 tcontext=system_u:object_r:opendnssec_conf_t:s0 tclass=dir permissive=0
type=AVC msg=audit(1464180277.125:7331): avc:  denied  { search } for  pid=5440 comm="ods-ksmutil" name="opendnssec" dev="dm-0" ino=26688527 scontext=system_u:system_r:ipa_dnskey_t:s0 tcontext=system_u:object_r:opendnssec_conf_t:s0 tclass=dir permissive=0
type=AVC msg=audit(1464180277.125:7332): avc:  denied  { search } for  pid=5440 comm="ods-ksmutil" name="opendnssec" dev="dm-0" ino=26688527 scontext=system_u:system_r:ipa_dnskey_t:s0 tcontext=system_u:object_r:opendnssec_conf_t:s0 tclass=dir permissive=0
type=AVC msg=audit(1464180277.125:7333): avc:  denied  { search } for  pid=5440 comm="ods-ksmutil" name="opendnssec" dev="dm-0" ino=26688527 scontext=system_u:system_r:ipa_dnskey_t:s0 tcontext=system_u:object_r:opendnssec_conf_t:s0 tclass=dir permissive=0
type=AVC msg=audit(1464180277.125:7334): avc:  denied  { search } for  pid=5440 comm="ods-ksmutil" name="opendnssec" dev="dm-0" ino=26688527 scontext=system_u:system_r:ipa_dnskey_t:s0 tcontext=system_u:object_r:opendnssec_conf_t:s0 tclass=dir permissive=0
type=AVC msg=audit(1464180277.257:7336): avc:  denied  { unlink } for  pid=5442 comm="systemd" name="ipa-dnskeysyncd.ccache" dev="tmpfs" ino=21987984 scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:ipa_tmp_t:s0 tclass=file permissive=0
type=AVC msg=audit(1464180339.403:7340): avc:  denied  { search } for  pid=5453 comm="ipa-dnskeysyncd" name="httpd" dev="dm-0" ino=26687697 scontext=system_u:system_r:ipa_dnskey_t:s0 tcontext=system_u:object_r:httpd_config_t:s0 tclass=dir permissive=0
type=AVC msg=audit(1464180339.404:7341): avc:  denied  { search } for  pid=5453 comm="ipa-dnskeysyncd" name="httpd" dev="dm-0" ino=26687697 scontext=system_u:system_r:ipa_dnskey_t:s0 tcontext=system_u:object_r:httpd_config_t:s0 tclass=dir permissive=0
type=AVC msg=audit(1464180343.091:7342): avc:  denied  { search } for  pid=5467 comm="ods-ksmutil" name="opendnssec" dev="dm-0" ino=26688527 scontext=system_u:system_r:ipa_dnskey_t:s0 tcontext=system_u:object_r:opendnssec_conf_t:s0 tclass=dir permissive=0
type=AVC msg=audit(1464180343.091:7343): avc:  denied  { search } for  pid=5467 comm="ods-ksmutil" name="opendnssec" dev="dm-0" ino=26688527 scontext=system_u:system_r:ipa_dnskey_t:s0 tcontext=system_u:object_r:opendnssec_conf_t:s0 tclass=dir permissive=0
type=AVC msg=audit(1464180343.092:7344): avc:  denied  { search } for  pid=5467 comm="ods-ksmutil" name="opendnssec" dev="dm-0" ino=26688527 scontext=system_u:system_r:ipa_dnskey_t:s0 tcontext=system_u:object_r:opendnssec_conf_t:s0 tclass=dir permissive=0
type=AVC msg=audit(1464180343.092:7345): avc:  denied  { search } for  pid=5467 comm="ods-ksmutil" name="opendnssec" dev="dm-0" ino=26688527 scontext=system_u:system_r:ipa_dnskey_t:s0 tcontext=system_u:object_r:opendnssec_conf_t:s0 tclass=dir permissive=0
type=AVC msg=audit(1464180343.092:7346): avc:  denied  { search } for  pid=5467 comm="ods-ksmutil" name="opendnssec" dev="dm-0" ino=26688527 scontext=system_u:system_r:ipa_dnskey_t:s0 tcontext=system_u:object_r:opendnssec_conf_t:s0 tclass=dir permissive=0
type=AVC msg=audit(1464180343.092:7347): avc:  denied  { search } for  pid=5467 comm="ods-ksmutil" name="opendnssec" dev="dm-0" ino=26688527 scontext=system_u:system_r:ipa_dnskey_t:s0 tcontext=system_u:object_r:opendnssec_conf_t:s0 tclass=dir permissive=0
type=AVC msg=audit(1464180343.092:7348): avc:  denied  { search } for  pid=5467 comm="ods-ksmutil" name="opendnssec" dev="dm-0" ino=26688527 scontext=system_u:system_r:ipa_dnskey_t:s0 tcontext=system_u:object_r:opendnssec_conf_t:s0 tclass=dir permissive=0
type=AVC msg=audit(1464180343.092:7349): avc:  denied  { search } for  pid=5467 comm="ods-ksmutil" name="opendnssec" dev="dm-0" ino=26688527 scontext=system_u:system_r:ipa_dnskey_t:s0 tcontext=system_u:object_r:opendnssec_conf_t:s0 tclass=dir permissive=0
type=AVC msg=audit(1464180343.092:7350): avc:  denied  { search } for  pid=5467 comm="ods-ksmutil" name="opendnssec" dev="dm-0" ino=26688527 scontext=system_u:system_r:ipa_dnskey_t:s0 tcontext=system_u:object_r:opendnssec_conf_t:s0 tclass=dir permissive=0
type=AVC msg=audit(1464180343.301:7352): avc:  denied  { unlink } for  pid=5469 comm="systemd" name="ipa-dnskeysyncd.ccache" dev="tmpfs" ino=21969907 scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:ipa_tmp_t:s0 tclass=file permissive=0
type=AVC msg=audit(1464180405.383:7360): avc:  denied  { search } for  pid=5532 comm="ipa-dnskeysyncd" name="httpd" dev="dm-0" ino=26687697 scontext=system_u:system_r:ipa_dnskey_t:s0 tcontext=system_u:object_r:httpd_config_t:s0 tclass=dir permissive=0
type=AVC msg=audit(1464180405.385:7361): avc:  denied  { search } for  pid=5532 comm="ipa-dnskeysyncd" name="httpd" dev="dm-0" ino=26687697 scontext=system_u:system_r:ipa_dnskey_t:s0
......snip....................

Comment 18 Lukas Vrabec 2016-05-25 13:55:16 UTC
Could you re-test it but in permissive mode? 

Thank you.

Comment 19 Martin Bašti 2016-05-25 15:55:45 UTC
Attaching audit.log from permissive mode

Please note that command ods-ksmtuil is also required for IPA DNSSEC

Comment 20 Martin Bašti 2016-05-25 15:56:30 UTC
Created attachment 1161492 [details]
DNSSEC audit.log

Comment 21 Fedora Update System 2016-05-26 05:01:44 UTC
selinux-policy-3.13.1-189.fc24 has been pushed to the Fedora 24 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-2016-43d1395a18

Comment 22 Fedora Update System 2016-05-30 21:30:48 UTC
selinux-policy-3.13.1-190.fc24 has been submitted as an update to Fedora 24. https://bodhi.fedoraproject.org/updates/FEDORA-2016-f85aa7dd6b

Comment 23 Fedora Update System 2016-05-31 08:53:02 UTC
selinux-policy-3.13.1-190.fc24 has been pushed to the Fedora 24 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-2016-f85aa7dd6b

Comment 24 Adam Williamson 2016-05-31 19:29:51 UTC
I tweaked openQA staging to run the deployment test with updates-testing enabled temporarily and confirmed that it worked:

https://openqa.stg.fedoraproject.org/tests/overview?build=Fedora-24-20160531.n.0-DCUT&version=24&groupid=1&distri=fedora

so this looks good.

Comment 25 Fedora Update System 2016-06-01 19:53:36 UTC
selinux-policy-3.13.1-190.fc24 has been pushed to the Fedora 24 stable repository. If problems still persist, please make note of it in this bug report.