#6721 While performing ipa-server-upgrade, sssd goes offline and stalls the upgrade process
Closed: fixed Opened by pvoborni.

Ticket was cloned from Red Hat Bugzilla (product Red Hat Enterprise Linux 7): Bug 1424735

Please note that this Bug is private and may not be accessible as it contains confidential Red Hat customer information.

Description of problem:
While perfomring an ipa-server-upgrade on an IPA Replica, the upgrade stopped
at the schema-compat plugin:
[09/Feb/2017:17:39:47.226915666 -0500] schema-compat-plugin - group
"group@example.com" does not exist because SSSD is offline.
[09/Feb/2017:17:39:47.227283732 -0500] schema-compat-plugin - waiting for SSSD
to become online...
SSSD logs showed sssd going offline. We restarted sssd and the upgrade process
completed after a few minutes.
Version-Release number of selected component (if applicable):
389-ds-base-1.3.4.0-30.el7_2.x86_64
ipa-server-4.2.0-15.el7_2.15.x86_64
sssd-1.13.0-40.el7_2.4.x86_64
How reproducible:
This happened while upgrading IPA Replica, but may have also happened on while
upgrading the IPA Master initially
Steps to Reproduce:
1. Upgrade from RHEL 7.2 ipa-server-4.2.0-15.el7_2.15.x86_64 to RHEL 7.3
ipa-server-4.4.0-14.el7_3.4.x86_64
2. Upgrade process hangs
3. See dirsrv error logs showing:
   schema-compat-plugin - waiting for SSSD to become online...
Actual results:
Upgrade process stops at:
[09/Feb/2017:19:32:27.489895058 -0500] schema-compat-plugin - group
"hdpdev_developer@dmt.rogers.com" does not exist because SSSD is offline.
[09/Feb/2017:19:32:27.490415919 -0500] schema-compat-plugin - waiting for SSSD
to become online...
Expected results:
Successful upgrade
Additional info:

Metadata Update from @pvoborni:
- Custom field rhbz adjusted to https://bugzilla.redhat.com/show_bug.cgi?id=1424735

Metadata Update from @pvoborni:
- Custom field rhbz adjusted to https://bugzilla.redhat.com/show_bug.cgi?id=1424735

adding some details on eventual resolution of a situation that should not have happened, but did not find any defect, so far.

before updgrade:
389-ds-base-1.3.4.0-30.el7_2.x86_64
ipa-server-4.2.0-15.el7_2.15.x86_64
redhat-release-server-7.2-9.el7.x86_64

master with failed upgrade:
ipa1.example.com
389-ds-base-1.3.5.10-15.el7_3.x86_64
ipa-server-4.4.0-14.el7_3.4.x86_64
redhat-release-server-7.3-7.el7.x86_64

there may have been different problems, like caches too small for a small number of entries, too high idlistscanlimit and lookthroughlimit.

but the initial customer issue was resolved with a re-index in the the LDAP server, allowing SSSD to come on-line after some ldapsearches finally completed.

the key was this LDAP server log entry
[09/Feb/2017:17:40:22.263538217 -0500] schema-compat-plugin - waiting for SSSD to become online...

details:

looked into the various logs (edited), there were a couple of unexpected messages, like:

var/log/krb5kdc.log
Feb 08 11:55:26 ipa1.example.com krb5kdc32384: AS_REQ (6 etypes {18 17 16 23 25 26}) 10.9.20.145: CLIENT_NOT_FOUND: admin@EXAMPLE.COM for krbtgt/EXAMPLE.COM@EXAMPLE.COM, Client not found in Kerberos database
Feb 08 11:55:35 ipa1.example.com krb5kdc32385: AS_REQ (6 etypes {18 17 16 23 25 26}) 10.9.20.145: CLIENT_NOT_FOUND: user1@EXAMPLE.COM for krbtgt/EXAMPLE.COM@EXAMPLE.COM, Client not found in Kerberos database

