Skip to content

Catalog confusion when a member is added and immediately deleted from the catalog zone before the adding is done in the catalog

Hello!

In our setup, we have a dynamic catalog zone called 'catz.'. From our provision system (syslog name: sync_db_to_knot) we send dynamic updates whenever a zone should be added or removed from the catalog zone. We queue a maximum of 30 member changes into one DDNS UPDATE packet.

Recently a customer of us added several zones and immediately afterwards removed them. This lead to a DDNS UPDATE packet where we added the member zones and shortly afterwards sent another DDNS UPDATE where we removed the same zones.

It seems that Knot correctly added and removed the zones from the catalog zone, but NOT from the catalog. On of the problematic zones was: XXXXXXXXXXigital.cg

See log below:

14:56:32 sync_db_to_knot[29464]: Queued 30 actions, building DDNS packet ...
14:56:32 sync_db_to_knot[29464]: ADD <27366095> XXXXXXXXXXigital.vu into DDNS packet
14:56:32 sync_db_to_knot[29464]: ADD <27366098> XXXXXXXXXX.ws into DDNS packet
14:56:32 sync_db_to_knot[29464]: ADD <27365824> XXXXXXXXXXigital.co.at into DDNS packet
14:56:32 sync_db_to_knot[29464]: ADD <27365832> XXXXXXXXXXigital.bi into DDNS packet
14:56:32 sync_db_to_knot[29464]: ADD <27365833> XXXXXXXXXXigital.bj into DDNS packet
14:56:32 sync_db_to_knot[29464]: ADD <27365919> XXXXXXXXXX.id into DDNS packet
14:56:32 sync_db_to_knot[29464]: ADD <27365896> XXXXXXXXXX.gq into DDNS packet
14:56:32 sync_db_to_knot[29464]: ADD <27365954> XXXXXXXXXX.mk into DDNS packet
14:56:32 sync_db_to_knot[29464]: ADD <27365821> XXXXXXXXXX.com.ar into DDNS packet
14:56:32 sync_db_to_knot[29464]: ADD <27365819> XXXXXXXXXX.am into DDNS packet
14:56:32 sync_db_to_knot[29464]: ADD <27365845> XXXXXXXXXX.by into DDNS packet
14:56:32 sync_db_to_knot[29464]: ADD <27365837> XXXXXXXXXXigital.bs into DDNS packet
14:56:32 sync_db_to_knot[29464]: ADD <27365915> XXXXXXXXXX.hu into DDNS packet
14:56:32 sync_db_to_knot[29464]: ADD <27365969> XXXXXXXXXX.com.my into DDNS packet
14:56:32 sync_db_to_knot[29464]: ADD <27365970> XXXXXXXXXX.my into DDNS packet
14:56:32 sync_db_to_knot[29464]: ADD <27365827> XXXXXXXXXXigital.co.az into DDNS packet
14:56:32 sync_db_to_knot[29464]: ADD <27365826> XXXXXXXXXXigital.az into DDNS packet
14:56:32 sync_db_to_knot[29464]: ADD <27365918> XXXXXXXXXX.co.id into DDNS packet
14:56:32 sync_db_to_knot[29464]: ADD <27365818> XXXXXXXXXX.al into DDNS packet
14:56:32 sync_db_to_knot[29464]: ADD <27365852> XXXXXXXXXXigital.cg into DDNS packet
--> DDNS UPDATE with "add PTR XXXXXXXXXXigital.cg"
14:56:32 sync_db_to_knot[29464]: ADD <27365949> XXXXXXXXXX.lv into DDNS packet
14:56:32 sync_db_to_knot[29464]: ADD <27365823> XXXXXXXXXX.at into DDNS packet
14:56:32 sync_db_to_knot[29464]: ADD <27365856> XXXXXXXXXX.cm into DDNS packet
14:56:32 sync_db_to_knot[29464]: ADD <27365935> XXXXXXXXXX.kz into DDNS packet
14:56:32 sync_db_to_knot[29464]: ADD <27365886> XXXXXXXXXX.ga into DDNS packet
14:56:32 sync_db_to_knot[29464]: ADD <27365834> XXXXXXXXXXigital.bo into DDNS packet
14:56:32 sync_db_to_knot[29464]: ADD <27365849> XXXXXXXXXX.ca into DDNS packet
14:56:32 sync_db_to_knot[29464]: ADD <27365851> XXXXXXXXXX.cf into DDNS packet
14:56:32 sync_db_to_knot[29464]: ADD <27365947> XXXXXXXXXX.lu into DDNS packet
14:56:32 sync_db_to_knot[29464]: ADD <27365927> XXXXXXXXXX.co.ke into DDNS packet
14:56:32 sync_db_to_knot[29464]: Sending DDNS packet to Knot ...
14:56:32 knotd[28837]: 2022-10-04T14:56:32+0000 debug: [catz.] ACL, allowed, action update, remote AA.BB.CC.DD@56014, key 'XXXXX.'
14:56:32 knotd[28837]: 2022-10-04T14:56:32+0000 info: [catz.] DDNS, processing 1 updates
14:56:32 knotd[28837]: 2022-10-04T14:56:32+0000 info: [catz.] catalog reloaded, 30 updates
14:56:32 knotd[28837]: 2022-10-04T14:56:32+0000 info: [catz.] DDNS, finished, serial 1661343424 -> 1661343425, 0.11 seconds
14:56:32 sync_db_to_knot[29464]: Sending DDNS packet to Knot ... done
--> DDNS UPDATE received by Knot and "30 updates" detected.

