Bug 1357665

Summary:	named-pkcs11.service failed to start after normal system upgrade
Product:	[Fedora] Fedora	Reporter:	Robbie Harwood <rharwood>
Component:	selinux-policy	Assignee:	Lukas Vrabec <lvrabec>
Status:	CLOSED ERRATA	QA Contact:	Fedora Extras Quality Assurance <extras-qa>
Severity:	unspecified	Docs Contact:
Priority:	unspecified
Version:	23	CC:	abokovoy, arthur-fayzullin, blipton, dominick.grift, dwalsh, ipa-maint, jhrozek, jpazdziora, lvrabec, mgrepl, mkosek, plautrba, pspacek, pvoborni, rcritten, rharwood, richard.berg, roberto.cornacchia, ssorce
Target Milestone:	---
Target Release:	---
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:	selinux-policy-3.13.1-158.23.fc23 selinux-policy-3.13.1-158.24.fc23	Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2016-09-29 22:52:36 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 Robbie Harwood 2016-07-18 19:44:48 UTC

FreeIPA fails to start, saying:

Job for named-pkcs11.service failed because the control process exited with error code. See "systemctl status named-pkcs11.service" and "journalctl -xe" for details.

which leads to the error from its logs:

Jul 18 14:39:32 freeipa.rharwood.biz named-pkcs11[1486]: ObjectStore.cpp(59): Failed to enumerate object store in /var/lib/ipa/dnssec/tokens

ipa-server-upgrade has not been run recently (should it have been run on upgrade somewhere?), except that it was run after the failure was observed and seems to complain about dogtag.  However, pki-tomcatd appears to have been up for the duration and reports no errors.

Machine image available from https://rharwood.fedorapeople.org/freeipa.img.gz (~2.7 GB uncompressed).  It thinks it is named freeipa.rharwood.biz and has address 192.168.122.10; all passwords are "secretes".

Comment 1 Petr Vobornik 2016-07-19 07:35:20 UTC

Are there any AVCs? 

Could you check file permissions of:
  chmod 770 /var/lib/ipa/dnssec
  chmod 644 /etc/ipa/dnssec/softhsm2.conf

To check if it is not: https://fedorahosted.org/freeipa/ticket/5520

What is the freeipa-server version? The one in F23 - freeipa-4.2.3-2.fc23?

Comment 2 Robbie Harwood 2016-07-19 21:24:09 UTC

