unexpected deletion of configured catalog zone

Job #2034208 failed for 8a962622:

dom1.example is deleted despite it being added.

11-Oct-2021 23:27:45.427 catz: dns_catz_add_zone catalog1.example
11-Oct-2021 23:27:45.427 catz: dns_catz_add_zone catalog2.example
11-Oct-2021 23:27:45.427 catz: dns_catz_add_zone catalog3.example
11-Oct-2021 23:27:45.427 /builds/isc-projects/bind9/bin/tests/system/catz/ns2/named.conf:39: catz: zone-directory 'nonexistent' not found; zone files will not be saved
11-Oct-2021 23:27:45.639 catz: updating catalog zone 'catalog1.example' with serial 1
11-Oct-2021 23:27:45.639 catz: update_from_db: iteration finished
11-Oct-2021 23:27:45.655 catz: update_from_db: new zone merged
11-Oct-2021 23:27:45.743 catz: updating catalog zone 'catalog3.example' with serial 1
11-Oct-2021 23:27:45.743 catz: update_from_db: iteration finished
11-Oct-2021 23:27:45.759 catz: update_from_db: new zone merged
11-Oct-2021 23:27:50.835 catz: updating catalog zone 'catalog1.example' with serial 2
11-Oct-2021 23:27:50.835 catz: update_from_db: iteration finished
11-Oct-2021 23:27:50.843 catz: iterating over 'dom1.example' from catalog 'catalog1.example'
11-Oct-2021 23:27:50.843 catz: adding zone 'dom1.example' from catalog 'catalog1.example' - success
11-Oct-2021 23:27:50.855 catz: update_from_db: new zone merged
11-Oct-2021 23:27:50.855 catz: new zone version came too soon, deferring update
11-Oct-2021 23:27:55.859 catz: updating catalog zone 'catalog1.example' with serial 2
11-Oct-2021 23:27:55.859 catz: update_from_db: iteration finished
11-Oct-2021 23:27:55.867 catz: iterating over 'dom1.example' from catalog 'catalog1.example'
11-Oct-2021 23:27:55.867 catz: deleting zone 'dom1.example' from catalog 'catalog1.example' - success
11-Oct-2021 23:27:55.879 catz: update_from_db: new zone merged
11-Oct-2021 23:27:55.879 catz: catz_delzone_taskaction: zone 'dom1.example' deleted
11-Oct-2021 23:28:00.747 catz: updating catalog zone 'catalog2.example' with serial 1
11-Oct-2021 23:28:00.747 catz: update_from_db: iteration finished
11-Oct-2021 23:28:00.767 catz: update_from_db: new zone merged
11-Oct-2021 23:28:02.863 catz: update already queued
11-Oct-2021 23:28:02.863 catz: updating catalog zone 'catalog1.example' with serial 3
11-Oct-2021 23:28:02.863 catz: update_from_db: iteration finished
11-Oct-2021 23:28:02.867 catz: deleting zone 'dom1.example' from catalog 'catalog1.example' - success
11-Oct-2021 23:28:02.879 catz: update_from_db: new zone merged
11-Oct-2021 23:28:02.879 catz: catz_delzone_taskaction: zone 'dom1.example' not found
11-Oct-2021 23:28:03.351 catz: new zone version came too soon, deferring update
11-Oct-2021 23:28:06.355 catz: updating catalog zone 'catalog2.example' with serial 2
11-Oct-2021 23:28:06.355 catz: update_from_db: iteration finished
11-Oct-2021 23:28:06.359 catz: iterating over 'dom4.example' from catalog 'catalog2.example'
11-Oct-2021 23:28:06.359 catz: adding zone 'dom4.example' from catalog 'catalog2.example' - success
11-Oct-2021 23:28:06.367 catz: update_from_db: new zone merged
11-Oct-2021 23:28:07.867 catz: new zone version came too soon, deferring update
11-Oct-2021 23:28:07.867 catz: update already queued
11-Oct-2021 23:28:08.871 catz: updating catalog zone 'catalog1.example' with serial 4
11-Oct-2021 23:28:08.871 catz: unknown record in catalog zone - trash2.foo.catalog1.example IN A(failure) - ignoring
11-Oct-2021 23:28:08.871 catz: unknown record in catalog zone - trash.catalog1.example IN A(failure) - ignoring
11-Oct-2021 23:28:08.871 catz: unknown record in catalog zone - version.catalog1.example IN A(failure) - ignoring
11-Oct-2021 23:28:08.871 catz: unknown record in catalog zone - blahblah.636722929740e507aaf27c502812fc395d30fb17.zones.catalog1.example IN TXT(failure) - ignoring
11-Oct-2021 23:28:08.871 catz: unknown record in catalog zone - foobarbaz.b901f492f3ebf6c1e5b597e51766f02f0479eb03.zones.catalog1.example IN APL(failure) - ignoring
11-Oct-2021 23:28:08.871 catz: unknown record in catalog zone - e721433b6160b450260d4f54b3ec8bab30cb3b83.zones.catalog1.example IN NS(failure) - ignoring
11-Oct-2021 23:28:08.871 catz: unknown record in catalog zone - trash3.zones.catalog1.example IN NS(failure) - ignoring
11-Oct-2021 23:28:08.871 catz: update_from_db: iteration finished