14:56:32 sync_db_to_knot[29464]: Queued 30 actions, building DDNS packet ...
14:56:32 sync_db_to_knot[29464]: ADD <27365902> XXXXXXXXXX.com.hk into DDNS packet
14:56:32 sync_db_to_knot[29464]: ADD <27365923> XXXXXXXXXX.is into DDNS packet
14:56:32 sync_db_to_knot[29464]: ADD <27365986> XXXXXXXXXX.no into DDNS packet
14:56:32 sync_db_to_knot[29464]: DELETE <27365918> XXXXXXXXXX.co.id into DDNS packet
14:56:32 sync_db_to_knot[29464]: DELETE <27365849> XXXXXXXXXX.ca into DDNS packet
14:56:32 sync_db_to_knot[29464]: DELETE <27365845> XXXXXXXXXX.by into DDNS packet
14:56:32 sync_db_to_knot[29464]: DELETE <27365827> XXXXXXXXXXigital.co.az into DDNS packet
14:56:32 sync_db_to_knot[29464]: DELETE <27365833> XXXXXXXXXXigital.bj into DDNS packet
14:56:32 sync_db_to_knot[29464]: DELETE <27365927> XXXXXXXXXX.co.ke into DDNS packet
14:56:32 sync_db_to_knot[29464]: DELETE <27366033> XXXXXXXXXX.rs into DDNS packet
14:56:32 sync_db_to_knot[29464]: DELETE <27365969> XXXXXXXXXX.com.my into DDNS packet
14:56:32 sync_db_to_knot[29464]: DELETE <27366076> XXXXXXXXXX.uz into DDNS packet
14:56:32 sync_db_to_knot[29464]: DELETE <27366043> XXXXXXXXXX.sg into DDNS packet
14:56:32 sync_db_to_knot[29464]: DELETE <27365935> XXXXXXXXXX.kz into DDNS packet
14:56:32 sync_db_to_knot[29464]: DELETE <27365954> XXXXXXXXXX.mk into DDNS packet
14:56:32 sync_db_to_knot[29464]: DELETE <27365826> XXXXXXXXXXigital.az into DDNS packet
14:56:32 sync_db_to_knot[29464]: DELETE <27366007> XXXXXXXXXX.pk into DDNS packet
14:56:32 sync_db_to_knot[29464]: DELETE <27365852> XXXXXXXXXXigital.cg into DDNS packet
--> DDNS UPDATE with "del PTR XXXXXXXXXXigital.cg"
14:56:32 sync_db_to_knot[29464]: DELETE <27365819> XXXXXXXXXX.am into DDNS packet
14:56:32 sync_db_to_knot[29464]: DELETE <27365834> XXXXXXXXXXigital.bo into DDNS packet
14:56:32 sync_db_to_knot[29464]: DELETE <27365949> XXXXXXXXXX.lv into DDNS packet
14:56:32 sync_db_to_knot[29464]: DELETE <27365919> XXXXXXXXXX.id into DDNS packet
14:56:32 sync_db_to_knot[29464]: DELETE <25286404> XXXXXXXXXXigital.ar into DDNS packet
14:56:32 sync_db_to_knot[29464]: DELETE <27365832> XXXXXXXXXXigital.bi into DDNS packet
14:56:32 sync_db_to_knot[29464]: DELETE <27366045> XXXXXXXXXX.si into DDNS packet
14:56:32 sync_db_to_knot[29464]: DELETE <27365821> XXXXXXXXXX.com.ar into DDNS packet
14:56:32 sync_db_to_knot[29464]: DELETE <27365851> XXXXXXXXXX.cf into DDNS packet
14:56:32 sync_db_to_knot[29464]: DELETE <27366008> XXXXXXXXXX.pl into DDNS packet
14:56:32 sync_db_to_knot[29464]: DELETE <27365824> XXXXXXXXXXigital.co.at into DDNS packet
14:56:32 sync_db_to_knot[29464]: DELETE <27365837> XXXXXXXXXXigital.bs into DDNS packet
14:56:32 sync_db_to_knot[29464]: Sending DDNS packet to Knot ...
14:56:32 knotd[28837]: 2022-10-04T14:56:32+0000 debug: [catz.] ACL, allowed, action update, remote AA.BB.CC.DD@39450, key 'XXXXX.'
14:56:33 knotd[28837]: 2022-10-04T14:56:33+0000 info: [catz.] zone file updated, serial 1661343424 -> 1661343425
14:56:33 knotd[28837]: 2022-10-04T14:56:33+0000 info: [catz.] DDNS, processing 1 updates
14:56:33 knotd[28837]: 2022-10-04T14:56:33+0000 info: [catz.] catalog reloaded, 10 updates
14:56:33 knotd[28837]: 2022-10-04T14:56:33+0000 info: [catz.] DDNS, finished, serial 1661343425 -> 1661343426, 0.10 seconds
14:56:33 sync_db_to_knot[29464]: Sending DDNS packet to Knot ... done
--> DDNS UPDATE received by Knot. Altough there are 30 updates in the UPDATE packet, Knot sees only "10 updates".
--> My suspicion: The catalog updates from the first DDNS UPDATE were not processed completely into the catalog or the Knot config. Hence, only "10 updates" were detected and queued. So, deleting XXXXXXXXXXigital.cg was not queued as it was not created yet.

