803054 – ipa commands after upgrade return Insufficient access: KDC returned NOT_ALLOWED_TO_DELEGATE

RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.

Bug 803054 - ipa commands after upgrade return Insufficient access: KDC returned NOT_ALLOWED_TO_DELEGATE

Summary: ipa commands after upgrade return Insufficient access: KDC returned NOT_ALLOW...

Keywords:
Status:	CLOSED WORKSFORME
Alias:	None
Product:	Red Hat Enterprise Linux 6
Classification:	Red Hat
Component:	ipa
Sub Component:
Version:	6.3
Hardware:	Unspecified
OS:	Unspecified
Priority:	unspecified
Severity:	unspecified
Target Milestone:	rc
Target Release:	---
Assignee:	Rob Crittenden
QA Contact:	IDM QE LIST
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2012-03-13 21:12 UTC by Scott Poore
Modified:	2013-10-07 18:51 UTC (History)
CC List:	4 users (show)
Fixed In Version:
Doc Type:	Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed:	2012-04-09 18:37:55 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)
ipaupgrade.log (1.57 KB, application/x-gzip) 2012-03-14 12:56 UTC, Scott Poore	no flags	Details
yum.log for more complete listing of what was updated (2.36 KB, application/x-gzip) 2012-03-14 12:56 UTC, Scott Poore	no flags	Details
partial output of yum update ipa (2.63 KB, application/x-gzip) 2012-03-14 12:57 UTC, Scott Poore	no flags	Details
View All

Description Scott Poore 2012-03-13 21:12:41 UTC

Description of problem:

IPA upgrades on RHEL6.2 from 2.1.3 to 2.2.0 seems to have an issue after upgrade.

# yum -y update 'ipa*'
...
# ipactl restart
...
# ipa user-find
ipa: ERROR: Insufficient access: KDC returned NOT_ALLOWED_TO_DELEGATE

I'm hoping this is straightforward and maybe even something I missed but, I also tried updating everything as well as trying this:

# ipa-ldap-updater --ldapi /usr/share/ipa/updates/30-s4u2proxy.update
ipa         : INFO     Parsing file /usr/share/ipa/updates/30-s4u2proxy.update
ipa         : INFO     New entry: cn=s4u2proxy,cn=etc,dc=testrelm,dc=com
ipa         : INFO     New entry: cn=ipa-http-delegation,cn=s4u2proxy,cn=etc,dc=testrelm,dc=com
ipa         : ERROR    Add failure 'NoneType' object is not callable
ipa         : INFO     New entry: cn=ipa-ldap-delegation-targets,cn=s4u2proxy,cn=etc,dc=testrelm,dc=com
ipa         : ERROR    Add failure 'NoneType' object is not callable
ipa         : INFO     Update complete


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

RHEL 6.2 pointing to RHEL 6.3 test repo and repo containing IPA 2.2.0-3 rpms.

How reproducible:

So far, always.

Steps to Reproduce:

1.  <Install IPA on RHEL6.2 server>
2.  kinit admin
3.  <add some content (users, groups, etc)>
4.  <add yum repo with RHEL 6.3 and 2.2.0-3 rpms>
5.  yum -y update 'ipa*'
6.  ipactl restart
7.  ipa user-find
  
Actual results:

command returns the following:

ipa: ERROR: Insufficient access: KDC returned NOT_ALLOWED_TO_DELEGATE

Expected results:

ipa command to run and return normal output.

Additional info:

/var/log/messages entry:

Mar 13 16:49:53 ibm-ls22-05 httpd: GSSAPI Error: Unspecified GSS failure.  Minor code may provide more information (KDC returned error string: NOT_ALLOWED_TO_DELEGATE)


/var/log/krb5kdc.log entries:

Mar 13 16:49:53 HOSTNAME krb5kdc[17278](info): TGS_REQ (4 etypes {18 17 16 23}) 10.34.54.41: NOT_ALLOWED_TO_DELEGATE: authtime 0,  HTTP/hostname.testrelm.com for ldap/hostname.testrelm.com, Server error

Mar 13 16:49:53 hostname.testrelm.com krb5kdc[17279](info): TGS_REQ (4 etypes {18 17 16 23}) 10.34.54.41: NOT_ALLOWED_TO_DELEGATE: authtime 0,  HTTP/hostname.testrelm.com for ldap/hostname.testrelm.com, Server error

Comment 2 Rob Crittenden 2012-03-13 21:56:37 UTC

Can you check 389-ds error and logs? The Add failures mean that the delegation entries were not added and logs may tell the tale.