Closer look at the zone disappearing while the TXT queries for the new records are being made.

11-Oct-2021 23:27:54.819 query client=0x7b7c00070178 thread=0x7feb7696e700(dom1.example/TXT): ns__query_start
11-Oct-2021 23:27:54.819 client @0x7b7c00070178 10.53.0.1#39041 (dom1.example): query 'dom1.example/TXT/IN' approved
11-Oct-2021 23:27:54.819 query client=0x7b7c00070178 thread=0x7feb7696e700(dom1.example/TXT): query_lookup
11-Oct-2021 23:27:54.819 query client=0x7b7c00070178 thread=0x7feb7696e700(dom1.example/TXT): query_gotanswer
11-Oct-2021 23:27:54.819 client @0x7b7c00070178 10.53.0.1#39041 (dom1.example): rrl=(nil), HAVECOOKIE=0, result=DNS_R_NXRRSET, fname=0x7b5400030480(1), is_zone=1, RECURSIONOK=0, query.rpz_st=(nil)(0), RRL_CHECKED=0
11-Oct-2021 23:27:54.819 query client=0x7b7c00070178 thread=0x7feb7696e700(dom1.example/TXT): query_checkrpz
11-Oct-2021 23:27:54.819 query client=0x7b7c00070178 thread=0x7feb7696e700(dom1.example/TXT): rpz_rewrite
11-Oct-2021 23:27:54.819 query client=0x7b7c00070178 thread=0x7feb7696e700(dom1.example/TXT): query_nodata
11-Oct-2021 23:27:54.819 query client=0x7b7c00070178 thread=0x7feb7696e700(dom1.example/TXT): query_sign_nodata
11-Oct-2021 23:27:54.819 query client=0x7b7c00070178 thread=0x7feb7696e700(dom1.example/TXT): query_addsoa
11-Oct-2021 23:27:54.819 query client=0x7b7c00070178 thread=0x7feb7696e700(dom1.example/TXT): query_addrrset
11-Oct-2021 23:27:54.819 query client=0x7b7c00070178 thread=0x7feb7696e700(dom1.example/TXT): query_setorder
11-Oct-2021 23:27:54.819 query client=0x7b7c00070178 thread=0x7feb7696e700(dom1.example/TXT): query_additional
11-Oct-2021 23:27:54.819 query client=0x7b7c00070178 thread=0x7feb7696e700(dom1.example/TXT): query_additional: done
11-Oct-2021 23:27:54.819 query client=0x7b7c00070178 thread=0x7feb7696e700(dom1.example/TXT): query_addrrset: done
11-Oct-2021 23:27:54.819 query client=0x7b7c00070178 thread=0x7feb7696e700(dom1.example/TXT): ns_query_done
11-Oct-2021 23:27:54.819 client @0x7b7c00070178 10.53.0.1#39041 (dom1.example): reset client
11-Oct-2021 23:27:54.819 query client=0x7b7c00070178 thread=0x7feb7696e700(dom1.example/TXT): query_reset
11-Oct-2021 23:27:55.435 client @0x7b7c0002f578 10.53.0.1#36757: received notify for zone 'dom1.example'
11-Oct-2021 23:27:55.435 zone dom1.example/IN: notify from 10.53.0.1#36757: serial 2
11-Oct-2021 23:27:55.435 queue_soa_query: zone dom1.example/IN: enter
11-Oct-2021 23:27:55.435 soa_query: zone dom1.example/IN: enter
11-Oct-2021 23:27:55.439 refresh_callback: zone dom1.example/IN: enter
11-Oct-2021 23:27:55.439 refresh_callback: zone dom1.example/IN: serial: new 2, old 1
11-Oct-2021 23:27:55.439 queue_xfrin: zone dom1.example/IN: enter
11-Oct-2021 23:27:55.439 zone dom1.example/IN: Transfer started.
11-Oct-2021 23:27:55.439 zone dom1.example/IN: requesting IXFR from 10.53.0.1#6200
11-Oct-2021 23:27:55.439 transfer of 'dom1.example/IN' from 10.53.0.1#6200: connected using 10.53.0.2#44285
11-Oct-2021 23:27:55.439 transfer of 'dom1.example/IN' from 10.53.0.1#6200: requesting IXFR for serial 1
11-Oct-2021 23:27:55.439 transfer of 'dom1.example/IN' from 10.53.0.1#6200: sent request data
11-Oct-2021 23:27:55.443 transfer of 'dom1.example/IN' from 10.53.0.1#6200: received 191 bytes
;dom1.example.                  IN      IXFR
dom1.example.           3600    IN      SOA     . . 2 3600 3600 3600 3600
dom1.example.           3600    IN      SOA     . . 1 3600 3600 3600 3600
dom1.example.           3600    IN      SOA     . . 2 3600 3600 3600 3600
dom1.example.           0       IN      TXT     "added" "record"
dom1.example.           3600    IN      SOA     . . 2 3600 3600 3600 3600
11-Oct-2021 23:27:55.443 transfer of 'dom1.example/IN' from 10.53.0.1#6200: got incremental response
11-Oct-2021 23:27:55.443 journal file zonedir/__catz___default_catalog1.example_dom1.example.db.jnl does not exist, creating it
11-Oct-2021 23:27:55.443 del dom1.example.              3600    IN      SOA     . . 1 3600 3600 3600 3600
11-Oct-2021 23:27:55.447 add dom1.example.              3600    IN      SOA     . . 2 3600 3600 3600 3600
11-Oct-2021 23:27:55.447 add dom1.example.              0       IN      TXT     "added" "record"
11-Oct-2021 23:27:55.447 dns_zone_verifydb: zone dom1.example/IN: enter
11-Oct-2021 23:27:55.447 zone_needdump: zone dom1.example/IN: enter
11-Oct-2021 23:27:55.447 zone_settimer: zone dom1.example/IN: enter
11-Oct-2021 23:27:55.447 zone dom1.example/IN: zone transfer finished: success
11-Oct-2021 23:27:55.447 zone dom1.example/IN: transferred serial 2
11-Oct-2021 23:27:55.447 zone_needdump: zone dom1.example/IN: enter
11-Oct-2021 23:27:55.447 zone_settimer: zone dom1.example/IN: enter
11-Oct-2021 23:27:55.447 zone_settimer: zone dom1.example/IN: enter
11-Oct-2021 23:27:55.447 transfer of 'dom1.example/IN' from 10.53.0.1#6200: Transfer status: success
11-Oct-2021 23:27:55.447 transfer of 'dom1.example/IN' from 10.53.0.1#6200: Transfer completed: 1 messages, 5 records, 191 bytes, 0.007 secs (27285 bytes/sec) (serial 2)
11-Oct-2021 23:27:55.447 transfer of 'dom1.example/IN' from 10.53.0.1#6200: freeing transfer context
11-Oct-2021 23:27:55.859 catz: updating catalog zone 'catalog1.example' with serial 2
11-Oct-2021 23:27:55.859 catz: update_from_db: iteration finished
11-Oct-2021 23:27:55.867 catz: iterating over 'dom1.example' from catalog 'catalog1.example'
11-Oct-2021 23:27:55.867 catz: deleting zone 'dom1.example' from catalog 'catalog1.example' - success
11-Oct-2021 23:27:55.879 catz: update_from_db: new zone merged
11-Oct-2021 23:27:55.879 calling free_rbtdb(dom1.example)
11-Oct-2021 23:27:55.879 done free_rbtdb(dom1.example)
11-Oct-2021 23:27:55.879 catz: catz_delzone_taskaction: zone 'dom1.example' deleted
11-Oct-2021 23:27:55.883 zone_shutdown: zone dom1.example/IN: shutting down
11-Oct-2021 23:27:56.027 query client=0x7b7c0001f978 thread=0x7feb78537700(dom1.example/TXT): qctx_init
11-Oct-2021 23:27:56.027 query client=0x7b7c0001f978 thread=0x7feb78537700(dom1.example/TXT): client attr:0x22300, query attr:0x700, restarts:0, origqname:dom1.example, timer:0, authdb:0, referral:0
11-Oct-2021 23:27:56.027 query client=0x7b7c0001f978 thread=0x7feb78537700(dom1.example/TXT): ns__query_start
11-Oct-2021 23:27:56.027 query client=0x7b7c0001f978 thread=0x7feb78537700(dom1.example/TXT): ns_query_done
11-Oct-2021 23:27:56.027 client @0x7b7c0001f978 10.53.0.1#34865 (dom1.example): query failed (REFUSED) for dom1.example/IN/TXT at query.c:5484

S:catz:2021-10-11T23:27:42+0000
T:catz:1:A
A:catz:System test catz
I:catz:PORTRANGE:6200 - 6299
I:catz:starting servers
I:catz:Testing adding/removing of domain in catalog zone
I:catz:checking that dom1.example. is not served by primary (1)
I:catz:Adding a domain dom1.example. to primary via RNDC (2)
I:catz:checking that dom1.example. is now served by primary (3)
I:catz:Adding domain dom1.example. to catalog1 zone (4)
I:catz:waiting for secondary to sync up (5)
I:catz:checking that dom1.example. is served by secondary (6)
I:catz:checking that zone-directory is populated (7)
I:catz:update dom1.example. (8)
I:catz:wait for secondary to be updated (9)
I:catz:failed
I:catz:check that journal was created for cleanup test (10)
I:catz:failed

Need to check v9.17

Edited Oct 13, 2021 by Mark Andrews

To upload designs, you'll need to enable LFS and have an admin enable hashed storage. More information