var/log/httpd/error_log
[Wed Feb 08 11:55:26.124329 2017] [:error] [pid 32464] ipa: INFO: 401 Unauthorized: kinit: Client 'admin@EXAMPLE.COM' not found in Kerberos database while getting initial credentials
[Wed Feb 08 11:55:26.124352 2017] [:error] [pid 32464]
[Wed Feb 08 11:55:35.655225 2017] [:error] [pid 32465] ipa: INFO: 401 Unauthorized: kinit: Client 'user1@EXAMPLE.COM' not found in Kerberos database while getting initial credentials

var/log/dirsrv/slapd-EXAMPLE-COM/access
[08/Feb/2017:11:54:48.739077830 -0500] conn=4879 op=30 SRCH base="dc=example,dc=com" scope=2 filter="(&(|(objectClass=krbprincipalaux)(objectClass=krbprincipal)(objectClass=ipakrbprincipal))(|(ipaKrbPrincipalAlias=admin@EXAMPLE.COM)(krbPrincipalName:caseIgnoreIA5Match:=admin@EXAMPLE.COM)))" attrs="krbPrincipalName krbCanonicalName krbUPEnabled krbPrincipalKey krbTicketPolicyReference krbPrincipalExpiration krbPasswordExpiration krbPwdPolicyReference krbPrincipalType krbPwdHistory krbLastPwdChange krbPrincipalAliases krbLastSuccessfulAuth krbLastFailedAuth krbLoginFailedCount krbPrincipalAuthInd krbExtraData krbLastAdminUnlock krbObjectReferences krbTicketFlags krbMaxTicketLife krbMaxRenewableAge nsAccountLock passwordHistory ipaKrbAuthzData ipaUserAuthType ipatokenRadiusConfigLink objectClass"
[08/Feb/2017:11:54:48.739256430 -0500] conn=4879 op=30 RESULT err=0 tag=101 nentries=0 etime=0

[08/Feb/2017:11:55:35.654134764 -0500] conn=4885 op=195 SRCH base="dc=example,dc=com" scope=2 filter="(&(|(objectClass=krbprincipalaux)(objectClass=krbprincipal)(objectClass=ipakrbprincipal))(|(ipaKrbPrincipalAlias=user1@EXAMPLE.COM)(krbPrincipalName:caseIgnoreIA5Match:=user1@EXAMPLE.COM)))" attrs="krbPrincipalName krbCanonicalName krbUPEnabled krbPrincipalKey krbTicketPolicyReference krbPrincipalExpiration krbPasswordExpiration krbPwdPolicyReference krbPrincipalType krbPwdHistory krbLastPwdChange krbPrincipalAliases krbLastSuccessfulAuth krbLastFailedAuth krbLoginFailedCount krbPrincipalAuthInd krbExtraData krbLastAdminUnlock krbObjectReferences krbTicketFlags krbMaxTicketLife krbMaxRenewableAge nsAccountLock passwordHistory ipaKrbAuthzData ipaUserAuthType ipatokenRadiusConfigLink objectClass"
[08/Feb/2017:11:55:35.654228304 -0500] conn=4885 op=195 RESULT err=0 tag=101 nentries=0 etime=0

it was verified the uid admin and user1 existed,

then asked to do similar BIND and ldapsearch as from SSSD, and for some unknown reason, 2 searches were indeed not returning any entries, nor errors, 1 entry was expected:

ldapsearch -LLLx -D "cn=directory manager" -W -b "dc=example,dc=com" scope=2 filter="(&(|(objectClass=krbprincipalaux)(objectClass=krbprincipal)(objectClass=ipakrbprincipal))(|(ipaKrbPrincipalAlias=admin@EXAMPLE.COM)(krbPrincipalName:caseIgnoreIA5Match:=admin@EXAMPLE.COM)))" attrs="krbPrincipalName krbCanonicalName krbUPEnabled krbPrincipalKey krbTicketPolicyReference krbPrincipalExpiration krbPasswordExpiration krbPwdPolicyReference krbPrincipalType krbPwdHistory krbLastPwdChange krbPrincipalAliases krbLastSuccessfulAuth krbLastFailedAuth krbLoginFailedCount krbPrincipalAuthInd krbExtraData krbLastAdminUnlock krbObjectReferences krbTicketFlags krbMaxTicketLife krbMaxRenewableAge nsAccountLock passwordHistory ipaKrbAuthzData ipaUserAuthType ipatokenRadiusConfigLink objectClass"

ldapsearch -LLLx -D "cn=directory manager" -W -b "dc=example,dc=com" scope=2 filter="(&(|(objectClass=krbprincipalaux)(objectClass=krbprincipal)(objectClass=ipakrbprincipal))(|(ipaKrbPrincipalAlias=user1@EXAMPLE.COM)(krbPrincipalName:caseIgnoreIA5Match:=user1@EXAMPLE.COM)))" attrs="krbPrincipalName krbCanonicalName krbUPEnabled krbPrincipalKey krbTicketPolicyReference krbPrincipalExpiration krbPasswordExpiration krbPwdPolicyReference krbPrincipalType krbPwdHistory krbLastPwdChange krbPrincipalAliases krbLastSuccessfulAuth krbLastFailedAuth krbLoginFailedCount krbPrincipalAuthInd krbExtraData krbLastAdminUnlock krbObjectReferences krbTicketFlags krbMaxTicketLife krbMaxRenewableAge nsAccountLock passwordHistory ipaKrbAuthzData ipaUserAuthType ipatokenRadiusConfigLink objectClass"

so SSSD staid off-line.

so I suggested a re-index a re-index of the userroot LDAP server db, like this:

systemctl stop dirsrv@EXAMPLE-COM.service
db2index -Z EXAMPLE-COM -n userroot
systemctl start dirsrv@EXAMPLE-COM.service

but a whole re-index was performed for
userRoot - 725 entries
ipaca - 145 entries
changelog - 8789 entries

then the next ipa-server-upgrade command was successful.

we do not know why the indexes may have been corrupted, without any errors in the LDAP server errors log file. (not expected), or if the re-index cleaned up something else, it just seem it solved th e problem.

Two searches you try with 'ldapsearch' were not from SSSD, they are krb5kdc trying to access LDAP store. They are done via LDAPI socket and are ignored by the schema-compat plugin. As you show in httpd's error_log, these request are actually part of processing of access via IPA framework -- either from Web UI or from ipa CLI tool.

When upgrade is being performed, access to LDAP store is limited. No connection is available through 389/tcp or 636/tcp ports. Ideally, we should also limit access via IPA framework too. IPA framework uses LDAPI socket (same as krb5kdc). LDAPI socket remains accessible during upgrade because this is how actual upgrade is performed, but we really should not allow its use by other components at the same time.

Metadata Update from @abbra:
- Custom field tester adjusted to wanted

Metadata Update from @pvoborni:
- Issue priority set to: 4

Metadata Update from @mbasti:
- Issue set to the milestone: FreeIPA 4.5.1 (was: FreeIPA 4.5)

Metadata Update from @pvoborni:
- Issue set to the milestone: FreeIPA 4.7 (was: FreeIPA 4.5.1)

Metadata Update from @rcritten:
- Issue assigned to rcritten

Metadata Update from @rcritten:
- Issue set to the milestone: FreeIPA 4.6.4 (was: FreeIPA 4.7)

master:

  • 2b3eb5c567e1e5d4fe7d945e36615cef3dd4d144 Disable Schema Compat plugin during server upgrade

ipa-4-6:

  • 36e95d2aa8b7979573707a560c01561efe9521ae Disable Schema Compat plugin during server upgrade

Metadata Update from @stlaz:
- Issue close_status updated to: fixed
- Issue status updated to: Closed (was: Open)

Metadata