Unexpected SERVFAIL (RRsigs missing) from pdns-recursor for a non-secured zone

[kpfleming]

My DNS configuration is hidden primary -> hidden secondary -> recursor. The auth servers are running pdns-auth 5.0.0-1pdns.debian13 and the recursor is running 5.3.0-1pdns.debian13.

The hidden primary has a 'producer' catalog zone along with a number of normal 'primary' zones. The hidden secondary has a matching 'consumer' catalog zone. The recursor also uses this catalog zone for configuring forward-zones; it forwards queries to the hidden secondary (the hidden secondary and recursor are on the same machine). The hidden secondary is configured with secondary-do-renotify so that it will send NOTIFY to the recursor when it receives new content for any of the zones; the recursor uses this both to refresh the catalog zone and to wipe caches for the regular zones.

Today I added a new zone 714durham.us on the hidden primary, and included it into the catalog zone. The hidden primary sent NOTIFY to the hidden secondary for both zones, and the hidden secondary used AXFR to retrieve the contents of both zones. The hidden secondary sent NOTIFY to the recursor once those AXFRs were completed. The recursor used IXFR to retrieve the contents of the catalog zone from the hidden secondary. All of this was expected.

After that was completed, I used pdnsutil zone edit 714durham.us to add a number of RRs to the zone, including an MX RRset. The NOTIFY+AXFR process happened again. I then attempted to query the recursor for the MX RRs, and got a SERVFAIL response with EDE indicating "EDE: 10 (RRSIGs Missing)", which was surprising since the zone is not signed.

Querying the hidden secondary for the same RRs worked fine. I did not see anything out of the ordinary in the recursor logs, so I restarted it and sent the query again, and this time the recursor provided the proper answer.

Log from the hidden primary:

Oct 12 06:49:41 dns25 pdns_server[66]: new CATALOG-HASH 'SlZ9Zp7CJUUMVSU28jBdGOIqEzMmHeJQGEuH9PlEPxY=' for zone 'public.catalog.km6g.us'
Oct 12 06:49:41 dns25 pdns_server[66]: AXFR-out zone 'public.catalog.km6g.us', client '[fddd:a03f:2620:707::1]:54369', transfer initiated
Oct 12 06:49:41 dns25 pdns_server[66]: AXFR-out zone '714durham.us', client '[fddd:a03f:2620:707::1]:56313', transfer initiated
Oct 12 06:49:42 dns25 pdns_server[66]: AXFR-out zone 'public.catalog.km6g.us', client '[fddd:a03f:2620:400::1]:56019', transfer initiated
Oct 12 06:49:42 dns25 pdns_server[66]: AXFR-out zone 'public.catalog.km6g.us', client '[fddd:a03f:2620:186::21]:34671', transfer initiated
Oct 12 06:49:42 dns25 pdns_server[66]: AXFR-out zone '714durham.us', client '[fddd:a03f:2620:186::21]:33917', transfer initiated
Oct 12 06:49:42 dns25 pdns_server[66]: AXFR-out zone '714durham.us', client '[fddd:a03f:2620:400::1]:39571', transfer initiated
Oct 12 06:49:42 dns25 pdns_server[66]: AXFR-out zone 'public.catalog.km6g.us', client '[fddd:a03f:2620:186::20]:47711', transfer initiated
Oct 12 06:49:42 dns25 pdns_server[66]: AXFR-out zone '714durham.us', client '[fddd:a03f:2620:186::20]:53577', transfer initiated
Oct 12 06:49:42 dns25 pdns_server[66]: Received unsuccessful notification report for '714durham.us' from [fddd:a03f:2620:707::1]:53, error: Query Refused
Oct 12 06:49:42 dns25 pdns_server[66]: Received unsuccessful notification report for '714durham.us' from [fddd:a03f:2620:186::20]:53153, error: Query Refused
Oct 12 06:49:42 dns25 pdns_server[66]: Received unsuccessful notification report for '714durham.us' from [fddd:a03f:2620:186::21]:53153, error: Query Refused
Oct 12 06:49:42 dns25 pdns_server[66]: Received unsuccessful notification report for '714durham.us' from [fddd:a03f:2620:300::1]:53, error: Query Refused
Oct 12 06:49:42 dns25 pdns_server[66]: Received unsuccessful notification report for '714durham.us' from [fddd:a03f:2620:400::1]:53, error: Query Refused
Oct 12 06:49:42 dns25 pdns_server[66]: AXFR-out zone 'public.catalog.km6g.us', client '[fddd:a03f:2620:300::1]:40281', transfer initiated
Oct 12 06:49:42 dns25 pdns_server[66]: AXFR-out zone '714durham.us', client '[fddd:a03f:2620:300::1]:55541', transfer initiated
Oct 12 06:53:41 dns25 pdns_server[66]: AXFR-out zone '415eighth.us', client '[fddd:a03f:2620:707::1]:47867', transfer initiated
Oct 12 06:53:42 dns25 pdns_server[66]: AXFR-out zone '415eighth.us', client '[fddd:a03f:2620:400::1]:49567', transfer initiated
Oct 12 06:53:42 dns25 pdns_server[66]: AXFR-out zone '415eighth.us', client '[fddd:a03f:2620:186::21]:35297', transfer initiated
Oct 12 06:53:42 dns25 pdns_server[66]: AXFR-out zone '415eighth.us', client '[fddd:a03f:2620:186::20]:57063', transfer initiated
Oct 12 06:53:42 dns25 pdns_server[66]: AXFR-out zone '415eighth.us', client '[fddd:a03f:2620:300::1]:35335', transfer initiated
Oct 12 06:54:41 dns25 pdns_server[66]: AXFR-out zone '714durham.us', client '[fddd:a03f:2620:707::1]:39071', transfer initiated
Oct 12 06:54:42 dns25 pdns_server[66]: AXFR-out zone '714durham.us', client '[fddd:a03f:2620:186::21]:59183', transfer initiated
Oct 12 06:54:42 dns25 pdns_server[66]: AXFR-out zone '714durham.us', client '[fddd:a03f:2620:400::1]:45013', transfer initiated
Oct 12 06:54:42 dns25 pdns_server[66]: AXFR-out zone '714durham.us', client '[fddd:a03f:2620:186::20]:45297', transfer initiated
Oct 12 06:54:42 dns25 pdns_server[66]: AXFR-out zone '714durham.us', client '[fddd:a03f:2620:300::1]:48997', transfer initiated

