Bug 1918075 - FreeIPA replica deployment fails since Fedora-Rawhide-20210118.n.1 (389-ds-base-2.0.2-1.fc34)
Summary: FreeIPA replica deployment fails since Fedora-Rawhide-20210118.n.1 (389-ds-ba...
Keywords:
Status: CLOSED RAWHIDE
Alias: None
Product: Fedora
Classification: Fedora
Component: freeipa
Version: rawhide
Hardware: All
OS: Linux
unspecified
high
Target Milestone: ---
Assignee: IPA Maintainers
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard: openqa
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2021-01-20 00:45 UTC by Adam Williamson
Modified: 2021-01-23 01:17 UTC (History)
17 users (show)

Fixed In Version: freeipa-4.9.0-2.fc34
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2021-01-23 01:17:47 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
/var/log tarball from the replica (1.54 MB, application/octet-stream)
2021-01-20 00:49 UTC, Adam Williamson
no flags Details

Description Adam Williamson 2021-01-20 00:45:59 UTC
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.

Comment 1 Adam Williamson 2021-01-20 00:49:37 UTC
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.

Comment 2 mreynolds 2021-01-20 13:48:17 UTC
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...

Comment 5 Florence Blanc-Renaud 2021-01-20 18:18:55 UTC
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.

Comment 7 Adam Williamson 2021-01-20 19:48:20 UTC
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.

Comment 8 Adam Williamson 2021-01-21 17:39:31 UTC
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.

Comment 9 Adam Williamson 2021-01-23 01:17:47 UTC
Replica tests all passed in today's Rawhide, so looks good.


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