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
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:
ipa-4-6:
Metadata Update from @stlaz: - Issue close_status updated to: fixed - Issue status updated to: Closed (was: Open)