14:56:33 sync_db_to_knot[29464]: Queued 9 actions, building DDNS packet ...
14:56:33 sync_db_to_knot[29464]: DELETE <27366031> XXXXXXXXXX.ro into DDNS packet
14:56:33 sync_db_to_knot[29464]: DELETE <27365823> XXXXXXXXXX.at into DDNS packet
14:56:33 sync_db_to_knot[29464]: DELETE <27366080> XXXXXXXXXX.com.ve into DDNS packet
14:56:33 sync_db_to_knot[29464]: DELETE <27366042> XXXXXXXXXX.com.sg into DDNS packet
14:56:33 sync_db_to_knot[29464]: DELETE <27365856> XXXXXXXXXX.cm into DDNS packet
14:56:33 sync_db_to_knot[29464]: DELETE <27365902> XXXXXXXXXX.com.hk into DDNS packet
14:56:33 sync_db_to_knot[29464]: DELETE <27365986> XXXXXXXXXX.no into DDNS packet
14:56:33 sync_db_to_knot[29464]: DELETE <27365818> XXXXXXXXXX.al into DDNS packet
14:56:33 sync_db_to_knot[29464]: DELETE <27365886> XXXXXXXXXX.ga into DDNS packet
14:56:33 sync_db_to_knot[29464]: Sending DDNS packet to Knot
14:56:33 knotd[28837]: 2022-10-04T14:56:33+0000 debug: [catz.] ACL, allowed, action update, remote AA.BB.CC.DD@56155, key 'XXXXX.'
14:56:33 knotd[28837]: 2022-10-04T14:56:33+0000 info: [catz.] zone file updated, serial 1661343425 -> 1661343426
14:56:33 knotd[28837]: 2022-10-04T14:56:33+0000 info: [catz.] DDNS, processing 1 updates
14:56:34 knotd[28837]: 2022-10-04T14:56:34+0000 info: [catz.] catalog reloaded, 3 updates
14:56:35 knotd[28837]: 2022-10-04T14:56:35+0000 notice: [catz.] journal is full, flushing
14:56:35 knotd[28837]: 2022-10-04T14:56:35+0000 info: [catz.] DDNS, finished, serial 1661343426 -> 1661343427, 1.56 seconds
14:56:35 sync_db_to_knot[29464]: Sending DDNS packet to Knot ... done
14:56:35 sync_db_to_knot[29464]: Sent DDNS UPDATE to knot.
--> Same problem here: the DDNS packet cotnains 9 DELETE actions, but Knot only detects "3 updates"