(In reply to Petr Vobornik from comment #1)
> Are there any AVCs? 

type=USER_AVC msg=audit(1468865282.020:159): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='avc:  denied  { start } for auid=n/a uid=0 gid=0 path="/dev/null" cmdline="/usr/bin/systemctl reload named.service" scontext=system_u:system_r:logrotate_t:s0-s0:c0.c1023 tcontext=system_u:object_r:null_device_t:s0 tclass=service  exe="/usr/lib/systemd/systemd" sauid=0 hostname=? addr=? terminal=?'

repeated several times.

> Could you check file permissions of:
>   chmod 770 /var/lib/ipa/dnssec

drwxr-x---. 3 999 25 4096 Mar 11 16:13 var/lib/ipa/dnssec

>   chmod 644 /etc/ipa/dnssec/softhsm2.conf

-rw-r--r--. 1 0 0 145 Jun 20 14:59 etc/ipa/dnssec/softhsm2.conf

> To check if it is not: https://fedorahosted.org/freeipa/ticket/5520
> 
> What is the freeipa-server version? The one in F23 - freeipa-4.2.3-2.fc23?

Correct.

Comment 3 Richard Berg 2016-07-20 19:34:13 UTC

I got the same error (Failed to enumerate object store in /var/lib/ipa/dnssec/tokens) today after restarting named-pkcs11.service.

Versions:
  bind.x86_64                            32:9.10.3-13.P4.fc23            @updates
  freeipa-server.x86_64                  4.2.4-1.fc23                    @updates
  selinux-policy.noarch                  3.13.1-158.21.fc23              @updates

AVCs:
  type=AVC msg=audit(1469039718.528:63783): avc:  denied  { read } for  pid=3675 comm="named-pkcs11" name="tokens" dev="dm-1" ino=6448714 scontext=system_u:system_r:named_t:s0 tcontext=system_u:object_r:ipa_var_lib_t:s0 tclass=dir permissive=1
  type=AVC msg=audit(1469039718.528:63784): avc:  denied  { getattr } for  pid=3675 comm="named-pkcs11" path="/var/lib/ipa/dnssec/tokens/73c216bf-fe3e-03e3-0c89-45892f9492ed/token.object" dev="dm-1" ino=6448716 scontext=system_u:system_r:named_t:s0 tcontext=system_u:object_r:ipa_var_lib_t:s0 tclass=file permissive=1
  type=AVC msg=audit(1469039718.528:63785): avc:  denied  { read write } for  pid=3675 comm="named-pkcs11" name="generation" dev="dm-1" ino=6448718 scontext=system_u:system_r:named_t:s0 tcontext=system_u:object_r:ipa_var_lib_t:s0 tclass=file permissive=1
  type=AVC msg=audit(1469039718.528:63786): avc:  denied  { open } for  pid=3675 comm="named-pkcs11" path="/var/lib/ipa/dnssec/tokens/73c216bf-fe3e-03e3-0c89-45892f9492ed/generation" dev="dm-1" ino=6448718 scontext=system_u:system_r:named_t:s0 tcontext=system_u:object_r:ipa_var_lib_t:s0 tclass=file permissive=1
  type=AVC msg=audit(1469039718.528:63787): avc:  denied  { lock } for  pid=3675 comm="named-pkcs11" path="/var/lib/ipa/dnssec/tokens/73c216bf-fe3e-03e3-0c89-45892f9492ed/generation" dev="dm-1" ino=6448718 scontext=system_u:system_r:named_t:s0 tcontext=system_u:object_r:ipa_var_lib_t:s0 tclass=file permissive=1
  type=AVC msg=audit(1469040532.448:64481): avc:  denied  { search } for  pid=14294 comm="named-pkcs11" name="ipa" dev="dm-1" ino=73407 scontext=system_u:system_r:named_t:s0 tcontext=system_u:object_r:ipa_var_lib_t:s0 tclass=dir permissive=0
  type=AVC msg=audit(1469040546.833:64527): avc:  denied  { getattr } for  pid=14364 comm="named-pkcs11" path="/var/lib/ipa/dnssec/tokens" dev="dm-1" ino=6448714 scontext=system_u:system_r:named_t:s0 tcontext=system_u:object_r:ipa_var_lib_t:s0 tclass=dir permissive=1
  type=AVC msg=audit(1469040546.833:64528): avc:  denied  { open } for  pid=14364 comm="named-pkcs11" path="/var/lib/ipa/dnssec/tokens" dev="dm-1" ino=6448714 scontext=system_u:system_r:named_t:s0 tcontext=system_u:object_r:ipa_var_lib_t:s0 tclass=dir permissive=1
  type=AVC msg=audit(1469040742.312:64725): avc:  denied  { read } for  pid=16899 comm="named-pkcs11" name="tokens" dev="dm-1" ino=6448714 scontext=system_u:system_r:named_t:s0 tcontext=system_u:object_r:ipa_var_lib_t:s0 tclass=dir permissive=1

This didn't help:
  restorecon -r /var/lib/ipa/dnssec

I currently use this local policy as a workaround:
  module named_local 1.0;

  require {
          type named_t;
          type ipa_var_lib_t;
          class dir { open getattr search read };
          class file { getattr open read lock write };
  }

  #============= named_t ==============
  allow named_t ipa_var_lib_t:dir { open getattr search read };
  allow named_t ipa_var_lib_t:file { lock open getattr read write };

Comment 4 Petr Spacek 2016-07-21 10:00:48 UTC

Please add output from
rpm -q freeipa-server-dns selinux-policy

Does it work in permissive mode? I suspect that it will. Please gather AVCs from run in permissive mode. After that we can switch the bug to SELinux-policy component.

Thank you!

Comment 5 Richard Berg 2016-07-21 13:33:05 UTC

rpm -q freeipa-server-dns selinux-policy
  freeipa-server-dns-4.2.4-1.fc23.x86_64
  selinux-policy-3.13.1-158.21.fc23.noarch

It works when named_t is set to permissive:
  semanage permissive -a named_t
  
Output from "ausearch -m avc -r -ts recent -se named_t" with permissive named_t:
type=AVC msg=audit(1469106284.705:75828): avc:  denied  { read } for  pid=17496 comm="named-pkcs11" name="tokens" dev="dm-1" ino=6448714 scontext=system_u:system_r:named_t:s0 tcontext=system_u:object_r:ipa_var_lib_t:s0 tclass=dir permissive=1
type=AVC msg=audit(1469106284.705:75829): avc:  denied  { getattr } for  pid=17496 comm="named-pkcs11" path="/var/lib/ipa/dnssec/tokens/73c216bf-fe3e-03e3-0c89-45892f9492ed/token.object" dev="dm-1" ino=6448716 scontext=system_u:system_r:named_t:s0 tcontext=system_u:object_r:ipa_var_lib_t:s0 tclass=file permissive=1
type=AVC msg=audit(1469106284.705:75830): avc:  denied  { read write } for  pid=17496 comm="named-pkcs11" name="generation" dev="dm-1" ino=6448718 scontext=system_u:system_r:named_t:s0 tcontext=system_u:object_r:ipa_var_lib_t:s0 tclass=file permissive=1
type=AVC msg=audit(1469106284.705:75831): avc:  denied  { open } for  pid=17496 comm="named-pkcs11" path="/var/lib/ipa/dnssec/tokens/73c216bf-fe3e-03e3-0c89-45892f9492ed/generation" dev="dm-1" ino=6448718 scontext=system_u:system_r:named_t:s0 tcontext=system_u:object_r:ipa_var_lib_t:s0 tclass=file permissive=1
type=AVC msg=audit(1469106284.705:75832): avc:  denied  { lock } for  pid=17496 comm="named-pkcs11" path="/var/lib/ipa/dnssec/tokens/73c216bf-fe3e-03e3-0c89-45892f9492ed/generation" dev="dm-1" ino=6448718 scontext=system_u:system_r:named_t:s0 tcontext=system_u:object_r:ipa_var_lib_t:s0 tclass=file permissive=1

With "semanage dontaudit off" there are a couple of more AVCs:
type=AVC msg=audit(1469106332.532:75882): avc:  denied  { getattr } for  pid=18338 comm="named-pkcs11" path="/var/lib/ipa/dnssec/tokens" dev="dm-1" ino=6448714 scontext=system_u:system_r:named_t:s0 tcontext=system_u:object_r:ipa_var_lib_t:s0 tclass=dir permissive=1
type=AVC msg=audit(1469106332.532:75883): avc:  denied  { read } for  pid=18338 comm="named-pkcs11" name="tokens" dev="dm-1" ino=6448714 scontext=system_u:system_r:named_t:s0 tcontext=system_u:object_r:ipa_var_lib_t:s0 tclass=dir permissive=1
type=AVC msg=audit(1469106332.532:75884): avc:  denied  { open } for  pid=18338 comm="named-pkcs11" path="/var/lib/ipa/dnssec/tokens" dev="dm-1" ino=6448714 scontext=system_u:system_r:named_t:s0 tcontext=system_u:object_r:ipa_var_lib_t:s0 tclass=dir permissive=1
type=AVC msg=audit(1469106332.532:75885): avc:  denied  { getattr } for  pid=18338 comm="named-pkcs11" path="/var/lib/ipa/dnssec/tokens/73c216bf-fe3e-03e3-0c89-45892f9492ed/token.object" dev="dm-1" ino=6448716 scontext=system_u:system_r:named_t:s0 tcontext=system_u:object_r:ipa_var_lib_t:s0 tclass=file permissive=1
type=AVC msg=audit(1469106332.532:75886): avc:  denied  { read write } for  pid=18338 comm="named-pkcs11" name="generation" dev="dm-1" ino=6448718 scontext=system_u:system_r:named_t:s0 tcontext=system_u:object_r:ipa_var_lib_t:s0 tclass=file permissive=1
type=AVC msg=audit(1469106332.532:75887): avc:  denied  { open } for  pid=18338 comm="named-pkcs11" path="/var/lib/ipa/dnssec/tokens/73c216bf-fe3e-03e3-0c89-45892f9492ed/generation" dev="dm-1" ino=6448718 scontext=system_u:system_r:named_t:s0 tcontext=system_u:object_r:ipa_var_lib_t:s0 tclass=file permissive=1
type=AVC msg=audit(1469106332.532:75888): avc:  denied  { lock } for  pid=18338 comm="named-pkcs11" path="/var/lib/ipa/dnssec/tokens/73c216bf-fe3e-03e3-0c89-45892f9492ed/generation" dev="dm-1" ino=6448718 scontext=system_u:system_r:named_t:s0 tcontext=system_u:object_r:ipa_var_lib_t:s0 tclass=file permissive=1

Comment 6 Petr Spacek 2016-07-21 13:49:31 UTC

Thanks, so it will be a SELinux policy bug. I'm going to change component. Thank you for patience!

Comment 7 Jan Pazdziora (Red Hat) 2016-09-07 08:47:06 UTC

Is this related to Fedora 24 bug 1333106 and/or RHEL 7 bug 1350957?

Could we get the fixes backported to Fedora 23?

Comment 9 Jan Pazdziora (Red Hat) 2016-09-12 13:03:24 UTC

Is this a dupe of bug 1363967?

Comment 11 Fedora Update System 2016-09-16 08:37:25 UTC

selinux-policy-3.13.1-158.24.fc23 has been submitted as an update to Fedora 23. https://bodhi.fedoraproject.org/updates/FEDORA-2016-f739cc7524

Comment 12 Fedora Update System 2016-09-17 00:53:04 UTC

selinux-policy-3.13.1-158.24.fc23 has been pushed to the Fedora 23 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-f739cc7524

Comment 13 Fedora Update System 2016-09-29 22:52:36 UTC

selinux-policy-3.13.1-158.24.fc23 has been pushed to the Fedora 23 stable repository. If problems still persist, please make note of it in this bug report.