Warning of unexpectedly missing active key never stops
I'm experimenting with KSK rollovers and have a validating BIND 9.16.4
running on FreeBSD.
BIND 9.16.4 (Stable Release) <id:0849b42>
running on FreeBSD amd64 12.1-RELEASE FreeBSD 12.1-RELEASE r354233 GENERIC
built by make with '--disable-linux-caps' '--localstatedir=/var' '--sysconfdir=/usr/local/etc/namedb' '--with-dlopen=yes' '--with-libxml2' '--with-openssl=/usr' '--with-readline=-L/usr/local/lib -ledit' '--with-dlz-filesystem=yes' '--disable-dnstap' '--disable-fixed-rrset' '--disable-geoip' '--without-maxminddb' '--without-gssapi' '--with-libidn2=/usr/local' '--with-json-c' '--disable-largefile' '--with-lmdb=/usr/local' '--disable-native-pkcs11' '--without-python' '--disable-querytrace' 'STD_CDEFINES=-DDIG_SIGCHASE=1' '--enable-tcp-fastopen' '--with-tuning=default' '--disable-symtable' '--prefix=/usr/local' '--mandir=/usr/local/man' '--infodir=/usr/local/share/info/' '--build=amd64-portbld-freebsd12.1' 'build_alias=amd64-portbld-freebsd12.1' 'CC=cc' 'CFLAGS=-O2 -pipe -DLIBICONV_PLUG -fstack-protector-strong -isystem /usr/local/include -fno-strict-aliasing ' 'LDFLAGS= -L/usr/local/lib -ljson-c -fstack-protector-strong ' 'LIBS=-L/usr/local/lib' 'CPPFLAGS=-DLIBICONV_PLUG -isystem /usr/local/include' 'CPP=cpp' 'PKG_CONFIG=pkgconf'
compiled by CLANG 4.2.1 Compatible FreeBSD Clang 8.0.1 (tags/RELEASE_801/final 366581)
compiled with OpenSSL version: OpenSSL 1.1.1d-freebsd 10 Sep 2019
linked to OpenSSL version: OpenSSL 1.1.1d-freebsd 10 Sep 2019
compiled with libxml2 version: 2.9.10
linked to libxml2 version: 20910
compiled with json-c version: 0.14
linked to json-c version: 0.14
compiled with zlib version: 1.2.11
linked to zlib version: 1.2.11
threads support is enabled
The server is configured with a private root. Here's it's full configuration:
options {
directory "/usr/local/etc/namedb/working";
pid-file "/var/run/named/pid";
dump-file "/var/dump/named_dump.db";
statistics-file "/var/stats/named.stats";
listen-on { 127.0.0.1; 192.168.1.157; };
allow-query { any; };
};
zone "." { type hint; file "/usr/local/etc/namedb/named.root"; };
and the hint file
. 3600000 NS ksigner.aa.
ksigner.aa. 3600000 A 192.168.1.150
I configured bind.keys
with the initial trust anchor (key tag 41155
)
trust-anchors {
"." initial-key 257 3 8 "AwEAAdVfg0pf59Z7QyOVnPcm41C6H5ohxIQv4PVjYR4e
w9+FzVKrG+T894UgqTjOmiwPjskdJCU1Cbm16/a1opd6
WJ+3sJwyY2+/yQ2iTMpQOgHnW9jBYH5ffvNBzaHLZfCC
prkHyOPbdaxHzHhjKBi+PoJr67uJH4/6AS8Le9ncayag
TK0UM/fi9Emu2k5o/XOav2MXiW+WjjFAHTUTwggWN5nY
g6NrEDAtVb62yNqgGIG3NyZoKGyVQSyBI3JX6o0LCeyh
UENV6yvlnN9uvOdwzS4EOfoEkE8lt3NwBTBfaCp3pO9L
egaG2VALhWMIjz35tWiAF3AFqd293dq9VTeVljM="; // 41155
};
I'm running the server as follows:
named -g -T mkeytimers=2/5/300
The server validated fine.
I then began a KSK rollover several hours ago and observed that the new KSK (30377
) appeared in managed-keys.bind
:
$ORIGIN .
$TTL 0 ; 0 seconds
@ IN SOA . . (
3567 ; serial
0 ; refresh (0 seconds)
0 ; retry (0 seconds)
0 ; expire (0 seconds)
0 ; minimum (0 seconds)
)
KEYDATA 20200714075405 20200713205807 19700101000000 257 3 8 (
AwEAAdVfg0pf59Z7QyOVnPcm41C6H5ohxIQv4PVjYR4e
w9+FzVKrG+T894UgqTjOmiwPjskdJCU1Cbm16/a1opd6
WJ+3sJwyY2+/yQ2iTMpQOgHnW9jBYH5ffvNBzaHLZfCC
prkHyOPbdaxHzHhjKBi+PoJr67uJH4/6AS8Le9ncayag
TK0UM/fi9Emu2k5o/XOav2MXiW+WjjFAHTUTwggWN5nY
g6NrEDAtVb62yNqgGIG3NyZoKGyVQSyBI3JX6o0LCeyh
UENV6yvlnN9uvOdwzS4EOfoEkE8lt3NwBTBfaCp3pO9L
egaG2VALhWMIjz35tWiAF3AFqd293dq9VTeVljM=
) ; KSK; alg = RSASHA256; key id = 41155
; next refresh: Tue, 14 Jul 2020 07:54:05 GMT
; trusted since: Mon, 13 Jul 2020 20:58:07 GMT
KEYDATA 20200714075433 20200713220851 19700101000000 257 3 8 (
AwEAAcq2mOD4nCqlDOzXmaHJF5MrcxMiPOvclSnb8F0K
dKnFWaTGwucwtf2r0GYP2wRvybfyhUXhraHXAkzVSI4I
h435qW3b9TMPmi9VAxWnU4Gex5DT0VSPF3pDrR46A67v
DBy6i1fsQB7coIB3SyWtq19KRCS4GBGp86tTTishSVCd
) ; KSK; alg = RSASHA256; key id = 30377
; next refresh: Tue, 14 Jul 2020 07:54:33 GMT
; trusted since: Mon, 13 Jul 2020 22:08:51 GMT
The authoriative server is Knot and I don't seem to be able to actually revoke a KSK so I "retired" and then removed the KSK 41155
from the zone.
BIND then started logging the following:
14-Jul-2020 07:54:01.121 managed-keys-zone: Key 30377 for zone . is now trusted (acceptance timer complete)
14-Jul-2020 07:54:03.143 managed-keys-zone: Active key 41155 for zone . unexpectedly missing
14-Jul-2020 07:54:03.143 managed-keys-zone: Key 30377 for zone . is now trusted (acceptance timer complete)
14-Jul-2020 07:54:05.195 managed-keys-zone: Active key 41155 for zone . unexpectedly missing
14-Jul-2020 07:54:05.195 managed-keys-zone: Key 30377 for zone . is now trusted (acceptance timer complete)
14-Jul-2020 07:54:07.241 managed-keys-zone: Active key 41155 for zone . unexpectedly missing
14-Jul-2020 07:54:07.241 managed-keys-zone: Key 30377 for zone . is now trusted (acceptance timer complete)
...
and has been doing so for over an hour; it doesn't seem to stop.
Will it ever stop, or is this unexpected behaviour?