14:56:37 knotd[28837]: 2022-10-04T14:56:37+0000 notice: [XXXXXXXXXXigital.ar.] zone purged
14:56:37 knotd[28837]: 2022-10-04T14:56:37+0000 notice: [XXXXXXXXXX.pk.] zone purged
14:56:37 knotd[28837]: 2022-10-04T14:56:37+0000 notice: [XXXXXXXXXX.pl.] zone purged
14:56:37 knotd[28837]: 2022-10-04T14:56:37+0000 notice: [XXXXXXXXXX.ro.] zone purged
14:56:37 knotd[28837]: 2022-10-04T14:56:37+0000 notice: [XXXXXXXXXX.rs.] zone purged
14:56:37 knotd[28837]: 2022-10-04T14:56:37+0000 notice: [XXXXXXXXXX.com.sg.] zone purged
14:56:37 knotd[28837]: 2022-10-04T14:56:37+0000 notice: [XXXXXXXXXX.sg.] zone purged
14:56:37 knotd[28837]: 2022-10-04T14:56:37+0000 notice: [XXXXXXXXXX.si.] zone purged
14:56:37 knotd[28837]: 2022-10-04T14:56:37+0000 notice: [XXXXXXXXXX.uz.] zone purged
14:56:37 knotd[28837]: 2022-10-04T14:56:37+0000 notice: [XXXXXXXXXX.com.ve.] zone purged
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXX.al.] zone will be loaded
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXX.al.] zone added from catalog
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXX.am.] zone will be loaded
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXX.am.] zone added from catalog
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXX.com.ar.] zone will be loaded
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXX.al.] zone will be bootstrapped
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXX.com.ar.] zone added from catalog
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXX.am.] zone will be bootstrapped
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXXigital.co.at.] zone will be loaded
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXX.com.ar.] zone will be bootstrapped
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXXigital.co.at.] zone added from catalog
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXX.at.] zone will be loaded
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXX.at.] zone added from catalog
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXXigital.co.az.] zone will be loaded
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXXigital.co.az.] zone added from catalog
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXXigital.co.at.] zone will be bootstrapped
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXXigital.az.] zone will be loaded
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXX.at.] zone will be bootstrapped
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXXigital.az.] zone added from catalog
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXXigital.bi.] zone will be loaded
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXXigital.co.az.] zone will be bootstrapped
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXXigital.az.] zone will be bootstrapped
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXXigital.bi.] zone added from catalog
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXXigital.bj.] zone will be loaded
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXXigital.bj.] zone added from catalog
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXXigital.bo.] zone will be loaded
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXXigital.bo.] zone added from catalog
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXXigital.bs.] zone will be loaded
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXXigital.bs.] zone added from catalog
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXX.by.] zone will be loaded
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXX.by.] zone added from catalog
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXX.ca.] zone will be loaded
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXX.ca.] zone added from catalog
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXX.by.] zone will be bootstrapped
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXX.cf.] zone will be loaded
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXX.cf.] zone added from catalog
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXX.ca.] zone will be bootstrapped
14:56:43 knotd[28837]: 2022-10-04T14:56:43+0000 info: [XXXXXXXXXXigital.cg.] zone will be loaded
--> the zone XXXXXXXXXXigital.cg gets added to the catalog and zone config although the zone is not present in the catalog zone anymore.

Hence, at this point in time, XXXXXXXXXXigital.cg is not present in the catalog zone, but is present in the catalog.

To recover from this error, we had to restart Knot. On startup, Knot detects that XXXXXXXXXXigital.cg is not part of the catalog anymore and purges the zone.