(fddd:a03f:2620:186::20 is the hidden secondary involved here)

Log from the hidden secondary:

Oct 12 06:49:42 core23-a pdns_server[3032849]: AXFR-in zone: 'public.catalog.km6g.us', primary: 'fddd:a03f:2620:701::1', Catalog-Zone backend transaction started
Oct 12 06:49:42 core23-a pdns_server[3032849]: AXFR-in zone: 'public.catalog.km6g.us', primary: 'fddd:a03f:2620:701::1', Catalog-Zone create zone '714durham.us'
Oct 12 06:49:42 core23-a pdns_server[3032849]: AXFR-in zone: 'public.catalog.km6g.us', primary: 'fddd:a03f:2620:701::1', Catalog-Zone backend transaction committed
Oct 12 06:49:42 core23-a pdns_server[3032849]: AXFR-in zone: 'public.catalog.km6g.us', primary: 'fddd:a03f:2620:701::1', zone committed with serial 1760266181
Oct 12 06:49:42 core23-a pdns_server[3032849]: AXFR-in zone: '714durham.us', primary: 'fddd:a03f:2620:701::1', zone committed with serial 2025101201
Oct 12 06:49:43 core23-a pdns_server[3032849]: IXFR-out zone 'public.catalog.km6g.us', client '[::1]:33431', transfer initiated with serial 1760178280
Oct 12 06:49:43 core23-a pdns_server[3032849]: AXFR-out zone 'public.catalog.km6g.us', client '[::1]:33431', transfer initiated
Oct 12 06:53:42 core23-a pdns_server[3032849]: AXFR-in zone: '415eighth.us', primary: 'fddd:a03f:2620:701::1', zone committed with serial 2025101112
Oct 12 06:54:42 core23-a pdns_server[3032849]: AXFR-in zone: '714durham.us', primary: 'fddd:a03f:2620:701::1', zone committed with serial 2025101202
Oct 12 07:06:51 core23-a pdns_server[3032849]: AXFR-out zone 'public.catalog.km6g.us', client '[::1]:35643', transfer initiated
Oct 12 07:06:51 core23-a pdns_server[3032849]: AXFR-out zone 'private.catalog.km6g.us', client '[::1]:60491', transfer initiated

(the final two AXFR-out are from the recursor being restarted)

Log from the recursor (with stats and webserver entries removed):

