Bug 1044994

Summary: ipa-client-install part of ipa-server-install fails on reinstall
Product: [Fedora] Fedora Reporter: Tomas Babej <tbabej>
Component: freeipaAssignee: Rob Crittenden <rcritten>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 20CC: abokovoy, jorton, mkosek, nalin, pviktori, rcritten, ssorce
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: freeipa-3.3.4-3.fc20 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2014-02-28 18:36:59 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 Tomas Babej 2013-12-19 12:05:42 UTC
Description of problem:

The second installation of IPA on the same server (after the first one has been removed using ipa-server-install --uninstall) fails with:

<DEBUG>: Done configuring the web interface (httpd).
<DEBUG>: Applying LDAP updates
<DEBUG>: Restarting the directory server
<DEBUG>: Restarting the KDC
<DEBUG>: Configuring DNS (named)
<DEBUG>:   [1/11]: adding DNS container
<DEBUG>:   [2/11]: setting up our zone
<DEBUG>:   [3/11]: setting up reverse zone
<DEBUG>:   [4/11]: setting up our own record
<DEBUG>:   [5/11]: setting up records for other masters
<DEBUG>:   [6/11]: setting up CA record
<DEBUG>:   [7/11]: setting up kerberos principal
<DEBUG>:   [8/11]: setting up named.conf
<DEBUG>:   [9/11]: restarting named
<DEBUG>:   [10/11]: configuring named to start on boot
<DEBUG>:   [11/11]: changing resolv.conf to point to ourselves
<DEBUG>: Done configuring DNS (named).
<DEBUG>: 
<DEBUG>: Global DNS configuration in LDAP server is empty
<DEBUG>: You can use 'dnsconfig-mod' command to set global DNS options that
<DEBUG>: would override settings in local named.conf files
<DEBUG>: 
<DEBUG>: Restarting the web server
<DEBUG>: Configuration of client side components failed!
<DEBUG>: ipa-client-install returned: Command '/usr/sbin/ipa-client-install --on-master --unattended --domain dom227.jenkinsad.idm.lab.eng.brq.redhat.com --server vm-227.dom227.jenkinsad.idm.lab.eng.brq.redhat.com --realm DOM227.JENKINSAD.IDM.LAB.ENG.BRQ.REDHAT.COM --hostname vm-227.dom227.jenkinsad.idm.lab.eng.brq.redhat.com' returned non-zero exit status 1

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

master

How reproducible:

always

Steps to Reproduce:
1. Install IPA
2. Uninstall IPA
3. Install IPA

Actual results:

Second IPA installation fails with:

ipa-client-install returned: Command '/usr/sbin/ipa-client-install --on-master --unattended --domain dom227.jenkinsad.idm.lab.eng.brq.redhat.com --server vm-227.dom227.jenkinsad.idm.lab.eng.brq.redhat.com --realm DOM227.JENKINSAD.IDM.LAB.ENG.BRQ.REDHAT.COM --hostname vm-227.dom227.jenkinsad.idm.lab.eng.brq.redhat.com' returned non-zero exit status 1


Expected results:

Second IPA installation succeeds.

Additional info:

There's nothing interesting in the journalctl at the time of the failure, all services are up and running.

The actual failure happens in our wsgi.py script:

(from httpd's error_log)
GSSAPI Error: Unspecified GSS failure.  Minor code may provide more information (Decrypt integrity check failed)

wsgi.py uses /etc/httpd/conf/ipa.keytab and by the timestamp this comes from the second installation.

This looks similiar to https://fedorahosted.org/freeipa/ticket/2395, but adding a call to clean httpd's cache on uninstall (along the lines of https://git.fedorahosted.org/cgit/freeipa.git/commit/?id=08413612d485b02294c3bf570fd167a340f11ac9) makes no difference. Additionaly, there are no non-empty ccache files in /tmp or /tmp/systemd-httpd.service-*/


(from dirsrv's access log)

[19/Dec/2013:00:17:58 +0100] conn=13 fd=69 slot=69 connection from 10.34.47.227 to 10.34.47.227
[19/Dec/2013:00:17:58 +0100] conn=2 op=38 SRCH base="dc=dom227,dc=jenkinsad,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com" scope=2 filter="(&(|(objectClass=krbprincipalaux)(objectClass=krbprincipal))(krbPrincipalName=krbtgt/DOM227.JENKINSAD.IDM.LAB.ENG.BRQ.REDHAT.COM.IDM.LAB.ENG.BRQ.REDHAT.COM))" attrs="krbPrincipalName krbCanonicalName ipaKrbPrincipalAlias krbUPEnabled krbPrincipalKey krbTicketPolicyReference krbPrincipalExpiration krbPasswordExpiration krbPwdPolicyReference krbPrincipalType krbPwdHistory krbLastPwdChange krbPrincipalAliases krbLastSuccessfulAuth krbLastFailedAuth krbLoginFailedCount krbExtraData krbLastAdminUnlock krbObjectReferences krbTicketFlags krbMaxTicketLife krbMaxRenewableAge nsAccountLock passwordHistory ipaKrbAuthzData ipaUserAuthType objectClass"
[19/Dec/2013:00:17:58 +0100] conn=2 op=38 RESULT err=0 tag=101 nentries=1 etime=0
[19/Dec/2013:00:17:58 +0100] conn=2 op=39 SRCH base="dc=dom227,dc=jenkinsad,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com" scope=2 filter="(&(|(objectClass=krbprincipalaux)(objectClass=krbprincipal))(krbPrincipalName=krbtgt/DOM227.JENKINSAD.IDM.LAB.ENG.BRQ.REDHAT.COM.IDM.LAB.ENG.BRQ.REDHAT.COM))" attrs="krbPrincipalName krbCanonicalName ipaKrbPrincipalAlias krbUPEnabled krbPrincipalKey krbTicketPolicyReference krbPrincipalExpiration krbPasswordExpiration krbPwdPolicyReference krbPrincipalType krbPwdHistory krbLastPwdChange krbPrincipalAliases krbLastSuccessfulAuth krbLastFailedAuth krbLoginFailedCount krbExtraData krbLastAdminUnlock krbObjectReferences krbTicketFlags krbMaxTicketLife krbMaxRenewableAge nsAccountLock passwordHistory ipaKrbAuthzData ipaUserAuthType objectClass"
[19/Dec/2013:00:17:58 +0100] conn=2 op=39 RESULT err=0 tag=101 nentries=1 etime=0
[19/Dec/2013:00:17:58 +0100] conn=13 op=0 UNBIND
[19/Dec/2013:00:17:58 +0100] conn=13 op=0 fd=69 closed - U1

Comment 1 Tomas Babej 2013-12-19 12:08:07 UTC
I should also note that the failure happened at 00.17.58.

(the relevant part of krb5kdc's log)

Dec 19 00:17:49 vm-227.dom227.jenkinsad.idm.lab.eng.brq.redhat.com krb5kdc[7367](info): AS_REQ (6 etypes {18 17 16 23 25 26}) 10.34.47.227: NEEDED_PREAUTH: DNS/vm-227.dom227.jenkinsad.idm.lab.eng.brq.redhat.com.IDM.LAB.ENG.BRQ.REDHAT.COM for krbtgt/DOM227.JENKINSAD.IDM.LAB.ENG.BRQ.REDHAT.COM.IDM.LAB.ENG.BRQ.REDHAT.COM, Additional pre-authentication required
Dec 19 00:17:49 vm-227.dom227.jenkinsad.idm.lab.eng.brq.redhat.com krb5kdc[7367](info): AS_REQ (6 etypes {18 17 16 23 25 26}) 10.34.47.227: ISSUE: authtime 1387408669, etypes {rep=18 tkt=18 ses=18}, DNS/vm-227.dom227.jenkinsad.idm.lab.eng.brq.redhat.com.IDM.LAB.ENG.BRQ.REDHAT.COM for krbtgt/DOM227.JENKINSAD.IDM.LAB.ENG.BRQ.REDHAT.COM.IDM.LAB.ENG.BRQ.REDHAT.COM
Dec 19 00:17:49 vm-227.dom227.jenkinsad.idm.lab.eng.brq.redhat.com krb5kdc[7367](info): TGS_REQ (6 etypes {18 17 16 23 25 26}) 10.34.47.227: ISSUE: authtime 1387408669, etypes {rep=18 tkt=18 ses=18}, DNS/vm-227.dom227.jenkinsad.idm.lab.eng.brq.redhat.com.IDM.LAB.ENG.BRQ.REDHAT.COM for ldap/vm-227.dom227.jenkinsad.idm.lab.eng.brq.redhat.com.IDM.LAB.ENG.BRQ.REDHAT.COM
Dec 19 00:17:56 vm-227.dom227.jenkinsad.idm.lab.eng.brq.redhat.com krb5kdc[7367](info): AS_REQ (6 etypes {18 17 16 23 25 26}) 10.34.47.227: NEEDED_PREAUTH: host/vm-227.dom227.jenkinsad.idm.lab.eng.brq.redhat.com.IDM.LAB.ENG.BRQ.REDHAT.COM for krbtgt/DOM227.JENKINSAD.IDM.LAB.ENG.BRQ.REDHAT.COM.IDM.LAB.ENG.BRQ.REDHAT.COM, Additional pre-authentication required
Dec 19 00:17:56 vm-227.dom227.jenkinsad.idm.lab.eng.brq.redhat.com krb5kdc[7367](info): AS_REQ (6 etypes {18 17 16 23 25 26}) 10.34.47.227: ISSUE: authtime 1387408676, etypes {rep=18 tkt=18 ses=18}, host/vm-227.dom227.jenkinsad.idm.lab.eng.brq.redhat.com.IDM.LAB.ENG.BRQ.REDHAT.COM for krbtgt/DOM227.JENKINSAD.IDM.LAB.ENG.BRQ.REDHAT.COM.IDM.LAB.ENG.BRQ.REDHAT.COM
Dec 19 00:17:56 vm-227.dom227.jenkinsad.idm.lab.eng.brq.redhat.com krb5kdc[7367](info): TGS_REQ (6 etypes {18 17 16 23 25 26}) 10.34.47.227: ISSUE: authtime 1387408676, etypes {rep=18 tkt=18 ses=18}, host/vm-227.dom227.jenkinsad.idm.lab.eng.brq.redhat.com.IDM.LAB.ENG.BRQ.REDHAT.COM for HTTP/vm-227.dom227.jenkinsad.idm.lab.eng.brq.redhat.com.IDM.LAB.ENG.BRQ.REDHAT.COM
Dec 19 00:17:58 vm-227.dom227.jenkinsad.idm.lab.eng.brq.redhat.com krb5kdc[7367](info): TGS_REQ (6 etypes {18 17 16 23 25 26}) 10.34.47.227: PROCESS_TGS: authtime 0,  <unknown client> for <unknown server>, Decrypt integrity check failed
Dec 19 00:17:58 vm-227.dom227.jenkinsad.idm.lab.eng.brq.redhat.com krb5kdc[7367](info): closing down fd 13
Dec 19 00:17:58 vm-227.dom227.jenkinsad.idm.lab.eng.brq.redhat.com krb5kdc[7367](info): TGS_REQ (6 etypes {18 17 16 23 25 26}) 10.34.47.227: PROCESS_TGS: authtime 0,  <unknown client> for <unknown server>, Decrypt integrity check failed
Dec 19 00:17:58 vm-227.dom227.jenkinsad.idm.lab.eng.brq.redhat.com krb5kdc[7367](info): closing down fd 13

Comment 2 Petr Viktorin (pviktori) 2013-12-19 12:35:34 UTC
Upstream ticket:
https://fedorahosted.org/freeipa/ticket/4084

Comment 3 Martin Kosek 2014-01-10 14:32:26 UTC
I spent some time investigating this issue as well and I think it is related to kerberos persistent keyrings (at minimum, the problem does not reproduce when default_ccache_name is removed from krb5.conf). Let me paste my investigation on this one.

Second IPA server install failed as expected:

# ipa-server-install
...
Restarting the web server
Configuration of client side components failed!
ipa-client-install returned: Command '/usr/sbin/ipa-client-install --on-master --unattended --domain example.com --server vm-236.example.com --realm EXAMPLE.COM --hostname vm-236.example.com' returned non-zero exit status 1


So I tried to at least kinit and run some command:

# kinit admin
Password for admin: 

# ipa user-find
ipa: ERROR: cannot connect to 'https://vm-236.example.com/ipa/json': Internal Server Error

# tail -n 1 /var/log/httpd/error_log
[Fri Jan 10 15:17:26.099043 2014] [:error] [pid 14394] [remote 10.34.47.236:36611] ACIError: Insufficient access: SASL(-1): generic failure: GSSAPI Error: Unspecified GSS failure.  Minor code may provide more information (Decrypt integrity check failed)

klist looks OK though:

# klist
Ticket cache: KEYRING:persistent:0:0
Default principal: admin

Valid starting       Expires              Service principal
01/10/2014 15:17:26  01/11/2014 15:17:21  HTTP/vm-236.example.com
01/10/2014 15:17:22  01/11/2014 15:17:21  krbtgt/EXAMPLE.COM

List of stored keyring keys:

# keyctl show @s
Keyring
 345580470 --alswrv      0     0  keyring: _ses
 380235755 --alswrv      0 65534   \_ keyring: _uid.0
 172057041 --alswrv      0 65534   \_ keyring: _persistent.0
 468549466 --alswrv      0     0       \_ keyring: _krb
 839078625 --alswrv      0     0           \_ user: krb_ccache:primary
 301788255 --alswrv      0     0           \_ keyring: krb_ccache_As1lhZG
 735426773 --alswrv      0     0           |   \_ user: __krb5_princ__
 395598031 --als-rv      0     0           |   \_ big_key: HTTP/vm-236.example.com
 478954327 --als-rv      0     0           |   \_ big_key: krb5_ccache_conf_data/pa_type/krbtgt\/EXAMPLE.COM\@EXAMPLE.COM@X-CACHECONF:
 111917919 --als-rv      0     0           |   \_ big_key: krb5_ccache_conf_data/fast_avail/krbtgt\/EXAMPLE.COM\@EXAMPLE.COM@X-CACHECONF:
 866677082 --als-rv      0     0           |   \_ big_key: krbtgt/EXAMPLE.COM
 451242335 --alswrv      0     0           |   \_ user: __krb5_time_offsets__
 398283496 --alswrv      0     0           \_ keyring: krb_ccache_1SpAiC5
 264969193 --alswrv      0     0           \_ keyring: 0
 174019722 --alswrv      0     0               \_ user: __krb5_princ__
 183291836 --als-rv      0     0               \_ big_key: HTTP/vm-236.example.com
 872061046 --als-rv      0     0               \_ big_key: krb5_ccache_conf_data/pa_type/krbtgt\/EXAMPLE.COM\@EXAMPLE.COM@X-CACHECONF:
 991606458 --als-rv      0     0               \_ big_key: krb5_ccache_conf_data/fast_avail/krbtgt\/EXAMPLE.COM\@EXAMPLE.COM@X-CACHECONF:
 455875030 --als-rv      0     0               \_ big_key: krbtgt/EXAMPLE.COM
 871660836 --alswrv      0     0               \_ user: __krb5_time_offsets__


So I tried to clear old keyring just to make sure that some old keys do not intergere:

# keyctl clear 264969193
# keyctl clear 301788255
# klist
klist: No credentials cache found while retrieving principal name

... and tried to kinit & auth again:

# kinit admin
Password for admin: 

# ipa user-find
ipa: ERROR: cannot connect to 'https://vm-236.example.com/ipa/json': Internal Server Error

# tail -n 1 /var/log/httpd/error_log
[Fri Jan 10 15:18:15.174541 2014] [:error] [pid 14393] [remote 10.34.47.236:212] ACIError: Insufficient access: SASL(-1): generic failure: GSSAPI Error: Unspecified GSS failure.  Minor code may provide more information (Decrypt integrity check failed)


Then I tried to switch to file based CCACHE, but still no luck:

# export KRB5CCNAME=/tmp/cc
# klist
klist: No credentials cache found (ticket cache FILE:/tmp/cc)
# kinit admin
Password for admin: 
# ipa user-find
ipa: ERROR: cannot connect to 'https://vm-236.example.com/ipa/json': Internal Server Error
# klist
Ticket cache: FILE:/tmp/cc
Default principal: admin

Valid starting       Expires              Service principal
01/10/2014 15:20:25  01/11/2014 15:20:24  krbtgt/EXAMPLE.COM
01/10/2014 15:20:30  01/11/2014 15:20:24  HTTP/vm-236.example.com


What helped me in this case was to comment default_ccache_name in /etc/krb5.conf:

# ipa user-find
--------------
1 user matched
--------------
  User login: admin
  Last name: Administrator
  Home directory: /home/admin
  Login shell: /bin/bash
  UID: 1158000000
  GID: 1158000000
  Account disabled: False
  Password: True
  Kerberos keys available: True
----------------------------
Number of entries returned 1
----------------------------
[root@vm-236 ~]# keyctl show @s
Keyring
 345580470 --alswrv      0     0  keyring: _ses
 380235755 --alswrv      0 65534   \_ keyring: _uid.0
1056588253 --alswrv      0     0   \_ user: ipa_session_cookie:admin
 172057041 --alswrv      0 65534   \_ keyring: _persistent.0
 468549466 --alswrv      0     0       \_ keyring: _krb
 839078625 --alswrv      0     0           \_ user: krb_ccache:primary
 301788255 --alswrv      0     0           \_ keyring: krb_ccache_As1lhZG
 398283496 --alswrv      0     0           \_ keyring: krb_ccache_1SpAiC5
 264969193 --alswrv      0     0           \_ keyring: 0


To sum it up, there is really something wrong with the keyring ccaches. Nalin, does anything comes to your mind?

Comment 6 Martin Kosek 2014-01-14 09:00:02 UTC
We found out that this issue is related to F20's httpd omitting the /etc/sysconfig/httpd environment file and ignoring the configuration here.

FreeIPA updates this file and configures Kerberos CCACHE setting for httpd so that it uses file based Kerberos CCACHE instead of kernel keyring CCACHE which is obviously not cleared on uninstall of the service.

When I updated [service] section of /usr/lib/systemd/system/httpd.service and added EnvironmentFile back, subsequent ipa-server-install's in F20 started working again:

...
[Service]
Type=notify
Environment=LANG=C
EnvironmentFile=-/etc/sysconfig/httpd
...

Joe, what is your take on this? Can we please add EnvironmentFile to httpd's stock service file? As Alexander already pointed out, recommendations in

http://fedoraproject.org/wiki/Packaging%3aSystemd#EnvironmentFiles_and_support_for_.2Fetc.2Fsysconfig_files

are not against this approach. IMO it is much more convenient for services like FreeIPA to just drop environment variable to the environment file instead of preparing/parsing a systemd unit files to /etc/systemd/system/httpd.service

Comment 7 Petr Viktorin (pviktori) 2014-01-22 11:45:29 UTC
Fixed upstream: https://fedorahosted.org/freeipa/changeset/f49c26db2c38e5b60a6be990b95c2926ecfa6247/

Comment 8 Petr Viktorin (pviktori) 2014-01-22 11:50:00 UTC
This patch is also needed: 252ad0b8c150954e773c7739994d1d4d9c5dc927

Comment 9 Martin Kosek 2014-01-22 16:03:23 UTC
One more improvement based on Simo's recommendation:
master: b7f1531262723d9a9c50bedad21c3b3cc51e34e9

Comment 10 Fedora Update System 2014-01-28 14:45:23 UTC
freeipa-3.3.4-1.fc20 has been submitted as an update for Fedora 20.
https://admin.fedoraproject.org/updates/freeipa-3.3.4-1.fc20

Comment 11 Fedora Update System 2014-01-29 03:01:38 UTC
Package freeipa-3.3.4-1.fc20:
* should fix your issue,
* was pushed to the Fedora 20 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing freeipa-3.3.4-1.fc20'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2014-1666/freeipa-3.3.4-1.fc20
then log in and leave karma (feedback).

Comment 12 Fedora Update System 2014-02-06 04:03:04 UTC
Package freeipa-3.3.4-2.fc20:
* should fix your issue,
* was pushed to the Fedora 20 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing freeipa-3.3.4-2.fc20'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2014-1666/freeipa-3.3.4-2.fc20
then log in and leave karma (feedback).

Comment 13 Fedora Update System 2014-02-12 14:46:30 UTC
Package freeipa-3.3.4-3.fc20:
* should fix your issue,
* was pushed to the Fedora 20 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing freeipa-3.3.4-3.fc20'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2014-1666/freeipa-3.3.4-3.fc20
then log in and leave karma (feedback).

Comment 14 Fedora Update System 2014-02-28 18:36:59 UTC
freeipa-3.3.4-3.fc20 has been pushed to the Fedora 20 stable repository.  If problems still persist, please make note of it in this bug report.