Running the updater again may help isolate the access log entries, and can you add the -d flag to get more verbose output from it (it still won't log the failure reason but it will at least show if it would have tried the right thing)?

Comment 3 Scott Poore 2012-03-13 23:20:48 UTC

Should I attach the full logs from /var/log/dirsrv/slapd-<domain>/ for access and errors?  Or is what I list below what you're looking for?

I think I see some errors in the access log but, I'm not quite sure what I'm looking at there.

Running the updater again:

# ipa-ldap-updater -d --ldapi /usr/share/ipa/updates/30-s4u2proxy.update
ipa         : DEBUG    importing all plugin modules in '/usr/lib/python2.6/site-packages/ipalib/plugins'...
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/aci.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/automember.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/automount.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/baseldap.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/batch.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/cert.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/config.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/delegation.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/dns.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/group.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/hbacrule.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/hbacsvc.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/hbacsvcgroup.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/hbactest.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/host.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/hostgroup.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/internal.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/kerberos.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/krbtpolicy.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/migration.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/misc.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/netgroup.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/passwd.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/permission.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/ping.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/privilege.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/pwpolicy.py'
ipa         : DEBUG    args=klist -V
ipa         : DEBUG    stdout=Kerberos 5 version 1.9

ipa         : DEBUG    stderr=
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/role.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/selfservice.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/selinuxusermap.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/service.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/sudocmd.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/sudocmdgroup.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/sudorule.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/user.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/virtual.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipalib/plugins/xmlclient.py'
ipa         : DEBUG    importing all plugin modules in '/usr/lib/python2.6/site-packages/ipaserver/plugins'...
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipaserver/plugins/dogtag.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipaserver/plugins/join.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipaserver/plugins/ldap2.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipaserver/plugins/rabase.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipaserver/plugins/selfsign.py'
ipa         : DEBUG    skipping plugin module ipaserver.plugins.selfsign: selfsign is not selected as RA plugin, it is dogtag
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipaserver/plugins/xmlserver.py'
ipa         : DEBUG    importing all plugin modules in '/usr/lib/python2.6/site-packages/ipaserver/install/plugins'...
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipaserver/install/plugins/baseupdate.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipaserver/install/plugins/dns.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipaserver/install/plugins/fix_replica_memberof.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipaserver/install/plugins/rename_managed.py'
ipa         : DEBUG    importing plugin module '/usr/lib/python2.6/site-packages/ipaserver/install/plugins/updateclient.py'
ipa.ipalib.session.SessionAuthManager: DEBUG    SessionAuthManager.register: name=jsonserver_session
ipa.ipaserver.rpcserver.wsgi_dispatch: DEBUG    Mounting ipaserver.rpcserver.xmlserver() at '/xml'
ipa.ipaserver.rpcserver.wsgi_dispatch: DEBUG    Mounting ipaserver.rpcserver.jsonserver_kerb() at '/json'
ipa.ipaserver.rpcserver.wsgi_dispatch: DEBUG    Mounting ipaserver.rpcserver.jsonserver_session() at '/session/json'
ipa.ipaserver.rpcserver.jsonserver_session: DEBUG    session_auth_duration: 0:20:00
ipa.ipaserver.rpcserver.wsgi_dispatch: DEBUG    Mounting ipaserver.rpcserver.login_password() at '/session/login_password'
ipa.ipaserver.rpcserver.login_password: DEBUG    session_auth_duration: 0:20:00
ipa.ipaserver.rpcserver.wsgi_dispatch: DEBUG    Mounting ipaserver.rpcserver.login_kerberos() at '/session/login_kerberos'
ipa.ipaserver.rpcserver.login_kerberos: DEBUG    session_auth_duration: 0:20:00
ipa         : INFO     Parsing file /usr/share/ipa/updates/30-s4u2proxy.update
ipa         : INFO     Updating existing entry: cn=s4u2proxy,cn=etc,dc=testrelm,dc=com
ipa         : DEBUG    ---------------------------------------------
ipa         : DEBUG    dn: cn=s4u2proxy,cn=etc,dc=testrelm,dc=com
ipa         : DEBUG    objectclass: 
ipa         : DEBUG    	nsContainer
ipa         : DEBUG    	top
ipa         : DEBUG    cn: s4u2proxy
ipa         : DEBUG    ---------------------------------------------
ipa         : DEBUG    Final value
ipa         : DEBUG    dn: cn=s4u2proxy,cn=etc,dc=testrelm,dc=com
ipa         : DEBUG    objectclass: 
ipa         : DEBUG    	nsContainer
ipa         : DEBUG    	top
ipa         : DEBUG    cn: s4u2proxy
ipa         : DEBUG    []
ipa         : DEBUG    Live 1, updated 0
ipa         : INFO     Done
ipa         : INFO     New entry: cn=ipa-http-delegation,cn=s4u2proxy,cn=etc,dc=testrelm,dc=com
ipa         : DEBUG    ---------------------------------------------
ipa         : DEBUG    dn: cn=ipa-http-delegation,cn=s4u2proxy,cn=etc,dc=testrelm,dc=com
ipa         : DEBUG    objectclass: 
ipa         : DEBUG    	ipaKrb5DelegationACL
ipa         : DEBUG    	groupOfPrincipals
ipa         : DEBUG    	top
ipa         : DEBUG    ipaallowedtarget: cn=ipa-ldap-delegation-targets,cn=s4u2proxy,cn=etc,dc=testrelm,dc=com
ipa         : DEBUG    memberprincipal: HTTP/ibm-ls22-05.testrelm.com
ipa         : DEBUG    cn: ipa-http-delegation
ipa         : DEBUG    add: 'HTTP/ibm-ls22-05.testrelm.com' to memberPrincipal, current value ['HTTP/ibm-ls22-05.testrelm.com']
ipa         : DEBUG    add: updated value [u'HTTP/ibm-ls22-05.testrelm.com']
ipa         : DEBUG    ---------------------------------------------
ipa         : DEBUG    dn: cn=ipa-http-delegation,cn=s4u2proxy,cn=etc,dc=testrelm,dc=com
ipa         : DEBUG    objectclass: 
ipa         : DEBUG    	ipaKrb5DelegationACL
ipa         : DEBUG    	groupOfPrincipals
ipa         : DEBUG    	top
ipa         : DEBUG    ipaallowedtarget: cn=ipa-ldap-delegation-targets,cn=s4u2proxy,cn=etc,dc=testrelm,dc=com
ipa         : DEBUG    memberPrincipal: 
ipa         : DEBUG    	HTTP/ibm-ls22-05.testrelm.com
ipa         : DEBUG    cn: ipa-http-delegation
ipa         : DEBUG    ---------------------------------------------
ipa         : DEBUG    Final value
ipa         : DEBUG    dn: cn=ipa-http-delegation,cn=s4u2proxy,cn=etc,dc=testrelm,dc=com
ipa         : DEBUG    objectclass: 
ipa         : DEBUG    	ipaKrb5DelegationACL
ipa         : DEBUG    	groupOfPrincipals
ipa         : DEBUG    	top
ipa         : DEBUG    ipaallowedtarget: cn=ipa-ldap-delegation-targets,cn=s4u2proxy,cn=etc,dc=testrelm,dc=com
ipa         : DEBUG    memberPrincipal: 
ipa         : DEBUG    	HTTP/ibm-ls22-05.testrelm.com
ipa         : DEBUG    cn: ipa-http-delegation
ipa         : ERROR    Add failure 'NoneType' object is not callable
ipa         : INFO     New entry: cn=ipa-ldap-delegation-targets,cn=s4u2proxy,cn=etc,dc=testrelm,dc=com
ipa         : DEBUG    ---------------------------------------------
ipa         : DEBUG    dn: cn=ipa-ldap-delegation-targets,cn=s4u2proxy,cn=etc,dc=testrelm,dc=com
ipa         : DEBUG    objectclass: 
ipa         : DEBUG    	groupOfPrincipals
ipa         : DEBUG    	top
ipa         : DEBUG    memberprincipal: ldap/ibm-ls22-05.testrelm.com
ipa         : DEBUG    cn: ipa-ldap-delegation-targets
ipa         : DEBUG    add: 'ldap/ibm-ls22-05.testrelm.com' to memberPrincipal, current value ['ldap/ibm-ls22-05.testrelm.com']
ipa         : DEBUG    add: updated value [u'ldap/ibm-ls22-05.testrelm.com']
ipa         : DEBUG    ---------------------------------------------
ipa         : DEBUG    dn: cn=ipa-ldap-delegation-targets,cn=s4u2proxy,cn=etc,dc=testrelm,dc=com
ipa         : DEBUG    objectclass: 
ipa         : DEBUG    	groupOfPrincipals
ipa         : DEBUG    	top
ipa         : DEBUG    memberPrincipal: 
ipa         : DEBUG    	ldap/ibm-ls22-05.testrelm.com
ipa         : DEBUG    cn: ipa-ldap-delegation-targets
ipa         : DEBUG    ---------------------------------------------
ipa         : DEBUG    Final value
ipa         : DEBUG    dn: cn=ipa-ldap-delegation-targets,cn=s4u2proxy,cn=etc,dc=testrelm,dc=com
ipa         : DEBUG    objectclass: 
ipa         : DEBUG    	groupOfPrincipals
ipa         : DEBUG    	top
ipa         : DEBUG    memberPrincipal: 
ipa         : DEBUG    	ldap/ibm-ls22-05.testrelm.com
ipa         : DEBUG    cn: ipa-ldap-delegation-targets
ipa         : ERROR    Add failure 'NoneType' object is not callable
ipa         : INFO     Update complete


From /var/log/dirsrv/slapd-TESTRELM-COM/errors:

[13/Mar/2012:19:17:15 -0400] - Entry "cn=ipa-http-delegation,cn=s4u2proxy,cn=etc,dc=testrelm,dc=com" has unknown object class "ipaKrb5DelegationACL"
[13/Mar/2012:19:17:15 -0400] - Entry "cn=ipa-http-delegation,cn=s4u2proxy,cn=etc,dc=testrelm,dc=com" has unknown object class "groupOfPrincipals"
[13/Mar/2012:19:17:15 -0400] - Entry "cn=ipa-ldap-delegation-targets,cn=s4u2proxy,cn=etc,dc=testrelm,dc=com" has unknown object class "groupOfPrincipals"


From /var/log/dirsrv/slapd-TESTRELM-COM/access:

[13/Mar/2012:19:17:15 -0400] conn=15 op=639 SRCH base="idnsName=_ldap._tcp,idnsname=testrelm.com,cn=dns,dc=testrelm,dc=com" scope=0 filter="(objectClass=idnsRecord)" attrs=ALL
[13/Mar/2012:19:17:15 -0400] conn=15 op=639 RESULT err=0 tag=101 nentries=1 etime=0
[13/Mar/2012:19:17:15 -0400] conn=15 op=640 SRCH base="idnsName=ibm-ls22-05,idnsname=testrelm.com,cn=dns,dc=testrelm,dc=com" scope=0 filter="(objectClass=idnsRecord)" attrs=ALL
[13/Mar/2012:19:17:15 -0400] conn=15 op=640 RESULT err=0 tag=101 nentries=1 etime=0
[13/Mar/2012:19:17:15 -0400] conn=15 op=641 SRCH base="idnsname=testrelm.com,cn=dns,dc=testrelm,dc=com" scope=0 filter="(objectClass=idnsRecord)" attrs=ALL
[13/Mar/2012:19:17:15 -0400] conn=15 op=641 RESULT err=0 tag=101 nentries=1 etime=0
[13/Mar/2012:19:17:15 -0400] conn=31 fd=68 slot=68 connection from local to /var/run/slapd-TESTRELM-COM.socket
[13/Mar/2012:19:17:15 -0400] conn=31 AUTOBIND dn="cn=Directory Manager"
[13/Mar/2012:19:17:15 -0400] conn=31 op=0 BIND dn="cn=Directory Manager" method=sasl version=3 mech=EXTERNAL
[13/Mar/2012:19:17:15 -0400] conn=31 op=0 RESULT err=0 tag=97 nentries=0 etime=0 dn="cn=Directory Manager"
[13/Mar/2012:19:17:15 -0400] conn=31 op=1 SRCH base="cn=config,cn=ldbm database,cn=plugins,cn=config" scope=0 filter="(objectClass=*)" attrs="nsslapd-directory"
[13/Mar/2012:19:17:15 -0400] conn=31 op=1 RESULT err=0 tag=101 nentries=1 etime=0
[13/Mar/2012:19:17:15 -0400] conn=31 op=2 UNBIND
[13/Mar/2012:19:17:15 -0400] conn=31 op=2 fd=68 closed - U1
[13/Mar/2012:19:17:15 -0400] conn=32 fd=76 slot=76 connection from local to /var/run/slapd-TESTRELM-COM.socket
[13/Mar/2012:19:17:15 -0400] conn=32 AUTOBIND dn="cn=Directory Manager"
[13/Mar/2012:19:17:15 -0400] conn=32 op=0 BIND dn="cn=Directory Manager" method=sasl version=3 mech=EXTERNAL
[13/Mar/2012:19:17:15 -0400] conn=32 op=0 RESULT err=0 tag=97 nentries=0 etime=0 dn="cn=Directory Manager"
[13/Mar/2012:19:17:15 -0400] conn=32 op=1 SRCH base="cn=config,cn=ldbm database,cn=plugins,cn=config" scope=0 filter="(objectClass=*)" attrs="nsslapd-directory"
[13/Mar/2012:19:17:15 -0400] conn=32 op=1 RESULT err=0 tag=101 nentries=1 etime=0
[13/Mar/2012:19:17:15 -0400] conn=32 op=2 SRCH base="cn=s4u2proxy,cn=etc,dc=testrelm,dc=com" scope=0 filter="(objectClass=*)" attrs="* aci attributeTypes objectClasses aci"
[13/Mar/2012:19:17:15 -0400] conn=32 op=2 RESULT err=0 tag=101 nentries=1 etime=0
[13/Mar/2012:19:17:15 -0400] conn=32 op=3 SRCH base="cn=ipa-http-delegation,cn=s4u2proxy,cn=etc,dc=testrelm,dc=com" scope=0 filter="(objectClass=*)" attrs="* aci attributeTypes objectClasses aci"
[13/Mar/2012:19:17:15 -0400] conn=32 op=3 RESULT err=32 tag=101 nentries=0 etime=0
[13/Mar/2012:19:17:15 -0400] conn=32 op=4 ADD dn="cn=ipa-http-delegation,cn=s4u2proxy,cn=etc,dc=testrelm,dc=com"
[13/Mar/2012:19:17:15 -0400] conn=32 op=4 RESULT err=65 tag=105 nentries=0 etime=0
[13/Mar/2012:19:17:15 -0400] conn=32 op=5 SRCH base="cn=ipa-ldap-delegation-targets,cn=s4u2proxy,cn=etc,dc=testrelm,dc=com" scope=0 filter="(objectClass=*)" attrs="* aci attributeTypes objectClasses aci"
[13/Mar/2012:19:17:15 -0400] conn=32 op=5 RESULT err=32 tag=101 nentries=0 etime=0
[13/Mar/2012:19:17:15 -0400] conn=32 op=6 ADD dn="cn=ipa-ldap-delegation-targets,cn=s4u2proxy,cn=etc,dc=testrelm,dc=com"
[13/Mar/2012:19:17:15 -0400] conn=32 op=6 RESULT err=65 tag=105 nentries=0 etime=0
[13/Mar/2012:19:17:15 -0400] conn=32 op=7 UNBIND
[13/Mar/2012:19:17:15 -0400] conn=32 op=7 fd=76 closed - U1
[13/Mar/2012:19:17:32 -0400] conn=15 op=643 SRCH base="cn=dns,dc=testrelm,dc=com" scope=2 filter="(&(objectClass=idnsZone)(idnsZoneActive=TRUE))" attrs="idnsName idnsUpdatePolicy idnsallowquery idnsallowtransfer"
[13/Mar/2012:19:17:32 -0400] conn=15 op=643 RESULT err=0 tag=101 nentries=4 etime=0
[13/Mar/2012:19:18:02 -0400] conn=15 op=645 SRCH base="cn=dns,dc=testrelm,dc=com" scope=2 filter="(&(objectClass=idnsZone)(idnsZoneActive=TRUE))" attrs="idnsName idnsUpdatePolicy idnsallowquery idnsallowtransfer"
[13/Mar/2012:19:18:02 -0400] conn=15 op=645 RESULT err=0 tag=101 nentries=4 etime=0
[13/Mar/2012:19:18:32 -0400] conn=15 op=647 SRCH base="cn=dns,dc=testrelm,dc=com" scope=2 filter="(&(objectClass=idnsZone)(idnsZoneActive=TRUE))" attrs="idnsName idnsUpdatePolicy idnsallowquery idnsallowtransfer"
[13/Mar/2012:19:18:32 -0400] conn=15 op=647 RESULT err=0 tag=101 nentries=4 etime=0

Comment 4 Rob Crittenden 2012-03-14 02:13:31 UTC

This is enough information. It is missing schema for some reason.

Comment 5 Rob Crittenden 2012-03-14 02:15:47 UTC

Upstream ticket:
https://fedorahosted.org/freeipa/ticket/2530

Comment 6 Rob Crittenden 2012-03-14 02:30:35 UTC

Can you compress and attach /var/log/ipaupgrade.log?

Also, can you provide the output from the yum upgrade ipa*? What packages are updated (particularly interested in starting and ending versions of 389-ds-base and krb5-*)? I'm unable to reproduce but I'm starting out with an otherwise updated system.

Comment 7 Scott Poore 2012-03-14 12:56:17 UTC

Created attachment 569976 [details]
ipaupgrade.log

Comment 8 Scott Poore 2012-03-14 12:56:59 UTC

Created attachment 569977 [details]
yum.log for more complete listing of what was updated

Comment 9 Scott Poore 2012-03-14 12:57:44 UTC

Created attachment 569978 [details]
partial output of yum update ipa

Comment 10 Scott Poore 2012-03-14 13:04:56 UTC

I don't have all of the output from the yum update ipa* command because my 10000 line scroll buffer just wasn't enough.   I attached what I did have though.  And if needed, I can reproduce this on another server.  


I do see some errors in the ipaupgrade.log file though about starting dirsrv.  

This upgrade was attempted with everything running.  Could that be causing that issue?

Comment 11 Rob Crittenden 2012-03-14 13:37:34 UTC

The upgrade failed because the IPA dirsrv instance would not restart.

[13/Mar/2012:16:19:43 -0400] createprlistensockets - PR_Bind() on localhost file /var/run/slapd-TESTRELM-COM.socket failed: Netscape Portable Runtime error -5982 (Local Network address is in use.)

I'm not sure what would cause that to be considered in use since it apparently successfully shut down in the previous step.

389-ds-base is being upgraded in the same rpm transaction, I wonder if that is related.

Comment 12 Scott Poore 2012-03-14 14:12:49 UTC

Seems like I've seen errors or warnings (at least) for that socket file.  Pretty sure I had to delete it to be able to cleanly restart.  Maybe the stop didn't clean up the socket file and that caused the failure to start?

I'll look at that on a test box I'm setting up for this.

Comment 13 Rich Megginson 2012-03-14 15:37:18 UTC

(In reply to comment #11)
> The upgrade failed because the IPA dirsrv instance would not restart.
> 
> [13/Mar/2012:16:19:43 -0400] createprlistensockets - PR_Bind() on localhost
> file /var/run/slapd-TESTRELM-COM.socket failed: Netscape Portable Runtime error
> -5982 (Local Network address is in use.)
> 
> I'm not sure what would cause that to be considered in use since it apparently
> successfully shut down in the previous step.
> 
> 389-ds-base is being upgraded in the same rpm transaction, I wonder if that is
> related.

What does the script use to shutdown the directory server?  Is it perhaps not waiting long enough for the directory server to be shutdown before it restarts it?

Comment 14 Rob Crittenden 2012-03-14 15:41:03 UTC

It uses /sbin/service dirsrv stop.

Comment 15 Rich Megginson 2012-03-14 15:50:11 UTC

(In reply to comment #14)
> It uses /sbin/service dirsrv stop.

So perhaps when stop returns, it is not really stopped?

Where is this code in ipa?

Comment 16 Scott Poore 2012-03-14 17:33:48 UTC

On a test server, I was able to see dirsrv not starting after upgrade.  This is what I saw in that test when (and after) I was trying to get dirsrv to start

1. When I removed the /var/run/slapd-TESTRELM-COM.socket file, it could start. 
2. If I moved the good socket file out of the way and copied the old one back, it failed to start.
3. If I moved the bad socket file out of the way and moved the good one back, it would start.
4. Moving bad one back again reproduced the failure to start again.


I'm still testing some other options but, thought I'd share that info in case it sparks something.

Comment 17 Rich Megginson 2012-03-14 18:39:09 UTC

(In reply to comment #16)
> On a test server, I was able to see dirsrv not starting after upgrade.  This is
> what I saw in that test when (and after) I was trying to get dirsrv to start
> 
> 1. When I removed the /var/run/slapd-TESTRELM-COM.socket file, it could start. 
> 2. If I moved the good socket file out of the way and copied the old one back,
> it failed to start.
> 3. If I moved the bad socket file out of the way and moved the good one back,
> it would start.
> 4. Moving bad one back again reproduced the failure to start again.
> 
> 
> I'm still testing some other options but, thought I'd share that info in case
> it sparks something.

I'm not sure what you mean by "good socket file" and "bad socket file"

Comment 18 Scott Poore 2012-03-14 18:47:49 UTC

good = one that dirsrv would start with
bad = one that dirsrv would not start with

I mv'd them out of the way and back into place for that testing...that was a guess anyway and wasn't sure what to expect.

Also,

    Trying:

    1. <known working 2.1.3 install with some test data>
    2. add 6.3 test repos
    3. yum update '389-ds-*'
    4. service dirsrv restart
    5. service dirsrv stop
    6. rm /var/run/slapd-TESTRELM-COM.socket
    7. service dirsrv start
    8. ipactl restart
    9. yum update 'ipa*'

    no dice.

    [root@spoore-dvm1 ipa-upgrade]# ipa user-find
    ipa: ERROR: Kerberos error: ('Unspecified GSS failure.  Minor code may provide
    more information', 851968)/("Cannot contact any KDC for realm 'TESTRELM.COM'",
    -1765328228)
    [root@spoore-dvm1 ipa-upgrade]# ipactl status
    Directory Service: STOPPED
    Unknown error when retrieving list of services from LDAP: [Errno 111]
    Connection refused
    [root@spoore-dvm1 ipa-upgrade]# ipactl restart
    Restarting Directory Service
    Shutting down dirsrv: 
        PKI-IPA...                                             [  OK  ]
        TESTRELM-COM... server already stopped                 [FAILED]
      *** Error: 1 instance(s) unsuccessfully stopped          [FAILED]
    Starting dirsrv: 
        PKI-IPA...                                             [  OK  ]
        TESTRELM-COM...[14/Mar/2012:13:41:30 -0500] createprlistensockets -
    PR_Bind() on localhost file /var/run/slapd-TESTRELM-COM.socket failed: Netscape
    Portable Runtime error -5982 (Local Network address is in use.)
                                                               [FAILED]
      *** Warning: 1 instance(s) failed to start
    Failed to read data from Directory Service: Unknown error when retrieving list
    of services from LDAP: [Errno 111] Connection refused
    Shutting down
    Shutting down dirsrv: 
        PKI-IPA...                                             [  OK  ]
        TESTRELM-COM... server already stopped                 [FAILED]
      *** Error: 1 instance(s) unsuccessfully stopped          [FAILED]
    [root@spoore-dvm1 ipa-upgrade]# rm /var/run/slapd-TESTRELM-COM.socket 
    rm: remove socket `/var/run/slapd-TESTRELM-COM.socket'? y
    [root@spoore-dvm1 ipa-upgrade]# ipactl start
    Starting Directory Service
    Starting dirsrv: 
        PKI-IPA...                                             [  OK  ]
        TESTRELM-COM...                                        [  OK  ]
    Starting KDC Service
    Starting Kerberos 5 KDC:                                   [  OK  ]
    Starting KPASSWD Service
    Starting Kerberos 5 Admin Server:                          [  OK  ]
    Starting DNS Service
    Starting named: named: already running                     [  OK  ]
    Starting MEMCACHE Service
    Starting HTTP Service
    Starting httpd: 
    Starting CA Service
    Starting pki-ca:                                           [  OK  ]
    [root@spoore-dvm1 ipa-upgrade]# ipactl restart
    Restarting Directory Service
    Shutting down dirsrv: 
        PKI-IPA...                                             [  OK  ]
        TESTRELM-COM...                                        [  OK  ]
    Starting dirsrv: 
        PKI-IPA...                                             [  OK  ]
        TESTRELM-COM...                                        [  OK  ]
    Restarting KDC Service
    Stopping Kerberos 5 KDC:                                   [  OK  ]
    Starting Kerberos 5 KDC:                                   [  OK  ]
    Restarting KPASSWD Service
    Stopping Kerberos 5 Admin Server:                          [  OK  ]
    Starting Kerberos 5 Admin Server:                          [  OK  ]
    Restarting DNS Service
    Stopping named: .                                          [  OK  ]
    Starting named:                                            [  OK  ]
    Restarting MEMCACHE Service
    Stopping ipa_memcached:                                    [  OK  ]
    Starting ipa_memcached:                                    [  OK  ]
    Restarting HTTP Service
    Stopping httpd:                                            [  OK  ]
    Starting httpd: [Wed Mar 14 13:42:09 2012] [warn] worker ajp://localhost:9447/
    already used by another worker
    [Wed Mar 14 13:42:09 2012] [warn] worker ajp://localhost:9447/ already used by
    another worker
                                                               [  OK  ]
    Restarting CA Service
    Stopping pki-ca:                                           [  OK  ]
    Starting pki-ca:                                           [  OK  ]
    [root@spoore-dvm1 ipa-upgrade]# ipa user-find
    ipa: ERROR: Kerberos error: ('Unspecified GSS failure.  Minor code may provide
    more information', 851968)/('Ticket not yet valid', -1765328351)
    [root@spoore-dvm1 ipa-upgrade]# ipactl status
    Directory Service: RUNNING
    KDC Service: RUNNING
    KPASSWD Service: RUNNING
    DNS Service: RUNNING
    MEMCACHE Service: RUNNING
    HTTP Service: RUNNING
    CA Service: RUNNING


    And I see the same type of socket file errors in the ipaupgrade.log there as
    well:

    2012-03-14T18:39:42Z DEBUG stdout=Starting dirsrv: 
        PKI-IPA...[  OK  ]
        TESTRELM-COM...[FAILED]
      *** Warning: 1 instance(s) failed to start

    2012-03-14T18:39:42Z DEBUG stderr=[14/Mar/2012:13:39:41 -0500] - Information:
    Non-Secure Port Disabled
    [14/Mar/2012:13:39:41 -0500] createprlistensockets - PR_Bind() on localhost
    file /var/run/slapd-TESTRELM-COM.socket
     failed: Netscape Portable Runtime error -5982 (Local Network address is in
    use.)

    2012-03-14T18:39:42Z DEBUG   duration: 1 seconds
    2012-03-14T18:39:42Z DEBUG   [5/8]: upgrading server
    2012-03-14T18:39:52Z ERROR Upgrade failed with Unable to connect to LDAP server
    ldapi://%2fvar%2frun%2fslapd-TESTRE
    LM-COM.socket
    2012-03-14T18:39:52Z DEBUG Traceback (most recent call last):
      File "/usr/lib/python2.6/site-packages/ipaserver/install/upgradeinstance.py",
    line 104, in __upgrade
        ld = ldapupdate.LDAPUpdate(dm_password='', ldapi=True,
    live_run=self.live_run, plugins=True)
      File "/usr/lib/python2.6/site-packages/ipaserver/install/ldapupdate.py", line
    133, in __init__
        raise RuntimeError("Unable to connect to LDAP server %s" % fqdn)
    RuntimeError: Unable to connect to LDAP server
    ldapi://%2fvar%2frun%2fslapd-TESTRELM-COM.socket

Comment 19 Rob Crittenden 2012-03-14 19:01:39 UTC

richm, the code is a bit abstracted out but the actual execution is done in ipapython/platform/redhat.py::RedHatService::stop()

This just forks out /sbin/service dirsrv stop and returns.

Comment 20 Rich Megginson 2012-03-14 19:18:08 UTC

The socket files are labeled under selinux policy.  In general, you cannot use the mv command because it doesn't label the files properly.  You can if you know what you're doing (know the selinux commands to label the file properly after the mv).  Removing the socket file and letting the directory server create it should work and should label the file properly.

Do you have any selinux AVC messages?

Comment 21 Scott Poore 2012-03-14 21:24:08 UTC

I thought mv handled the selinux context for the files.   Is it not reliable or you're saying it never handles the labels?

And I do actually see some AVC messages here that match the times of some of the errors from my last comment.

# ausearch -m AVC -ts 03/14/2012 13:30
----
time->Wed Mar 14 13:39:41 2012
type=SYSCALL msg=audit(1331750381.939:38509): arch=c000003e syscall=87 success=no exit=-13 a0=14a8aa2 a1=148bde2 a2=45 a3=7fff9bfb31f0 items=0 ppid=4092 pid=4093 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=pts0 ses=1 comm="ns-slapd" exe="/usr/sbin/ns-slapd" subj=unconfined_u:system_r:dirsrv_t:s0 key=(null)
type=AVC msg=audit(1331750381.939:38509): avc:  denied  { unlink } for  pid=4093 comm="ns-slapd" name="slapd-TESTRELM-COM.socket" dev=dm-1 ino=47596 scontext=unconfined_u:system_r:dirsrv_t:s0 tcontext=unconfined_u:object_r:var_run_t:s0 tclass=sock_file

----
time->Wed Mar 14 13:39:54 2012
type=SYSCALL msg=audit(1331750394.598:38510): arch=c000003e syscall=87 success=no exit=-13 a0=163fc02 a1=1622e52 a2=45 a3=7fff948f8b50 items=0 ppid=4221 pid=4222 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=pts0 ses=1 comm="ns-slapd" exe="/usr/sbin/ns-slapd" subj=unconfined_u:system_r:dirsrv_t:s0 key=(null)
type=AVC msg=audit(1331750394.598:38510): avc:  denied  { unlink } for  pid=4222 comm="ns-slapd" name="slapd-TESTRELM-COM.socket" dev=dm-1 ino=47596 scontext=unconfined_u:system_r:dirsrv_t:s0 tcontext=unconfined_u:object_r:var_run_t:s0 tclass=sock_file

----
time->Wed Mar 14 13:41:30 2012
type=SYSCALL msg=audit(1331750490.937:38518): arch=c000003e syscall=87 success=no exit=-13 a0=215ec02 a1=2141e52 a2=45 a3=7fff4cf89600 items=0 ppid=4483 pid=4484 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=pts0 ses=1 comm="ns-slapd" exe="/usr/sbin/ns-slapd" subj=unconfined_u:system_r:dirsrv_t:s0 key=(null)
type=AVC msg=audit(1331750490.937:38518): avc:  denied  { unlink } for  pid=4484 comm="ns-slapd" name="slapd-TESTRELM-COM.socket" dev=dm-1 ino=47596 scontext=unconfined_u:system_r:dirsrv_t:s0 tcontext=unconfined_u:object_r:var_run_t:s0 tclass=sock_file

Comment 22 Rich Megginson 2012-03-14 22:12:33 UTC

(In reply to comment #21)
> I thought mv handled the selinux context for the files.   Is it not reliable or
> you're saying it never handles the labels?

I thought mv did not relabel the files.  Nathan, can you clarify?

> 
> And I do actually see some AVC messages here that match the times of some of
> the errors from my last comment.

This sounds vaguely familiar - what version of selinux-policy do you have?

> 
> # ausearch -m AVC -ts 03/14/2012 13:30
> ----
> time->Wed Mar 14 13:39:41 2012
> type=SYSCALL msg=audit(1331750381.939:38509): arch=c000003e syscall=87
> success=no exit=-13 a0=14a8aa2 a1=148bde2 a2=45 a3=7fff9bfb31f0 items=0
> ppid=4092 pid=4093 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0
> fsgid=0 tty=pts0 ses=1 comm="ns-slapd" exe="/usr/sbin/ns-slapd"
> subj=unconfined_u:system_r:dirsrv_t:s0 key=(null)
> type=AVC msg=audit(1331750381.939:38509): avc:  denied  { unlink } for 
> pid=4093 comm="ns-slapd" name="slapd-TESTRELM-COM.socket" dev=dm-1 ino=47596
> scontext=unconfined_u:system_r:dirsrv_t:s0
> tcontext=unconfined_u:object_r:var_run_t:s0 tclass=sock_file
> 
> ----
> time->Wed Mar 14 13:39:54 2012
> type=SYSCALL msg=audit(1331750394.598:38510): arch=c000003e syscall=87
> success=no exit=-13 a0=163fc02 a1=1622e52 a2=45 a3=7fff948f8b50 items=0
> ppid=4221 pid=4222 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0
> fsgid=0 tty=pts0 ses=1 comm="ns-slapd" exe="/usr/sbin/ns-slapd"
> subj=unconfined_u:system_r:dirsrv_t:s0 key=(null)
> type=AVC msg=audit(1331750394.598:38510): avc:  denied  { unlink } for 
> pid=4222 comm="ns-slapd" name="slapd-TESTRELM-COM.socket" dev=dm-1 ino=47596
> scontext=unconfined_u:system_r:dirsrv_t:s0
> tcontext=unconfined_u:object_r:var_run_t:s0 tclass=sock_file
> 
> ----
> time->Wed Mar 14 13:41:30 2012
> type=SYSCALL msg=audit(1331750490.937:38518): arch=c000003e syscall=87
> success=no exit=-13 a0=215ec02 a1=2141e52 a2=45 a3=7fff4cf89600 items=0
> ppid=4483 pid=4484 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0
> fsgid=0 tty=pts0 ses=1 comm="ns-slapd" exe="/usr/sbin/ns-slapd"
> subj=unconfined_u:system_r:dirsrv_t:s0 key=(null)
> type=AVC msg=audit(1331750490.937:38518): avc:  denied  { unlink } for 
> pid=4484 comm="ns-slapd" name="slapd-TESTRELM-COM.socket" dev=dm-1 ino=47596
> scontext=unconfined_u:system_r:dirsrv_t:s0
> tcontext=unconfined_u:object_r:var_run_t:s0 tclass=sock_file

Comment 23 Scott Poore 2012-03-14 22:48:52 UTC

This is the version of selinux-policy installed

selinux-policy-3.7.19-138.el6.noarch

Comment 24 Nathan Kinder 2012-03-14 22:49:37 UTC

(In reply to comment #22)
> (In reply to comment #21)
> > I thought mv handled the selinux context for the files.   Is it not reliable or
> > you're saying it never handles the labels?
> 
> I thought mv did not relabel the files.  Nathan, can you clarify?

Files are labelled when they are created.  When you create a file, it is labelled based off of the location is was created in.  When you move it, it's original label is retained, even if the fcontext rule for the destination says to use a different label.  Copying a file will cause the new copy to be labelled appropriately for it's destination.

> 
> > 
> > And I do actually see some AVC messages here that match the times of some of
> > the errors from my last comment.
> 
> This sounds vaguely familiar - what version of selinux-policy do you have?
> 
> > 
> > # ausearch -m AVC -ts 03/14/2012 13:30
> > ----
> > time->Wed Mar 14 13:39:41 2012
> > type=SYSCALL msg=audit(1331750381.939:38509): arch=c000003e syscall=87
> > success=no exit=-13 a0=14a8aa2 a1=148bde2 a2=45 a3=7fff9bfb31f0 items=0
> > ppid=4092 pid=4093 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0
> > fsgid=0 tty=pts0 ses=1 comm="ns-slapd" exe="/usr/sbin/ns-slapd"
> > subj=unconfined_u:system_r:dirsrv_t:s0 key=(null)
> > type=AVC msg=audit(1331750381.939:38509): avc:  denied  { unlink } for 
> > pid=4093 comm="ns-slapd" name="slapd-TESTRELM-COM.socket" dev=dm-1 ino=47596
> > scontext=unconfined_u:system_r:dirsrv_t:s0
> > tcontext=unconfined_u:object_r:var_run_t:s0 tclass=sock_file
> > 
> > ----
> > time->Wed Mar 14 13:39:54 2012
> > type=SYSCALL msg=audit(1331750394.598:38510): arch=c000003e syscall=87
> > success=no exit=-13 a0=163fc02 a1=1622e52 a2=45 a3=7fff948f8b50 items=0
> > ppid=4221 pid=4222 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0
> > fsgid=0 tty=pts0 ses=1 comm="ns-slapd" exe="/usr/sbin/ns-slapd"
> > subj=unconfined_u:system_r:dirsrv_t:s0 key=(null)
> > type=AVC msg=audit(1331750394.598:38510): avc:  denied  { unlink } for 
> > pid=4222 comm="ns-slapd" name="slapd-TESTRELM-COM.socket" dev=dm-1 ino=47596
> > scontext=unconfined_u:system_r:dirsrv_t:s0
> > tcontext=unconfined_u:object_r:var_run_t:s0 tclass=sock_file
> > 
> > ----
> > time->Wed Mar 14 13:41:30 2012
> > type=SYSCALL msg=audit(1331750490.937:38518): arch=c000003e syscall=87
> > success=no exit=-13 a0=215ec02 a1=2141e52 a2=45 a3=7fff4cf89600 items=0
> > ppid=4483 pid=4484 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0
> > fsgid=0 tty=pts0 ses=1 comm="ns-slapd" exe="/usr/sbin/ns-slapd"
> > subj=unconfined_u:system_r:dirsrv_t:s0 key=(null)
> > type=AVC msg=audit(1331750490.937:38518): avc:  denied  { unlink } for 
> > pid=4484 comm="ns-slapd" name="slapd-TESTRELM-COM.socket" dev=dm-1 ino=47596
> > scontext=unconfined_u:system_r:dirsrv_t:s0
> > tcontext=unconfined_u:object_r:var_run_t:s0 tclass=sock_file

I think the ldapi socket file is labelled incorrectly.  This does sound familiar.  Please try running the following command:

    semanage fcontext -l | grep /var/run/slapd

Comment 25 Nathan Kinder 2012-03-14 23:03:07 UTC

I believe that this is a duplicate of bug 799102

Comment 26 Scott Poore 2012-03-15 03:24:40 UTC

Looks very similar to 799102.  

# semanage fcontext -l | grep /var/run/slapd
/var/run/slapd\.args                               regular file       system_u:object_r:slapd_var_run_t:s0 
/var/run/slapd\.pid                                regular file       system_u:object_r:slapd_var_run_t:s0 

I don't see anything for socket files but, it is getting labelled as dirsrv_var_run_t when it's created by a starting the dirsrv service.

So, am I reading the AVC correctly?

ns-slapd is trying to run an unlink syscall as dirsrv_t.  This fails because the syscall is against the directory (not the file) so it's target context is var_run_t instead of dirsrv_t or dirsrv_var_run_t.

Is that right?   

So this is killing my upgrades when the service is restarted at some point because ns-slapd can't delete the file?   That causes the failure to restart at the point during the upgrade when it's supposed to update ldap and the delegation gets lost?

Is that close?

Comment 27 Nathan Kinder 2012-03-15 14:45:59 UTC

(In reply to comment #26)
> Looks very similar to 799102.  
> 
> # semanage fcontext -l | grep /var/run/slapd
> /var/run/slapd\.args                               regular file      
> system_u:object_r:slapd_var_run_t:s0 
> /var/run/slapd\.pid                                regular file      
> system_u:object_r:slapd_var_run_t:s0 
> 
> I don't see anything for socket files but, it is getting labelled as
> dirsrv_var_run_t when it's created by a starting the dirsrv service.
> 
> So, am I reading the AVC correctly?
> 
> ns-slapd is trying to run an unlink syscall as dirsrv_t.  This fails because
> the syscall is against the directory (not the file) so it's target context is
> var_run_t instead of dirsrv_t or dirsrv_var_run_t.
> 
> Is that right?   

Close.  The ns-slapd program (running as dirsrv_t) is attempting to unlink the slapd-TESTRELM-COM.socket file (labelled as var_run_t).  A program running as dirsrv_t is not allowed to do this.  We expect the socket file to be labelled as dirsrv_var_run_t, which we have permission to unlink.

> 
> So this is killing my upgrades when the service is restarted at some point
> because ns-slapd can't delete the file?   That causes the failure to restart at
> the point during the upgrade when it's supposed to update ldap and the
> delegation gets lost?
> 
> Is that close?

Yes.  If the socket file is around at start up, we try to remove it.  The SELinux policy is preventing us from removing it, so restart fails.

What I believe is happening is that the socket file is being relabelled by restorecon during upgrade.  The fcontext rules in the policy don't have anything to properly label the ldapi socket file, so it uses the label from it's parent directory (/var/run), which is var_run_t.  The policy has some special transition rules in place which causes the socket file to be created with the dirsrv_var_run_t context only when it is created by a dirsrv_t program.

You would be able to easily simulate the problem by running the following command when your ns-slapd is up and running properly:

  restorecon -v /var/run/slapd-TESTRELM-COM.socket

This will cause the label to change to var_run_t, which would not allow ns-slapd to use the file anymore.  A policy rule needs to be put in place to prevent restorecon from changing the label.

Comment 28 Scott Poore 2012-03-15 16:37:02 UTC

(In reply to comment #27)
> (In reply to comment #26)
> > Looks very similar to 799102.  
> > 
> > # semanage fcontext -l | grep /var/run/slapd
> > /var/run/slapd\.args                               regular file      
> > system_u:object_r:slapd_var_run_t:s0 
> > /var/run/slapd\.pid                                regular file      
> > system_u:object_r:slapd_var_run_t:s0 
> > 
> > I don't see anything for socket files but, it is getting labelled as
> > dirsrv_var_run_t when it's created by a starting the dirsrv service.
> > 
> > So, am I reading the AVC correctly?
> > 
> > ns-slapd is trying to run an unlink syscall as dirsrv_t.  This fails because
> > the syscall is against the directory (not the file) so it's target context is
> > var_run_t instead of dirsrv_t or dirsrv_var_run_t.
> > 
> > Is that right?   
> 
> Close.  The ns-slapd program (running as dirsrv_t) is attempting to unlink the
> slapd-TESTRELM-COM.socket file (labelled as var_run_t).  A program running as
> dirsrv_t is not allowed to do this.  We expect the socket file to be labelled
> as dirsrv_var_run_t, which we have permission to unlink.
> 
> > 
> > So this is killing my upgrades when the service is restarted at some point
> > because ns-slapd can't delete the file?   That causes the failure to restart at
> > the point during the upgrade when it's supposed to update ldap and the
> > delegation gets lost?
> > 
> > Is that close?
> 
> Yes.  If the socket file is around at start up, we try to remove it.  The
> SELinux policy is preventing us from removing it, so restart fails.
> 
> What I believe is happening is that the socket file is being relabelled by
> restorecon during upgrade.  The fcontext rules in the policy don't have
> anything to properly label the ldapi socket file, so it uses the label from
> it's parent directory (/var/run), which is var_run_t.  The policy has some
> special transition rules in place which causes the socket file to be created
> with the dirsrv_var_run_t context only when it is created by a dirsrv_t
> program.
> 

Ok, that makes much more sense now.  I was getting confused as to why it was ever showing the error for var_run_t.   But, if it's restoring context during upgrade, that makes sense now considering no policy in place for socket files.


> You would be able to easily simulate the problem by running the following
> command when your ns-slapd is up and running properly:
> 
>   restorecon -v /var/run/slapd-TESTRELM-COM.socket
> 
> This will cause the label to change to var_run_t, which would not allow
> ns-slapd to use the file anymore.  A policy rule needs to be put in place to
> prevent restorecon from changing the label.

Yes, I did see that yesterday (although with rm, then touch).  

So, that will be addressed in bug 799102 right?

Thanks

Comment 29 Nathan Kinder 2012-03-21 16:40:29 UTC

Bug 799102 has been addressed in selinux-policy-3.7.19-142.el6.  Could you please test with that package to confirm that it resolves this issue?  If so, you can close this bug.

Comment 30 Scott Poore 2012-03-21 19:48:47 UTC

Before I tried an upgrade of ipa, I ran 'ipactl restart' and had issues:

# rpm -q selinux-policy
selinux-policy-3.7.19-142.el6.noarch

# ipactl restart
Restarting Directory Service
Shutting down dirsrv: 
    PKI-IPA...[  OK  ]
    TESTRELM-COM...[  OK  ]
Starting dirsrv: 
    PKI-IPA...[  OK  ]
    TESTRELM-COM...[21/Mar/2012:15:32:03 -0400] createprlistensockets - PR_Bind() on localhost file /var/run/slapd-TESTRELM-COM.socket failed: Netscape Portable Runtime error -5982 (Local Network address is in use.)
[FAILED]
  *** Warning: 1 instance(s) failed to start
Failed to read data from Directory Service: Failed to get list of services to probe status:
Directory Server is stopped
Shutting down
Shutting down dirsrv: 
    PKI-IPA...[  OK  ]
    TESTRELM-COM... server already stopped[FAILED]
  *** Error: 1 instance(s) unsuccessfully stopped[FAILED]

# ausearch -m AVC
----
time->Wed Mar 21 15:32:03 2012
type=SYSCALL msg=audit(1332358323.624:202): arch=c000003e syscall=87 success=no exit=-13 a0=f68fd2 a1=f682f2 a2=45 a3=6b636f732e4d4f43 items=0 ppid=14688 pid=14689 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=pts0 ses=10 comm="ns-slapd" exe="/usr/sbin/ns-slapd" subj=unconfined_u:system_r:dirsrv_t:s0 key=(null)
type=AVC msg=audit(1332358323.624:202): avc:  denied  { unlink } for  pid=14689 comm="ns-slapd" name="slapd-TESTRELM-COM.socket" dev=dm-0 ino=1966792 scontext=unconfined_u:system_r:dirsrv_t:s0 tcontext=unconfined_u:object_r:slapd_var_run_t:s0 tclass=sock_file

# semanage fcontext -l | grep /var/run/slapd
/var/run/slapd.*                                   socket             system_u:object_r:slapd_var_run_t:s0 
/var/run/slapd\.args                               regular file       system_u:object_r:slapd_var_run_t:s0 
/var/run/slapd\.pid                                regular file       system_u:object_r:slapd_var_run_t:s0

Comment 31 Scott Poore 2012-03-22 18:52:19 UTC

So, was that expected?  I'd thought that some additional rules had been suggest to allow the slapd_var_run_t label to work here.

How can I check if the rules from bug 799102 comment 6 were implemented?

Comment 32 Scott Poore 2012-04-05 20:10:25 UTC

I don't seem to be able to reproduce this issue anymore after some ipa-server, 389-ds-base, and selinux-policy updates.   Was something fixed in the order of start/stop that corrected this without the selinux-policy dirsrv module update?

Since I can no longer see the issue opened here, I'm just curious if this was fixed in dirsrv's handling of the socket file or something similar?

# rpm -q ipa-server 389-ds-base selinux-policy
ipa-server-2.2.0-8.el6.x86_64
389-ds-base-1.2.10.2-4.el6.x86_64
selinux-policy-3.7.19-142.el6.noarch

# ausearch -m avc
<no matches>

# ls -Z /var/run/slapd-TESTRELM-COM.socket 
srw-rw-rw-. root root unconfined_u:object_r:dirsrv_var_run_t:s0 /var/run/slapd-TESTRELM-COM.socket

# semanage fcontext -l|grep /var/run/slapd
/var/run/slapd.*                                   socket             system_u:object_r:slapd_var_run_t:s0 
/var/run/slapd\.args                               regular file       system_u:object_r:slapd_var_run_t:s0 
/var/run/slapd\.pid                                regular file       system_u:object_r:slapd_var_run_t:s0 

# bunzip2 -c  /usr/share/selinux/targeted/dirsrv.pp.bz2 > /tmp/dirsrv.pp

# strings /tmp/dirsrv.pp|grep slap
slapd_var_run_t
slapd_t
slapd_var_run_t
slapd_t
/usr/sbin/ns-slapd	--	system_u:object_r:dirsrv_exec_t:s0

# yum -y update 'ipa*'
<snip>
Installed products updated.

Updated:
  bind-dyndb-ldap.x86_64 0:1.1.0-0.5.b1.el6                   ipa-admintools.x86_64 0:2.2.0-8.el6                      
  ipa-client.x86_64 0:2.2.0-8.el6                             ipa-python.x86_64 0:2.2.0-8.el6                          
  ipa-server.x86_64 0:2.2.0-8.el6                             ipa-server-selinux.x86_64 0:2.2.0-8.el6                  

Dependency Updated:
  389-ds-base.x86_64 0:1.2.10.2-4.el6                        389-ds-base-libs.x86_64 0:1.2.10.2-4.el6                  
  bind.x86_64 32:9.8.2-0.6.rc1.el6                           bind-libs.x86_64 32:9.8.2-0.6.rc1.el6                     
  bind-utils.x86_64 32:9.8.2-0.6.rc1.el6                     krb5-devel.x86_64 0:1.9-32.el6                            
  krb5-libs.x86_64 0:1.9-32.el6                              krb5-pkinit-openssl.x86_64 0:1.9-32.el6                   
  krb5-server.x86_64 0:1.9-32.el6                            krb5-server-ldap.x86_64 0:1.9-32.el6                      
  krb5-workstation.x86_64 0:1.9-32.el6                       libipa_hbac.x86_64 0:1.8.0-20.el6                         
  libipa_hbac-python.x86_64 0:1.8.0-20.el6                   mod_auth_kerb.x86_64 0:5.4-9.el6                          
  pki-ca.noarch 0:9.0.3-24.el6                               pki-common.noarch 0:9.0.3-24.el6                          
  pki-java-tools.noarch 0:9.0.3-24.el6                       pki-native-tools.x86_64 0:9.0.3-24.el6                    
  pki-selinux.noarch 0:9.0.3-24.el6                          pki-setup.noarch 0:9.0.3-24.el6                           
  pki-silent.noarch 0:9.0.3-24.el6                           pki-symkey.x86_64 0:9.0.3-24.el6                          
  pki-util.noarch 0:9.0.3-24.el6                             sssd.x86_64 0:1.8.0-20.el6                                
  sssd-client.x86_64 0:1.8.0-20.el6                         

Complete!
</snip>

# ipactl restart
Restarting Directory Service
Shutting down dirsrv: 
    PKI-IPA...                                             [  OK  ]
    TESTRELM-COM...                                        [  OK  ]
Starting dirsrv: 
    PKI-IPA...                                             [  OK  ]
    TESTRELM-COM...                                        [  OK  ]
Restarting KDC Service
Stopping Kerberos 5 KDC:                                   [  OK  ]
Starting Kerberos 5 KDC:                                   [  OK  ]
Restarting KPASSWD Service
Stopping Kerberos 5 Admin Server:                          [  OK  ]
Starting Kerberos 5 Admin Server:                          [  OK  ]
Restarting DNS Service
Stopping named: .                                          [  OK  ]
Starting named:                                            [  OK  ]
Restarting MEMCACHE Service
Stopping ipa_memcached:                                    [  OK  ]
Starting ipa_memcached:                                    [  OK  ]
Restarting HTTP Service
Stopping httpd:                                            [  OK  ]
Starting httpd: [Thu Apr 05 14:03:06 2012] [warn] worker ajp://localhost:9447/ already used by another worker
[Thu Apr 05 14:03:06 2012] [warn] worker ajp://localhost:9447/ already used by another worker
                                                           [  OK  ]
Restarting CA Service
Stopping pki-ca:                                           [  OK  ]
Starting pki-ca:                                           [  OK  ]

# ipa user-find
---------------
3 users matched
---------------
  User login: admin
  Last name: Administrator
  Home directory: /home/admin
  Login shell: /bin/bash
  UID: 1392000000
  GID: 1392000000
  Account disabled: False
  Password: True
  Kerberos keys available: True

  User login: jack
  First name: First
  Last name: Last
  Home directory: /home/jack
  Login shell: /bin/sh
  UID: 1392000003
  GID: 1392000003
  Account disabled: False
  Password: True
  Kerberos keys available: True

  User login: jill
  First name: First
  Last name: Last
  Home directory: /home/jill
  Login shell: /bin/sh
  UID: 1392000004
  GID: 1392000004
  Account disabled: False
  Password: True
  Kerberos keys available: True
----------------------------
Number of entries returned 3
----------------------------

Comment 33 Nathan Kinder 2012-04-05 20:44:32 UTC

(In reply to comment #32)
> I don't seem to be able to reproduce this issue anymore after some ipa-server,
> 389-ds-base, and selinux-policy updates.   Was something fixed in the order of
> start/stop that corrected this without the selinux-policy dirsrv module update?
> 
> Since I can no longer see the issue opened here, I'm just curious if this was
> fixed in dirsrv's handling of the socket file or something similar?
> 

No, nothing changed in 389-ds-base around this.  You should be able to reproduce still by doing a restorecon on /var/run/slapd.* while the dirsrv service is running.  That will cause the socket file to be relabelled as slapd_var_run_t.  If you then try to restart dirsrv, you will see the AVC.

Comment 34 Scott Poore 2012-04-05 21:39:40 UTC

Yes, that I can reproduce.   But, I'm no longer seeing the issue with IPA upgrades that was caused by that from the original issue.

I was wondering if maybe the setup-ds.pl moving from %posttrans to %post in 1.2.10.2-4 may have helped with this one too.  Or, some other change in IPA's upgrade affected it so the socket file is no longer removed during a restart?

In any case, the IPA upgrades are working but, the restorecon does switch labels as you mentioned.

Comment 35 Scott Poore 2012-04-09 18:37:55 UTC

I am going to go ahead and close this one as WORKSFORME since I cannot reproduce the "symptom" since the following updates:

ipa-server 2.2.0-5 
389-ds-base 1.2.10.2-4
selinux-policy-targetd 3.7.19-142

The selinux labelling issue is addressed in bug 799102 and my test results have been posted there.

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