Sun 2025-10-12 06:49:43.360027 EDT [s=a541e44e9ca0469b91cf29c334463518;i=a09988a;b=db11580091224e01b49556df9f0c34d3;m=ec621ec2fa;t=640f3e891be80;x=1496e1c16eb347a8]
    MESSAGE=Getting IXFR deltas
    SUBSYSTEM=fwcatzixfr
    ZONE=public.catalog.km6g.us
    TIMESTAMP=1760266183.359
Sun 2025-10-12 06:49:43.363095 EDT [s=a541e44e9ca0469b91cf29c334463518;i=a09988d;b=db11580091224e01b49556df9f0c34d3;m=ec621ed13c;t=640f3e891ccc2;x=93c25b2203cd38fc]
    SUBSYSTEM=fwcatzixfr
    ZONE=public.catalog.km6g.us
    MESSAGE=Processing deltas
    TIMESTAMP=1760266183.362
Sun 2025-10-12 06:49:43.363371 EDT [s=a541e44e9ca0469b91cf29c334463518;i=a09988e;b=db11580091224e01b49556df9f0c34d3;m=ec621ed36e;t=640f3e891cef4;x=799522e73d258f6e]
    SUBSYSTEM=fwcatzixfr
    ZONE=public.catalog.km6g.us
    MESSAGE=IXFR update is a whole new zone
    TIMESTAMP=1760266183.363
Sun 2025-10-12 06:49:43.363908 EDT [s=a541e44e9ca0469b91cf29c334463518;i=a09988f;b=db11580091224e01b49556df9f0c34d3;m=ec621ed595;t=640f3e891d11c;x=a8900ca083bdfd1d]
    SUBSYSTEM=fwcatzixfr
    ZONE=public.catalog.km6g.us
    MESSAGE=Zone mutations
    TIMESTAMP=1760266183.363
Sun 2025-10-12 06:49:43.370012 EDT [s=a541e44e9ca0469b91cf29c334463518;i=a099890;b=db11580091224e01b49556df9f0c34d3;m=ec621ee9df;t=640f3e891e565;x=c36eb000788e6510]
    MESSAGE=Reloading zones, purging data from cache
    SUBSYSTEM=config
    TIMESTAMP=1760266183.369
Sun 2025-10-12 06:49:43.370257 EDT [s=a541e44e9ca0469b91cf29c334463518;i=a099891;b=db11580091224e01b49556df9f0c34d3;m=ec621eecc6;t=640f3e891e84d;x=d0f79f11d7664493]
    SUBSYSTEM=config
    MESSAGE=Processing main YAML settings
    TIMESTAMP=1760266183.370
Sun 2025-10-12 06:49:43.374013 EDT [s=a541e44e9ca0469b91cf29c334463518;i=a099892;b=db11580091224e01b49556df9f0c34d3;m=ec621ef977;t=640f3e891f4fd;x=efd5a7fd7cfe9952]
    SUBSYSTEM=config
    MESSAGE=Redirecting queries
    ZONE=.
    TIMESTAMP=1760266183.373
Sun 2025-10-12 06:49:43.374209 EDT [s=a541e44e9ca0469b91cf29c334463518;i=a099893;b=db11580091224e01b49556df9f0c34d3;m=ec621efbe1;t=640f3e891f767;x=5e7696a8e6057cf6]
    SUBSYSTEM=config
    MESSAGE=Processing ApiZones YAML settings
    TIMESTAMP=1760266183.374
Sun 2025-10-12 06:49:43.374921 EDT [s=a541e44e9ca0469b91cf29c334463518;i=a099894;b=db11580091224e01b49556df9f0c34d3;m=ec621efee5;t=640f3e891fa6c;x=4197261a9247a411]
    SUBSYSTEM=config
    MESSAGE=Done parsing ApiZones YAML from file
    TIMESTAMP=1760266183.374
Sun 2025-10-12 06:49:43.375084 EDT [s=a541e44e9ca0469b91cf29c334463518;i=a099895;b=db11580091224e01b49556df9f0c34d3;m=ec621f00ee;t=640f3e891fc74;x=f612fcf42c7f3154]
    SUBSYSTEM=config
    MESSAGE=Processing ApiZones YAML settings
    TIMESTAMP=1760266183.374
Sun 2025-10-12 06:49:43.376395 EDT [s=a541e44e9ca0469b91cf29c334463518;i=a099896;b=db11580091224e01b49556df9f0c34d3;m=ec621f02cb;t=640f3e891fe51;x=8eda2e5dd9673200]
    SUBSYSTEM=config
    MESSAGE=Done parsing ApiZones YAML from file
    TIMESTAMP=1760266183.376
