The nightly test test_dns_locations.py::TestDNSLocations::test_without_locations is failing when the repo updates-testing is enabled, see PR 468 [testing_master_testing]. logs, report
test_dns_locations.py::TestDNSLocations::test_without_locations
The issue appeared with 389-ds update to 389-ds-base-1.4.3.13-1.fc32.x86_64 and seems indeed linked to the new version, as we can see errors in dirsrv error log:
[11/Oct/2020:05:20:44.915642535 +0000] - ERR - content-sync-plugin - ignore_op_pl can not retrieve an operation (0x7f4cf370fe00) in pending list [11/Oct/2020:05:20:46.108335425 +0000] - ERR - content-sync-plugin - ignore_op_pl can not retrieve an operation (0x7f4cf370f600) in pending list [11/Oct/2020:05:20:46.151355081 +0000] - ERR - content-sync-plugin - ignore_op_pl can not retrieve an operation (0x7f4cf370f600) in pending list [11/Oct/2020:05:20:47.282344683 +0000] - ERR - content-sync-plugin - ignore_op_pl can not retrieve an operation (0x7f4cef172400) in pending list [...] [11/Oct/2020:05:22:58.728373068 +0000] - ERR - content-sync-plugin - ignore_op_pl operation (0x7f4cdbebbe00) from the pending list [11/Oct/2020:05:22:58.780623922 +0000] - NOTICE - NSMMReplicationPlugin - changelog program - _cl5ConstructRUV - Rebuilding the replication changelog RUV, this may take several minutes... [11/Oct/2020:05:22:58.781926757 +0000] - NOTICE - NSMMReplicationPlugin - changelog program - _cl5ConstructRUV - Rebuilding replication changelog RUV complete. Result 0 (Success) [11/Oct/2020:05:22:58.786714788 +0000] - NOTICE - NSMMReplicationPlugin - changelog program - _cl5ConstructRUV - Rebuilding the replication changelog RUV, this may take several minutes... [11/Oct/2020:05:22:58.787986129 +0000] - NOTICE - NSMMReplicationPlugin - changelog program - _cl5ConstructRUV - Rebuilding replication changelog RUV complete. Result 0 (Success) [11/Oct/2020:05:22:58.799454840 +0000] - ERR - content-sync-plugin - ignore_op_pl can not retrieve an operation (0x7f4cdbea1a00) in pending list [11/Oct/2020:05:22:59.977005627 +0000] - INFO - NSMMReplicationPlugin - repl5_tot_run - Beginning total update of replica "agmt="cn=meToreplica1.ipa.test" (replica1:389)". [11/Oct/2020:05:22:59.982389030 +0000] - NOTICE - NSMMReplicationPlugin - replica_subentry_check - Need to create replication keep alive entry <cn=repl keep alive 4,dc=ipa,dc=test> [11/Oct/2020:05:22:59.983814557 +0000] - INFO - NSMMReplicationPlugin - replica_subentry_create - add dn: cn=repl keep alive 4,dc=ipa,dc=test objectclass: top objectclass: ldapsubentry objectclass: extensibleObject cn: repl keep alive 4 [11/Oct/2020:05:23:02.774513033 +0000] - INFO - NSMMReplicationPlugin - repl5_tot_run - Finished total update of replica "agmt="cn=meToreplica1.ipa.test" (replica1:389)". Sent 499 entries. [11/Oct/2020:05:23:04.777601506 +0000] - ERR - content-sync-plugin - ignore_op_pl can not retrieve an operation (0x7f4cdbea1a00) in pending list
The issue may be linked to https://github.com/389ds/389-ds-base/issues/4363, @tbordaz is already investigating.
Similar error messages seen in test_integration/test_replica_promotion.py::TestHiddenReplicaPromotion::test_hidden_replica_demote
test_integration/test_replica_promotion.py::TestHiddenReplicaPromotion::test_hidden_replica_demote
Same failure in [testing_master_testing Nightly PR #481 ; logs
Metadata Update from @frenaud: - Issue tagged with: tracker
We see this also reproducible in Azure CI with test_sign_root_zone test, for example. https://dev.azure.com/freeipa/freeipa/_build/results?buildId=6771&view=ms.vss-test-web.build-test-results-tab&runId=146146&resultId=100000&paneView=debug contains symptoms. There we can see a bug with the entries returned by syncrepl, bind-dyndb-ldap even complains about an attempt to reconstruct non-existing entry:
test_sign_root_zone
Nov 11 20:52:12 master1.ipa.test ipa-dnskeysyncd[4289]: ipaserver.dnssec.syncrepl: DEBUG New cookie is: master1.ipa.test:389#krbprincipalname=ipa-dnskeysyncd/master1.ipa.test@ipa.test,cn=services,cn=accounts,dc=ipa,dc=test:cn=dns,dc=ipa,dc=test:(|(obj ectClass=idnsZone)(objectClass=idnsSecKey)(objectClass=ipk11PublicKey))#66 Nov 11 20:52:12 master1.ipa.test ipa-ods-exporter[4878]: ipa-ods-exporter: INFO HSM synchronization finished, skipping zone synchronization. Nov 11 20:52:12 master1.ipa.test ns-slapd[3371]: [11/Nov/2020:20:52:12.448994578 +0000] - ERR - log_result - Internal unindexed search: source (cn=server,cn=plugins,cn=config) search base="cn=changelog" filter="(&(changenumber>=66)(targetuniqueid=c4126e0 1-245e11eb-89449097-0080450e))" etime=0.000316580 nentries=1 notes=U details="Partially Unindexed Filter" Nov 11 20:52:12 master1.ipa.test ns-slapd[3371]: [11/Nov/2020:20:52:12.452045884 +0000] - ERR - log_result - Internal unindexed search: source (cn=server,cn=plugins,cn=config) search base="cn=changelog" filter="(&(changenumber>=69)(targetuniqueid=c4126e0 1-245e11eb-89449097-0080450e))" etime=0.000210087 nentries=1 notes=U details="Partially Unindexed Filter" Nov 11 20:52:12 master1.ipa.test ipa-dnskeysyncd[4289]: ipaserver.dnssec.syncrepl: DEBUG Detected modify of entry: idnsname=ipa.test.,cn=dns,dc=ipa,dc=test c4126e01-245e-11eb-8944-90970080450e Nov 11 20:52:12 master1.ipa.test ipa-dnskeysyncd[4289]: ipaserver.dnssec.syncrepl: DEBUG New cookie is: master1.ipa.test:389#krbprincipalname=ipa-dnskeysyncd/master1.ipa.test@ipa.test,cn=services,cn=accounts,dc=ipa,dc=test:cn=dns,dc=ipa,dc=test:(|(obj ectClass=idnsZone)(objectClass=idnsSecKey)(objectClass=ipk11PublicKey))#71 Nov 11 20:52:12 master1.ipa.test named[4296]: zone ipa.test/IN: sending notifies (serial 1605127932) Nov 11 20:52:12 master1.ipa.test ns-slapd[3371]: [11/Nov/2020:20:52:12.619590493 +0000] - ERR - log_result - Internal unindexed search: source (cn=server,cn=plugins,cn=config) search base="cn=changelog" filter="(&(changenumber>=71)(targetuniqueid=c4126e2 8-245e11eb-89449097-0080450e))" etime=0.000175489 nentries=1 notes=U details="Partially Unindexed Filter" Nov 11 20:52:12 master1.ipa.test ns-slapd[3371]: [11/Nov/2020:20:52:12.635189598 +0000] - ERR - log_result - Internal unindexed search: source (cn=server,cn=plugins,cn=config) search base="cn=changelog" filter="(&(changenumber>=71)(targetuniqueid=c4126e0 1-245e11eb-89449097-0080450e))" etime=0.000361477 nentries=2 notes=U details="Partially Unindexed Filter" Nov 11 20:52:12 master1.ipa.test ns-slapd[3371]: [11/Nov/2020:20:52:12.637167372 +0000] - ERR - log_result - Internal unindexed search: source (cn=server,cn=plugins,cn=config) search base="cn=changelog" filter="(&(changenumber>=72)(targetuniqueid=c4126e0 1-245e11eb-89449097-0080450e))" etime=0.000265383 nentries=1 notes=U details="Partially Unindexed Filter" Nov 11 20:52:12 master1.ipa.test ipa-dnskeysyncd[4289]: ipaserver.dnssec.syncrepl: DEBUG Detected modify of entry: idnsname=ipa.test.,cn=dns,dc=ipa,dc=test c4126e01-245e-11eb-8944-90970080450e Nov 11 20:52:12 master1.ipa.test ipa-dnskeysyncd[4289]: ipaserver.dnssec.syncrepl: DEBUG New cookie is: master1.ipa.test:389#krbprincipalname=ipa-dnskeysyncd/master1.ipa.test@ipa.test,cn=services,cn=accounts,dc=ipa,dc=test:cn=dns,dc=ipa,dc=test:(|(obj ectClass=idnsZone)(objectClass=idnsSecKey)(objectClass=ipk11PublicKey))#71 Nov 11 20:52:12 master1.ipa.test systemd[1]: ipa-ods-exporter.service: Succeeded. Nov 11 20:52:12 master1.ipa.test ns-slapd[3371]: [11/Nov/2020:20:52:12.728491444 +0000] - ERR - log_result - Internal unindexed search: source (cn=server,cn=plugins,cn=config) search base="cn=changelog" filter="(&(changenumber>=73)(targetuniqueid=c4126e2 c-245e11eb-89449097-0080450e))" etime=0.000235085 nentries=1 notes=U details="Partially Unindexed Filter" Nov 11 20:52:12 master1.ipa.test ns-slapd[3371]: [11/Nov/2020:20:52:12.736314445 +0000] - ERR - log_result - Internal unindexed search: source (cn=server,cn=plugins,cn=config) search base="cn=changelog" filter="(&(changenumber>=71)(targetuniqueid=c4126e01-245e11eb-89449097-0080450e))" etime=0.000380876 nentries=3 notes=U details="Partially Unindexed Filter" Nov 11 20:52:12 master1.ipa.test ipa-dnskeysyncd[4289]: ipaserver.dnssec.syncrepl: DEBUG Detected modify of entry: idnsname=ipa.test.,cn=dns,dc=ipa,dc=test c4126e01-245e-11eb-8944-90970080450e Nov 11 20:52:12 master1.ipa.test ipa-dnskeysyncd[4289]: ipaserver.dnssec.syncrepl: DEBUG New cookie is: master1.ipa.test:389#krbprincipalname=ipa-dnskeysyncd/master1.ipa.test@ipa.test,cn=services,cn=accounts,dc=ipa,dc=test:cn=dns,dc=ipa,dc=test:(|(objectClass=idnsZone)(objectClass=idnsSecKey)(objectClass=ipk11PublicKey))#71 Nov 11 20:52:12 master1.ipa.test ns-slapd[3371]: [11/Nov/2020:20:52:12.739010173 +0000] - ERR - log_result - Internal unindexed search: source (cn=server,cn=plugins,cn=config) search base="cn=changelog" filter="(&(changenumber>=74)(targetuniqueid=c4126e01-245e11eb-89449097-0080450e))" etime=0.000271783 nentries=1 notes=U details="Partially Unindexed Filter" Nov 11 20:52:12 master1.ipa.test ns-slapd[3371]: [11/Nov/2020:20:52:12.874229045 +0000] - ERR - log_result - Internal unindexed search: source (cn=server,cn=plugins,cn=config) search base="cn=changelog" filter="(&(changenumber>=75)(targetuniqueid=c4126e30-245e11eb-89449097-0080450e))" etime=0.000166289 nentries=1 notes=U details="Partially Unindexed Filter" Nov 11 20:52:12 master1.ipa.test ns-slapd[3371]: [11/Nov/2020:20:52:12.883743838 +0000] - ERR - log_result - Internal unindexed search: source (cn=server,cn=plugins,cn=config) search base="cn=changelog" filter="(&(changenumber>=76)(targetuniqueid=c4126e34-245e11eb-89449097-0080450e))" etime=0.000136792 nentries=1 notes=U details="Partially Unindexed Filter" Nov 11 20:52:12 master1.ipa.test ns-slapd[3371]: [11/Nov/2020:20:52:12.887687786 +0000] - ERR - log_result - Internal unindexed search: source (cn=server,cn=plugins,cn=config) search base="cn=changelog" filter="(&(changenumber>=71)(targetuniqueid=c4126e01-245e11eb-89449097-0080450e))" etime=0.000952539 nentries=4 notes=U details="Partially Unindexed Filter" Nov 11 20:52:12 master1.ipa.test ipa-dnskeysyncd[4289]: ipaserver.dnssec.syncrepl: DEBUG Detected modify of entry: idnsname=ipa.test.,cn=dns,dc=ipa,dc=test c4126e01-245e-11eb-8944-90970080450e Nov 11 20:52:12 master1.ipa.test ipa-dnskeysyncd[4289]: ipaserver.dnssec.syncrepl: DEBUG New cookie is: master1.ipa.test:389#krbprincipalname=ipa-dnskeysyncd/master1.ipa.test@ipa.test,cn=services,cn=accounts,dc=ipa,dc=test:cn=dns,dc=ipa,dc=test:(|(objectClass=idnsZone)(objectClass=idnsSecKey)(objectClass=ipk11PublicKey))#71 Nov 11 20:52:12 master1.ipa.test ns-slapd[3371]: [11/Nov/2020:20:52:12.890710794 +0000] - ERR - log_result - Internal unindexed search: source (cn=server,cn=plugins,cn=config) search base="cn=changelog" filter="(&(changenumber>=77)(targetuniqueid=c4126e01-245e11eb-89449097-0080450e))" etime=0.001003136 nentries=1 notes=U details="Partially Unindexed Filter" Nov 11 20:52:12 master1.ipa.test ns-slapd[3371]: [11/Nov/2020:20:52:12.894072579 +0000] - ERR - log_result - Internal unindexed search: source (cn=server,cn=plugins,cn=config) search base="cn=changelog" filter="(&(changenumber>=78)(targetuniqueid=c4126e01-245e11eb-89449097-0080450e))" etime=0.000411374 nentries=2 notes=U details="Partially Unindexed Filter" Nov 11 20:52:12 master1.ipa.test ns-slapd[3371]: [11/Nov/2020:20:52:12.895515787 +0000] - ERR - log_result - Internal unindexed search: source (cn=server,cn=plugins,cn=config) search base="cn=changelog" filter="(&(changenumber>=71)(targetuniqueid=c4126e01-245e11eb-89449097-0080450e))" etime=0.000423473 nentries=5 notes=U details="Partially Unindexed Filter" Nov 11 20:52:12 master1.ipa.test ipa-dnskeysyncd[4289]: ipaserver.dnssec.syncrepl: DEBUG Detected modify of entry: idnsname=ipa.test.,cn=dns,dc=ipa,dc=test c4126e01-245e-11eb-8944-90970080450e Nov 11 20:52:12 master1.ipa.test ipa-dnskeysyncd[4289]: ipaserver.dnssec.syncrepl: DEBUG New cookie is: master1.ipa.test:389#krbprincipalname=ipa-dnskeysyncd/master1.ipa.test@ipa.test,cn=services,cn=accounts,dc=ipa,dc=test:cn=dns,dc=ipa,dc=test:(|(objectClass=idnsZone)(objectClass=idnsSecKey)(objectClass=ipk11PublicKey))#71 Nov 11 20:52:13 master1.ipa.test ns-slapd[3371]: [11/Nov/2020:20:52:13.029194957 +0000] - ERR - log_result - Internal unindexed search: source (cn=server,cn=plugins,cn=config) search base="cn=changelog" filter="(&(changenumber>=78)(targetuniqueid=c4126e38-245e11eb-89449097-0080450e))" etime=0.000208387 nentries=1 notes=U details="Partially Unindexed Filter" Nov 11 20:52:13 master1.ipa.test named[4296]: bug in ldap_entry_reconstruct(): protocol violation: attempt to reconstruct non-existing entry Nov 11 20:52:13 master1.ipa.test named[4296]: ldap_sync_search_entry failed: not found Nov 11 20:52:13 master1.ipa.test ns-slapd[3371]: [11/Nov/2020:20:52:13.032904221 +0000] - ERR - log_result - Internal unindexed search: source (cn=server,cn=plugins,cn=config) search base="cn=changelog" filter="(&(changenumber>=80)(targetuniqueid=c4126e3b-245e11eb-89449097-0080450e))" etime=0.000210186 nentries=1 notes=U details="Partially Unindexed Filter" Nov 11 20:52:13 master1.ipa.test ns-slapd[3371]: [11/Nov/2020:20:52:13.038452267 +0000] - ERR - log_result - Internal unindexed search: source (cn=server,cn=plugins,cn=config) search base="cn=changelog" filter="(&(changenumber>=71)(targetuniqueid=c4126e01-245e11eb-89449097-0080450e))" etime=0.000655058 nentries=6 notes=U details="Partially Unindexed Filter" Nov 11 20:52:13 master1.ipa.test ipa-dnskeysyncd[4289]: ipaserver.dnssec.syncrepl: DEBUG Detected modify of entry: idnsname=ipa.test.,cn=dns,dc=ipa,dc=test c4126e01-245e-11eb-8944-90970080450e Nov 11 20:52:13 master1.ipa.test ipa-dnskeysyncd[4289]: ipaserver.dnssec.syncrepl: DEBUG New cookie is: master1.ipa.test:389#krbprincipalname=ipa-dnskeysyncd/master1.ipa.test@ipa.test,cn=services,cn=accounts,dc=ipa,dc=test:cn=dns,dc=ipa,dc=test:(|(objectClass=idnsZone)(objectClass=idnsSecKey)(objectClass=ipk11PublicKey))#71 Nov 11 20:52:13 master1.ipa.test ns-slapd[3371]: [11/Nov/2020:20:52:13.040821015 +0000] - ERR - log_result - Internal unindexed search: source (cn=server,cn=plugins,cn=config) search base="cn=changelog" filter="(&(changenumber>=81)(targetuniqueid=c4126e01-245e11eb-89449097-0080450e))" etime=0.000301781 nentries=1 notes=U details="Partially Unindexed Filter" Nov 11 20:52:16 master1.ipa.test named[4296]: client @0x7fb58c0ce0e0 172.22.0.3#52434: received notify for zone '0.22.172.in-addr.arpa': not authoritative Nov 11 20:52:17 master1.ipa.test named[4296]: client @0x7fb58c0ce0e0 172.22.0.3#38735: received notify for zone 'ipa.test' Nov 11 20:52:17 master1.ipa.test named[4296]: zone ipa.test/IN: sending notifies (serial 1605127937)
This all happens with 389-ds-base 1.4.3.15-1.fc32 which supposedly has a fix for 389-ds issue 4363. Logs attached here. <img alt="logs-GATING.InstallDNSSECFirst_1_to_5-6771-5-5-2-Linux-X64.zip" src="/freeipa/issue/raw/files/8d3b99508551f41e98328f533315692608e33346ddb2459a0f37b7881893e0b1-logs-GATING.InstallDNSSECFirst_1_to_5-6771-5-5-2-Linux-X64.zip" />
Also happened on the master branch in PR #537
Same failure in [testing_master_pki] Nightly PR #535 report
Also affects:
TestDNSLocations::test_nsupdate_without_locations
TestDNSLocations::test_one_replica_in_location
TestDNSLocations::test_adtrust_system_records
PR363, details
Duplicate of https://pagure.io/freeipa/issue/8496, same root cause related to sync repl issue, hence closing this ticket and keeping all the info in 8496.
Metadata Update from @frenaud: - Issue close_status updated to: duplicate - Issue status updated to: Closed (was: Open)
Login to comment on this ticket.