DLV dnssec setup

[Wolfgang Rosenauer]

Hi,

I'm pretty much new to DNSSEC and try to deploy my first bind to
support it correctly.
My bind version is 9.9.4P2 and what I did is the following just to
allow DNSSEC verification (no zone management yet):

        dnssec-enable yes;
        dnssec-validation auto;
        dnssec-lookaside . trust-anchor dlv.isc.org.;
        managed-keys-directory "/var/lib/named/dyn/";

managed-keys {
        # ISC DLV: See https://www.isc.org/solutions/dlv for details.
        # NOTE: This key is activated by setting "dnssec-lookaside auto;"
        # in named.conf.
        dlv.isc.org. initial-key 257 3 5
"BEAAAAPHMu/5onzrEE7z1egmhg/WPO0+juoZrW3euWEn4MxDCE1+lLy2
                brhQv5rN32RKtMzX6Mj70jdzeND4XknW58dnJNPCxn8+jAGl2FZLK8t+
                1uq4W+nnA3qO2+DL+k6BD4mewMLbIYFwe0PG73Te9fZ2kJb56dhgMde5
                ymX4BI/oQ+cAK50/xvJv00Frf8kw6ucMTwFlgPe+jnGxPPEmHAte/URk
                Y62ZfkLoBAADLHQ9IrS2tryAe7mbBZVcOwIeU/Rw/mRx/vwwMCTgNboM
                QKtUdvNXDrYJDSHZws3xiRXF1Rf+al9UmZfSav/4NWLKjHzpT59k/VSt
                TDN0YUuWrBNh";

        # ROOT KEY: See https://data.iana.org/root-anchors/root-anchors.xml
        # for current trust anchor information.
        # NOTE: This key is activated by setting "dnssec-validation auto;"
        # in named.conf.
        . initial-key 257 3 8
"AwEAAagAIKlVZrpC6Ia7gEzahOR+9W29euxhJhVVLOyQbSEW0O8gcCjF
                FVQUTf6v58fLjwBd0YI0EzrAcQqBGCzh/RStIoO8g0NfnfL2MTJRkxoX
                bfDaUeVPQuYEhg37NZWAJQ9VnMVDxP/VHL496M/QZxkjf5/Efucp2gaD
                X6RS6CXpoY68LsvPVjR0ZSwzz1apAzvN9dlzEheX7ICJBBtuA6G3LQpz
                W5hOA2hzCTMjJPJ8LbqF6dsV6DoBQzgul0sGIcGOYl7OyQdXfZ57relS
                Qageu+ipAdTTJ25AsRTAoub8ONGcLmqrAmRLKBP1dfwhYB4N7knNnulq
                QxA+Uk1ihz0=";
};

I get strange behaviour which I cannot explain though:

bind startup shows
2014-07-10T12:43:52.621536+02:00 s15418965 named[29093]: using
built-in root key for view _default
2014-07-10T12:43:52.622344+02:00 s15418965 named[29093]: set up
managed keys zone for view _default, file
'/var/lib/named/dyn//managed-keys.bind'
[...]
2014-07-10T12:43:52.684928+02:00 s15418965 named[29093]:
managed-keys-zone: journal file is out of date: removing journal file
2014-07-10T12:43:52.685668+02:00 s15418965 named[29093]:
managed-keys-zone: loaded serial 31

Afterwards I see:
s15418965:/var/lib/named/log # dig @127.0.0.1 www.isc.org

; <<>> DiG 9.9.4-rpz2.13269.14-P2 <<>> @127.0.0.1 www.isc.org
; (1 server found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 59813
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 4096
;; QUESTION SECTION:
;www.isc.org.                   IN      A

;; Query time: 2 msec
;; SERVER: 127.0.0.1#53(127.0.0.1)
;; WHEN: Thu Jul 10 12:48:57 CEST 2014
;; MSG SIZE  rcvd: 40

10-Jul-2014 12:48:47.466 dnssec: debug 3: validating @0x7f48140012e0:
. NS: starting
10-Jul-2014 12:48:47.466 dnssec: debug 3: validating @0x7f48140012e0:
. NS: attempting positive response validation
10-Jul-2014 12:48:47.483 dnssec: debug 3: validating @0x7f480c00c920:
. DNSKEY: starting
10-Jul-2014 12:48:47.483 dnssec: debug 3: validating @0x7f480c00c920:
. DNSKEY: attempting positive response validation
10-Jul-2014 12:48:47.484 dnssec: debug 3: validating @0x7f480c00c920:
. DNSKEY: verify rdataset (keyid=19036): success
10-Jul-2014 12:48:47.484 dnssec: debug 3: validating @0x7f480c00c920:
. DNSKEY: signed by trusted key; marking as secure
10-Jul-2014 12:48:47.484 dnssec: debug 3: validator @0x7f480c00c920:
dns_validator_destroy
10-Jul-2014 12:48:47.484 dnssec: debug 3: validating @0x7f48140012e0:
. NS: in fetch_callback_validator
10-Jul-2014 12:48:47.484 dnssec: debug 3: validating @0x7f48140012e0:
. NS: keyset with trust secure
10-Jul-2014 12:48:47.484 dnssec: debug 3: validating @0x7f48140012e0:
. NS: resuming validate
10-Jul-2014 12:48:47.484 dnssec: debug 3: validating @0x7f48140012e0:
. NS: verify rdataset (keyid=8230): success
10-Jul-2014 12:48:47.484 dnssec: debug 3: validating @0x7f48140012e0:
. NS: marking as secure, noqname proof not needed
10-Jul-2014 12:48:47.484 dnssec: debug 3: validator @0x7f48140012e0:
dns_validator_destroy

but also some working ones:

s15418965:/var/lib/named/log # dig @127.0.0.1 www.mailbox.org

; <<>> DiG 9.9.4-rpz2.13269.14-P2 <<>> @127.0.0.1 www.mailbox.org
; (1 server found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 40561
;; flags: qr rd ra ad; QUERY: 1, ANSWER: 1, AUTHORITY: 2, ADDITIONAL: 5

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 4096
;; QUESTION SECTION:
;www.mailbox.org.               IN      A

;; ANSWER SECTION:
www.mailbox.org.        900     IN      A       80.241.60.194

;; AUTHORITY SECTION:
mailbox.org.            900     IN      NS      ns2.jpberlin.de.
mailbox.org.            900     IN      NS      ns.jpberlin.de.

;; ADDITIONAL SECTION:
ns.jpberlin.de.         86400   IN      A       213.203.238.4
ns.jpberlin.de.         1800    IN      AAAA    2001:67c:2050:1::53:1
ns2.jpberlin.de.        86400   IN      A       194.150.191.56
ns2.jpberlin.de.        1800    IN      AAAA    2001:67c:14c:12f::56:2

;; Query time: 487 msec
;; SERVER: 127.0.0.1#53(127.0.0.1)
;; WHEN: Thu Jul 10 12:52:17 CEST 2014
;; MSG SIZE  rcvd: 194


Probably I miss some basic understanding but I'm confused about the
above behaviour.

Any explanations?


Thanks,
 Wolfgang