#8538 [Tracker] Nightly failure in test_dns_locations.py::TestDNSLocations::test_without_locations
Opened 2 months ago by frenaud. Modified 12 days ago

Issue

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

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

Metadata Update from @frenaud:
- Issue tagged with: tracker

24 days ago

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:

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.
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

Login to comment on this ticket.

Metadata