In Fedora-Rawhide-20210118.n.1, FreeIPA replica deployment fails, with these errors in ipareplica-install.log: 2021-01-19T15:44:46Z DEBUG Restart of dirsrv complete 2021-01-19T15:44:46Z DEBUG Created connection context.ldap2_140630216950544 2021-01-19T15:44:46Z DEBUG Fetching nsDS5ReplicaId from master [attempt 1/5] 2021-01-19T15:44:46Z DEBUG retrieving schema for SchemaCache url=ldap://ipa002.test.openqa.fedoraproject.org:389 conn=<ldap.ldapobject.SimpleLDAPObject object at 0x7fe7032a2b80> 2021-01-19T15:44:46Z DEBUG Successfully updated nsDS5ReplicaId. 2021-01-19T15:44:46Z DEBUG Add or update replica config cn=replica,cn=dc\=test\,dc\=openqa\,dc\=fedoraproject\,dc\=org,cn=mapping tree,cn=config 2021-01-19T15:44:46Z DEBUG Added replica config cn=replica,cn=dc\=test\,dc\=openqa\,dc\=fedoraproject\,dc\=org,cn=mapping tree,cn=config 2021-01-19T15:44:46Z DEBUG Fetching nsDS5ReplicaId from master [attempt 1/5] 2021-01-19T15:44:46Z DEBUG Successfully updated nsDS5ReplicaId. 2021-01-19T15:44:46Z DEBUG Add or update replica config cn=replica,cn=dc\=test\,dc\=openqa\,dc\=fedoraproject\,dc\=org,cn=mapping tree,cn=config 2021-01-19T15:44:46Z DEBUG Added replica config cn=replica,cn=dc\=test\,dc\=openqa\,dc\=fedoraproject\,dc\=org,cn=mapping tree,cn=config 2021-01-19T15:44:47Z DEBUG Waiting up to 300 seconds for replication (ldap://ipa002.test.openqa.fedoraproject.org:389) cn=meToipa003.test.openqa.fedoraproject.org,cn=replica,cn=dc\ =test\,dc\=openqa\,dc\=fedoraproject\,dc\=org,cn=mapping tree,cn=config (objectclass=*) 2021-01-19T15:44:47Z DEBUG Entry found [LDAPEntry(ipapython.dn.DN('cn=meToipa003.test.openqa.fedoraproject.org,cn=replica,cn=dc\=test\,dc\=openqa\,dc\=fedoraproject\,dc\=org,cn=map ping tree,cn=config'), {'objectClass': [b'nsds5replicationagreement', b'top'], 'cn': [b'meToipa003.test.openqa.fedoraproject.org'], 'nsDS5ReplicaHost': [b'ipa003.test.openqa.fedora project.org'], 'nsDS5ReplicaPort': [b'389'], 'nsds5replicaTimeout': [b'120'], 'nsDS5ReplicaRoot': [b'dc=test,dc=openqa,dc=fedoraproject,dc=org'], 'description': [b'me to ipa003.tes t.openqa.fedoraproject.org'], 'nsDS5ReplicatedAttributeList': [b'(objectclass=*) $ EXCLUDE memberof idnssoaserial entryusn krblastsuccessfulauth krblastfailedauth krbloginfailedcou nt'], 'nsDS5ReplicaTransportInfo': [b'LDAP'], 'nsDS5ReplicaBindMethod': [b'SASL/GSSAPI'], 'nsds5ReplicaStripAttrs': [b'modifiersName modifyTimestamp internalModifiersName internalM odifyTimestamp'], 'nsDS5ReplicatedAttributeListTotal': [b'(objectclass=*) $ EXCLUDE entryusn krblastsuccessfulauth krblastfailedauth krbloginfailedcount'], 'nsds5replicareapactive' : [b'0'], 'nsds5replicaLastUpdateStart': [b'19700101000000Z'], 'nsds5replicaLastUpdateEnd': [b'19700101000000Z'], 'nsds5replicaChangesSentSinceStartup': [b''], 'nsds5replicaLastUpd ateStatus': [b'Error (-2) Problem connecting to replica - LDAP error: Local error (connection error)'], 'nsds5replicaLastUpdateStatusJSON': [b'{"state": "red", "ldap_rc": "-2", "ld ap_rc_text": "Local error", "repl_rc": "16", "repl_rc_text": "connection error", "date": "2021-01-19T15:44:46Z", "message": "Error (-2) Problem connecting to replica - LDAP error: Local error (connection error)"}'], 'nsds5replicaUpdateInProgress': [b'FALSE'], 'nsds5replicaLastInitStart': [b'19700101000000Z'], 'nsds5replicaLastInitEnd': [b'19700101000000Z']})] 2021-01-19T15:44:47Z DEBUG Waiting up to 300 seconds for replication (ldapi://%2Frun%2Fslapd-TEST-OPENQA-FEDORAPROJECT-ORG.socket) cn=meToipa002.test.openqa.fedoraproject.org,cn=replica,cn=dc\=test\,dc\=openqa\,dc\=fedoraproject\,dc\=org,cn=mapping tree,cn=config (objectclass=*) 2021-01-19T15:44:47Z DEBUG Entry found [LDAPEntry(ipapython.dn.DN('cn=meToipa002.test.openqa.fedoraproject.org,cn=replica,cn=dc\=test\,dc\=openqa\,dc\=fedoraproject\,dc\=org,cn=mapping tree,cn=config'), {'objectClass': [b'nsds5replicationagreement', b'top'], 'cn': [b'meToipa002.test.openqa.fedoraproject.org'], 'nsDS5ReplicaHost': [b'ipa002.test.openqa.fedoraproject.org'], 'nsDS5ReplicaPort': [b'389'], 'nsds5replicaTimeout': [b'120'], 'nsDS5ReplicaRoot': [b'dc=test,dc=openqa,dc=fedoraproject,dc=org'], 'description': [b'me to ipa002.test.openqa.fedoraproject.org'], 'nsDS5ReplicatedAttributeList': [b'(objectclass=*) $ EXCLUDE memberof idnssoaserial entryusn krblastsuccessfulauth krblastfailedauth krbloginfailedcount'], 'nsDS5ReplicaTransportInfo': [b'LDAP'], 'nsDS5ReplicaBindMethod': [b'SASL/GSSAPI'], 'nsds5ReplicaStripAttrs': [b'modifiersName modifyTimestamp internalModifiersName internalModifyTimestamp'], 'nsDS5ReplicatedAttributeListTotal': [b'(objectclass=*) $ EXCLUDE entryusn krblastsuccessfulauth krblastfailedauth krbloginfailedcount'], 'nsds5replicareapactive': [b'0'], 'nsds5replicaLastUpdateStart': [b'19700101000000Z'], 'nsds5replicaLastUpdateEnd': [b'19700101000000Z'], 'nsds5replicaChangesSentSinceStartup': [b''], 'nsds5replicaLastUpdateStatus': [b'Error (-2) Problem connecting to replica - LDAP error: Local error (connection error)'], 'nsds5replicaLastUpdateStatusJSON': [b'{"state": "red", "ldap_rc": "-2", "ldap_rc_text": "Local error", "repl_rc": "16", "repl_rc_text": "connection error", "date": "2021-01-19T15:44:47Z", "message": "Error (-2) Problem connecting to replica - LDAP error: Local error (connection error)"}'], 'nsds5replicaUpdateInProgress': [b'FALSE'], 'nsds5replicaLastInitStart': [b'19700101000000Z'], 'nsds5replicaLastInitEnd': [b'19700101000000Z']})] 2021-01-19T15:45:02Z DEBUG Traceback (most recent call last): File "/usr/lib/python3.9/site-packages/ipaserver/install/service.py", line 635, in start_creation run_step(full_msg, method) File "/usr/lib/python3.9/site-packages/ipaserver/install/service.py", line 621, in run_step method() File "/usr/lib/python3.9/site-packages/ipaserver/install/dsinstance.py", line 425, in __setup_replica repl.setup_promote_replication( File "/usr/lib/python3.9/site-packages/ipaserver/install/replication.py", line 1922, in setup_promote_replication raise RuntimeError("Failed to start replication") RuntimeError: Failed to start replication 2021-01-19T15:45:02Z DEBUG [error] RuntimeError: Failed to start replication In system journal, we see a lot of this repeated: Jan 19 15:44:47 ipa003.test.openqa.fedoraproject.org ns-slapd[28327]: GSSAPI client step 1 Jan 19 15:44:47 ipa003.test.openqa.fedoraproject.org ns-slapd[28327]: GSSAPI client step 1 Jan 19 15:44:47 ipa003.test.openqa.fedoraproject.org ns-slapd[28327]: GSSAPI Error: No credentials were supplied, or the credentials were unavailable or inaccessible (No Kerberos credentials available (default cache: /tmp/krb5cc_389)) Jan 19 15:44:47 ipa003.test.openqa.fedoraproject.org ns-slapd[28327]: GSSAPI client step 1 Jan 19 15:44:47 ipa003.test.openqa.fedoraproject.org ns-slapd[28327]: GSSAPI client step 1 Jan 19 15:44:47 ipa003.test.openqa.fedoraproject.org ns-slapd[28327]: GSSAPI Error: No credentials were supplied, or the credentials were unavailable or inaccessible (No Kerberos credentials available (default cache: /tmp/krb5cc_389)) Jan 19 15:44:50 ipa003.test.openqa.fedoraproject.org ns-slapd[28327]: GSSAPI client step 1 Jan 19 15:44:50 ipa003.test.openqa.fedoraproject.org ns-slapd[28327]: GSSAPI client step 1 Jan 19 15:44:50 ipa003.test.openqa.fedoraproject.org ns-slapd[28327]: GSSAPI Error: No credentials were supplied, or the credentials were unavailable or inaccessible (No Kerberos credentials available (default cache: /tmp/krb5cc_389)) Jan 19 15:44:53 ipa003.test.openqa.fedoraproject.org ns-slapd[28327]: GSSAPI client step 1 Jan 19 15:44:53 ipa003.test.openqa.fedoraproject.org ns-slapd[28327]: GSSAPI client step 1 Jan 19 15:44:53 ipa003.test.openqa.fedoraproject.org ns-slapd[28327]: GSSAPI Error: No credentials were supplied, or the credentials were unavailable or inaccessible (No Kerberos credentials available (default cache: /tmp/krb5cc_389)) Jan 19 15:44:56 ipa003.test.openqa.fedoraproject.org ns-slapd[28327]: GSSAPI client step 1 Jan 19 15:44:56 ipa003.test.openqa.fedoraproject.org ns-slapd[28327]: GSSAPI client step 1 Jan 19 15:44:56 ipa003.test.openqa.fedoraproject.org ns-slapd[28327]: GSSAPI Error: No credentials were supplied, or the credentials were unavailable or inaccessible (No Kerberos credentials available (default cache: /tmp/krb5cc_389)) Jan 19 15:44:59 ipa003.test.openqa.fedoraproject.org ns-slapd[28327]: GSSAPI client step 1 Jan 19 15:44:59 ipa003.test.openqa.fedoraproject.org ns-slapd[28327]: GSSAPI client step 1 Jan 19 15:44:59 ipa003.test.openqa.fedoraproject.org ns-slapd[28327]: GSSAPI Error: No credentials were supplied, or the credentials were unavailable or inaccessible (No Kerberos credentials available (default cache: /tmp/krb5cc_389)) Jan 19 15:45:02 ipa003.test.openqa.fedoraproject.org ns-slapd[28327]: GSSAPI client step 1 Jan 19 15:45:02 ipa003.test.openqa.fedoraproject.org ns-slapd[28327]: GSSAPI client step 1 Jan 19 15:45:02 ipa003.test.openqa.fedoraproject.org ns-slapd[28327]: GSSAPI Error: No credentials were supplied, or the credentials were unavailable or inaccessible (No Kerberos credentials available (default cache: /tmp/krb5cc_389)) Jan 19 15:45:05 ipa003.test.openqa.fedoraproject.org ns-slapd[28327]: GSSAPI client step 1 Jan 19 15:45:05 ipa003.test.openqa.fedoraproject.org ns-slapd[28327]: GSSAPI client step 1 Jan 19 15:45:05 ipa003.test.openqa.fedoraproject.org ns-slapd[28327]: GSSAPI Error: No credentials were supplied, or the credentials were unavailable or inaccessible (No Kerberos credentials available (default cache: /tmp/krb5cc_389)) Not sure what the ultimate problem is here, but the most obvious candidate for "thing that changed" is 389-ds-base, which went from 389-ds-base-2.0.1-1.fc34 to 389-ds-base-2.0.2-1.fc34 with a huge changelog.
Created attachment 1748892 [details] /var/log tarball from the replica Full tarball of /var/log from the replica system (or the system that was *trying* to be a replica, anyway :>) If logs from the server it was trying to replicate are needed let me know and I'll try to extract them.
This is a regression from by a fix proposed by the Kerberos team: https://github.com/389ds/389-ds-base/issues/4537 https://bugzilla.redhat.com/show_bug.cgi?id=1868482 It had apparently gone through some FreeIPA tests, but it obviously is breaking here. We will need to revert that fix for now...
Hi Mark, I can also reproduce the issue on rawhide, with the following pkgs: krb5-server-1.19-0.beta2.1.fc34.x86_64 389-ds-base-2.0.2-1.fc34.x86_64 freeipa-server-4.9.0-1.fc34.x86_64 If I apply the fix from this PR https://github.com/freeipa/freeipa/pull/5409, the installation of the replica completes successfully. The patch has already been committed upstream in master + ipa-4-9 branches but is not included in any build yet.
RH folks from the last few comments: please don't make comments on Fedora bugs RH confidential unless there is actually some RH confidential information in them. AFAICS there is none in those comments; please change your comments to public unless there's some reason they need to be private. The comments say that https://github.com/freeipa/freeipa/pull/5409 fixes this, so re-assigning to freeipa and setting POST.
There's now a build with the fix: https://koji.fedoraproject.org/koji/buildinfo?buildID=1671929 so setting MODIFIED. Next Rawhide compose should have it fixed, hopefully.
Replica tests all passed in today's Rawhide, so looks good.