Sun 2025-10-12 06:49:43.376566 EDT [s=a541e44e9ca0469b91cf29c334463518;i=a099897;b=db11580091224e01b49556df9f0c34d3;m=ec621f04e7;t=640f3e892006d;x=e1a4a953d6be351]
    SUBSYSTEM=config
    MESSAGE=Processing ApiZones YAML settings
    TIMESTAMP=1760266183.376
Sun 2025-10-12 06:49:43.377319 EDT [s=a541e44e9ca0469b91cf29c334463518;i=a099898;b=db11580091224e01b49556df9f0c34d3;m=ec621f06cd;t=640f3e8920254;x=31fe622db939af61]
    SUBSYSTEM=config
    MESSAGE=Done parsing ApiZones YAML from file
    TIMESTAMP=1760266183.377
Sun 2025-10-12 06:49:43.377424 EDT [s=a541e44e9ca0469b91cf29c334463518;i=a099899;b=db11580091224e01b49556df9f0c34d3;m=ec621f08cc;t=640f3e8920452;x=5ce8e47c070afb3a]
    SUBSYSTEM=config
    MESSAGE=Inserting rfc 1918 private space zones
    TIMESTAMP=1760266183.377
Sun 2025-10-12 06:49:43.377661 EDT [s=a541e44e9ca0469b91cf29c334463518;i=a09989a;b=db11580091224e01b49556df9f0c34d3;m=ec621f0a9b;t=640f3e8920621;x=3d51698d56a35e9b]
    SUBSYSTEM=config
    MESSAGE=Will not overwrite already loaded zone
    ZONE=168.192.in-addr.arpa
    TIMESTAMP=1760266183.377
Sun 2025-10-12 06:49:43.378392 EDT [s=a541e44e9ca0469b91cf29c334463518;i=a09989b;b=db11580091224e01b49556df9f0c34d3;m=ec621f0c7c;t=640f3e8920803;x=b005c69db4faf802]
    SUBSYSTEM=config
    MESSAGE=Inserting rfc 6303 private space zones
    TIMESTAMP=1760266183.378
Sun 2025-10-12 06:49:46.362716 EDT [s=a541e44e9ca0469b91cf29c334463518;i=a09989d;b=db11580091224e01b49556df9f0c34d3;m=ec624c9426;t=640f3e8bf8fad;x=c14a9f32bf1fbf75]
    MESSAGE=Wiped cache
    SUBSYSTEM=runtime
    TIMESTAMP=1760266186.362
Sun 2025-10-12 06:53:43.431601 EDT [s=a541e44e9ca0469b91cf29c334463518;i=a099901;b=db11580091224e01b49556df9f0c34d3;m=ec706df678;t=640f3f6e0f1fe;x=988dee68abdab331]
    MESSAGE=Wiped cache
    SUBSYSTEM=runtime
    TIMESTAMP=1760266423.431
Sun 2025-10-12 06:54:43.465933 EDT [s=a541e44e9ca0469b91cf29c334463518;i=a09992b;b=db11580091224e01b49556df9f0c34d3;m=ec740203c8;t=640f3fa74ff4d;x=40dd88270d32414a]
    MESSAGE=Wiped cache
    SUBSYSTEM=runtime
    TIMESTAMP=1760266483.465

I can likely reproduce this by adding another zone, so if additional details are needed I'll give that a try.

[omoerbeek]

I trace of the failing recursor query would probably shed some light on what was happening here.

[omoerbeek]

For rec, to know that a zone inside a Secure zone (us. in this case) is Insecure it has to have the denial of the DS record from the us. nameservers. I suppose due to some (aggressive?) caching it did not have the denial and did not go out looking for one. After some time it should do so and come to the right conclusion that your zone is Insecure. I suppose the clearing of cache entries on new forward is not enough as the relevant data is in the parent zone. A restart is the most drastic way fo clearing caches so that worked.

[kpfleming]

What would be the best combination of recursor configuration options to get the information desired?

[omoerbeek]

rec_control trace-regex thedomain /tmp/tracefile
Do the failing dig query
rec_control trace-regex # to switch off tracing
a cache dump would also be useful:
rec_control dump-cache /tmp/cachedump

[kpfleming]

Heh... I just realized this morning that part of the cause could be that this was a newly-registered domain, and so the content of the .us TLD servers may have been in a state of change as well. Replicating this may require registering another domain :-)