Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix NxDomain and NoData responses #286

Merged
merged 11 commits into from
Nov 21, 2017
Merged

Fix NxDomain and NoData responses #286

merged 11 commits into from
Nov 21, 2017

Conversation

bluejekyll
Copy link
Member

fixes: #53

@bluejekyll
Copy link
Member Author

@Darkspirit, this is an initial pass at a fix for the incorrect negative response. I still need some tests for this case, but otherwise, I think this is correct.

// see https://tools.ietf.org/html/rfc2308 for proper response construct
match records {
AuthLookup::NoName => response.set_response_code(ResponseCode::NXDomain),
AuthLookup::NameExists => response.set_response_code(ResponseCode::NoError),
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is where the actual fix is.

// records in a list except when there are a lot of records. But this makes indexed lookups by name+type
// always return empty sets. This is only important in the negative case, where other DNS authorities
// generally return NoError and no results when other types exist at the same name. bah.
if result.is_empty() {
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is where, IMO, the stupidity of the spec is detected, for proper response handling later...

@codecov
Copy link

codecov bot commented Nov 14, 2017

Codecov Report

❗ No coverage uploaded for pull request base (master@43f3390). Click here to learn what that means.
The diff coverage is 77.6%.

Impacted file tree graph

@@           Coverage Diff            @@
##             master    #286   +/-   ##
========================================
  Coverage          ?   87.1%           
========================================
  Files             ?     115           
  Lines             ?   12015           
  Branches          ?       0           
========================================
  Hits              ?   10466           
  Misses            ?    1549           
  Partials          ?       0
Impacted Files Coverage Δ
server/src/authority/mod.rs 100% <ø> (ø)
server/src/server/request_stream.rs 66.66% <0%> (ø)
proto/src/rr/dnssec/rdata/nsec3.rs 96.77% <100%> (ø)
proto/src/rr/rr_key.rs 100% <100%> (ø)
server/src/server/server_future.rs 77.19% <64.91%> (ø)
server/src/authority/catalog.rs 81.59% <76.47%> (ø)
server/src/authority/authority.rs 89.37% <87.65%> (ø)
server/src/authority/auth_lookup.rs 95.45% <95.45%> (ø)

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 43f3390...b4c6333. Read the comment docs.

@bluejekyll
Copy link
Member Author

@Darkspirit, I think this is ready for review. After this, I don't think we'll see any issues with the NxDomain/NoData issues.

@Darkspirit
Copy link
Contributor

Darkspirit commented Nov 15, 2017

cargo install trust-dns-server --git https://github.com/bluejekyll/trust-dns --branch fix_nxdomain --features=dnssec-ring --force

Before: http://dnsviz.net/d/dev.terrax.net/Wgujmg/dnssec/ + SSLLabs: "Unable to resolve domain name"
After: http://dnsviz.net/d/dev.terrax.net/WgvP_g/dnssec/ (only some time warnings are left and they would be gone in a few hours, I think.) + SSLLabs can resolve.

nftables.conf (nft is very new to me. I made this to redirect port 53 to 8053, so dns and web server don't need to run as root. I am unsure whether this is acceptable or something dirty.)

!/usr/sbin/nft -f

flush ruleset

table ip6 filter {
        chain input {
                type filter hook input priority 0; policy accept;
                tcp dport 8443 ct state established,related counter accept
                tcp dport 8443 ct mark 0x11 accept
                tcp dport 8443 counter drop
                tcp dport 8053 ct state established,related counter accept
                tcp dport 8053 ct mark 0x11 accept
                tcp dport 8053 counter drop
                udp dport 8053 ct mark 0x11 accept
                udp dport 8053 counter drop
        }
}
table ip6 nat {
        chain prerouting {
                type nat hook prerouting priority 0; policy accept;
                ip6 daddr 2a01:4f8:c0c:2c12::50 tcp dport { https } ct mark set 0x11 dnat to :8443
                ip6 daddr 2a01:4f8:c0c:2c12::50 tcp dport { 53 } ct mark set 0x11 dnat to :8053
                ip6 daddr 2a01:4f8:c0c:2c12::51 tcp dport { 53 } ct mark set 0x11 dnat to :8053
                ip6 daddr 2a01:4f8:c0c:2c12::50 udp dport { 53 } ct mark set 0x11 dnat to :8053
                ip6 daddr 2a01:4f8:c0c:2c12::51 udp dport { 53 } ct mark set 0x11 dnat to :8053
        }

        chain postrouting {
                type nat hook postrouting priority 0; policy accept;
        }

        chain output {
                type nat hook output priority 0; policy accept;
        }
}

config.toml

listen_addrs_ipv6 = ["2a01:4f8:c0c:2c12::50","2a01:4f8:c0c:2c12::51"]
listen_port = 8053

[[zones]]
zone = "dev.terrax.net"
zone_type = "MASTER"
file = "dev.terrax.net.zone"
allow_update = false
enable_dnssec = true

[[zones.keys]]
key_path = "dev.terrax.net.csk.pem"
algorithm = "ECDSAP384SHA384"
is_zone_signing_key = true
is_zone_update_auth = false
create_if_absent = true

zone file

; replace the trust-dns.org with your own name
@               IN      SOA     dev.h.terrax.net. hostmaster.terrax.net. (
                                201711121       ; Serial
                                600   ; Refresh
                                600    ; Retry
                                600  ; Expire
                                600)  ; Minimum TTL
                        NS      dev.h.terrax.net.

@ MX 0 .
@ AAAA 2a01:4f8:c0c:2c12::50
@ TXT "v=spf1 -all"
@ CAA 128 issue "letsencrypt.org"
@ CAA 128 iodef "mailto:hostmaster@terrax.net"
_443._tcp 60 IN TLSA 3 1 2 a991082596fab5f8475c22686435f22e6b67f5409b674ce3ccdccb9401aa0a882513c0946a8973e00a386519e401773ce025daeee14454b9859c096b5b798593

A direct request works:

$ dig tlsa _443._tcp.dev.terrax.net @dev.h.terrax.net
                                                                                                                                           
; <<>> DiG 9.10.6-Debian <<>> tlsa _443._tcp.dev.terrax.net @dev.h.terrax.net                                                              
;; global options: +cmd                                                                                                                    
;; Got answer:                                                                                                                             
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 37178                                                                                  
;; flags: qr aa; QUERY: 1, ANSWER: 1, AUTHORITY: 1, ADDITIONAL: 1                                                                          
                                                                                                                                           
;; OPT PSEUDOSECTION:                                                                                                                      
; EDNS: version: 0, flags: do; udp: 4096                                                                                                   
; OPT=5: 08 0d 0e 0f ("....")                                                                                                              
; OPT=6: 08 0d 0e 0f ("....")                                                                                                              
;; QUESTION SECTION:                                                                                                                       
;_443._tcp.dev.terrax.net.      IN      TLSA                                                                                               
                                                                                                                                           
;; ANSWER SECTION:                                                                                                                         
_443._tcp.dev.terrax.net. 60    IN      TLSA    3 1 2 A991082596FAB5F8475C22686435F22E6B67F5409B674CE3CCDCCB94 01AA0A882513C0946A8973E00A386519E401773CE025DAEEE14454B9 859C096B5B798593
                                                                                                                                           
;; AUTHORITY SECTION:                                                                                                                      
dev.terrax.net.         600     IN      NS      dev.h.terrax.net.                                                                          
                                                                                                                                           
;; Query time: 25 msec                                                                                                                     
;; SERVER: 2a01:4f8:c0c:2c12::50#53(2a01:4f8:c0c:2c12::50)                                                                                 
;; WHEN: Wed Nov 15 06:4
3:13 CET 2017                                                                                                      
;; MSG SIZE  rcvd: 178 

But my freshly restarted local unbound don't want to answer this (SERVFAIL):

$ dig TLSA _443._tcp.dev.terrax.net

; <<>> DiG 9.10.6-Debian <<>> TLSA _443._tcp.dev.terrax.net
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 30561
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 4096
;; QUESTION SECTION:
;_443._tcp.dev.terrax.net.      IN      TLSA

;; Query time: 162 msec
;; SERVER: ::1#53(::1)
;; WHEN: Wed Nov 15 06:27:51 CET 2017
;; MSG SIZE  rcvd: 53

unbound.log

[1510724040] unbound[24727:0] info: resolving . DNSKEY IN
[1510724040] unbound[24727:0] info: validate keys with anchor(DS): sec_status_secure
[1510724040] unbound[24727:0] info: Successfully primed trust anchor . DNSKEY IN
[1510724040] unbound[24727:0] info: resolving _ta-4a5c-4f66. NULL IN
[1510724040] unbound[24727:0] info: validated DS net. DS IN
[1510724040] unbound[24727:0] info: resolving . DNSKEY IN
------------------------------------------------------------------------------------
[1510724040] unbound[24727:0] info: resolving net. DNSKEY IN
[1510724040] unbound[24727:0] info: validated DNSKEY net. DNSKEY IN
[1510724040] unbound[24727:0] info: validated DS terrax.net. DS IN
------------------------------------------------------------------------------------
[1510724040] unbound[24727:0] info: resolving terrax.net. DNSKEY IN
[1510724040] unbound[24727:0] info: validated DNSKEY terrax.net. DNSKEY IN
[1510724040] unbound[24727:0] info: validated DS dev.terrax.net. DS IN
------------------------------------------------------------------------------------
[1510724040] unbound[24727:0] info: response for dev.terrax.net. DNSKEY IN
[1510724040] unbound[24727:0] info: reply from <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510724040] unbound[24727:0] info: query response was ANSWER
[1510724040] unbound[24727:0] info: validated DNSKEY dev.terrax.net. DNSKEY IN
[1510724040] unbound[24727:0] info: Validate: message contains bad rrsets
[1510724040] unbound[24727:0] info: resolving _443._tcp.dev.terrax.net. TLSA IN
[1510724040] unbound[24727:0] info: resolving dev.terrax.net. DNSKEY IN
------------------------------------------------------------------------------------
[1510724040] unbound[24727:0] info: response for gw1.h.terrax.net. AAAA IN
[1510724040] unbound[24727:0] info: reply from <terrax.net.> 94.130.76.133#53
[1510724040] unbound[24727:0] info: query response was ANSWER
[1510724040] unbound[24727:0] info: response for _ta-4a5c-4f66. NULL IN
[1510724040] unbound[24727:0] info: reply from <.> 2001:500:2d::d#53
[1510724040] unbound[24727:0] info: query response was NXDOMAIN ANSWER
[1510724040] unbound[24727:0] info: response for gw2.h.terrax.net. AAAA IN
[1510724040] unbound[24727:0] info: reply from <terrax.net.> 94.130.76.133#53
[1510724040] unbound[24727:0] info: query response was ANSWER
------------------------------------------------------------------------------------
[1510724040] unbound[24727:0] info: response for dev.h.terrax.net. A IN
[1510724040] unbound[24727:0] info: reply from <terrax.net.> 94.130.73.109#53
[1510724040] unbound[24727:0] info: query response was nodata ANSWER
[1510724040] unbound[24727:0] info: response for gw1.h.terrax.net. AAAA IN
[1510724040] unbound[24727:0] info: reply from <terrax.net.> 94.130.76.133#53
[1510724040] unbound[24727:0] info: query response was ANSWER
------------------------------------------------------------------------------------
[1510724040] unbound[24727:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510724040] unbound[24727:0] info: reply from <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510724040] unbound[24727:0] info: query response was NXDOMAIN ANSWER
[1510724040] unbound[24727:0] info: Validate: message contains bad rrsets
------------------------------------------------------------------------------------
[1510724040] unbound[24727:0] info: resolving _443._tcp.dev.terrax.net. TLSA IN
[1510724040] unbound[24727:0] info: resolving dev.terrax.net. DNSKEY IN
[1510724040] unbound[24727:0] info: response for gw2.h.terrax.net. AAAA IN
[1510724040] unbound[24727:0] info: reply from <terrax.net.> 94.130.73.109#53
[1510724040] unbound[24727:0] info: query response was ANSWER
------------------------------------------------------------------------------------
[1510724040] unbound[24727:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510724040] unbound[24727:0] info: reply from <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510724040] unbound[24727:0] info: query response was NXDOMAIN ANSWER
[1510724040] unbound[24727:0] info: validate(nxdomain): sec_status_bogus
------------------------------------------------------------------------------------
[1510724040] unbound[24727:0] info: resolving _443._tcp.dev.terrax.net. TLSA IN
[1510724040] unbound[24727:0] info: resolving dev.terrax.net. DNSKEY IN
[1510724040] unbound[24727:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510724040] unbound[24727:0] info: reply from <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510724040] unbound[24727:0] info: query response was NXDOMAIN ANSWER
[1510724040] unbound[24727:0] info: validate(nxdomain): sec_status_bogus
------------------------------------------------------------------------------------
[1510724040] unbound[24727:0] info: resolving _443._tcp.dev.terrax.net. TLSA IN
[1510724040] unbound[24727:0] info: resolving dev.terrax.net. DNSKEY IN
[1510724040] unbound[24727:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510724040] unbound[24727:0] info: reply from <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510724040] unbound[24727:0] info: query response was NXDOMAIN ANSWER
[1510724040] unbound[24727:0] info: Validate: message contains bad rrsets
------------------------------------------------------------------------------------
[1510724040] unbound[24727:0] info: resolving _443._tcp.dev.terrax.net. TLSA IN
[1510724040] unbound[24727:0] info: resolving dev.terrax.net. DNSKEY IN
[1510724040] unbound[24727:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510724040] unbound[24727:0] info: reply from <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510724040] unbound[24727:0] info: query response was NXDOMAIN ANSWER
[1510724040] unbound[24727:0] info: Validate: message contains bad rrsets
  • "message contains bad rrsets" (maybe it's that temporary "clock skew" thing from dnsviz?)
  • Although dnsviz is now largely fine, there is still an NXDOMAIN for _443._tcp.dev.terrax.net. TLSA, but only for my local unbound.
  • Maybe I am doing something wrong?

@bluejekyll
Copy link
Member Author

Can you remind of what unbound is doing in the picture here? Is it just forwarding on to trust-dns?

The clock skew is probably not something I can fix with backdated dates to the current day. I think we already have a bug open for that.

@Darkspirit
Copy link
Contributor

Darkspirit commented Nov 15, 2017

Can you remind of what unbound is doing in the picture here? Is it just forwarding on to trust-dns?

Unbound doesn't use any public resolver. It seems to know the root zone + TLD.

Somehow like this:

  1. hidden: who are the NS of terrax.net? -> glue records gw1.h and gw2.h (94.130.x.x)
  2. hidden: Hey, 94.130.x.x, do you know _443._tcp.dev.terrax.net. TLSA? -> No, but "dev.terrax.net NS dev.h.terrax.net"
  3. And which IPs does dev.h have? -> 2a01:4f8:c0c:2c12::50
  4. Hey, 2a01:4f8:c0c:2c12::50 (trustdns), do you know _443._tcp.dev.terrax.net. TLSA? -> NXDOMAIN

Edit: I added some dashes to unbound's log to seperate things a little bit, but don't know whether they are positioned correctly or not.

Edit2: I am confused, but there are multiple blocks of:

[1510724040] unbound[24727:0] info: resolving _443._tcp.dev.terrax.net. TLSA IN
[1510724040] unbound[24727:0] info: resolving dev.terrax.net. DNSKEY IN
[1510724040] unbound[24727:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510724040] unbound[24727:0] info: reply from <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510724040] unbound[24727:0] info: query response was NXDOMAIN ANSWER

and 2a01:4f8:c0c:2c12::50 is trustdns

@Darkspirit
Copy link
Contributor

Darkspirit commented Nov 15, 2017

[1510769512] unbound[11615:0] info: resolving _443._tcp.dev.terrax.net. TLSA IN
[1510769512] unbound[11615:0] info: resolving (init part 2):  _443._tcp.dev.terrax.net. TLSA IN
[1510769512] unbound[11615:0] info: resolving (init part 3):  _443._tcp.dev.terrax.net. TLSA IN
[1510769512] unbound[11615:0] info: processQueryTargets: _443._tcp.dev.terrax.net. TLSA IN
[1510769512] unbound[11615:0] debug: removing 1 labels
[1510769512] unbound[11615:0] info: sending query: _tcp.dev.terrax.net. A IN
[1510769512] unbound[11615:0] debug: sending to target: <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510769512] unbound[11615:0] debug: cache memory msg=70007 rrset=91657 infra=7953 val=69876 subnet=74488
[1510769512] unbound[11615:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510769512] unbound[11615:0] info: iterator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510769512] unbound[11615:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510769512] unbound[11615:0] info: reply from <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510769512] unbound[11615:0] info: query response was NXDOMAIN ANSWER
[1510769512] unbound[11615:0] info: finishing processing for _443._tcp.dev.terrax.net. TLSA IN
[1510769512] unbound[11615:0] debug: validator[module 1] operate: extstate:module_restart_next event:module_event_moddone
[1510769512] unbound[11615:0] info: validator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510769512] unbound[11615:0] info: validator operate: chased to . TYPE0 CLASS0
[1510769512] unbound[11615:0] debug: NameError response has failed to prove: qname does not exist
[1510769512] unbound[11615:0] debug: NODATA response failed to prove NODATA status with NSEC/NSEC3
[1510769512] unbound[11615:0] info: validate(nxdomain): sec_status_bogus
[1510769512] unbound[11615:0] debug: iterator[module 2] operate: extstate:module_finished event:module_event_pass

(and repeat)

So it's asking for "_tcp.dev.terrax.net. A IN" at some point
and there is also:

[1510769512] unbound[11615:0] info: validator operate: chased to . TYPE0 CLASS0
[1510769512] unbound[11615:0] debug: NameError response has failed to prove: qname does not exist
[1510769512] unbound[11615:0] debug: NODATA response failed to prove NODATA status with NSEC/NSEC3

https://github.com/k0nsl/unbound/blob/master/validator/validator.c#L982

/* The wildcard NODATA is 1 NSEC proving that qname does not exist
* (and also proving what the closest encloser is), and 1 NSEC
* showing the matching wildcard, which must be *.closest_encloser. */

@bluejekyll
Copy link
Member Author

I'm confused by the NxDomain that unbound is getting. Do you have the logs from trust-dns?

@Darkspirit
Copy link
Contributor

  1. Before stopping trustdns: http://dnsviz.net/d/dev.terrax.net/WgzNYA/dnssec/
  2. stopped unbound and trustdns, cleared unbound.log
  3. started trustdns with --debug in screen and made a screenlog
  4. started unbound
  5. dig TLSA _443._tcp.dev.terrax.net
  6. stopped unbound
  7. stopped trustdns
  8. After starting trustdns without --debug: http://dnsviz.net/d/dev.terrax.net/WgzQ4w/dnssec/ (just the time thing that will go away)

trustdns screenlog (Is this correct? It doesn't really show the request and requesting IP.):

2017-11-15T23:37:44.464343306+00:00 INFO trust_dns::logger:26 logging initialized
2017-11-15T23:37:44.464391834+00:00 INFO named:331 Trust-DNS 0.12.0 starting
2017-11-15T23:37:44.464397031+00:00 INFO named:337 loading configuration from: "/home/trustdns/config.toml"
2017-11-15T23:37:44.464622623+00:00 DEBUG named:135 loading zone with config: ZoneConfig {
    zone: "dev.terrax.net",
    zone_type: Master,
    file: "dev.terrax.net.zone",
    allow_update: Some(
        false
    ),
    enable_dnssec: Some(
        true
    ),
    keys: [
        KeyConfig {
            key_path: "dev.terrax.net.csk.pem",
            password: None,
            algorithm: "ECDSAP384SHA384",
            signer_name: None,
            is_zone_signing_key: Some(
                true
            ),
            is_zone_update_auth: Some(
                false
            )
        }
    ]
}
2017-11-15T23:37:44.464731785+00:00 INFO named:164 loading zone file: "/home/trustdns/dev.terrax.net.zone"
cert_data: A991082596FAB5F8475C22686435F22E6B67F5409B674CE3CCDCCB9401AA0A882513C0946A8973E00A386519E401773CE025DAEEE14454B9859C096B5B798593
2017-11-15T23:37:44.489064040+00:00 INFO named:195 zone file loaded: dev.terrax.net.
2017-11-15T23:37:44.489101716+00:00 INFO named:268 reading key: "dev.terrax.net.csk.pem"
2017-11-15T23:37:44.491490908+00:00 INFO named:209 adding key to zone: "dev.terrax.net.csk.pem", is_zsk: true, is_auth: false
2017-11-15T23:37:44.491620704+00:00 INFO named:220 signing zone: dev.terrax.net.
2017-11-15T23:37:44.491635310+00:00 DEBUG trust_dns_server::authority::authority:1142 generating nsec records: dev.terrax.net.
2017-11-15T23:37:44.491698233+00:00 DEBUG trust_dns_server::authority::authority:1212 signing zone: dev.terrax.net.
2017-11-15T23:37:44.491709371+00:00 DEBUG trust_dns_server::authority::authority:1231 signing rr_set: dev.terrax.net., NS with: ECDSAP384SHA384
2017-11-15T23:37:44.493038512+00:00 DEBUG trust_dns_server::authority::authority:1231 signing rr_set: dev.terrax.net., SOA with: ECDSAP384SHA384
2017-11-15T23:37:44.494247198+00:00 DEBUG trust_dns_server::authority::authority:1231 signing rr_set: dev.terrax.net., MX with: ECDSAP384SHA384
2017-11-15T23:37:44.495630873+00:00 DEBUG trust_dns_server::authority::authority:1231 signing rr_set: dev.terrax.net., TXT with: ECDSAP384SHA384
2017-11-15T23:37:44.496829105+00:00 DEBUG trust_dns_server::authority::authority:1231 signing rr_set: dev.terrax.net., AAAA with: ECDSAP384SHA384
2017-11-15T23:37:44.497946152+00:00 DEBUG trust_dns_server::authority::authority:1231 signing rr_set: dev.terrax.net., NSEC with: ECDSAP384SHA384
2017-11-15T23:37:44.499085033+00:00 DEBUG trust_dns_server::authority::authority:1231 signing rr_set: dev.terrax.net., DNSKEY with: ECDSAP384SHA384
2017-11-15T23:37:44.500288154+00:00 DEBUG trust_dns_server::authority::authority:1231 signing rr_set: dev.terrax.net., CAA with: ECDSAP384SHA384
2017-11-15T23:37:44.501532977+00:00 DEBUG trust_dns_server::authority::authority:1231 signing rr_set: _443._tcp.dev.terrax.net., NSEC with: ECDSAP384SHA384
2017-11-15T23:37:44.502719491+00:00 DEBUG trust_dns_server::authority::authority:1231 signing rr_set: _443._tcp.dev.terrax.net., TLSA with: ECDSAP384SHA384
2017-11-15T23:37:44.503861464+00:00 INFO named:235 zone successfully loaded: dev.terrax.net.
2017-11-15T23:37:44.504011164+00:00 INFO named:398 listening for UDP on UdpSocket { addr: V6([2a01:4f8:c0c:2c12::50]:8053), fd: 3 }
2017-11-15T23:37:44.504028547+00:00 DEBUG trust_dns_server::server::server_future:47 registered udp: UdpSocket { addr: V6([2a01:4f8:c0c:2c12::50]:8053), fd: 3 }
2017-11-15T23:37:44.504053673+00:00 DEBUG tokio_core::reactor:466 adding a new I/O source
2017-11-15T23:37:44.504062501+00:00 INFO named:398 listening for UDP on UdpSocket { addr: V6([2a01:4f8:c0c:2c12::51]:8053), fd: 4 }
2017-11-15T23:37:44.504067636+00:00 DEBUG trust_dns_server::server::server_future:47 registered udp: UdpSocket { addr: V6([2a01:4f8:c0c:2c12::51]:8053), fd: 4 }
2017-11-15T23:37:44.504074266+00:00 DEBUG tokio_core::reactor:466 adding a new I/O source
2017-11-15T23:37:44.504080432+00:00 INFO named:404 listening for TCP on TcpListener { addr: V6([2a01:4f8:c0c:2c12::50]:8053), fd: 5 }
2017-11-15T23:37:44.504097610+00:00 DEBUG tokio_core::reactor:466 adding a new I/O source
2017-11-15T23:37:44.504105710+00:00 DEBUG trust_dns_server::server::server_future:87 registered tcp: TcpListener { sys: TcpListener { inner: TcpListener { addr: V6([2a01:4f8:c0c:2c12::50]:8053), fd: 5 } }, selector_id: SelectorId { id: AtomicUsize(1) } }
2017-11-15T23:37:44.504118275+00:00 INFO named:404 listening for TCP on TcpListener { addr: V6([2a01:4f8:c0c:2c12::51]:8053), fd: 6 }
2017-11-15T23:37:44.504126949+00:00 DEBUG tokio_core::reactor:466 adding a new I/O source
2017-11-15T23:37:44.504134113+00:00 DEBUG trust_dns_server::server::server_future:87 registered tcp: TcpListener { sys: TcpListener { inner: TcpListener { addr: V6([2a01:4f8:c0c:2c12::51]:8053), fd: 6 } }, selector_id: SelectorId { id: AtomicUsize(1) } }
2017-11-15T23:37:44.504144512+00:00 INFO named:486 
2017-11-15T23:37:44.504150336+00:00 INFO named:487     o                      o            o             
2017-11-15T23:37:44.504156139+00:00 INFO named:488     |                      |            |             
2017-11-15T23:37:44.504161853+00:00 INFO named:489   --O--  o-o  o  o  o-o  --O--  o-o   o-O  o-o   o-o  
2017-11-15T23:37:44.504167344+00:00 INFO named:490     |    |    |  |   \     |         |  |  |  |   \   
2017-11-15T23:37:44.504173107+00:00 INFO named:491     o    o    o--o  o-o    o          o-o  o  o  o-o  
2017-11-15T23:37:44.504178632+00:00 INFO named:492 
2017-11-15T23:37:44.504184139+00:00 INFO named:424 awaiting connections...
2017-11-15T23:37:44.504189812+00:00 INFO trust_dns_server::server::server_future:189 Server starting up
2017-11-15T23:37:44.504204113+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 6150 }
2017-11-15T23:37:44.504211706+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1483947, tv_nsec: 785614704 }
2017-11-15T23:37:44.504219469+00:00 DEBUG tokio_core::reactor:404 consuming notification queue
2017-11-15T23:37:44.504237667+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 0
2017-11-15T23:37:44.504245353+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-15T23:37:44.504252672+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 1
2017-11-15T23:37:44.504258419+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-15T23:37:44.504264959+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 2
2017-11-15T23:37:44.504270576+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-15T23:37:44.504277492+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 3
2017-11-15T23:37:44.504283865+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-15T23:37:44.504289587+00:00 DEBUG tokio_core::reactor:307 loop process - 7 events, Duration { secs: 0, nanos: 86010 }
2017-11-15T23:37:44.504297153+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 795 }
2017-11-15T23:37:44.504303296+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1483947, tv_nsec: 785708306 }
2017-11-15T23:37:44.504309495+00:00 DEBUG tokio_core::reactor:307 loop process - 0 events, Duration { secs: 0, nanos: 12341 }
2017-11-15T23:37:50.177374676+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 5, nanos: 673025307 }
2017-11-15T23:37:50.177461895+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1483953, tv_nsec: 458752155 }
2017-11-15T23:37:50.177511618+00:00 DEBUG tokio_core::reactor:399 notifying a task handle
2017-11-15T23:37:50.177531559+00:00 DEBUG tokio_core::reactor:307 loop process - 1 events, Duration { secs: 0, nanos: 190472 }
2017-11-15T23:37:50.177544498+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 5027 }
2017-11-15T23:37:50.177550583+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1483953, tv_nsec: 458955597 }
2017-11-15T23:37:50.177600218+00:00 DEBUG trust_dns_server::server::request_stream:68 received message: 31180
2017-11-15T23:37:50.177621268+00:00 INFO trust_dns_server::authority::catalog:43 request id: 31180 type: Query op_code: Query
2017-11-15T23:37:50.177649511+00:00 DEBUG trust_dns_server::authority::catalog:286 found authority: Name { is_fqdn: true, labels: ["dev", "terrax", "net"] }
2017-11-15T23:37:50.177677520+00:00 DEBUG trust_dns_server::authority::catalog:295 no DAU in request, used default SupportAlgorithms
2017-11-15T23:37:50.177683814+00:00 DEBUG trust_dns_server::authority::catalog:302 request: 31180 supported_algs: 
2017-11-15T23:37:50.177745245+00:00 DEBUG trust_dns_server::server::request_stream:101 sending message: 31180
2017-11-15T23:37:50.177872827+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 0
2017-11-15T23:37:50.177889640+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-15T23:37:50.177897176+00:00 DEBUG tokio_core::reactor:307 loop process - 1 events, Duration { secs: 0, nanos: 352660 }
2017-11-15T23:37:50.177906057+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 1432 }
2017-11-15T23:37:50.177912745+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1483953, tv_nsec: 459317149 }
2017-11-15T23:37:50.177920874+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 0
2017-11-15T23:37:50.177926757+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-15T23:37:50.177932788+00:00 DEBUG tokio_core::reactor:307 loop process - 2 events, Duration { secs: 0, nanos: 26794 }
2017-11-15T23:37:50.177939980+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 511 }
2017-11-15T23:37:50.177946173+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1483953, tv_nsec: 459351134 }
2017-11-15T23:37:50.177952713+00:00 DEBUG tokio_core::reactor:307 loop process - 0 events, Duration { secs: 0, nanos: 12732 }
2017-11-15T23:37:50.420125740+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 242164869 }
2017-11-15T23:37:50.420176741+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1483953, tv_nsec: 701535053 }
2017-11-15T23:37:50.420186890+00:00 DEBUG tokio_core::reactor:399 notifying a task handle
2017-11-15T23:37:50.420200290+00:00 DEBUG tokio_core::reactor:307 loop process - 1 events, Duration { secs: 0, nanos: 76271 }
2017-11-15T23:37:50.420213011+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 4999 }
2017-11-15T23:37:50.420219477+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1483953, tv_nsec: 701624169 }
2017-11-15T23:37:50.420244900+00:00 DEBUG trust_dns_server::server::request_stream:68 received message: 18377
2017-11-15T23:37:50.420254232+00:00 INFO trust_dns_server::authority::catalog:43 request id: 18377 type: Query op_code: Query
2017-11-15T23:37:50.420288026+00:00 DEBUG trust_dns_server::authority::catalog:286 found authority: Name { is_fqdn: true, labels: ["dev", "terrax", "net"] }
2017-11-15T23:37:50.420304856+00:00 DEBUG trust_dns_server::authority::catalog:295 no DAU in request, used default SupportAlgorithms
2017-11-15T23:37:50.420326822+00:00 DEBUG trust_dns_server::authority::catalog:302 request: 18377 supported_algs: 
2017-11-15T23:37:50.420358209+00:00 DEBUG trust_dns_server::server::request_stream:101 sending message: 18377
2017-11-15T23:37:50.420430362+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 0
2017-11-15T23:37:50.420443769+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-15T23:37:50.420450002+00:00 DEBUG tokio_core::reactor:307 loop process - 1 events, Duration { secs: 0, nanos: 236965 }
2017-11-15T23:37:50.420457620+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 1200 }
2017-11-15T23:37:50.420463380+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1483953, tv_nsec: 701868727 }
2017-11-15T23:37:50.420470780+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 0
2017-11-15T23:37:50.420476196+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-15T23:37:50.420481475+00:00 DEBUG tokio_core::reactor:307 loop process - 2 events, Duration { secs: 0, nanos: 23910 }
2017-11-15T23:37:50.420487719+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 412 }
2017-11-15T23:37:50.420493706+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1483953, tv_nsec: 701898881 }
2017-11-15T23:37:50.420499277+00:00 DEBUG tokio_core::reactor:307 loop process - 0 events, Duration { secs: 0, nanos: 11557 }
2017-11-15T23:37:50.454163875+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 33656248 }
2017-11-15T23:37:50.454235265+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1483953, tv_nsec: 735572278 }
2017-11-15T23:37:50.454270347+00:00 DEBUG tokio_core::reactor:399 notifying a task handle
2017-11-15T23:37:50.454295145+00:00 DEBUG tokio_core::reactor:307 loop process - 1 events, Duration { secs: 0, nanos: 133877 }
2017-11-15T23:37:50.454317277+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 8468 }
2017-11-15T23:37:50.454328594+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1483953, tv_nsec: 735728340 }
2017-11-15T23:37:50.454373780+00:00 DEBUG trust_dns_server::server::request_stream:68 received message: 15007
2017-11-15T23:37:50.454397482+00:00 INFO trust_dns_server::authority::catalog:43 request id: 15007 type: Query op_code: Query
2017-11-15T23:37:50.454429536+00:00 DEBUG trust_dns_server::authority::catalog:286 found authority: Name { is_fqdn: true, labels: ["dev", "terrax", "net"] }
2017-11-15T23:37:50.454449216+00:00 DEBUG trust_dns_server::authority::catalog:295 no DAU in request, used default SupportAlgorithms
2017-11-15T23:37:50.454456311+00:00 DEBUG trust_dns_server::authority::catalog:302 request: 15007 supported_algs: 
2017-11-15T23:37:50.454530067+00:00 DEBUG trust_dns_server::server::request_stream:101 sending message: 15007
2017-11-15T23:37:50.454844601+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 0
2017-11-15T23:37:50.454902701+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-15T23:37:50.454921207+00:00 DEBUG tokio_core::reactor:307 loop process - 1 events, Duration { secs: 0, nanos: 603665 }
2017-11-15T23:37:50.454946230+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 5266 }
2017-11-15T23:37:50.454969753+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1483953, tv_nsec: 736356989 }
2017-11-15T23:37:50.454987845+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 0
2017-11-15T23:37:50.455004090+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-15T23:37:50.455017755+00:00 DEBUG tokio_core::reactor:307 loop process - 2 events, Duration { secs: 0, nanos: 71834 }
2017-11-15T23:37:50.455033022+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 1333 }
2017-11-15T23:37:50.455044514+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1483953, tv_nsec: 736444086 }
2017-11-15T23:37:50.455066108+00:00 DEBUG tokio_core::reactor:307 loop process - 0 events, Duration { secs: 0, nanos: 33020 }
2017-11-15T23:37:50.483846469+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 28766449 }
2017-11-15T23:37:50.483940710+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1483953, tv_nsec: 765255248 }
2017-11-15T23:37:50.483961168+00:00 DEBUG tokio_core::reactor:399 notifying a task handle
2017-11-15T23:37:50.483975856+00:00 DEBUG tokio_core::reactor:307 loop process - 1 events, Duration { secs: 0, nanos: 131625 }
2017-11-15T23:37:50.484005138+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 6837 }
2017-11-15T23:37:50.484017628+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1483953, tv_nsec: 765416206 }
2017-11-15T23:37:50.484065606+00:00 DEBUG trust_dns_server::server::request_stream:68 received message: 62489
2017-11-15T23:37:50.484084591+00:00 INFO trust_dns_server::authority::catalog:43 request id: 62489 type: Query op_code: Query
2017-11-15T23:37:50.484113061+00:00 DEBUG trust_dns_server::authority::catalog:286 found authority: Name { is_fqdn: true, labels: ["dev", "terrax", "net"] }
2017-11-15T23:37:50.484139817+00:00 DEBUG trust_dns_server::authority::catalog:295 no DAU in request, used default SupportAlgorithms
2017-11-15T23:37:50.484147543+00:00 DEBUG trust_dns_server::authority::catalog:302 request: 62489 supported_algs: 
2017-11-15T23:37:50.484197226+00:00 DEBUG trust_dns_server::server::request_stream:101 sending message: 62489
2017-11-15T23:37:50.484286421+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 0
2017-11-15T23:37:50.484302333+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-15T23:37:50.484309686+00:00 DEBUG tokio_core::reactor:307 loop process - 1 events, Duration { secs: 0, nanos: 304570 }
2017-11-15T23:37:50.484319127+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 1618 }
2017-11-15T23:37:50.484326046+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1483953, tv_nsec: 765730168 }
2017-11-15T23:37:50.484333844+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 0
2017-11-15T23:37:50.484339776+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-15T23:37:50.484347004+00:00 DEBUG tokio_core::reactor:307 loop process - 2 events, Duration { secs: 0, nanos: 27983 }
2017-11-15T23:37:50.484354138+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 560 }
2017-11-15T23:37:50.484360421+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1483953, tv_nsec: 765765293 }
2017-11-15T23:37:50.484366832+00:00 DEBUG tokio_core::reactor:307 loop process - 0 events, Duration { secs: 0, nanos: 12692 }
2017-11-15T23:37:50.509576343+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 25201100 }
2017-11-15T23:37:50.509649163+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1483953, tv_nsec: 790985444 }
2017-11-15T23:37:50.509666383+00:00 DEBUG tokio_core::reactor:399 notifying a task handle
2017-11-15T23:37:50.509686694+00:00 DEBUG tokio_core::reactor:307 loop process - 1 events, Duration { secs: 0, nanos: 112256 }
2017-11-15T23:37:50.509722204+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 7384 }
2017-11-15T23:37:50.509734044+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1483953, tv_nsec: 791133260 }
2017-11-15T23:37:50.509771621+00:00 DEBUG trust_dns_server::server::request_stream:68 received message: 10557
2017-11-15T23:37:50.509795244+00:00 INFO trust_dns_server::authority::catalog:43 request id: 10557 type: Query op_code: Query
2017-11-15T23:37:50.509822122+00:00 DEBUG trust_dns_server::authority::catalog:286 found authority: Name { is_fqdn: true, labels: ["dev", "terrax", "net"] }
2017-11-15T23:37:50.509845993+00:00 DEBUG trust_dns_server::authority::catalog:295 no DAU in request, used default SupportAlgorithms
2017-11-15T23:37:50.509857864+00:00 DEBUG trust_dns_server::authority::catalog:302 request: 10557 supported_algs: 
2017-11-15T23:37:50.509941062+00:00 DEBUG trust_dns_server::server::request_stream:101 sending message: 10557
2017-11-15T23:37:50.510062756+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 0
2017-11-15T23:37:50.510087310+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-15T23:37:50.510100218+00:00 DEBUG tokio_core::reactor:307 loop process - 1 events, Duration { secs: 0, nanos: 377896 }
2017-11-15T23:37:50.510115337+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 2131 }
2017-11-15T23:37:50.510127339+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1483953, tv_nsec: 791526348 }
2017-11-15T23:37:50.510140998+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 0
2017-11-15T23:37:50.510151284+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-15T23:37:50.510161483+00:00 DEBUG tokio_core::reactor:307 loop process - 2 events, Duration { secs: 0, nanos: 46246 }
2017-11-15T23:37:50.510174377+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 852 }
2017-11-15T23:37:50.510185103+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1483953, tv_nsec: 791585453 }
2017-11-15T23:37:50.510195676+00:00 DEBUG tokio_core::reactor:307 loop process - 0 events, Duration { secs: 0, nanos: 21348 }
2017-11-15T23:37:50.539283313+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 29074671 }
2017-11-15T23:37:50.539374441+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1483953, tv_nsec: 820692570 }
2017-11-15T23:37:50.539390839+00:00 DEBUG tokio_core::reactor:399 notifying a task handle
2017-11-15T23:37:50.539407244+00:00 DEBUG tokio_core::reactor:307 loop process - 1 events, Duration { secs: 0, nanos: 125748 }
2017-11-15T23:37:50.539425996+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 6523 }
2017-11-15T23:37:50.539447830+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1483953, tv_nsec: 820837047 }
2017-11-15T23:37:50.539494275+00:00 DEBUG trust_dns_server::server::request_stream:68 received message: 45690
2017-11-15T23:37:50.539566090+00:00 INFO trust_dns_server::authority::catalog:43 request id: 45690 type: Query op_code: Query
2017-11-15T23:37:50.539592478+00:00 DEBUG trust_dns_server::authority::catalog:286 found authority: Name { is_fqdn: true, labels: ["dev", "terrax", "net"] }
2017-11-15T23:37:50.539613784+00:00 DEBUG trust_dns_server::authority::catalog:295 no DAU in request, used default SupportAlgorithms
2017-11-15T23:37:50.539624762+00:00 DEBUG trust_dns_server::authority::catalog:302 request: 45690 supported_algs: 
2017-11-15T23:37:50.539703562+00:00 DEBUG trust_dns_server::server::request_stream:101 sending message: 45690
2017-11-15T23:37:50.539872911+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 0
2017-11-15T23:37:50.539899686+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-15T23:37:50.539911760+00:00 DEBUG tokio_core::reactor:307 loop process - 1 events, Duration { secs: 0, nanos: 485731 }
2017-11-15T23:37:50.539926620+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 1958 }
2017-11-15T23:37:50.540013369+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1483953, tv_nsec: 821337510 }
2017-11-15T23:37:50.540031440+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 0
2017-11-15T23:37:50.540042420+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-15T23:37:50.540053018+00:00 DEBUG tokio_core::reactor:307 loop process - 2 events, Duration { secs: 0, nanos: 126552 }
2017-11-15T23:37:50.540066329+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 1320 }
2017-11-15T23:37:50.540077946+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1483953, tv_nsec: 821477350 }
2017-11-15T23:37:50.540089563+00:00 DEBUG tokio_core::reactor:307 loop process - 0 events, Duration { secs: 0, nanos: 23285 }
2017-11-15T23:37:50.564707403+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 24604543 }
2017-11-15T23:37:50.564758386+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1483953, tv_nsec: 846116610 }
2017-11-15T23:37:50.564772169+00:00 DEBUG tokio_core::reactor:399 notifying a task handle
2017-11-15T23:37:50.564789432+00:00 DEBUG tokio_core::reactor:307 loop process - 1 events, Duration { secs: 0, nanos: 83801 }
2017-11-15T23:37:50.564836109+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 21153 }
2017-11-15T23:37:50.564846768+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1483953, tv_nsec: 846247183 }
2017-11-15T23:37:50.564897339+00:00 DEBUG trust_dns_server::server::request_stream:68 received message: 20290
2017-11-15T23:37:50.564911865+00:00 INFO trust_dns_server::authority::catalog:43 request id: 20290 type: Query op_code: Query
2017-11-15T23:37:50.564936819+00:00 DEBUG trust_dns_server::authority::catalog:286 found authority: Name { is_fqdn: true, labels: ["dev", "terrax", "net"] }
2017-11-15T23:37:50.564977982+00:00 DEBUG trust_dns_server::authority::catalog:295 no DAU in request, used default SupportAlgorithms
2017-11-15T23:37:50.565004096+00:00 DEBUG trust_dns_server::authority::catalog:302 request: 20290 supported_algs: 
2017-11-15T23:37:50.565090601+00:00 DEBUG trust_dns_server::server::request_stream:101 sending message: 20290
2017-11-15T23:37:50.565403978+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 0
2017-11-15T23:37:50.565421947+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-15T23:37:50.565433278+00:00 DEBUG tokio_core::reactor:307 loop process - 1 events, Duration { secs: 0, nanos: 597084 }
2017-11-15T23:37:50.565446806+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 1762 }
2017-11-15T23:37:50.565457510+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1483953, tv_nsec: 846857844 }
2017-11-15T23:37:50.565485579+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 0
2017-11-15T23:37:50.565513192+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-15T23:37:50.565522975+00:00 DEBUG tokio_core::reactor:307 loop process - 2 events, Duration { secs: 0, nanos: 76221 }
2017-11-15T23:37:50.565534306+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 640 }
2017-11-15T23:37:50.565544398+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1483953, tv_nsec: 846945417 }
2017-11-15T23:37:50.565554627+00:00 DEBUG tokio_core::reactor:307 loop process - 0 events, Duration { secs: 0, nanos: 20333 }
^C

dig

$ dig TLSA _443._tcp.dev.terrax.net
                                                                                                                                           
; <<>> DiG 9.10.6-Debian <<>> TLSA _443._tcp.dev.terrax.net                                                                                
;; global options: +cmd                                                                                                                    
;; Got answer:                                                                                                                             
;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 60852                                                                                 
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1                                                                       
                                                                                                                                           
;; OPT PSEUDOSECTION:                                                                                                                      
; EDNS: version: 0, flags:; udp: 4096                                                                                                      
;; QUESTION SECTION:                                                                                                                       
;_443._tcp.dev.terrax.net.      IN      TLSA                                                                                               
                                                                                                                                           
;; Query time: 544 msec                                                                                                                    
;; SERVER: ::1#53(::1)                                                                                                                     
;; WHEN: Thu Nov 16 00:37:50 CET 2017                                                                                                      
;; MSG SIZE  rcvd: 53 

unbound.log


[1510789067] unbound[16798:0] debug: module config: "subnetcache validator iterator"
[1510789067] unbound[16798:0] notice: init module 0: subnet
[1510789067] unbound[16798:0] debug: subnet: option registered (8)
[1510789067] unbound[16798:0] notice: init module 1: validator
[1510789067] unbound[16798:0] info: adding trusted key . DNSKEY IN
[1510789067] unbound[16798:0] info: adding trusted key . DNSKEY IN
[1510789067] unbound[16798:0] notice: init module 2: iterator
[1510789067] unbound[16798:0] debug: target fetch policy for level 0 is 3
[1510789067] unbound[16798:0] debug: target fetch policy for level 1 is 2
[1510789067] unbound[16798:0] debug: target fetch policy for level 2 is 1
[1510789067] unbound[16798:0] debug: target fetch policy for level 3 is 0
[1510789067] unbound[16798:0] debug: target fetch policy for level 4 is 0
[1510789067] unbound[16798:0] debug: Reading root hints from /etc/unbound/root.hints
[1510789067] unbound[16798:0] info: DelegationPoint<.>: 13 names (0 missing), 26 addrs (0 result, 26 avail) parentNS
[1510789067] unbound[16798:0] debug: cache memory msg=66072 rrset=66072 infra=5224 val=66336 subnet=74488
[1510789067] unbound[16798:0] info: start of service (unbound 1.6.7).
[1510789070] unbound[16798:0] info: ::1 _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_new
[1510789070] unbound[16798:0] info: subnet operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
[1510789070] unbound[16798:0] info: validator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510789070] unbound[16798:0] info: resolving _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: priming . IN NS
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510789070] unbound[16798:0] info: iterator operate: query . NS IN
[1510789070] unbound[16798:0] info: processQueryTargets: . NS IN
[1510789070] unbound[16798:0] info: sending query: . NS IN
[1510789070] unbound[16798:0] debug: sending to target: <.> 2001:503:ba3e::2:30#53
[1510789070] unbound[16798:0] debug: cache memory msg=66072 rrset=66072 infra=5521 val=66336 subnet=74488
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510789070] unbound[16798:0] info: iterator operate: query . NS IN
[1510789070] unbound[16798:0] info: response for . NS IN
[1510789070] unbound[16798:0] info: reply from <.> 2001:503:ba3e::2:30#53
[1510789070] unbound[16798:0] info: query response was ANSWER
[1510789070] unbound[16798:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
[1510789070] unbound[16798:0] info: validator operate: query . NS IN
[1510789070] unbound[16798:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_moddone
[1510789070] unbound[16798:0] info: subnet operate: query . NS IN
[1510789070] unbound[16798:0] info: priming successful for . NS IN
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
[1510789070] unbound[16798:0] info: iterator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: resolving (init part 2):  _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: resolving (init part 3):  _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: processQueryTargets: _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] debug: removing 4 labels
[1510789070] unbound[16798:0] info: sending query: net. A IN
[1510789070] unbound[16798:0] debug: sending to target: <.> 2001:7fd::1#53
[1510789070] unbound[16798:0] debug: cache memory msg=66929 rrset=73612 infra=5818 val=66336 subnet=74488
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510789070] unbound[16798:0] info: iterator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: reply from <.> 2001:7fd::1#53
[1510789070] unbound[16798:0] info: query response was REFERRAL
[1510789070] unbound[16798:0] info: processQueryTargets: _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] debug: removing 3 labels
[1510789070] unbound[16798:0] info: sending query: terrax.net. A IN
[1510789070] unbound[16798:0] debug: sending to target: <net.> 2001:503:39c1::30#53
[1510789070] unbound[16798:0] debug: cache memory msg=66929 rrset=81415 infra=6119 val=66336 subnet=74488
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510789070] unbound[16798:0] info: iterator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: reply from <net.> 2001:503:39c1::30#53
[1510789070] unbound[16798:0] info: query response was REFERRAL
[1510789070] unbound[16798:0] info: processQueryTargets: _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: new target gw2.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] info: new target gw1.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] debug: removing 2 labels
[1510789070] unbound[16798:0] info: sending query: dev.terrax.net. A IN
[1510789070] unbound[16798:0] debug: sending to target: <terrax.net.> 94.130.76.133#53
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510789070] unbound[16798:0] info: iterator operate: query gw2.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] info: resolving gw2.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] info: resolving (init part 2):  gw2.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] info: resolving (init part 3):  gw2.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] info: processQueryTargets: gw2.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] info: skipping target due to dependency cycle (harden-glue: no may fix some of the cycles) gw2.h.terrax.net. A IN
[1510789070] unbound[16798:0] info: new target gw1.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] debug: removing 1 labels
[1510789070] unbound[16798:0] info: sending query: h.terrax.net. A IN
[1510789070] unbound[16798:0] debug: sending to target: <terrax.net.> 94.130.73.109#53
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510789070] unbound[16798:0] info: iterator operate: query gw1.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] info: resolving gw1.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] info: resolving (init part 2):  gw1.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] info: resolving (init part 3):  gw1.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] info: processQueryTargets: gw1.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] info: skipping target due to dependency cycle (harden-glue: no may fix some of the cycles) gw2.h.terrax.net. A IN
[1510789070] unbound[16798:0] info: skipping target due to dependency cycle (harden-glue: no may fix some of the cycles) gw1.h.terrax.net. A IN
[1510789070] unbound[16798:0] debug: removing 1 labels
[1510789070] unbound[16798:0] info: sending query: h.terrax.net. A IN
[1510789070] unbound[16798:0] debug: sending to target: <terrax.net.> 94.130.73.109#53
[1510789070] unbound[16798:0] debug: cache memory msg=66929 rrset=82630 infra=6735 val=66336 subnet=74488
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510789070] unbound[16798:0] info: iterator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: reply from <terrax.net.> 94.130.76.133#53
[1510789070] unbound[16798:0] info: query response was REFERRAL
[1510789070] unbound[16798:0] info: processQueryTargets: _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: new target dev.h.terrax.net. A IN
[1510789070] unbound[16798:0] debug: removing 1 labels
[1510789070] unbound[16798:0] info: sending query: _tcp.dev.terrax.net. A IN
[1510789070] unbound[16798:0] debug: sending to target: <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510789070] unbound[16798:0] info: iterator operate: query dev.h.terrax.net. A IN
[1510789070] unbound[16798:0] info: resolving dev.h.terrax.net. A IN
[1510789070] unbound[16798:0] info: resolving (init part 2):  dev.h.terrax.net. A IN
[1510789070] unbound[16798:0] info: resolving (init part 3):  dev.h.terrax.net. A IN
[1510789070] unbound[16798:0] info: processQueryTargets: dev.h.terrax.net. A IN
[1510789070] unbound[16798:0] info: new target gw2.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] info: new target gw1.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] debug: removing 1 labels
[1510789070] unbound[16798:0] info: sending query: h.terrax.net. A IN
[1510789070] unbound[16798:0] debug: sending to target: <terrax.net.> 94.130.76.133#53
[1510789070] unbound[16798:0] debug: cache memory msg=66929 rrset=83708 infra=7047 val=66336 subnet=74488
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510789070] unbound[16798:0] info: iterator operate: query gw1.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] info: response for gw1.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] info: reply from <terrax.net.> 94.130.73.109#53
[1510789070] unbound[16798:0] info: query response was nodata ANSWER
[1510789070] unbound[16798:0] info: processQueryTargets: gw1.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] info: sending query: gw1.h.terrax.net. A IN
[1510789070] unbound[16798:0] debug: sending to target: <terrax.net.> 94.130.76.133#53
[1510789070] unbound[16798:0] debug: cache memory msg=67199 rrset=84566 infra=7047 val=66336 subnet=74488
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510789070] unbound[16798:0] info: iterator operate: query gw2.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] info: response for gw2.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] info: reply from <terrax.net.> 94.130.73.109#53
[1510789070] unbound[16798:0] info: query response was nodata ANSWER
[1510789070] unbound[16798:0] info: processQueryTargets: gw2.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] info: sending query: gw2.h.terrax.net. A IN
[1510789070] unbound[16798:0] debug: sending to target: <terrax.net.> 94.130.73.109#53
[1510789070] unbound[16798:0] debug: cache memory msg=67199 rrset=84566 infra=7047 val=66336 subnet=74488
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510789070] unbound[16798:0] info: iterator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: reply from <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510789070] unbound[16798:0] info: query response was NXDOMAIN ANSWER
[1510789070] unbound[16798:0] info: finishing processing for _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
[1510789070] unbound[16798:0] info: validator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: prime trust anchor
[1510789070] unbound[16798:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_pass
[1510789070] unbound[16798:0] info: subnet operate: query . DNSKEY IN
[1510789070] unbound[16798:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
[1510789070] unbound[16798:0] info: validator operate: query . DNSKEY IN
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510789070] unbound[16798:0] info: resolving . DNSKEY IN
[1510789070] unbound[16798:0] info: resolving (init part 2):  . DNSKEY IN
[1510789070] unbound[16798:0] info: resolving (init part 3):  . DNSKEY IN
[1510789070] unbound[16798:0] info: processQueryTargets: . DNSKEY IN
[1510789070] unbound[16798:0] info: sending query: . DNSKEY IN
[1510789070] unbound[16798:0] debug: sending to target: <.> 2001:500:12::d0d#53
[1510789070] unbound[16798:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_pass
[1510789070] unbound[16798:0] info: subnet operate: query _ta-4a5c-4f66. NULL IN
[1510789070] unbound[16798:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
[1510789070] unbound[16798:0] info: validator operate: query _ta-4a5c-4f66. NULL IN
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510789070] unbound[16798:0] info: resolving _ta-4a5c-4f66. NULL IN
[1510789070] unbound[16798:0] info: resolving (init part 2):  _ta-4a5c-4f66. NULL IN
[1510789070] unbound[16798:0] info: resolving (init part 3):  _ta-4a5c-4f66. NULL IN
[1510789070] unbound[16798:0] info: processQueryTargets: _ta-4a5c-4f66. NULL IN
[1510789070] unbound[16798:0] info: sending query: _ta-4a5c-4f66. A IN
[1510789070] unbound[16798:0] debug: sending to target: <.> 2001:500:9f::42#53
[1510789070] unbound[16798:0] debug: cache memory msg=67476 rrset=85445 infra=7641 val=66336 subnet=74488
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510789070] unbound[16798:0] info: iterator operate: query dev.h.terrax.net. A IN
[1510789070] unbound[16798:0] info: response for dev.h.terrax.net. A IN
[1510789070] unbound[16798:0] info: reply from <terrax.net.> 94.130.76.133#53
[1510789070] unbound[16798:0] info: query response was nodata ANSWER
[1510789070] unbound[16798:0] info: processQueryTargets: dev.h.terrax.net. A IN
[1510789070] unbound[16798:0] info: sending query: dev.h.terrax.net. A IN
[1510789070] unbound[16798:0] debug: sending to target: <terrax.net.> 94.130.73.109#53
[1510789070] unbound[16798:0] debug: cache memory msg=67476 rrset=85445 infra=7641 val=66336 subnet=74488
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510789070] unbound[16798:0] info: iterator operate: query gw1.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] info: response for gw1.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] info: reply from <terrax.net.> 94.130.76.133#53
[1510789070] unbound[16798:0] info: query response was ANSWER
[1510789070] unbound[16798:0] info: processQueryTargets: gw1.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] info: sending query: gw1.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] debug: sending to target: <terrax.net.> 94.130.76.133#53
[1510789070] unbound[16798:0] debug: cache memory msg=67726 rrset=85597 infra=7641 val=66336 subnet=74488
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510789070] unbound[16798:0] info: iterator operate: query gw2.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] info: response for gw2.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] info: reply from <terrax.net.> 94.130.73.109#53
[1510789070] unbound[16798:0] info: query response was ANSWER
[1510789070] unbound[16798:0] info: processQueryTargets: gw2.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] info: sending query: gw2.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] debug: sending to target: <terrax.net.> 94.130.76.133#53
[1510789070] unbound[16798:0] debug: cache memory msg=67976 rrset=85749 infra=7641 val=66336 subnet=74488
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510789070] unbound[16798:0] info: iterator operate: query gw1.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] info: response for gw1.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] info: reply from <terrax.net.> 94.130.76.133#53
[1510789070] unbound[16798:0] info: query response was ANSWER
[1510789070] unbound[16798:0] info: finishing processing for gw1.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
[1510789070] unbound[16798:0] info: validator operate: query gw1.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_moddone
[1510789070] unbound[16798:0] info: subnet operate: query gw1.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] debug: cache memory msg=68226 rrset=86153 infra=7641 val=66336 subnet=74488
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510789070] unbound[16798:0] info: iterator operate: query dev.h.terrax.net. A IN
[1510789070] unbound[16798:0] info: response for dev.h.terrax.net. A IN
[1510789070] unbound[16798:0] info: reply from <terrax.net.> 94.130.73.109#53
[1510789070] unbound[16798:0] info: query response was nodata ANSWER
[1510789070] unbound[16798:0] info: finishing processing for dev.h.terrax.net. A IN
[1510789070] unbound[16798:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
[1510789070] unbound[16798:0] info: validator operate: query dev.h.terrax.net. A IN
[1510789070] unbound[16798:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_moddone
[1510789070] unbound[16798:0] info: subnet operate: query dev.h.terrax.net. A IN
[1510789070] unbound[16798:0] debug: cache memory msg=68500 rrset=86567 infra=7641 val=66336 subnet=74488
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510789070] unbound[16798:0] info: iterator operate: query gw2.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] info: response for gw2.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] info: reply from <terrax.net.> 94.130.76.133#53
[1510789070] unbound[16798:0] info: query response was ANSWER
[1510789070] unbound[16798:0] info: finishing processing for gw2.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
[1510789070] unbound[16798:0] info: validator operate: query gw2.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_moddone
[1510789070] unbound[16798:0] info: subnet operate: query gw2.h.terrax.net. AAAA IN
[1510789070] unbound[16798:0] debug: cache memory msg=68750 rrset=86971 infra=7641 val=66336 subnet=74488
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510789070] unbound[16798:0] info: iterator operate: query _ta-4a5c-4f66. NULL IN
[1510789070] unbound[16798:0] info: response for _ta-4a5c-4f66. NULL IN
[1510789070] unbound[16798:0] info: reply from <.> 2001:500:9f::42#53
[1510789070] unbound[16798:0] info: query response was NXDOMAIN ANSWER
[1510789070] unbound[16798:0] info: finishing processing for _ta-4a5c-4f66. NULL IN
[1510789070] unbound[16798:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
[1510789070] unbound[16798:0] info: validator operate: query _ta-4a5c-4f66. NULL IN
[1510789070] unbound[16798:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1510789070] unbound[16798:0] info: subnet operate: query _ta-4a5c-4f66. NULL IN
[1510789070] unbound[16798:0] debug: cache memory msg=69021 rrset=88089 infra=7641 val=66336 subnet=74488
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510789070] unbound[16798:0] info: iterator operate: query . DNSKEY IN
[1510789070] unbound[16798:0] info: response for . DNSKEY IN
[1510789070] unbound[16798:0] info: reply from <.> 2001:500:12::d0d#53
[1510789070] unbound[16798:0] info: query response was ANSWER
[1510789070] unbound[16798:0] info: finishing processing for . DNSKEY IN
[1510789070] unbound[16798:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
[1510789070] unbound[16798:0] info: validator operate: query . DNSKEY IN
[1510789070] unbound[16798:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1510789070] unbound[16798:0] info: subnet operate: query . DNSKEY IN
[1510789070] unbound[16798:0] info: validate keys with anchor(DS): sec_status_secure
[1510789070] unbound[16798:0] info: Successfully primed trust anchor . DNSKEY IN
[1510789070] unbound[16798:0] debug: validator[module 1] operate: extstate:module_wait_subquery event:module_event_pass
[1510789070] unbound[16798:0] info: validator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: validated DS net. DS IN
[1510789070] unbound[16798:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_pass
[1510789070] unbound[16798:0] info: subnet operate: query net. DNSKEY IN
[1510789070] unbound[16798:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
[1510789070] unbound[16798:0] info: validator operate: query net. DNSKEY IN
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510789070] unbound[16798:0] info: resolving net. DNSKEY IN
[1510789070] unbound[16798:0] info: resolving (init part 2):  net. DNSKEY IN
[1510789070] unbound[16798:0] info: resolving (init part 3):  net. DNSKEY IN
[1510789070] unbound[16798:0] info: processQueryTargets: net. DNSKEY IN
[1510789070] unbound[16798:0] info: sending query: net. DNSKEY IN
[1510789070] unbound[16798:0] debug: sending to target: <net.> 2001:503:39c1::30#53
[1510789070] unbound[16798:0] debug: cache memory msg=69254 rrset=89453 infra=7641 val=67732 subnet=74488
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510789070] unbound[16798:0] info: iterator operate: query net. DNSKEY IN
[1510789070] unbound[16798:0] info: response for net. DNSKEY IN
[1510789070] unbound[16798:0] info: reply from <net.> 2001:503:39c1::30#53
[1510789070] unbound[16798:0] info: query response was ANSWER
[1510789070] unbound[16798:0] info: finishing processing for net. DNSKEY IN
[1510789070] unbound[16798:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
[1510789070] unbound[16798:0] info: validator operate: query net. DNSKEY IN
[1510789070] unbound[16798:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1510789070] unbound[16798:0] info: subnet operate: query net. DNSKEY IN
[1510789070] unbound[16798:0] info: validated DNSKEY net. DNSKEY IN
[1510789070] unbound[16798:0] debug: validator[module 1] operate: extstate:module_wait_subquery event:module_event_pass
[1510789070] unbound[16798:0] info: validator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: validated DS terrax.net. DS IN
[1510789070] unbound[16798:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_pass
[1510789070] unbound[16798:0] info: subnet operate: query terrax.net. DNSKEY IN
[1510789070] unbound[16798:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
[1510789070] unbound[16798:0] info: validator operate: query terrax.net. DNSKEY IN
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510789070] unbound[16798:0] info: resolving terrax.net. DNSKEY IN
[1510789070] unbound[16798:0] info: resolving (init part 2):  terrax.net. DNSKEY IN
[1510789070] unbound[16798:0] info: resolving (init part 3):  terrax.net. DNSKEY IN
[1510789070] unbound[16798:0] info: processQueryTargets: terrax.net. DNSKEY IN
[1510789070] unbound[16798:0] info: sending query: terrax.net. DNSKEY IN
[1510789070] unbound[16798:0] debug: sending to target: <terrax.net.> 2a01:4f8:c0c:2d1a::10#53
[1510789070] unbound[16798:0] debug: cache memory msg=69491 rrset=90403 infra=7949 val=68714 subnet=74488
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510789070] unbound[16798:0] info: iterator operate: query terrax.net. DNSKEY IN
[1510789070] unbound[16798:0] info: response for terrax.net. DNSKEY IN
[1510789070] unbound[16798:0] info: reply from <terrax.net.> 2a01:4f8:c0c:2d1a::10#53
[1510789070] unbound[16798:0] info: query response was ANSWER
[1510789070] unbound[16798:0] info: finishing processing for terrax.net. DNSKEY IN
[1510789070] unbound[16798:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
[1510789070] unbound[16798:0] info: validator operate: query terrax.net. DNSKEY IN
[1510789070] unbound[16798:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1510789070] unbound[16798:0] info: subnet operate: query terrax.net. DNSKEY IN
[1510789070] unbound[16798:0] info: validated DNSKEY terrax.net. DNSKEY IN
[1510789070] unbound[16798:0] debug: validator[module 1] operate: extstate:module_wait_subquery event:module_event_pass
[1510789070] unbound[16798:0] info: validator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: validated DS dev.terrax.net. DS IN
[1510789070] unbound[16798:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_pass
[1510789070] unbound[16798:0] info: subnet operate: query dev.terrax.net. DNSKEY IN
[1510789070] unbound[16798:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
[1510789070] unbound[16798:0] info: validator operate: query dev.terrax.net. DNSKEY IN
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510789070] unbound[16798:0] info: resolving dev.terrax.net. DNSKEY IN
[1510789070] unbound[16798:0] info: resolving (init part 2):  dev.terrax.net. DNSKEY IN
[1510789070] unbound[16798:0] info: resolving (init part 3):  dev.terrax.net. DNSKEY IN
[1510789070] unbound[16798:0] info: processQueryTargets: dev.terrax.net. DNSKEY IN
[1510789070] unbound[16798:0] info: sending query: dev.terrax.net. DNSKEY IN
[1510789070] unbound[16798:0] debug: sending to target: <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510789070] unbound[16798:0] debug: cache memory msg=69735 rrset=91011 infra=7949 val=69354 subnet=74488
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510789070] unbound[16798:0] info: iterator operate: query dev.terrax.net. DNSKEY IN
[1510789070] unbound[16798:0] info: response for dev.terrax.net. DNSKEY IN
[1510789070] unbound[16798:0] info: reply from <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510789070] unbound[16798:0] info: query response was ANSWER
[1510789070] unbound[16798:0] info: finishing processing for dev.terrax.net. DNSKEY IN
[1510789070] unbound[16798:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
[1510789070] unbound[16798:0] info: validator operate: query dev.terrax.net. DNSKEY IN
[1510789070] unbound[16798:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1510789070] unbound[16798:0] info: subnet operate: query dev.terrax.net. DNSKEY IN
[1510789070] unbound[16798:0] info: validated DNSKEY dev.terrax.net. DNSKEY IN
[1510789070] unbound[16798:0] debug: validator[module 1] operate: extstate:module_wait_subquery event:module_event_pass
[1510789070] unbound[16798:0] info: validator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] debug: NameError response has failed to prove: qname does not exist
[1510789070] unbound[16798:0] debug: NODATA response failed to prove NODATA status with NSEC/NSEC3
[1510789070] unbound[16798:0] info: validate(nxdomain): sec_status_bogus
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_finished event:module_event_pass
[1510789070] unbound[16798:0] info: resolving _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: resolving (init part 2):  _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: resolving (init part 3):  _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: processQueryTargets: _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] debug: removing 1 labels
[1510789070] unbound[16798:0] info: sending query: _tcp.dev.terrax.net. A IN
[1510789070] unbound[16798:0] debug: sending to target: <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510789070] unbound[16798:0] debug: cache memory msg=70007 rrset=91657 infra=7949 val=69876 subnet=74488
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510789070] unbound[16798:0] info: iterator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: reply from <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510789070] unbound[16798:0] info: query response was NXDOMAIN ANSWER
[1510789070] unbound[16798:0] info: finishing processing for _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] debug: validator[module 1] operate: extstate:module_restart_next event:module_event_moddone
[1510789070] unbound[16798:0] info: validator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: validator operate: chased to . TYPE0 CLASS0
[1510789070] unbound[16798:0] debug: verify: signature mismatch
[1510789070] unbound[16798:0] info: validator: response has failed AUTHORITY rrset: dev.terrax.net. NSEC IN
[1510789070] unbound[16798:0] info: Validate: message contains bad rrsets
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_finished event:module_event_pass
[1510789070] unbound[16798:0] info: resolving _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: resolving (init part 2):  _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: resolving (init part 3):  _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: processQueryTargets: _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] debug: removing 1 labels
[1510789070] unbound[16798:0] info: sending query: _tcp.dev.terrax.net. A IN
[1510789070] unbound[16798:0] debug: sending to target: <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510789070] unbound[16798:0] debug: cache memory msg=70007 rrset=92085 infra=7949 val=69876 subnet=74488
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510789070] unbound[16798:0] info: iterator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: reply from <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510789070] unbound[16798:0] info: query response was NXDOMAIN ANSWER
[1510789070] unbound[16798:0] info: finishing processing for _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] debug: validator[module 1] operate: extstate:module_restart_next event:module_event_moddone
[1510789070] unbound[16798:0] info: validator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: validator operate: chased to . TYPE0 CLASS0
[1510789070] unbound[16798:0] debug: NameError response has failed to prove: qname does not exist
[1510789070] unbound[16798:0] debug: NODATA response failed to prove NODATA status with NSEC/NSEC3
[1510789070] unbound[16798:0] info: validate(nxdomain): sec_status_bogus
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_finished event:module_event_pass
[1510789070] unbound[16798:0] info: resolving _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: resolving (init part 2):  _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: resolving (init part 3):  _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: processQueryTargets: _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] debug: removing 1 labels
[1510789070] unbound[16798:0] info: sending query: _tcp.dev.terrax.net. A IN
[1510789070] unbound[16798:0] debug: sending to target: <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510789070] unbound[16798:0] debug: cache memory msg=70007 rrset=92085 infra=7949 val=69876 subnet=74488
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510789070] unbound[16798:0] info: iterator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: reply from <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510789070] unbound[16798:0] info: query response was NXDOMAIN ANSWER
[1510789070] unbound[16798:0] info: finishing processing for _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] debug: validator[module 1] operate: extstate:module_restart_next event:module_event_moddone
[1510789070] unbound[16798:0] info: validator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: validator operate: chased to . TYPE0 CLASS0
[1510789070] unbound[16798:0] debug: verify: signature mismatch
[1510789070] unbound[16798:0] info: validator: response has failed AUTHORITY rrset: dev.terrax.net. NSEC IN
[1510789070] unbound[16798:0] info: Validate: message contains bad rrsets
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_finished event:module_event_pass
[1510789070] unbound[16798:0] info: resolving _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: resolving (init part 2):  _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: resolving (init part 3):  _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: processQueryTargets: _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] debug: removing 1 labels
[1510789070] unbound[16798:0] info: sending query: _tcp.dev.terrax.net. A IN
[1510789070] unbound[16798:0] debug: sending to target: <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510789070] unbound[16798:0] debug: cache memory msg=70007 rrset=92085 infra=7949 val=69876 subnet=74488
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510789070] unbound[16798:0] info: iterator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: reply from <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510789070] unbound[16798:0] info: query response was NXDOMAIN ANSWER
[1510789070] unbound[16798:0] info: finishing processing for _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] debug: validator[module 1] operate: extstate:module_restart_next event:module_event_moddone
[1510789070] unbound[16798:0] info: validator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: validator operate: chased to . TYPE0 CLASS0
[1510789070] unbound[16798:0] debug: NameError response has failed to prove: qname does not exist
[1510789070] unbound[16798:0] debug: NODATA response failed to prove NODATA status with NSEC/NSEC3
[1510789070] unbound[16798:0] info: validate(nxdomain): sec_status_bogus
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_finished event:module_event_pass
[1510789070] unbound[16798:0] info: resolving _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: resolving (init part 2):  _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: resolving (init part 3):  _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: processQueryTargets: _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] debug: removing 1 labels
[1510789070] unbound[16798:0] info: sending query: _tcp.dev.terrax.net. A IN
[1510789070] unbound[16798:0] debug: sending to target: <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510789070] unbound[16798:0] debug: cache memory msg=70007 rrset=92085 infra=7949 val=69876 subnet=74488
[1510789070] unbound[16798:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510789070] unbound[16798:0] info: iterator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: reply from <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510789070] unbound[16798:0] info: query response was NXDOMAIN ANSWER
[1510789070] unbound[16798:0] info: finishing processing for _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] debug: validator[module 1] operate: extstate:module_restart_next event:module_event_moddone
[1510789070] unbound[16798:0] info: validator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] info: validator operate: chased to . TYPE0 CLASS0
[1510789070] unbound[16798:0] debug: NameError response has failed to prove: qname does not exist
[1510789070] unbound[16798:0] debug: NODATA response failed to prove NODATA status with NSEC/NSEC3
[1510789070] unbound[16798:0] info: validate(nxdomain): sec_status_bogus
[1510789070] unbound[16798:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1510789070] unbound[16798:0] info: subnet operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510789070] unbound[16798:0] debug: cache memory msg=70007 rrset=92085 infra=7949 val=69876 subnet=74488
[1510789074] unbound[16798:0] info: service stopped (unbound 1.6.7).
[1510789074] unbound[16798:0] info: server stats for thread 0: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting
[1510789074] unbound[16798:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
[1510789074] unbound[16798:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 1 recursion replies sent, 0 replies dropped, 0 states jostled out
[1510789074] unbound[16798:0] info: average recursion processing time 0.543775 sec
[1510789074] unbound[16798:0] info: histogram of recursion processing times
[1510789074] unbound[16798:0] info: [25%]=0 median[50%]=0 [75%]=0
[1510789074] unbound[16798:0] info: lower(secs) upper(secs) recursions
[1510789074] unbound[16798:0] info:    0.524288    1.000000 1
[1510789074] unbound[16798:0] debug: cache memory msg=66072 rrset=66072 infra=7949 val=69876 subnet=74488
[1510789074] unbound[16798:0] debug: switching log to stderr

@bluejekyll
Copy link
Member Author

bluejekyll commented Nov 16, 2017

signing rr_set: _443._tcp.dev.terrax.net., NSEC with: ECDSAP384SHA384

That is very suspicious. NSEC records shouldn't be in the zone while it's being signed. They should be produced afterward. I'm going to load the zone file you posted and see if I can reproduce that behavior.

EDIT: nevermind, the NSEC records are being inserted into the zone dynamically and then the signing occurs. So this output is correct.


There's also something else funny going on here. In the logs from trust-dns I don't see any requests for the TLSA record itself. I need to clean up the logging configuration, that debug output is including too much from library dependencies.

@bluejekyll
Copy link
Member Author

bluejekyll commented Nov 16, 2017

Ok, I've added some better logs on requests. I should have had those there before. Now we'll actually be able to see the requests coming into the server. The logs are still very noisy on DEBUG, but these will be issue on the INFO level, that should be enough to gain better visibility into the requests being made by unbound, i.e. DEBUG shouldn't be necessary.

Btw, I took your configs, and added them to one of my test zones, and I couldn't repro any issues on lookup of TLSA. I'll keep looking.

@bluejekyll
Copy link
Member Author

I just noticed in your key configuration,: signer_name: None, This might cause a validation problem with other services, I wonder if unbound is rejecting signed records because of that? This should be set to something like ns.dev.terrax.net.. Though it seems to not be an issue elsewhere... based on your other descriptions.

@Darkspirit
Copy link
Contributor

Darkspirit commented Nov 17, 2017

  1. stopped unbound and trustdns, cleared unbound.log
  2. started trustdns with --debug in screen and made a screenlog
  3. started unbound
  4. dig TLSA _443._tcp.dev.terrax.net
  5. stopped unbound
  6. stopped trustdns

trustdns

2017-11-17T02:54:51.307420670+00:00 INFO trust_dns::logger:26 logging initialized
2017-11-17T02:54:51.307521742+00:00 INFO named:331 Trust-DNS 0.12.0 starting
2017-11-17T02:54:51.307566924+00:00 INFO named:337 loading configuration from: "/home/trustdns/config.toml"
2017-11-17T02:54:51.307770031+00:00 DEBUG named:135 loading zone with config: ZoneConfig {
    zone: "dev.terrax.net",
    zone_type: Master,
    file: "dev.terrax.net.zone",
    allow_update: Some(
        false
    ),
    enable_dnssec: Some(
        true
    ),
    keys: [
        KeyConfig {
            key_path: "dev.terrax.net.csk.pem",
            password: None,
            algorithm: "ECDSAP384SHA384",
            signer_name: None,
            is_zone_signing_key: Some(
                true
            ),
            is_zone_update_auth: Some(
                false
            )
        }
    ]
}
2017-11-17T02:54:51.308234116+00:00 INFO named:164 loading zone file: "/home/trustdns/dev.terrax.net.zone"
cert_data: A991082596FAB5F8475C22686435F22E6B67F5409B674CE3CCDCCB9401AA0A882513C0946A8973E00A386519E401773CE025DAEEE14454B9859C096B5B798593
2017-11-17T02:54:51.333064241+00:00 INFO named:195 zone file loaded: dev.terrax.net.
2017-11-17T02:54:51.333199181+00:00 INFO named:268 reading key: "dev.terrax.net.csk.pem"
2017-11-17T02:54:51.335528093+00:00 INFO named:209 adding key to zone: "dev.terrax.net.csk.pem", is_zsk: true, is_auth: false
2017-11-17T02:54:51.335670136+00:00 INFO named:220 signing zone: dev.terrax.net.
2017-11-17T02:54:51.335706214+00:00 DEBUG trust_dns_server::authority::authority:1142 generating nsec records: dev.terrax.net.
2017-11-17T02:54:51.335807576+00:00 DEBUG trust_dns_server::authority::authority:1212 signing zone: dev.terrax.net.
2017-11-17T02:54:51.335845067+00:00 DEBUG trust_dns_server::authority::authority:1231 signing rr_set: dev.terrax.net., NS with: ECDSAP384SHA384
2017-11-17T02:54:51.337201303+00:00 DEBUG trust_dns_server::authority::authority:1231 signing rr_set: dev.terrax.net., SOA with: ECDSAP384SHA384
2017-11-17T02:54:51.338528609+00:00 DEBUG trust_dns_server::authority::authority:1231 signing rr_set: dev.terrax.net., MX with: ECDSAP384SHA384
2017-11-17T02:54:51.339734651+00:00 DEBUG trust_dns_server::authority::authority:1231 signing rr_set: dev.terrax.net., TXT with: ECDSAP384SHA384
2017-11-17T02:54:51.340934329+00:00 DEBUG trust_dns_server::authority::authority:1231 signing rr_set: dev.terrax.net., AAAA with: ECDSAP384SHA384
2017-11-17T02:54:51.342171698+00:00 DEBUG trust_dns_server::authority::authority:1231 signing rr_set: dev.terrax.net., NSEC with: ECDSAP384SHA384
2017-11-17T02:54:51.343379840+00:00 DEBUG trust_dns_server::authority::authority:1231 signing rr_set: dev.terrax.net., DNSKEY with: ECDSAP384SHA384
2017-11-17T02:54:51.344537342+00:00 DEBUG trust_dns_server::authority::authority:1231 signing rr_set: dev.terrax.net., CAA with: ECDSAP384SHA384
2017-11-17T02:54:51.345802834+00:00 DEBUG trust_dns_server::authority::authority:1231 signing rr_set: _443._tcp.dev.terrax.net., NSEC with: ECDSAP384SHA384
2017-11-17T02:54:51.346988392+00:00 DEBUG trust_dns_server::authority::authority:1231 signing rr_set: _443._tcp.dev.terrax.net., TLSA with: ECDSAP384SHA384
2017-11-17T02:54:51.348142948+00:00 INFO named:235 zone successfully loaded: dev.terrax.net.
2017-11-17T02:54:51.348287587+00:00 INFO named:398 listening for UDP on UdpSocket { addr: V6([2a01:4f8:c0c:2c12::50]:8053), fd: 3 }
2017-11-17T02:54:51.348324791+00:00 DEBUG trust_dns_server::server::server_future:47 registered udp: UdpSocket { addr: V6([2a01:4f8:c0c:2c12::50]:8053), fd: 3 }
2017-11-17T02:54:51.348363837+00:00 DEBUG tokio_core::reactor:466 adding a new I/O source
2017-11-17T02:54:51.348394193+00:00 INFO named:398 listening for UDP on UdpSocket { addr: V6([2a01:4f8:c0c:2c12::51]:8053), fd: 4 }
2017-11-17T02:54:51.348452003+00:00 DEBUG trust_dns_server::server::server_future:47 registered udp: UdpSocket { addr: V6([2a01:4f8:c0c:2c12::51]:8053), fd: 4 }
2017-11-17T02:54:51.348523014+00:00 DEBUG tokio_core::reactor:466 adding a new I/O source
2017-11-17T02:54:51.348598369+00:00 INFO named:404 listening for TCP on TcpListener { addr: V6([2a01:4f8:c0c:2c12::50]:8053), fd: 5 }
2017-11-17T02:54:51.348629457+00:00 DEBUG tokio_core::reactor:466 adding a new I/O source
2017-11-17T02:54:51.348656191+00:00 DEBUG trust_dns_server::server::server_future:88 registered tcp: TcpListener { sys: TcpListener { inner: TcpListener { addr: V6([2a01:4f8:c0c:2c12::50]:8053), fd: 5 } }, selector_id: SelectorId { id: AtomicUsize(1) } }
2017-11-17T02:54:51.348700709+00:00 INFO named:404 listening for TCP on TcpListener { addr: V6([2a01:4f8:c0c:2c12::51]:8053), fd: 6 }
2017-11-17T02:54:51.348729212+00:00 DEBUG tokio_core::reactor:466 adding a new I/O source
2017-11-17T02:54:51.348753132+00:00 DEBUG trust_dns_server::server::server_future:88 registered tcp: TcpListener { sys: TcpListener { inner: TcpListener { addr: V6([2a01:4f8:c0c:2c12::51]:8053), fd: 6 } }, selector_id: SelectorId { id: AtomicUsize(1) } }
2017-11-17T02:54:51.348788857+00:00 INFO named:486 
2017-11-17T02:54:51.348808778+00:00 INFO named:487     o                      o            o             
2017-11-17T02:54:51.348831158+00:00 INFO named:488     |                      |            |             
2017-11-17T02:54:51.348855259+00:00 INFO named:489   --O--  o-o  o  o  o-o  --O--  o-o   o-O  o-o   o-o  
2017-11-17T02:54:51.348877411+00:00 INFO named:490     |    |    |  |   \     |         |  |  |  |   \   
2017-11-17T02:54:51.348899518+00:00 INFO named:491     o    o    o--o  o-o    o          o-o  o  o  o-o  
2017-11-17T02:54:51.348929273+00:00 INFO named:492 
2017-11-17T02:54:51.348948739+00:00 INFO named:424 awaiting connections...
2017-11-17T02:54:51.348969517+00:00 INFO trust_dns_server::server::server_future:196 Server starting up
2017-11-17T02:54:51.349001799+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 5235 }
2017-11-17T02:54:51.349027351+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1582174, tv_nsec: 630412489 }
2017-11-17T02:54:51.349053456+00:00 DEBUG tokio_core::reactor:404 consuming notification queue
2017-11-17T02:54:51.349108687+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 0
2017-11-17T02:54:51.349134403+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-17T02:54:51.349157447+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 1
2017-11-17T02:54:51.349180242+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-17T02:54:51.349202442+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 2
2017-11-17T02:54:51.349224954+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-17T02:54:51.349247337+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 3
2017-11-17T02:54:51.349269406+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-17T02:54:51.349290450+00:00 DEBUG tokio_core::reactor:307 loop process - 7 events, Duration { secs: 0, nanos: 288926 }
2017-11-17T02:54:51.349316397+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 1082 }
2017-11-17T02:54:51.349340180+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1582174, tv_nsec: 630727360 }
2017-11-17T02:54:51.349380279+00:00 DEBUG tokio_core::reactor:307 loop process - 0 events, Duration { secs: 0, nanos: 63992 }
2017-11-17T02:54:59.613698121+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 8, nanos: 264274474 }
2017-11-17T02:54:59.613799988+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1582182, tv_nsec: 895107595 }
2017-11-17T02:54:59.613831656+00:00 DEBUG tokio_core::reactor:399 notifying a task handle
2017-11-17T02:54:59.613870071+00:00 DEBUG tokio_core::reactor:307 loop process - 1 events, Duration { secs: 0, nanos: 173443 }
2017-11-17T02:54:59.613908870+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 11579 }
2017-11-17T02:54:59.613939922+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1582182, tv_nsec: 895319745 }
2017-11-17T02:54:59.613980765+00:00 DEBUG trust_dns_server::server::request_stream:68 received message: 61990
2017-11-17T02:54:59.614050191+00:00 INFO trust_dns_server::server::server_future:215 request: 61990 src: [2003:c4:bf23:b900:88c2:fcc3:81bf:b59e]:31440 type: Query op_code: Query name: _tcp.dev.terrax.net. type: A class: IN
2017-11-17T02:54:59.614097050+00:00 INFO trust_dns_server::authority::catalog:280 request: 61990 found authority: dev.terrax.net.
2017-11-17T02:54:59.614124213+00:00 DEBUG trust_dns_server::authority::catalog:293 no DAU in request, used default SupportAlgorithms
2017-11-17T02:54:59.614148126+00:00 INFO trust_dns_server::authority::catalog:303 request: 61990 supported_algs: 
2017-11-17T02:54:59.614233605+00:00 INFO trust_dns_server::server::server_future:225 request: 61990 response_code: Non-Existent Domain answers: 0 name_servers: 4 additionals: 0
2017-11-17T02:54:59.614262554+00:00 DEBUG trust_dns_server::server::request_stream:101 sending message: 61990
2017-11-17T02:54:59.614359056+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 0
2017-11-17T02:54:59.614406476+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-17T02:54:59.614428794+00:00 DEBUG tokio_core::reactor:307 loop process - 1 events, Duration { secs: 0, nanos: 520054 }
2017-11-17T02:54:59.614501417+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 1758 }
2017-11-17T02:54:59.614534753+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1582182, tv_nsec: 895912275 }
2017-11-17T02:54:59.614561571+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 0
2017-11-17T02:54:59.614584604+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-17T02:54:59.614624481+00:00 DEBUG tokio_core::reactor:307 loop process - 2 events, Duration { secs: 0, nanos: 123111 }
2017-11-17T02:54:59.614651390+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 883 }
2017-11-17T02:54:59.614675116+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1582182, tv_nsec: 896062366 }
2017-11-17T02:54:59.614699194+00:00 DEBUG tokio_core::reactor:307 loop process - 0 events, Duration { secs: 0, nanos: 47912 }
2017-11-17T02:54:59.957790433+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 343062303 }
2017-11-17T02:54:59.957911267+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1582183, tv_nsec: 239198588 }
2017-11-17T02:54:59.957942493+00:00 DEBUG tokio_core::reactor:399 notifying a task handle
2017-11-17T02:54:59.957974735+00:00 DEBUG tokio_core::reactor:307 loop process - 1 events, Duration { secs: 0, nanos: 187145 }
2017-11-17T02:54:59.958007038+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 5587 }
2017-11-17T02:54:59.958031856+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1582183, tv_nsec: 239418027 }
2017-11-17T02:54:59.958081518+00:00 DEBUG trust_dns_server::server::request_stream:68 received message: 43819
2017-11-17T02:54:59.958114816+00:00 INFO trust_dns_server::server::server_future:215 request: 43819 src: [2003:c4:bf23:b900:88c2:fcc3:81bf:b59e]:6418 type: Query op_code: Query name: dev.terrax.net. type: DNSKEY class: IN
2017-11-17T02:54:59.958159630+00:00 INFO trust_dns_server::authority::catalog:280 request: 43819 found authority: dev.terrax.net.
2017-11-17T02:54:59.958187738+00:00 DEBUG trust_dns_server::authority::catalog:293 no DAU in request, used default SupportAlgorithms
2017-11-17T02:54:59.958217868+00:00 INFO trust_dns_server::authority::catalog:303 request: 43819 supported_algs: 
2017-11-17T02:54:59.958265859+00:00 INFO trust_dns_server::server::server_future:225 request: 43819 response_code: No Error answers: 2 name_servers: 2 additionals: 0
2017-11-17T02:54:59.958295490+00:00 DEBUG trust_dns_server::server::request_stream:101 sending message: 43819
2017-11-17T02:54:59.958398851+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 0
2017-11-17T02:54:59.958429538+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-17T02:54:59.958452427+00:00 DEBUG tokio_core::reactor:307 loop process - 1 events, Duration { secs: 0, nanos: 445345 }
2017-11-17T02:54:59.958524754+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 1570 }
2017-11-17T02:54:59.958551915+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1582183, tv_nsec: 239935625 }
2017-11-17T02:54:59.958586501+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 0
2017-11-17T02:54:59.958670320+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-17T02:54:59.958693521+00:00 DEBUG tokio_core::reactor:307 loop process - 2 events, Duration { secs: 0, nanos: 168954 }
2017-11-17T02:54:59.958719510+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 879 }
2017-11-17T02:54:59.958748418+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1582183, tv_nsec: 240130513 }
2017-11-17T02:54:59.958773540+00:00 DEBUG tokio_core::reactor:307 loop process - 0 events, Duration { secs: 0, nanos: 54057 }
2017-11-17T02:54:59.988792735+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 29991979 }
2017-11-17T02:54:59.988918845+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1582183, tv_nsec: 270200937 }
2017-11-17T02:54:59.988950539+00:00 DEBUG tokio_core::reactor:399 notifying a task handle
2017-11-17T02:54:59.988982410+00:00 DEBUG tokio_core::reactor:307 loop process - 1 events, Duration { secs: 0, nanos: 192468 }
2017-11-17T02:54:59.989017659+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 6446 }
2017-11-17T02:54:59.989042773+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1582183, tv_nsec: 270428679 }
2017-11-17T02:54:59.989218663+00:00 DEBUG trust_dns_server::server::request_stream:68 received message: 26740
2017-11-17T02:54:59.989267566+00:00 INFO trust_dns_server::server::server_future:215 request: 26740 src: [2003:c4:bf23:b900:88c2:fcc3:81bf:b59e]:49835 type: Query op_code: Query name: _tcp.dev.terrax.net. type: A class: IN
2017-11-17T02:54:59.989339010+00:00 INFO trust_dns_server::authority::catalog:280 request: 26740 found authority: dev.terrax.net.
2017-11-17T02:54:59.989373775+00:00 DEBUG trust_dns_server::authority::catalog:293 no DAU in request, used default SupportAlgorithms
2017-11-17T02:54:59.989398561+00:00 INFO trust_dns_server::authority::catalog:303 request: 26740 supported_algs: 
2017-11-17T02:54:59.989490400+00:00 INFO trust_dns_server::server::server_future:225 request: 26740 response_code: Non-Existent Domain answers: 0 name_servers: 4 additionals: 0
2017-11-17T02:54:59.989555864+00:00 DEBUG trust_dns_server::server::request_stream:101 sending message: 26740
2017-11-17T02:54:59.989670378+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 0
2017-11-17T02:54:59.989710892+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-17T02:54:59.989734019+00:00 DEBUG tokio_core::reactor:307 loop process - 1 events, Duration { secs: 0, nanos: 716265 }
2017-11-17T02:54:59.989764536+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 4760 }
2017-11-17T02:54:59.989789903+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1582183, tv_nsec: 271175374 }
2017-11-17T02:54:59.989816005+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 0
2017-11-17T02:54:59.989841621+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-17T02:54:59.989866383+00:00 DEBUG tokio_core::reactor:307 loop process - 2 events, Duration { secs: 0, nanos: 102084 }
2017-11-17T02:54:59.989892615+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 860 }
2017-11-17T02:54:59.989916740+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1582183, tv_nsec: 271303616 }
2017-11-17T02:54:59.989940898+00:00 DEBUG tokio_core::reactor:307 loop process - 0 events, Duration { secs: 0, nanos: 48356 }
2017-11-17T02:55:00.021532694+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 31564110 }
2017-11-17T02:55:00.021656603+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1582183, tv_nsec: 302940280 }
2017-11-17T02:55:00.021754248+00:00 DEBUG tokio_core::reactor:399 notifying a task handle
2017-11-17T02:55:00.021789961+00:00 DEBUG tokio_core::reactor:307 loop process - 1 events, Duration { secs: 0, nanos: 260605 }
2017-11-17T02:55:00.021832469+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 7501 }
2017-11-17T02:55:00.021877358+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1582183, tv_nsec: 303243254 }
2017-11-17T02:55:00.021975773+00:00 DEBUG trust_dns_server::server::request_stream:68 received message: 55255
2017-11-17T02:55:00.022027856+00:00 INFO trust_dns_server::server::server_future:215 request: 55255 src: [2003:c4:bf23:b900:88c2:fcc3:81bf:b59e]:11395 type: Query op_code: Query name: _tcp.dev.terrax.net. type: A class: IN
2017-11-17T02:55:00.022082653+00:00 INFO trust_dns_server::authority::catalog:280 request: 55255 found authority: dev.terrax.net.
2017-11-17T02:55:00.022111818+00:00 DEBUG trust_dns_server::authority::catalog:293 no DAU in request, used default SupportAlgorithms
2017-11-17T02:55:00.022135878+00:00 INFO trust_dns_server::authority::catalog:303 request: 55255 supported_algs: 
2017-11-17T02:55:00.022205673+00:00 INFO trust_dns_server::server::server_future:225 request: 55255 response_code: Non-Existent Domain answers: 0 name_servers: 4 additionals: 0
2017-11-17T02:55:00.022235474+00:00 DEBUG trust_dns_server::server::request_stream:101 sending message: 55255
2017-11-17T02:55:00.022344798+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 0
2017-11-17T02:55:00.022374932+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-17T02:55:00.022406970+00:00 DEBUG tokio_core::reactor:307 loop process - 1 events, Duration { secs: 0, nanos: 574503 }
2017-11-17T02:55:00.022460412+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 1997 }
2017-11-17T02:55:00.022501761+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1582183, tv_nsec: 303871190 }
2017-11-17T02:55:00.022547724+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 0
2017-11-17T02:55:00.022584561+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-17T02:55:00.022659175+00:00 DEBUG tokio_core::reactor:307 loop process - 2 events, Duration { secs: 0, nanos: 198809 }
2017-11-17T02:55:00.022686633+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 1019 }
2017-11-17T02:55:00.022710613+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1582183, tv_nsec: 304097627 }
2017-11-17T02:55:00.022735058+00:00 DEBUG tokio_core::reactor:307 loop process - 0 events, Duration { secs: 0, nanos: 48500 }
2017-11-17T02:55:00.051517714+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 28738861 }
2017-11-17T02:55:00.051636751+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1582183, tv_nsec: 332925951 }
2017-11-17T02:55:00.051668046+00:00 DEBUG tokio_core::reactor:399 notifying a task handle
2017-11-17T02:55:00.051702443+00:00 DEBUG tokio_core::reactor:307 loop process - 1 events, Duration { secs: 0, nanos: 187426 }
2017-11-17T02:55:00.051750655+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 21489 }
2017-11-17T02:55:00.051775679+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1582183, tv_nsec: 333161675 }
2017-11-17T02:55:00.051851314+00:00 DEBUG trust_dns_server::server::request_stream:68 received message: 44379
2017-11-17T02:55:00.051883443+00:00 INFO trust_dns_server::server::server_future:215 request: 44379 src: [2003:c4:bf23:b900:88c2:fcc3:81bf:b59e]:27733 type: Query op_code: Query name: _tcp.dev.terrax.net. type: A class: IN
2017-11-17T02:55:00.051929496+00:00 INFO trust_dns_server::authority::catalog:280 request: 44379 found authority: dev.terrax.net.
2017-11-17T02:55:00.051956696+00:00 DEBUG trust_dns_server::authority::catalog:293 no DAU in request, used default SupportAlgorithms
2017-11-17T02:55:00.051979636+00:00 INFO trust_dns_server::authority::catalog:303 request: 44379 supported_algs: 
2017-11-17T02:55:00.052107142+00:00 INFO trust_dns_server::server::server_future:225 request: 44379 response_code: Non-Existent Domain answers: 0 name_servers: 4 additionals: 0
2017-11-17T02:55:00.052138027+00:00 DEBUG trust_dns_server::server::request_stream:101 sending message: 44379
2017-11-17T02:55:00.052258873+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 0
2017-11-17T02:55:00.052296977+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-17T02:55:00.052319877+00:00 DEBUG tokio_core::reactor:307 loop process - 1 events, Duration { secs: 0, nanos: 569137 }
2017-11-17T02:55:00.052352250+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 1742 }
2017-11-17T02:55:00.052376905+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1582183, tv_nsec: 333763208 }
2017-11-17T02:55:00.052403348+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 0
2017-11-17T02:55:00.052426143+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-17T02:55:00.052447429+00:00 DEBUG tokio_core::reactor:307 loop process - 2 events, Duration { secs: 0, nanos: 95307 }
2017-11-17T02:55:00.052472738+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 732 }
2017-11-17T02:55:00.052496979+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1582183, tv_nsec: 333883743 }
2017-11-17T02:55:00.052550571+00:00 DEBUG tokio_core::reactor:307 loop process - 0 events, Duration { secs: 0, nanos: 77708 }
2017-11-17T02:55:00.081166689+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 28586614 }
2017-11-17T02:55:00.081291974+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1582183, tv_nsec: 362574593 }
2017-11-17T02:55:00.081322893+00:00 DEBUG tokio_core::reactor:399 notifying a task handle
2017-11-17T02:55:00.081354510+00:00 DEBUG tokio_core::reactor:307 loop process - 1 events, Duration { secs: 0, nanos: 190894 }
2017-11-17T02:55:00.081387280+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 6154 }
2017-11-17T02:55:00.081430870+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1582183, tv_nsec: 362798304 }
2017-11-17T02:55:00.081480130+00:00 DEBUG trust_dns_server::server::request_stream:68 received message: 64051
2017-11-17T02:55:00.081547718+00:00 INFO trust_dns_server::server::server_future:215 request: 64051 src: [2003:c4:bf23:b900:88c2:fcc3:81bf:b59e]:33843 type: Query op_code: Query name: _tcp.dev.terrax.net. type: A class: IN
2017-11-17T02:55:00.081597334+00:00 INFO trust_dns_server::authority::catalog:280 request: 64051 found authority: dev.terrax.net.
2017-11-17T02:55:00.081625326+00:00 DEBUG trust_dns_server::authority::catalog:293 no DAU in request, used default SupportAlgorithms
2017-11-17T02:55:00.081649989+00:00 INFO trust_dns_server::authority::catalog:303 request: 64051 supported_algs: 
2017-11-17T02:55:00.081727983+00:00 INFO trust_dns_server::server::server_future:225 request: 64051 response_code: Non-Existent Domain answers: 0 name_servers: 4 additionals: 0
2017-11-17T02:55:00.081757998+00:00 DEBUG trust_dns_server::server::request_stream:101 sending message: 64051
2017-11-17T02:55:00.081866998+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 0
2017-11-17T02:55:00.081898014+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-17T02:55:00.081920584+00:00 DEBUG tokio_core::reactor:307 loop process - 1 events, Duration { secs: 0, nanos: 533214 }
2017-11-17T02:55:00.081948011+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 1623 }
2017-11-17T02:55:00.081973527+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1582183, tv_nsec: 363359010 }
2017-11-17T02:55:00.081999789+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 0
2017-11-17T02:55:00.082031928+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-17T02:55:00.082054127+00:00 DEBUG tokio_core::reactor:307 loop process - 2 events, Duration { secs: 0, nanos: 106162 }
2017-11-17T02:55:00.082082040+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 745 }
2017-11-17T02:55:00.082148348+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1582183, tv_nsec: 363493050 }
2017-11-17T02:55:00.082173839+00:00 DEBUG tokio_core::reactor:307 loop process - 0 events, Duration { secs: 0, nanos: 91810 }
2017-11-17T02:55:00.110648203+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 28430864 }
2017-11-17T02:55:00.110752284+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1582183, tv_nsec: 392057182 }
2017-11-17T02:55:00.110784670+00:00 DEBUG tokio_core::reactor:399 notifying a task handle
2017-11-17T02:55:00.110815893+00:00 DEBUG tokio_core::reactor:307 loop process - 1 events, Duration { secs: 0, nanos: 169605 }
2017-11-17T02:55:00.110848944+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 5509 }
2017-11-17T02:55:00.110875086+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1582183, tv_nsec: 392259896 }
2017-11-17T02:55:00.110938451+00:00 DEBUG trust_dns_server::server::request_stream:68 received message: 64457
2017-11-17T02:55:00.110971163+00:00 INFO trust_dns_server::server::server_future:215 request: 64457 src: [2003:c4:bf23:b900:88c2:fcc3:81bf:b59e]:54289 type: Query op_code: Query name: _tcp.dev.terrax.net. type: A class: IN
2017-11-17T02:55:00.111023319+00:00 INFO trust_dns_server::authority::catalog:280 request: 64457 found authority: dev.terrax.net.
2017-11-17T02:55:00.111051669+00:00 DEBUG trust_dns_server::authority::catalog:293 no DAU in request, used default SupportAlgorithms
2017-11-17T02:55:00.111076268+00:00 INFO trust_dns_server::authority::catalog:303 request: 64457 supported_algs: 
2017-11-17T02:55:00.111142343+00:00 INFO trust_dns_server::server::server_future:225 request: 64457 response_code: Non-Existent Domain answers: 0 name_servers: 4 additionals: 0
2017-11-17T02:55:00.111172189+00:00 DEBUG trust_dns_server::server::request_stream:101 sending message: 64457
2017-11-17T02:55:00.111288389+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 0
2017-11-17T02:55:00.111320895+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-17T02:55:00.111344325+00:00 DEBUG tokio_core::reactor:307 loop process - 1 events, Duration { secs: 0, nanos: 495373 }
2017-11-17T02:55:00.111372646+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 1545 }
2017-11-17T02:55:00.111398141+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1582183, tv_nsec: 392783595 }
2017-11-17T02:55:00.111426474+00:00 DEBUG tokio_core::reactor:499 scheduling direction for: 0
2017-11-17T02:55:00.111451357+00:00 DEBUG tokio_core::reactor:510 blocking
2017-11-17T02:55:00.111474050+00:00 DEBUG tokio_core::reactor:307 loop process - 2 events, Duration { secs: 0, nanos: 101457 }
2017-11-17T02:55:00.111501003+00:00 DEBUG tokio_core::reactor:283 loop poll - Duration { secs: 0, nanos: 790 }
2017-11-17T02:55:00.111526037+00:00 DEBUG tokio_core::reactor:284 loop time - Instant { tv_sec: 1582183, tv_nsec: 392911991 }
2017-11-17T02:55:00.111551522+00:00 DEBUG tokio_core::reactor:307 loop process - 0 events, Duration { secs: 0, nanos: 50560 }
^C

dig

$ dig TLSA _443._tcp.dev.terrax.net                                                                                 
                                                                                                                                           
; <<>> DiG 9.10.6-Debian <<>> TLSA _443._tcp.dev.terrax.net                                                                                
;; global options: +cmd                                                                                                                    
;; Got answer:                                                                                                                             
;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 21026                                                                                 
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1                                                                       
                                                                                                                                           
;; OPT PSEUDOSECTION:                                                                                                                      
; EDNS: version: 0, flags:; udp: 4096                                                                                                      
;; QUESTION SECTION:                                                                                                                       
;_443._tcp.dev.terrax.net.      IN      TLSA                                                                                               
                                                                                                                                           
;; Query time: 653 msec                                                                                                                    
;; SERVER: ::1#53(::1)                                                                                                                     
;; WHEN: Fri Nov 17 03:55:00 CET 2017                                                                                                      
;; MSG SIZE  rcvd: 53

unbound

[1510887295] unbound[8106:0] debug: module config: "subnetcache validator iterator"
[1510887295] unbound[8106:0] notice: init module 0: subnet
[1510887295] unbound[8106:0] debug: subnet: option registered (8)
[1510887295] unbound[8106:0] notice: init module 1: validator
[1510887295] unbound[8106:0] info: adding trusted key . DNSKEY IN
[1510887295] unbound[8106:0] info: adding trusted key . DNSKEY IN
[1510887295] unbound[8106:0] notice: init module 2: iterator
[1510887295] unbound[8106:0] debug: target fetch policy for level 0 is 3
[1510887295] unbound[8106:0] debug: target fetch policy for level 1 is 2
[1510887295] unbound[8106:0] debug: target fetch policy for level 2 is 1
[1510887295] unbound[8106:0] debug: target fetch policy for level 3 is 0
[1510887295] unbound[8106:0] debug: target fetch policy for level 4 is 0
[1510887295] unbound[8106:0] debug: Reading root hints from /etc/unbound/root.hints
[1510887295] unbound[8106:0] info: DelegationPoint<.>: 13 names (0 missing), 26 addrs (0 result, 26 avail) parentNS
[1510887295] unbound[8106:0] debug: cache memory msg=66072 rrset=66072 infra=5224 val=66336 subnet=74488
[1510887295] unbound[8106:0] info: start of service (unbound 1.6.7).
[1510887299] unbound[8106:0] info: ::1 _443._tcp.dev.terrax.net. TLSA IN
[1510887299] unbound[8106:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_new
[1510887299] unbound[8106:0] info: subnet operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510887299] unbound[8106:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
[1510887299] unbound[8106:0] info: validator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510887299] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510887299] unbound[8106:0] info: resolving _443._tcp.dev.terrax.net. TLSA IN
[1510887299] unbound[8106:0] info: priming . IN NS
[1510887299] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510887299] unbound[8106:0] info: iterator operate: query . NS IN
[1510887299] unbound[8106:0] info: processQueryTargets: . NS IN
[1510887299] unbound[8106:0] info: sending query: . NS IN
[1510887299] unbound[8106:0] debug: sending to target: <.> 2001:dc3::35#53
[1510887299] unbound[8106:0] debug: cache memory msg=66072 rrset=66072 infra=5521 val=66336 subnet=74488
[1510887299] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510887299] unbound[8106:0] info: iterator operate: query . NS IN
[1510887299] unbound[8106:0] info: response for . NS IN
[1510887299] unbound[8106:0] info: reply from <.> 2001:dc3::35#53
[1510887299] unbound[8106:0] info: query response was ANSWER
[1510887299] unbound[8106:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
[1510887299] unbound[8106:0] info: validator operate: query . NS IN
[1510887299] unbound[8106:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_moddone
[1510887299] unbound[8106:0] info: subnet operate: query . NS IN
[1510887299] unbound[8106:0] info: priming successful for . NS IN
[1510887299] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
[1510887299] unbound[8106:0] info: iterator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510887299] unbound[8106:0] info: resolving (init part 2):  _443._tcp.dev.terrax.net. TLSA IN
[1510887299] unbound[8106:0] info: resolving (init part 3):  _443._tcp.dev.terrax.net. TLSA IN
[1510887299] unbound[8106:0] info: processQueryTargets: _443._tcp.dev.terrax.net. TLSA IN
[1510887299] unbound[8106:0] debug: removing 4 labels
[1510887299] unbound[8106:0] info: sending query: net. A IN
[1510887299] unbound[8106:0] debug: sending to target: <.> 2001:500:a8::e#53
[1510887299] unbound[8106:0] debug: cache memory msg=66929 rrset=73612 infra=5818 val=66336 subnet=74488
[1510887299] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510887299] unbound[8106:0] info: iterator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510887299] unbound[8106:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510887299] unbound[8106:0] info: reply from <.> 2001:500:a8::e#53
[1510887299] unbound[8106:0] info: query response was REFERRAL
[1510887299] unbound[8106:0] info: processQueryTargets: _443._tcp.dev.terrax.net. TLSA IN
[1510887299] unbound[8106:0] debug: removing 3 labels
[1510887299] unbound[8106:0] info: sending query: terrax.net. A IN
[1510887299] unbound[8106:0] debug: sending to target: <net.> 2001:502:7094::30#53
[1510887299] unbound[8106:0] debug: cache memory msg=66929 rrset=81415 infra=6119 val=66336 subnet=74488
[1510887299] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510887299] unbound[8106:0] info: iterator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510887299] unbound[8106:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510887299] unbound[8106:0] info: reply from <net.> 2001:502:7094::30#53
[1510887299] unbound[8106:0] info: query response was REFERRAL
[1510887299] unbound[8106:0] info: processQueryTargets: _443._tcp.dev.terrax.net. TLSA IN
[1510887299] unbound[8106:0] info: new target gw2.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] info: new target gw1.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] debug: removing 2 labels
[1510887299] unbound[8106:0] info: sending query: dev.terrax.net. A IN
[1510887299] unbound[8106:0] debug: sending to target: <terrax.net.> 94.130.73.109#53
[1510887299] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510887299] unbound[8106:0] info: iterator operate: query gw2.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] info: resolving gw2.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] info: resolving (init part 2):  gw2.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] info: resolving (init part 3):  gw2.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] info: processQueryTargets: gw2.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] info: skipping target due to dependency cycle (harden-glue: no may fix some of the cycles) gw2.h.terrax.net. A IN
[1510887299] unbound[8106:0] info: new target gw1.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] debug: removing 1 labels
[1510887299] unbound[8106:0] info: sending query: h.terrax.net. A IN
[1510887299] unbound[8106:0] debug: sending to target: <terrax.net.> 94.130.76.133#53
[1510887299] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510887299] unbound[8106:0] info: iterator operate: query gw1.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] info: resolving gw1.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] info: resolving (init part 2):  gw1.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] info: resolving (init part 3):  gw1.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] info: processQueryTargets: gw1.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] info: skipping target due to dependency cycle (harden-glue: no may fix some of the cycles) gw2.h.terrax.net. A IN
[1510887299] unbound[8106:0] info: skipping target due to dependency cycle (harden-glue: no may fix some of the cycles) gw1.h.terrax.net. A IN
[1510887299] unbound[8106:0] debug: removing 1 labels
[1510887299] unbound[8106:0] info: sending query: h.terrax.net. A IN
[1510887299] unbound[8106:0] debug: sending to target: <terrax.net.> 94.130.76.133#53
[1510887299] unbound[8106:0] debug: cache memory msg=66929 rrset=82630 infra=6735 val=66336 subnet=74488
[1510887299] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510887299] unbound[8106:0] info: iterator operate: query gw1.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] info: response for gw1.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] info: reply from <terrax.net.> 94.130.76.133#53
[1510887299] unbound[8106:0] info: query response was nodata ANSWER
[1510887299] unbound[8106:0] info: processQueryTargets: gw1.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] info: sending query: gw1.h.terrax.net. A IN
[1510887299] unbound[8106:0] debug: sending to target: <terrax.net.> 94.130.73.109#53
[1510887299] unbound[8106:0] debug: cache memory msg=67199 rrset=83488 infra=6735 val=66336 subnet=74488
[1510887299] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510887299] unbound[8106:0] info: iterator operate: query gw2.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] info: response for gw2.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] info: reply from <terrax.net.> 94.130.76.133#53
[1510887299] unbound[8106:0] info: query response was nodata ANSWER
[1510887299] unbound[8106:0] info: processQueryTargets: gw2.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] info: sending query: gw2.h.terrax.net. A IN
[1510887299] unbound[8106:0] debug: sending to target: <terrax.net.> 94.130.73.109#53
[1510887299] unbound[8106:0] debug: cache memory msg=67199 rrset=83488 infra=6735 val=66336 subnet=74488
[1510887299] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510887299] unbound[8106:0] info: iterator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510887299] unbound[8106:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510887299] unbound[8106:0] info: reply from <terrax.net.> 94.130.73.109#53
[1510887299] unbound[8106:0] info: query response was REFERRAL
[1510887299] unbound[8106:0] info: processQueryTargets: _443._tcp.dev.terrax.net. TLSA IN
[1510887299] unbound[8106:0] info: new target dev.h.terrax.net. A IN
[1510887299] unbound[8106:0] debug: removing 1 labels
[1510887299] unbound[8106:0] info: sending query: _tcp.dev.terrax.net. A IN
[1510887299] unbound[8106:0] debug: sending to target: <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510887299] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510887299] unbound[8106:0] info: iterator operate: query dev.h.terrax.net. A IN
[1510887299] unbound[8106:0] info: resolving dev.h.terrax.net. A IN
[1510887299] unbound[8106:0] info: resolving (init part 2):  dev.h.terrax.net. A IN
[1510887299] unbound[8106:0] info: resolving (init part 3):  dev.h.terrax.net. A IN
[1510887299] unbound[8106:0] info: processQueryTargets: dev.h.terrax.net. A IN
[1510887299] unbound[8106:0] info: new target gw2.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] info: new target gw1.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] debug: removing 1 labels
[1510887299] unbound[8106:0] info: processQueryTargets: dev.h.terrax.net. A IN
[1510887299] unbound[8106:0] info: sending query: dev.h.terrax.net. A IN
[1510887299] unbound[8106:0] debug: sending to target: <terrax.net.> 94.130.73.109#53
[1510887299] unbound[8106:0] debug: cache memory msg=67199 rrset=84566 infra=7047 val=66336 subnet=74488
[1510887299] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510887299] unbound[8106:0] info: iterator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510887299] unbound[8106:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510887299] unbound[8106:0] info: reply from <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510887299] unbound[8106:0] info: query response was NXDOMAIN ANSWER
[1510887299] unbound[8106:0] info: finishing processing for _443._tcp.dev.terrax.net. TLSA IN
[1510887299] unbound[8106:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
[1510887299] unbound[8106:0] info: validator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510887299] unbound[8106:0] info: prime trust anchor
[1510887299] unbound[8106:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_pass
[1510887299] unbound[8106:0] info: subnet operate: query . DNSKEY IN
[1510887299] unbound[8106:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
[1510887299] unbound[8106:0] info: validator operate: query . DNSKEY IN
[1510887299] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510887299] unbound[8106:0] info: resolving . DNSKEY IN
[1510887299] unbound[8106:0] info: resolving (init part 2):  . DNSKEY IN
[1510887299] unbound[8106:0] info: resolving (init part 3):  . DNSKEY IN
[1510887299] unbound[8106:0] info: processQueryTargets: . DNSKEY IN
[1510887299] unbound[8106:0] info: sending query: . DNSKEY IN
[1510887299] unbound[8106:0] debug: sending to target: <.> 2001:500:1::53#53
[1510887299] unbound[8106:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_pass
[1510887299] unbound[8106:0] info: subnet operate: query _ta-4a5c-4f66. NULL IN
[1510887299] unbound[8106:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
[1510887299] unbound[8106:0] info: validator operate: query _ta-4a5c-4f66. NULL IN
[1510887299] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510887299] unbound[8106:0] info: resolving _ta-4a5c-4f66. NULL IN
[1510887299] unbound[8106:0] info: resolving (init part 2):  _ta-4a5c-4f66. NULL IN
[1510887299] unbound[8106:0] info: resolving (init part 3):  _ta-4a5c-4f66. NULL IN
[1510887299] unbound[8106:0] info: processQueryTargets: _ta-4a5c-4f66. NULL IN
[1510887299] unbound[8106:0] info: sending query: _ta-4a5c-4f66. A IN
[1510887299] unbound[8106:0] debug: sending to target: <.> 2001:7fd::1#53
[1510887299] unbound[8106:0] debug: cache memory msg=67476 rrset=85445 infra=7641 val=66336 subnet=74488
[1510887299] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510887299] unbound[8106:0] info: iterator operate: query dev.h.terrax.net. A IN
[1510887299] unbound[8106:0] info: response for dev.h.terrax.net. A IN
[1510887299] unbound[8106:0] info: reply from <terrax.net.> 94.130.73.109#53
[1510887299] unbound[8106:0] info: query response was nodata ANSWER
[1510887299] unbound[8106:0] info: finishing processing for dev.h.terrax.net. A IN
[1510887299] unbound[8106:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
[1510887299] unbound[8106:0] info: validator operate: query dev.h.terrax.net. A IN
[1510887299] unbound[8106:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_moddone
[1510887299] unbound[8106:0] info: subnet operate: query dev.h.terrax.net. A IN
[1510887299] unbound[8106:0] debug: cache memory msg=67750 rrset=85859 infra=7641 val=66336 subnet=74488
[1510887299] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510887299] unbound[8106:0] info: iterator operate: query gw2.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] info: response for gw2.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] info: reply from <terrax.net.> 94.130.73.109#53
[1510887299] unbound[8106:0] info: query response was ANSWER
[1510887299] unbound[8106:0] info: processQueryTargets: gw2.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] info: sending query: gw2.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] debug: sending to target: <terrax.net.> 94.130.76.133#53
[1510887299] unbound[8106:0] debug: cache memory msg=68000 rrset=86011 infra=7641 val=66336 subnet=74488
[1510887299] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510887299] unbound[8106:0] info: iterator operate: query gw1.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] info: response for gw1.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] info: reply from <terrax.net.> 94.130.73.109#53
[1510887299] unbound[8106:0] info: query response was ANSWER
[1510887299] unbound[8106:0] info: processQueryTargets: gw1.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] info: sending query: gw1.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] debug: sending to target: <terrax.net.> 94.130.73.109#53
[1510887299] unbound[8106:0] debug: cache memory msg=68250 rrset=86163 infra=7641 val=66336 subnet=74488
[1510887299] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510887299] unbound[8106:0] info: iterator operate: query _ta-4a5c-4f66. NULL IN
[1510887299] unbound[8106:0] info: response for _ta-4a5c-4f66. NULL IN
[1510887299] unbound[8106:0] info: reply from <.> 2001:7fd::1#53
[1510887299] unbound[8106:0] info: query response was NXDOMAIN ANSWER
[1510887299] unbound[8106:0] info: finishing processing for _ta-4a5c-4f66. NULL IN
[1510887299] unbound[8106:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
[1510887299] unbound[8106:0] info: validator operate: query _ta-4a5c-4f66. NULL IN
[1510887299] unbound[8106:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1510887299] unbound[8106:0] info: subnet operate: query _ta-4a5c-4f66. NULL IN
[1510887299] unbound[8106:0] debug: cache memory msg=68521 rrset=87281 infra=7641 val=66336 subnet=74488
[1510887299] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510887299] unbound[8106:0] info: iterator operate: query gw2.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] info: response for gw2.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] info: reply from <terrax.net.> 94.130.76.133#53
[1510887299] unbound[8106:0] info: query response was ANSWER
[1510887299] unbound[8106:0] info: finishing processing for gw2.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
[1510887299] unbound[8106:0] info: validator operate: query gw2.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_moddone
[1510887299] unbound[8106:0] info: subnet operate: query gw2.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] debug: cache memory msg=68771 rrset=87685 infra=7641 val=66336 subnet=74488
[1510887299] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510887299] unbound[8106:0] info: iterator operate: query gw1.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] info: response for gw1.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] info: reply from <terrax.net.> 94.130.73.109#53
[1510887299] unbound[8106:0] info: query response was ANSWER
[1510887299] unbound[8106:0] info: finishing processing for gw1.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
[1510887299] unbound[8106:0] info: validator operate: query gw1.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_moddone
[1510887299] unbound[8106:0] info: subnet operate: query gw1.h.terrax.net. AAAA IN
[1510887299] unbound[8106:0] debug: cache memory msg=69021 rrset=88089 infra=7641 val=66336 subnet=74488
[1510887299] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510887299] unbound[8106:0] info: iterator operate: query . DNSKEY IN
[1510887299] unbound[8106:0] info: response for . DNSKEY IN
[1510887299] unbound[8106:0] info: reply from <.> 2001:500:1::53#53
[1510887299] unbound[8106:0] info: query response was ANSWER
[1510887299] unbound[8106:0] info: finishing processing for . DNSKEY IN
[1510887299] unbound[8106:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
[1510887299] unbound[8106:0] info: validator operate: query . DNSKEY IN
[1510887299] unbound[8106:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1510887299] unbound[8106:0] info: subnet operate: query . DNSKEY IN
[1510887299] unbound[8106:0] info: validate keys with anchor(DS): sec_status_secure
[1510887299] unbound[8106:0] info: Successfully primed trust anchor . DNSKEY IN
[1510887299] unbound[8106:0] debug: validator[module 1] operate: extstate:module_wait_subquery event:module_event_pass
[1510887299] unbound[8106:0] info: validator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510887299] unbound[8106:0] info: validated DS net. DS IN
[1510887299] unbound[8106:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_pass
[1510887299] unbound[8106:0] info: subnet operate: query net. DNSKEY IN
[1510887299] unbound[8106:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
[1510887299] unbound[8106:0] info: validator operate: query net. DNSKEY IN
[1510887299] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510887299] unbound[8106:0] info: resolving net. DNSKEY IN
[1510887299] unbound[8106:0] info: resolving (init part 2):  net. DNSKEY IN
[1510887299] unbound[8106:0] info: resolving (init part 3):  net. DNSKEY IN
[1510887299] unbound[8106:0] info: processQueryTargets: net. DNSKEY IN
[1510887299] unbound[8106:0] info: sending query: net. DNSKEY IN
[1510887299] unbound[8106:0] debug: sending to target: <net.> 2001:503:d2d::30#53
[1510887299] unbound[8106:0] debug: cache memory msg=69254 rrset=89453 infra=7942 val=67732 subnet=74488
[1510887299] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510887299] unbound[8106:0] info: iterator operate: query net. DNSKEY IN
[1510887299] unbound[8106:0] info: response for net. DNSKEY IN
[1510887299] unbound[8106:0] info: reply from <net.> 2001:503:d2d::30#53
[1510887299] unbound[8106:0] info: query response was ANSWER
[1510887299] unbound[8106:0] info: finishing processing for net. DNSKEY IN
[1510887299] unbound[8106:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
[1510887299] unbound[8106:0] info: validator operate: query net. DNSKEY IN
[1510887299] unbound[8106:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1510887299] unbound[8106:0] info: subnet operate: query net. DNSKEY IN
[1510887299] unbound[8106:0] info: validated DNSKEY net. DNSKEY IN
[1510887299] unbound[8106:0] debug: validator[module 1] operate: extstate:module_wait_subquery event:module_event_pass
[1510887299] unbound[8106:0] info: validator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510887299] unbound[8106:0] info: validated DS terrax.net. DS IN
[1510887299] unbound[8106:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_pass
[1510887299] unbound[8106:0] info: subnet operate: query terrax.net. DNSKEY IN
[1510887299] unbound[8106:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
[1510887299] unbound[8106:0] info: validator operate: query terrax.net. DNSKEY IN
[1510887299] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510887299] unbound[8106:0] info: resolving terrax.net. DNSKEY IN
[1510887299] unbound[8106:0] info: resolving (init part 2):  terrax.net. DNSKEY IN
[1510887299] unbound[8106:0] info: resolving (init part 3):  terrax.net. DNSKEY IN
[1510887299] unbound[8106:0] info: processQueryTargets: terrax.net. DNSKEY IN
[1510887299] unbound[8106:0] info: sending query: terrax.net. DNSKEY IN
[1510887299] unbound[8106:0] debug: sending to target: <terrax.net.> 2a01:4f8:c0c:2c12::10#53
[1510887299] unbound[8106:0] debug: cache memory msg=69491 rrset=90403 infra=8250 val=68714 subnet=74488
[1510887299] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510887299] unbound[8106:0] info: iterator operate: query terrax.net. DNSKEY IN
[1510887299] unbound[8106:0] info: response for terrax.net. DNSKEY IN
[1510887299] unbound[8106:0] info: reply from <terrax.net.> 2a01:4f8:c0c:2c12::10#53
[1510887299] unbound[8106:0] info: query response was ANSWER
[1510887299] unbound[8106:0] info: finishing processing for terrax.net. DNSKEY IN
[1510887299] unbound[8106:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
[1510887299] unbound[8106:0] info: validator operate: query terrax.net. DNSKEY IN
[1510887299] unbound[8106:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1510887299] unbound[8106:0] info: subnet operate: query terrax.net. DNSKEY IN
[1510887299] unbound[8106:0] info: validated DNSKEY terrax.net. DNSKEY IN
[1510887299] unbound[8106:0] debug: validator[module 1] operate: extstate:module_wait_subquery event:module_event_pass
[1510887299] unbound[8106:0] info: validator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510887299] unbound[8106:0] info: validated DS dev.terrax.net. DS IN
[1510887299] unbound[8106:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_pass
[1510887299] unbound[8106:0] info: subnet operate: query dev.terrax.net. DNSKEY IN
[1510887299] unbound[8106:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
[1510887299] unbound[8106:0] info: validator operate: query dev.terrax.net. DNSKEY IN
[1510887299] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510887299] unbound[8106:0] info: resolving dev.terrax.net. DNSKEY IN
[1510887299] unbound[8106:0] info: resolving (init part 2):  dev.terrax.net. DNSKEY IN
[1510887299] unbound[8106:0] info: resolving (init part 3):  dev.terrax.net. DNSKEY IN
[1510887299] unbound[8106:0] info: processQueryTargets: dev.terrax.net. DNSKEY IN
[1510887299] unbound[8106:0] info: sending query: dev.terrax.net. DNSKEY IN
[1510887299] unbound[8106:0] debug: sending to target: <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510887299] unbound[8106:0] debug: cache memory msg=69735 rrset=91011 infra=8250 val=69354 subnet=74488
[1510887299] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510887299] unbound[8106:0] info: iterator operate: query dev.terrax.net. DNSKEY IN
[1510887299] unbound[8106:0] info: response for dev.terrax.net. DNSKEY IN
[1510887299] unbound[8106:0] info: reply from <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510887299] unbound[8106:0] info: query response was ANSWER
[1510887299] unbound[8106:0] info: finishing processing for dev.terrax.net. DNSKEY IN
[1510887299] unbound[8106:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
[1510887299] unbound[8106:0] info: validator operate: query dev.terrax.net. DNSKEY IN
[1510887299] unbound[8106:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1510887299] unbound[8106:0] info: subnet operate: query dev.terrax.net. DNSKEY IN
[1510887299] unbound[8106:0] info: validated DNSKEY dev.terrax.net. DNSKEY IN
[1510887299] unbound[8106:0] debug: validator[module 1] operate: extstate:module_wait_subquery event:module_event_pass
[1510887299] unbound[8106:0] info: validator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510887299] unbound[8106:0] debug: verify: signature mismatch
[1510887299] unbound[8106:0] info: validator: response has failed AUTHORITY rrset: dev.terrax.net. NSEC IN
[1510887299] unbound[8106:0] info: Validate: message contains bad rrsets
[1510887299] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_finished event:module_event_pass
[1510887299] unbound[8106:0] info: resolving _443._tcp.dev.terrax.net. TLSA IN
[1510887299] unbound[8106:0] info: resolving (init part 2):  _443._tcp.dev.terrax.net. TLSA IN
[1510887299] unbound[8106:0] info: resolving (init part 3):  _443._tcp.dev.terrax.net. TLSA IN
[1510887299] unbound[8106:0] info: processQueryTargets: _443._tcp.dev.terrax.net. TLSA IN
[1510887299] unbound[8106:0] debug: removing 1 labels
[1510887299] unbound[8106:0] info: sending query: _tcp.dev.terrax.net. A IN
[1510887299] unbound[8106:0] debug: sending to target: <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510887299] unbound[8106:0] debug: cache memory msg=70007 rrset=91657 infra=8250 val=69876 subnet=74488
[1510887300] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510887300] unbound[8106:0] info: iterator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] info: reply from <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510887300] unbound[8106:0] info: query response was NXDOMAIN ANSWER
[1510887300] unbound[8106:0] info: finishing processing for _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] debug: validator[module 1] operate: extstate:module_restart_next event:module_event_moddone
[1510887300] unbound[8106:0] info: validator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] info: validator operate: chased to . TYPE0 CLASS0
[1510887300] unbound[8106:0] debug: NameError response has failed to prove: qname does not exist
[1510887300] unbound[8106:0] debug: NODATA response failed to prove NODATA status with NSEC/NSEC3
[1510887300] unbound[8106:0] info: validate(nxdomain): sec_status_bogus
[1510887300] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_finished event:module_event_pass
[1510887300] unbound[8106:0] info: resolving _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] info: resolving (init part 2):  _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] info: resolving (init part 3):  _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] info: processQueryTargets: _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] debug: removing 1 labels
[1510887300] unbound[8106:0] info: sending query: _tcp.dev.terrax.net. A IN
[1510887300] unbound[8106:0] debug: sending to target: <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510887300] unbound[8106:0] debug: cache memory msg=70007 rrset=92085 infra=8250 val=69876 subnet=74488
[1510887300] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510887300] unbound[8106:0] info: iterator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] info: reply from <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510887300] unbound[8106:0] info: query response was NXDOMAIN ANSWER
[1510887300] unbound[8106:0] info: finishing processing for _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] debug: validator[module 1] operate: extstate:module_restart_next event:module_event_moddone
[1510887300] unbound[8106:0] info: validator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] info: validator operate: chased to . TYPE0 CLASS0
[1510887300] unbound[8106:0] debug: verify: signature mismatch
[1510887300] unbound[8106:0] info: validator: response has failed AUTHORITY rrset: dev.terrax.net. NSEC IN
[1510887300] unbound[8106:0] info: Validate: message contains bad rrsets
[1510887300] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_finished event:module_event_pass
[1510887300] unbound[8106:0] info: resolving _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] info: resolving (init part 2):  _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] info: resolving (init part 3):  _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] info: processQueryTargets: _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] debug: removing 1 labels
[1510887300] unbound[8106:0] info: sending query: _tcp.dev.terrax.net. A IN
[1510887300] unbound[8106:0] debug: sending to target: <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510887300] unbound[8106:0] debug: cache memory msg=70007 rrset=92085 infra=8250 val=69876 subnet=74488
[1510887300] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510887300] unbound[8106:0] info: iterator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] info: reply from <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510887300] unbound[8106:0] info: query response was NXDOMAIN ANSWER
[1510887300] unbound[8106:0] info: finishing processing for _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] debug: validator[module 1] operate: extstate:module_restart_next event:module_event_moddone
[1510887300] unbound[8106:0] info: validator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] info: validator operate: chased to . TYPE0 CLASS0
[1510887300] unbound[8106:0] debug: verify: signature mismatch
[1510887300] unbound[8106:0] info: validator: response has failed AUTHORITY rrset: dev.terrax.net. NSEC IN
[1510887300] unbound[8106:0] info: Validate: message contains bad rrsets
[1510887300] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_finished event:module_event_pass
[1510887300] unbound[8106:0] info: resolving _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] info: resolving (init part 2):  _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] info: resolving (init part 3):  _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] info: processQueryTargets: _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] debug: removing 1 labels
[1510887300] unbound[8106:0] info: sending query: _tcp.dev.terrax.net. A IN
[1510887300] unbound[8106:0] debug: sending to target: <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510887300] unbound[8106:0] debug: cache memory msg=70007 rrset=92085 infra=8250 val=69876 subnet=74488
[1510887300] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510887300] unbound[8106:0] info: iterator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] info: reply from <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510887300] unbound[8106:0] info: query response was NXDOMAIN ANSWER
[1510887300] unbound[8106:0] info: finishing processing for _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] debug: validator[module 1] operate: extstate:module_restart_next event:module_event_moddone
[1510887300] unbound[8106:0] info: validator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] info: validator operate: chased to . TYPE0 CLASS0
[1510887300] unbound[8106:0] debug: verify: signature mismatch
[1510887300] unbound[8106:0] info: validator: response has failed AUTHORITY rrset: dev.terrax.net. NSEC IN
[1510887300] unbound[8106:0] info: Validate: message contains bad rrsets
[1510887300] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_finished event:module_event_pass
[1510887300] unbound[8106:0] info: resolving _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] info: resolving (init part 2):  _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] info: resolving (init part 3):  _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] info: processQueryTargets: _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] debug: removing 1 labels
[1510887300] unbound[8106:0] info: sending query: _tcp.dev.terrax.net. A IN
[1510887300] unbound[8106:0] debug: sending to target: <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510887300] unbound[8106:0] debug: cache memory msg=70007 rrset=92085 infra=8250 val=69876 subnet=74488
[1510887300] unbound[8106:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510887300] unbound[8106:0] info: iterator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] info: reply from <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510887300] unbound[8106:0] info: query response was NXDOMAIN ANSWER
[1510887300] unbound[8106:0] info: finishing processing for _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] debug: validator[module 1] operate: extstate:module_restart_next event:module_event_moddone
[1510887300] unbound[8106:0] info: validator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] info: validator operate: chased to . TYPE0 CLASS0
[1510887300] unbound[8106:0] debug: NameError response has failed to prove: qname does not exist
[1510887300] unbound[8106:0] debug: NODATA response failed to prove NODATA status with NSEC/NSEC3
[1510887300] unbound[8106:0] info: validate(nxdomain): sec_status_bogus
[1510887300] unbound[8106:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1510887300] unbound[8106:0] info: subnet operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510887300] unbound[8106:0] debug: cache memory msg=70007 rrset=92085 infra=8250 val=69876 subnet=74488
[1510887304] unbound[8106:0] info: service stopped (unbound 1.6.7).
[1510887304] unbound[8106:0] info: server stats for thread 0: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting
[1510887304] unbound[8106:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
[1510887304] unbound[8106:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 1 recursion replies sent, 0 replies dropped, 0 states jostled out
[1510887304] unbound[8106:0] info: average recursion processing time 0.652456 sec
[1510887304] unbound[8106:0] info: histogram of recursion processing times
[1510887304] unbound[8106:0] info: [25%]=0 median[50%]=0 [75%]=0
[1510887304] unbound[8106:0] info: lower(secs) upper(secs) recursions
[1510887304] unbound[8106:0] info:    0.524288    1.000000 1
[1510887304] unbound[8106:0] debug: cache memory msg=66072 rrset=66072 infra=8250 val=69876 subnet=74488
[1510887304] unbound[8106:0] debug: switching log to stderr

unbound.conf

server:
        interface: ::1
        port: 53
        prefer-ip6: yes
        cache-max-ttl: 600
        cache-max-negative-ttl: 60
        do-ip4: yes 
        do-ip6: yes
        do-udp: yes
        do-tcp: yes 
        qname-minimisation: yes
        root-hints: "/etc/unbound/root.hints"
        auto-trust-anchor-file: "/var/lib/unbound/root.key"
        #prefetch-key: yes
        logfile: "/var/log/unbound/unbound.log"
        log-queries: yes
        verbosity: 3

remote-control:
        control-interface: ::1

@Darkspirit
Copy link
Contributor

Darkspirit commented Nov 17, 2017

PowerDNS (NOERROR)

darkspirit@darkspirit:~$ dig A _tcp.terrax.net @gw1.h.terrax.net +dnssec

; <<>> DiG 9.10.6-Debian <<>> A _tcp.terrax.net @gw1.h.terrax.net +dnssec
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 3724
;; flags: qr aa rd; QUERY: 1, ANSWER: 0, AUTHORITY: 4, ADDITIONAL: 1
;; WARNING: recursion requested but not available

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 512
;; QUESTION SECTION:
;_tcp.terrax.net.               IN      A

;; AUTHORITY SECTION:
terrax.net.             86400   IN      SOA     gw1.h.terrax.net. hostmaster.terrax.net. 2017110501 28800 7200 604800 86400
terrax.net.             86400   IN      RRSIG   SOA 14 2 86400 20171130000000 20171109000000 5248 terrax.net. 8iIJ10gZqP3bPSMcNc0RjbxiJnU7BRNhAQ0xooci6J+qTjT9ueIcAjnM fU1pPo6j1RR72qCee2Nl7VlDWlbXEWUYW6P0kt3MIu2KVse+1t8YxtuI aelz4Mk8E2bzcPwR
terrax._domainkey.terrax.net. 86400 IN  NSEC    _443._tcp.terrax.net. TXT RRSIG NSEC
terrax._domainkey.terrax.net. 86400 IN  RRSIG   NSEC 14 4 86400 20171130000000 20171109000000 5248 terrax.net. hdlW2JJ0akR6XkeC7nmFAkpNS/ekuSfnvS604aGHBvY0MmLqQDKMUBIE qwXYeSAgtECavwTsKjJ7lErJL9poXYoqfMAZ/1Q+PImNTfqq4lleT9Dp NAGY+qQ6kyzUsjPx

;; Query time: 36 msec
;; SERVER: 2a01:4f8:c0c:2c12::10#53(2a01:4f8:c0c:2c12::10)
;; WHEN: Fri Nov 17 04:40:53 CET 2017
;; MSG SIZE  rcvd: 433

TRust-DNS (always the same request: bad packet, NXDOMAIN, bad packet, NXDOMAIN. Other requests (like AAAA or DNSKEY from dev.terrax.net) to TRust-DNS seem to be always fine.)

darkspirit@darkspirit:~$ dig A _tcp.dev.terrax.net @dev.h.terrax.net +dnssec
;; Got bad packet: FORMERR
461 bytes
d7 ce 80 03 00 01 00 00 00 04 00 01 04 5f 74 63          ............._tc
70 03 64 65 76 06 74 65 72 72 61 78 03 6e 65 74          p.dev.terrax.net
00 00 01 00 01 c0 11 00 2f 00 01 00 00 02 58 00          ......../.....X.
26 04 5f 34 34 33 04 5f 74 63 70 03 64 65 76 06          &._443._tcp.dev.
74 65 72 72 61 78 03 6e 65 74 00 01 01 40 00 07          terrax.net...@..
22 01 80 08 00 00 80 c0 11 00 2e 00 01 00 00 02          "...............
58 00 82 00 2f 0e 03 00 00 02 58 5b ee 32 06 5a          X.../.....X[.2.Z
0e 50 06 15 e0 03 64 65 76 06 74 65 72 72 61 78          .P....dev.terrax
03 6e 65 74 00 e3 83 61 81 f1 e5 d3 bf 10 59 61          .net...a......Ya
f1 66 0f c8 76 99 a0 2c aa 3a 8e 0c 4f c7 81 42          .f..v..,.:..O..B
4e 21 2b 03 9e 53 9f 8d 11 36 31 6b 53 52 fa f5          N!+..S...61kSR..
ce 92 cf 2f 4b ea 5d 21 e8 90 4a d2 fc 0e 2c b5          .../K.]!..J...,.
45 b5 c8 48 25 f5 75 1e 0e 0d 30 57 f7 c4 5e 6f          E..H%.u...0W..^o
48 fb 08 bd eb fa 3b 31 81 83 99 f1 28 98 82 48          H.....;1....(..H
91 f7 76 75 7b c0 11 00 06 00 01 00 00 02 58 00          ..vu{.........X.
33 03 64 65 76 01 68 06 74 65 72 72 61 78 03 6e          3.dev.h.terrax.n
65 74 00 0a 68 6f 73 74 6d 61 73 74 65 72 c0 f7          et..hostmaster..
0c 05 de 12 00 00 02 58 00 00 02 58 00 00 02 58          .......X...X...X
00 00 02 58 c0 11 00 2e 00 01 00 00 02 58 00 82          ...X.........X..
00 06 0e 03 00 00 02 58 5b ee 32 06 5a 0e 50 06          .......X[.2.Z.P.
15 e0 03 64 65 76 06 74 65 72 72 61 78 03 6e 65          ...dev.terrax.ne
74 00 65 a4 60 f4 06 d0 be 19 80 0d 9a 24 da c5          t.e.`........$..
94 59 94 12 00 40 41 7e fd 00 da 45 5a 8c 38 cd          .Y...@A....EZ.8.
8f 27 65 a7 61 48 00 76 46 27 3e 9b b0 e8 1d 68          .'e.aH.vF'>....h
9a ca 5d a2 53 ce 68 9f 77 23 db 88 af 56 f7 2a          ..].S.h.w#...V.*
31 08 2f 02 ba bf 7e ca 37 80 fb a0 3f 0f 48 41          1./.....7...?.HA
8d 3d 2d b2 f9 3f 2d cf c6 b7 62 0a 59 aa e4 ed          .=-..?-...b.Y...
25 53 00 00 29 10 00 00 00 80 00 00 10 00 06 00          %S..)...........
04 08 0d 0e 0f 00 05 00 04 08 0d 0e 0f                   .............
darkspirit@darkspirit:~$ dig A _tcp.dev.terrax.net @dev.h.terrax.net +dnssec

; <<>> DiG 9.10.6-Debian <<>> A _tcp.dev.terrax.net @dev.h.terrax.net +dnssec
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NXDOMAIN, id: 55802
;; flags: qr; QUERY: 1, ANSWER: 0, AUTHORITY: 4, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 4096
; OPT=6: 08 0d 0e 0f ("....")
; OPT=5: 08 0d 0e 0f ("....")
;; QUESTION SECTION:
;_tcp.dev.terrax.net.           IN      A

;; AUTHORITY SECTION:
dev.terrax.net.         600     IN      NSEC    _443._tcp.dev.terrax.net. NS SOA MX TXT AAAA DNSKEY CAA
dev.terrax.net.         600     IN      RRSIG   NSEC 14 3 600 20181116025710 20171117025710 5600 dev.terrax.net. 44NhgfHl078QWWHxZg/IdpmgLKo6jgxPx4FCTiErA55Tn40RNjFrU1L6 9c6Szy9L6l0h6JBK0vwOLLVFtchIJfV1Hg4NMFf3xF5vSPsIvev6OzGB g5nxKJiCSJH3dnV7
dev.terrax.net.         600     IN      SOA     dev.h.terrax.net. hostmaster.terrax.net. 201711122 600 600 600 600
dev.terrax.net.         600     IN      RRSIG   SOA 14 3 600 20181116025710 20171117025710 5600 dev.terrax.net. ZaRg9AbQvhmADZok2sWUWZQSAEBBfv0A2kVajDjNjydlp2FIAHZGJz6b sOgdaJrKXaJTzmifdyPbiK9W9yoxCC8Cur9+yjeA+6A/D0hBjT0tsvk/ Lc/Gt2IKWark7SVT

;; Query time: 25 msec
;; SERVER: 2a01:4f8:c0c:2c12::50#53(2a01:4f8:c0c:2c12::50)
;; WHEN: Fri Nov 17 04:43:07 CET 2017
;; MSG SIZE  rcvd: 461

darkspirit@darkspirit:~$ dig A _tcp.dev.terrax.net @dev.h.terrax.net +dnssec
;; Got bad packet: FORMERR
461 bytes
4d a6 80 03 00 01 00 00 00 04 00 01 04 5f 74 63          M............_tc
70 03 64 65 76 06 74 65 72 72 61 78 03 6e 65 74          p.dev.terrax.net
00 00 01 00 01 c0 11 00 2f 00 01 00 00 02 58 00          ......../.....X.
26 04 5f 34 34 33 04 5f 74 63 70 03 64 65 76 06          &._443._tcp.dev.
74 65 72 72 61 78 03 6e 65 74 00 01 01 40 00 07          terrax.net...@..
22 01 80 08 00 00 80 c0 11 00 2e 00 01 00 00 02          "...............
58 00 82 00 2f 0e 03 00 00 02 58 5b ee 32 06 5a          X.../.....X[.2.Z
0e 50 06 15 e0 03 64 65 76 06 74 65 72 72 61 78          .P....dev.terrax
03 6e 65 74 00 e3 83 61 81 f1 e5 d3 bf 10 59 61          .net...a......Ya
f1 66 0f c8 76 99 a0 2c aa 3a 8e 0c 4f c7 81 42          .f..v..,.:..O..B
4e 21 2b 03 9e 53 9f 8d 11 36 31 6b 53 52 fa f5          N!+..S...61kSR..
ce 92 cf 2f 4b ea 5d 21 e8 90 4a d2 fc 0e 2c b5          .../K.]!..J...,.
45 b5 c8 48 25 f5 75 1e 0e 0d 30 57 f7 c4 5e 6f          E..H%.u...0W..^o
48 fb 08 bd eb fa 3b 31 81 83 99 f1 28 98 82 48          H.....;1....(..H
91 f7 76 75 7b c0 11 00 06 00 01 00 00 02 58 00          ..vu{.........X.
33 03 64 65 76 01 68 06 74 65 72 72 61 78 03 6e          3.dev.h.terrax.n
65 74 00 0a 68 6f 73 74 6d 61 73 74 65 72 c0 f7          et..hostmaster..
0c 05 de 12 00 00 02 58 00 00 02 58 00 00 02 58          .......X...X...X
00 00 02 58 c0 11 00 2e 00 01 00 00 02 58 00 82          ...X.........X..
00 06 0e 03 00 00 02 58 5b ee 32 06 5a 0e 50 06          .......X[.2.Z.P.
15 e0 03 64 65 76 06 74 65 72 72 61 78 03 6e 65          ...dev.terrax.ne
74 00 65 a4 60 f4 06 d0 be 19 80 0d 9a 24 da c5          t.e.`........$..
94 59 94 12 00 40 41 7e fd 00 da 45 5a 8c 38 cd          .Y...@A....EZ.8.
8f 27 65 a7 61 48 00 76 46 27 3e 9b b0 e8 1d 68          .'e.aH.vF'>....h
9a ca 5d a2 53 ce 68 9f 77 23 db 88 af 56 f7 2a          ..].S.h.w#...V.*
31 08 2f 02 ba bf 7e ca 37 80 fb a0 3f 0f 48 41          1./.....7...?.HA
8d 3d 2d b2 f9 3f 2d cf c6 b7 62 0a 59 aa e4 ed          .=-..?-...b.Y...
25 53 00 00 29 10 00 00 00 80 00 00 10 00 06 00          %S..)...........
04 08 0d 0e 0f 00 05 00 04 08 0d 0e 0f                   .............
darkspirit@darkspirit:~$ dig A _tcp.dev.terrax.net @dev.h.terrax.net +dnssec

; <<>> DiG 9.10.6-Debian <<>> A _tcp.dev.terrax.net @dev.h.terrax.net +dnssec
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NXDOMAIN, id: 15682
;; flags: qr; QUERY: 1, ANSWER: 0, AUTHORITY: 4, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 4096
; OPT=5: 08 0d 0e 0f ("....")
; OPT=6: 08 0d 0e 0f ("....")
;; QUESTION SECTION:
;_tcp.dev.terrax.net.           IN      A

;; AUTHORITY SECTION:
dev.terrax.net.         600     IN      NSEC    _443._tcp.dev.terrax.net. NS SOA MX TXT AAAA DNSKEY CAA
dev.terrax.net.         600     IN      RRSIG   NSEC 14 3 600 20181116025710 20171117025710 5600 dev.terrax.net. 44NhgfHl078QWWHxZg/IdpmgLKo6jgxPx4FCTiErA55Tn40RNjFrU1L6 9c6Szy9L6l0h6JBK0vwOLLVFtchIJfV1Hg4NMFf3xF5vSPsIvev6OzGB g5nxKJiCSJH3dnV7
dev.terrax.net.         600     IN      SOA     dev.h.terrax.net. hostmaster.terrax.net. 201711122 600 600 600 600
dev.terrax.net.         600     IN      RRSIG   SOA 14 3 600 20181116025710 20171117025710 5600 dev.terrax.net. ZaRg9AbQvhmADZok2sWUWZQSAEBBfv0A2kVajDjNjydlp2FIAHZGJz6b sOgdaJrKXaJTzmifdyPbiK9W9yoxCC8Cur9+yjeA+6A/D0hBjT0tsvk/ Lc/Gt2IKWark7SVT

;; Query time: 26 msec
;; SERVER: 2a01:4f8:c0c:2c12::50#53(2a01:4f8:c0c:2c12::50)
;; WHEN: Fri Nov 17 04:43:08 CET 2017
;; MSG SIZE  rcvd: 461

@bluejekyll
Copy link
Member Author

Thank you for your patience in trying to resolve this. If this doesn't fix it, I'll need to replicate your setup locally to try and replicate the issues you're seeing.

This is strange: request: 61990 src: [2003:c4:bf23:b900:88c2:fcc3:81bf:b59e]:31440 type: Query op_code: Query name: _tcp.dev.terrax.net. type: A class: IN

The dig query you specified was dig A _tcp.dev.terrax.net @dev.h.terrax.net +dnssec, but the record in the zone is: _443._tcp.dev.terrax.net.

So I expect an NXDomain for _tcp.dev.terrax.net.. Now with DNSSec enabled I think the NSEC response paired with NXDomain should be acceptable. I just reviewed https://tools.ietf.org/html/rfc7129 and it's not 100% clear that NXDomain is incorrect.

But I've pushed a change to change the NSEC response to NoError/NoData.


Question, when you make the _tcp.dev.terrax.net. query for TLSA, what is the response you're expecting (given the record is actually _443._tcp.dev.terrax.net.)? The authority lookup I have might be incorrect, but my reading of the RFCs implies to me that there is no special logic required for SRV or TLSA. I of course might be wrong here...

@Darkspirit
Copy link
Contributor

Darkspirit commented Nov 17, 2017

This is strange: request: 61990 src: [2003:c4:bf23:b900:88c2:fcc3:81bf:b59e]:31440 type: Query op_code: Query name: _tcp.dev.terrax.net. type: A class: IN

does not directly belong to

The dig query you specified was dig A _tcp.dev.terrax.net @dev.h.terrax.net +dnssec, but the record in the zone is: _443._tcp.dev.terrax.net.


Test 1:
After your commit "add better logs for requests", I repeated the test for _443._tcp.terrax.net TLSA:
#286 (comment)
I saw unbound's requests for "_tcp.dev.terrax.net IN A" in trustdns's log, maybe unbound only wanted to check first if it's worth to send a query for one subdomain deeper (_443._tcp.dev.terrax.net TLSA)?

Test 2:
Then I requested "_tcp.dev.terrax.net A" manually with dig and only posted dig's log.
#286 (comment)
This test should show what PowerDNS replies in such a situation: NOERROR for _tcp.terrax.net IN A.
But TRust-DNS replied NXDOMAIN or a bad packet for _tcp.dev.terrax.net IN A.


Thanks! I will test your new patches later.


Question, when you make the _tcp.dev.terrax.net. query for TLSA, what is the response you're expecting (given the record is actually _443._tcp.dev.terrax.net.)?

I wouldn't query that (and have not). But let's see what PowerDNS would tell us in such a situation:

$ dig TLSA _tcp.terrax.net @gw1.h.terrax.net +dnssec

; <<>> DiG 9.10.6-Debian <<>> TLSA _tcp.terrax.net @gw1.h.terrax.net +dnssec
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 55321
;; flags: qr aa rd; QUERY: 1, ANSWER: 0, AUTHORITY: 4, ADDITIONAL: 1
;; WARNING: recursion requested but not available

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 512
;; QUESTION SECTION:
;_tcp.terrax.net.               IN      TLSA

;; AUTHORITY SECTION:
terrax.net.             86400   IN      SOA     gw1.h.terrax.net. hostmaster.terrax.net. 2017110501 28800 7200 604800 86400
terrax.net.             86400   IN      RRSIG   SOA 14 2 86400 20171130000000 20171109000000 5248 terrax.net. 8iIJ10gZqP3bPSMcNc0RjbxiJnU7BRNhAQ0xooci6J+qTjT9ueIcAjnM fU1pPo6j1RR72qCee2Nl7VlDWlbXEWUYW6P0kt3MIu2KVse+1t8YxtuI aelz4Mk8E2bzcPwR
terrax._domainkey.terrax.net. 86400 IN  NSEC    _443._tcp.terrax.net. TXT RRSIG NSEC                                                       
terrax._domainkey.terrax.net. 86400 IN  RRSIG   NSEC 14 4 86400 20171130000000 20171109000000 5248 terrax.net. hdlW2JJ0akR6XkeC7nmFAkpNS/ekuSfnvS604aGHBvY0MmLqQDKMUBIE qwXYeSAgtECavwTsKjJ7lErJL9poXYoqfMAZ/1Q+PImNTfqq4lleT9Dp NAGY+qQ6kyzUsjPx                                     
                                                                                                                                           
;; Query time: 27 msec                                                                                                                     
;; SERVER: 2a01:4f8:c0c:2c12::10#53(2a01:4f8:c0c:2c12::10)                                                                                 
;; WHEN: Fri Nov 17 13:29:31 CET 2017                                                                                                      
;; MSG SIZE  rcvd: 433

@Darkspirit
Copy link
Contributor

Darkspirit commented Nov 17, 2017

Part A) dig via unbound works now.

  1. stopped unbound and trustdns, cleared unbound.log
  2. started trustdns in screen and made a screenlog
  3. started unbound
  4. dig TLSA _443._tcp.dev.terrax.net
  5. stopped unbound
  6. stopped trustdns
$ dig TLSA _443._tcp.dev.terrax.net

; <<>> DiG 9.10.6-Debian <<>> TLSA _443._tcp.dev.terrax.net
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 60901
;; flags: qr rd ra ad; QUERY: 1, ANSWER: 1, AUTHORITY: 1, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 4096
;; QUESTION SECTION:
;_443._tcp.dev.terrax.net.      IN      TLSA

;; ANSWER SECTION:
_443._tcp.dev.terrax.net. 60    IN      TLSA    3 1 2 A991082596FAB5F8475C22686435F22E6B67F5409B674CE3CCDCCB94 01AA0A882513C0946A8973E00A386519E401773CE025DAEEE14454B9 859C096B5B798593

;; AUTHORITY SECTION:
dev.terrax.net.         600     IN      NS      dev.h.terrax.net.

;; Query time: 439 msec
;; SERVER: ::1#53(::1)
;; WHEN: Fri Nov 17 23:21:58 CET 2017
;; MSG SIZE  rcvd: 152

trustdns

2017-11-17T22:21:46.688836522+00:00 INFO trust_dns::logger:26 logging initialized
2017-11-17T22:21:46.688883236+00:00 INFO named:331 Trust-DNS 0.12.0 starting
2017-11-17T22:21:46.688896161+00:00 INFO named:337 loading configuration from: "/home/trustdns/config.toml"
2017-11-17T22:21:46.689171789+00:00 INFO named:164 loading zone file: "/home/trustdns/dev.terrax.net.zone"
cert_data: A991082596FAB5F8475C22686435F22E6B67F5409B674CE3CCDCCB9401AA0A882513C0946A8973E00A386519E401773CE025DAEEE14454B9859C096B5B798593
2017-11-17T22:21:46.715098982+00:00 INFO named:195 zone file loaded: dev.terrax.net.
2017-11-17T22:21:46.715144833+00:00 INFO named:268 reading key: "dev.terrax.net.csk.pem"
2017-11-17T22:21:46.717295934+00:00 INFO named:209 adding key to zone: "dev.terrax.net.csk.pem", is_zsk: true, is_auth: false
2017-11-17T22:21:46.717432693+00:00 INFO named:220 signing zone: dev.terrax.net.
2017-11-17T22:21:46.729130891+00:00 INFO named:235 zone successfully loaded: dev.terrax.net.
2017-11-17T22:21:46.729395144+00:00 INFO named:398 listening for UDP on UdpSocket { addr: V6([2a01:4f8:c0c:2c12::50]:8053), fd: 3 }
2017-11-17T22:21:46.729425369+00:00 INFO named:398 listening for UDP on UdpSocket { addr: V6([2a01:4f8:c0c:2c12::51]:8053), fd: 4 }
2017-11-17T22:21:46.729435215+00:00 INFO named:404 listening for TCP on TcpListener { addr: V6([2a01:4f8:c0c:2c12::50]:8053), fd: 5 }
2017-11-17T22:21:46.729484361+00:00 INFO named:404 listening for TCP on TcpListener { addr: V6([2a01:4f8:c0c:2c12::51]:8053), fd: 6 }
2017-11-17T22:21:46.729525246+00:00 INFO named:486 
2017-11-17T22:21:46.729563378+00:00 INFO named:487     o                      o            o             
2017-11-17T22:21:46.729567283+00:00 INFO named:488     |                      |            |             
2017-11-17T22:21:46.729571+00:00 INFO named:489   --O--  o-o  o  o  o-o  --O--  o-o   o-O  o-o   o-o  
2017-11-17T22:21:46.729574120+00:00 INFO named:490     |    |    |  |   \     |         |  |  |  |   \   
2017-11-17T22:21:46.729577063+00:00 INFO named:491     o    o    o--o  o-o    o          o-o  o  o  o-o  
2017-11-17T22:21:46.729579975+00:00 INFO named:492 
2017-11-17T22:21:46.729582643+00:00 INFO named:424 awaiting connections...
2017-11-17T22:21:46.729586138+00:00 INFO trust_dns_server::server::server_future:196 Server starting up
2017-11-17T22:21:58.121866886+00:00 INFO trust_dns_server::server::server_future:215 request: 10795 src: [2003:c4:bf23:b900:7c04:5f85:3ec0:5f31]:48766 type: Query op_code: Query dnssec: true name: _tcp.dev.terrax.net. type: A class: IN
2017-11-17T22:21:58.121908835+00:00 INFO trust_dns_server::authority::catalog:280 request: 10795 found authority: dev.terrax.net.
2017-11-17T22:21:58.121984360+00:00 INFO trust_dns_server::authority::catalog:303 request: 10795 supported_algs: 
2017-11-17T22:21:58.122041925+00:00 INFO trust_dns_server::authority::catalog:345 request: 10795 non-existent adding nsecs: 2
2017-11-17T22:21:58.122100628+00:00 INFO trust_dns_server::server::server_future:226 request: 10795 response_code: No Error answers: 0 name_servers: 4 additionals: 0
2017-11-17T22:21:58.122169023+00:00 INFO trust_dns_server::server::request_stream:115 request: 10795 sending message len: 461
2017-11-17T22:21:58.123307426+00:00 INFO trust_dns_server::server::server_future:215 request: 16129 src: [2003:c4:bf23:b900:7c04:5f85:3ec0:5f31]:48256 type: Query op_code: Query dnssec: true name: dev.terrax.net. type: DNSKEY class: IN
2017-11-17T22:21:58.123362828+00:00 INFO trust_dns_server::authority::catalog:280 request: 16129 found authority: dev.terrax.net.
2017-11-17T22:21:58.123408799+00:00 INFO trust_dns_server::authority::catalog:303 request: 16129 supported_algs: 
2017-11-17T22:21:58.123451903+00:00 INFO trust_dns_server::server::server_future:226 request: 16129 response_code: No Error answers: 2 name_servers: 2 additionals: 0
2017-11-17T22:21:58.123489579+00:00 INFO trust_dns_server::server::request_stream:115 request: 16129 sending message len: 485
2017-11-17T22:21:58.147668673+00:00 INFO trust_dns_server::server::server_future:215 request: 60246 src: [2003:c4:bf23:b900:7c04:5f85:3ec0:5f31]:38634 type: Query op_code: Query dnssec: true name: _443._tcp.dev.terrax.net. type: A class: IN
2017-11-17T22:21:58.147710961+00:00 INFO trust_dns_server::authority::catalog:280 request: 60246 found authority: dev.terrax.net.
2017-11-17T22:21:58.147803608+00:00 INFO trust_dns_server::authority::catalog:303 request: 60246 supported_algs: 
2017-11-17T22:21:58.147930578+00:00 INFO trust_dns_server::authority::catalog:345 request: 60246 non-existent adding nsecs: 2
2017-11-17T22:21:58.147964308+00:00 INFO trust_dns_server::server::server_future:226 request: 60246 response_code: No Error answers: 0 name_servers: 4 additionals: 0
2017-11-17T22:21:58.148030514+00:00 INFO trust_dns_server::server::request_stream:115 request: 60246 sending message len: 466
2017-11-17T22:21:58.173310174+00:00 INFO trust_dns_server::server::server_future:215 request: 331 src: [2003:c4:bf23:b900:7c04:5f85:3ec0:5f31]:7875 type: Query op_code: Query dnssec: true name: _443._tcp.dev.terrax.net. type: TLSA class: IN
2017-11-17T22:21:58.173352021+00:00 INFO trust_dns_server::authority::catalog:280 request: 331 found authority: dev.terrax.net.
2017-11-17T22:21:58.173358905+00:00 INFO trust_dns_server::authority::catalog:303 request: 331 supported_algs: 
2017-11-17T22:21:58.173457170+00:00 INFO trust_dns_server::server::server_future:226 request: 331 response_code: No Error answers: 2 name_servers: 2 additionals: 0
2017-11-17T22:21:58.173509673+00:00 INFO trust_dns_server::server::request_stream:115 request: 331 sending message len: 462
^C
  • unbound asks for A (how disgusting) at first, even though "prefer-ip6: yes" is set.
  • (Please ask if you want to see unbound's log from this test.)

Part B) Those bad packets.

2017-11-17T22:25:39.963263471+00:00 INFO trust_dns::logger:26 logging initialized
2017-11-17T22:25:39.963305488+00:00 INFO named:331 Trust-DNS 0.12.0 starting
2017-11-17T22:25:39.963322859+00:00 INFO named:337 loading configuration from: "/home/trustdns/config.toml"
2017-11-17T22:25:39.963548444+00:00 INFO named:164 loading zone file: "/home/trustdns/dev.terrax.net.zone"
cert_data: A991082596FAB5F8475C22686435F22E6B67F5409B674CE3CCDCCB9401AA0A882513C0946A8973E00A386519E401773CE025DAEEE14454B9859C096B5B798593
2017-11-17T22:25:39.990894440+00:00 INFO named:195 zone file loaded: dev.terrax.net.
2017-11-17T22:25:39.990934842+00:00 INFO named:268 reading key: "dev.terrax.net.csk.pem"
2017-11-17T22:25:39.994007948+00:00 INFO named:209 adding key to zone: "dev.terrax.net.csk.pem", is_zsk: true, is_auth: false
2017-11-17T22:25:39.994196276+00:00 INFO named:220 signing zone: dev.terrax.net.
2017-11-17T22:25:40.008213646+00:00 INFO named:235 zone successfully loaded: dev.terrax.net.
2017-11-17T22:25:40.008395118+00:00 INFO named:398 listening for UDP on UdpSocket { addr: V6([2a01:4f8:c0c:2c12::50]:8053), fd: 3 }
2017-11-17T22:25:40.008421889+00:00 INFO named:398 listening for UDP on UdpSocket { addr: V6([2a01:4f8:c0c:2c12::51]:8053), fd: 4 }
2017-11-17T22:25:40.008434335+00:00 INFO named:404 listening for TCP on TcpListener { addr: V6([2a01:4f8:c0c:2c12::50]:8053), fd: 5 }
2017-11-17T22:25:40.008447644+00:00 INFO named:404 listening for TCP on TcpListener { addr: V6([2a01:4f8:c0c:2c12::51]:8053), fd: 6 }
2017-11-17T22:25:40.008457686+00:00 INFO named:486 
2017-11-17T22:25:40.008462244+00:00 INFO named:487     o                      o            o             
2017-11-17T22:25:40.008466857+00:00 INFO named:488     |                      |            |             
2017-11-17T22:25:40.008471815+00:00 INFO named:489   --O--  o-o  o  o  o-o  --O--  o-o   o-O  o-o   o-o  
2017-11-17T22:25:40.008476426+00:00 INFO named:490     |    |    |  |   \     |         |  |  |  |   \   
2017-11-17T22:25:40.008481041+00:00 INFO named:491     o    o    o--o  o-o    o          o-o  o  o  o-o  
2017-11-17T22:25:40.008485980+00:00 INFO named:492 
2017-11-17T22:25:40.008490223+00:00 INFO named:424 awaiting connections...
2017-11-17T22:25:40.008494766+00:00 INFO trust_dns_server::server::server_future:196 Server starting up
2017-11-17T22:25:46.536495724+00:00 INFO trust_dns_server::server::server_future:215 request: 52404 src: [2003:c4:bf23:b900:7c04:5f85:3ec0:5f31]:51699 type: Query op_code: Query dnssec: true name: _tcp.dev.terrax.net. type: A class: IN
2017-11-17T22:25:46.536544163+00:00 INFO trust_dns_server::authority::catalog:280 request: 52404 found authority: dev.terrax.net.
2017-11-17T22:25:46.536554093+00:00 INFO trust_dns_server::authority::catalog:303 request: 52404 supported_algs: 
2017-11-17T22:25:46.536592183+00:00 INFO trust_dns_server::authority::catalog:345 request: 52404 non-existent adding nsecs: 2
2017-11-17T22:25:46.536616480+00:00 INFO trust_dns_server::server::server_future:226 request: 52404 response_code: No Error answers: 0 name_servers: 4 additionals: 0
2017-11-17T22:25:46.536669046+00:00 INFO trust_dns_server::server::request_stream:115 request: 52404 sending message len: 461
2017-11-17T22:25:47.842494661+00:00 INFO trust_dns_server::server::server_future:215 request: 59780 src: [2003:c4:bf23:b900:7c04:5f85:3ec0:5f31]:51472 type: Query op_code: Query dnssec: true name: _tcp.dev.terrax.net. type: A class: IN
2017-11-17T22:25:47.842536386+00:00 INFO trust_dns_server::authority::catalog:280 request: 59780 found authority: dev.terrax.net.
2017-11-17T22:25:47.842543200+00:00 INFO trust_dns_server::authority::catalog:303 request: 59780 supported_algs: 
2017-11-17T22:25:47.842578032+00:00 INFO trust_dns_server::authority::catalog:345 request: 59780 non-existent adding nsecs: 2
2017-11-17T22:25:47.842637183+00:00 INFO trust_dns_server::server::server_future:226 request: 59780 response_code: No Error answers: 0 name_servers: 4 additionals: 0
2017-11-17T22:25:47.842667940+00:00 INFO trust_dns_server::server::request_stream:115 request: 59780 sending message len: 461
2017-11-17T22:25:48.922509473+00:00 INFO trust_dns_server::server::server_future:215 request: 36947 src: [2003:c4:bf23:b900:7c04:5f85:3ec0:5f31]:42963 type: Query op_code: Query dnssec: true name: _tcp.dev.terrax.net. type: A class: IN
2017-11-17T22:25:48.922561745+00:00 INFO trust_dns_server::authority::catalog:280 request: 36947 found authority: dev.terrax.net.
2017-11-17T22:25:48.922571558+00:00 INFO trust_dns_server::authority::catalog:303 request: 36947 supported_algs: 
2017-11-17T22:25:48.922653891+00:00 INFO trust_dns_server::authority::catalog:345 request: 36947 non-existent adding nsecs: 2
2017-11-17T22:25:48.922681085+00:00 INFO trust_dns_server::server::server_future:226 request: 36947 response_code: No Error answers: 0 name_servers: 4 additionals: 0
2017-11-17T22:25:48.922725652+00:00 INFO trust_dns_server::server::request_stream:115 request: 36947 sending message len: 461
2017-11-17T22:25:49.938807190+00:00 INFO trust_dns_server::server::server_future:215 request: 24735 src: [2003:c4:bf23:b900:7c04:5f85:3ec0:5f31]:45395 type: Query op_code: Query dnssec: true name: _tcp.dev.terrax.net. type: A class: IN
2017-11-17T22:25:49.938962240+00:00 INFO trust_dns_server::authority::catalog:280 request: 24735 found authority: dev.terrax.net.
2017-11-17T22:25:49.938985233+00:00 INFO trust_dns_server::authority::catalog:303 request: 24735 supported_algs: 
2017-11-17T22:25:49.939025332+00:00 INFO trust_dns_server::authority::catalog:345 request: 24735 non-existent adding nsecs: 2
2017-11-17T22:25:49.939046297+00:00 INFO trust_dns_server::server::server_future:226 request: 24735 response_code: No Error answers: 0 name_servers: 4 additionals: 0
2017-11-17T22:25:49.939146248+00:00 INFO trust_dns_server::server::request_stream:115 request: 24735 sending message len: 461
^C
$ dig A _tcp.dev.terrax.net @dev.h.terrax.net +dnssec
;; Got bad packet: FORMERR
461 bytes
cc b4 80 00 00 01 00 00 00 04 00 01 04 5f 74 63          ............._tc
70 03 64 65 76 06 74 65 72 72 61 78 03 6e 65 74          p.dev.terrax.net
00 00 01 00 01 c0 11 00 2f 00 01 00 00 02 58 00          ......../.....X.
26 04 5f 34 34 33 04 5f 74 63 70 03 64 65 76 06          &._443._tcp.dev.
74 65 72 72 61 78 03 6e 65 74 00 01 01 40 00 07          terrax.net...@..
22 01 80 08 00 00 80 c0 11 00 2e 00 01 00 00 02          "...............
58 00 82 00 2f 0e 03 00 00 02 58 5b ef 43 e3 5a          X.../.....X[.C.Z
0f 61 e3 15 e0 03 64 65 76 06 74 65 72 72 61 78          .a....dev.terrax
03 6e 65 74 00 ed 68 85 3d b5 37 83 c4 37 08 e6          .net..h.=.7..7..
5a 2b 2c 82 6f 29 57 50 e9 54 86 72 23 b6 4c d4          Z+,.o)WP.T.r#.L.
66 d1 e1 30 0f fc de 5e 6b 57 b3 c5 bc 3d 1c 42          f..0...^kW...=.B
97 b3 6f ba d7 55 28 60 cf 4b a1 78 73 bc 27 3b          ..o..U(`.K.xs.';
f0 65 b0 5c 6e be 55 8e 36 f5 d1 d4 54 a8 e5 d5          .e.\n.U.6...T...                                                                  
07 1e ee a5 4e c6 63 0a fc 3b fc e9 86 aa 36 c7          ....N.c..;....6.                                                                  
18 e1 61 e2 c7 c0 11 00 06 00 01 00 00 02 58 00          ..a...........X.                                                                  
33 03 64 65 76 01 68 06 74 65 72 72 61 78 03 6e          3.dev.h.terrax.n                                                                  
65 74 00 0a 68 6f 73 74 6d 61 73 74 65 72 c0 f7          et..hostmaster..                                                                  
0c 05 de 12 00 00 02 58 00 00 02 58 00 00 02 58          .......X...X...X                                                                  
00 00 02 58 c0 11 00 2e 00 01 00 00 02 58 00 82          ...X.........X..                                                                  
00 06 0e 03 00 00 02 58 5b ef 43 e3 5a 0f 61 e3          .......X[.C.Z.a.                                                                  
15 e0 03 64 65 76 06 74 65 72 72 61 78 03 6e 65          ...dev.terrax.ne                                                                  
74 00 1e 0b a7 38 a0 53 fb a2 50 ea 74 42 79 3b          t....8.S..P.tBy;                                                                  
f9 c4 35 45 b7 c2 03 a8 7d b3 1c 9f e1 da 53 39          ..5E....}.....S9                                                                  
f8 ee c7 2a 91 83 e0 58 16 07 26 cf 28 3b 89 68          ...*...X..&.(;.h                                                                  
92 29 4f d6 ea 95 04 fd f3 cd a2 c2 a9 cc 24 46          .)O...........$F                                                                  
e4 fa 11 e8 c9 ad d1 a6 08 7f 88 b6 cd c0 77 6a          ..............wj                                                                  
43 f5 a0 04 68 55 38 45 11 20 97 09 43 5b e8 1f          C...hU8E....C[..                                                                  
b8 54 00 00 29 10 00 00 00 80 00 00 10 00 06 00          .T..)...........                                                                  
04 08 0d 0e 0f 00 05 00 04 08 0d 0e 0f                   .............                                                                     
darkspirit@darkspirit:~$ dig A _tcp.dev.terrax.net @dev.h.terrax.net +dnssec                                                               
                                                                                                                                           
; <<>> DiG 9.10.6-Debian <<>> A _tcp.dev.terrax.net @dev.h.terrax.net +dnssec                                                              
;; global options: +cmd                                                                                                                    
;; Got answer:                                                                                                                             
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 59780                                                                                  
;; flags: qr; QUERY: 1, ANSWER: 0, AUTHORITY: 4, ADDITIONAL: 1                                                                             
                                                                                                                                           
;; OPT PSEUDOSECTION:                                                                                                                      
; EDNS: version: 0, flags: do; udp: 4096                                                                                                   
; OPT=6: 08 0d 0e 0f ("....")                                                                                                              
; OPT=5: 08 0d 0e 0f ("....")                                                                                                              
;; QUESTION SECTION:                                                                                                                       
;_tcp.dev.terrax.net.           IN      A                                                                                                  
                                                                                                                                           
;; AUTHORITY SECTION:                                                                                                                      
dev.terrax.net.         600     IN      NSEC    _443._tcp.dev.terrax.net. NS SOA MX TXT AAAA DNSKEY CAA                                    
dev.terrax.net.         600     IN      RRSIG   NSEC 14 3 600 20181116222539 20171117222539 5600 dev.terrax.net. 7WiFPbU3g8Q3COZaKyyCbylXUOlUhnIjtkzUZtHhMA/83l5rV7PFvD0c Qpezb7rXVShgz0uheHO8JzvwZbBcbr5Vjjb10dRUqOXVBx7upU7GYwr8 O/zphqo2xxjhYeLH                                   
dev.terrax.net.         600     IN      SOA     dev.h.terrax.net. hostmaster.terrax.net. 201711122 600 600 600 600                         
dev.terrax.net.         600     IN      RRSIG   SOA 14 3 600 20181116222539 20171117222539 5600 dev.terrax.net. HgunOKBT+6JQ6nRCeTv5xDVFt8IDqH2zHJ/h2lM5+O7HKpGD4FgWBybP KDuJaJIpT9bqlQT9882iwqnMJEbk+hHoya3Rpgh/iLbNwHdqQ/WgBGhV OEURIJcJQ1voH7hU                                    
                                                                                                                                           
;; Query time: 25 msec                                                                                                                     
;; SERVER: 2a01:4f8:c0c:2c12::50#53(2a01:4f8:c0c:2c12::50)                                                                                 
;; WHEN: Fri Nov 17 23:25:47 CET 2017
;; MSG SIZE  rcvd: 461

darkspirit@darkspirit:~$ dig A _tcp.dev.terrax.net @dev.h.terrax.net +dnssec

; <<>> DiG 9.10.6-Debian <<>> A _tcp.dev.terrax.net @dev.h.terrax.net +dnssec
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 36947
;; flags: qr; QUERY: 1, ANSWER: 0, AUTHORITY: 4, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 4096
; OPT=5: 08 0d 0e 0f ("....")
; OPT=6: 08 0d 0e 0f ("....")
;; QUESTION SECTION:
;_tcp.dev.terrax.net.           IN      A

;; AUTHORITY SECTION:
dev.terrax.net.         600     IN      NSEC    _443._tcp.dev.terrax.net. NS SOA MX TXT AAAA DNSKEY CAA
dev.terrax.net.         600     IN      RRSIG   NSEC 14 3 600 20181116222539 20171117222539 5600 dev.terrax.net. 7WiFPbU3g8Q3COZaKyyCbylXUOlUhnIjtkzUZtHhMA/83l5rV7PFvD0c Qpezb7rXVShgz0uheHO8JzvwZbBcbr5Vjjb10dRUqOXVBx7upU7GYwr8 O/zphqo2xxjhYeLH
dev.terrax.net.         600     IN      SOA     dev.h.terrax.net. hostmaster.terrax.net. 201711122 600 600 600 600
dev.terrax.net.         600     IN      RRSIG   SOA 14 3 600 20181116222539 20171117222539 5600 dev.terrax.net. HgunOKBT+6JQ6nRCeTv5xDVFt8IDqH2zHJ/h2lM5+O7HKpGD4FgWBybP KDuJaJIpT9bqlQT9882iwqnMJEbk+hHoya3Rpgh/iLbNwHdqQ/WgBGhV OEURIJcJQ1voH7hU

;; Query time: 25 msec
;; SERVER: 2a01:4f8:c0c:2c12::50#53(2a01:4f8:c0c:2c12::50)
;; WHEN: Fri Nov 17 23:25:48 CET 2017
;; MSG SIZE  rcvd: 461

darkspirit@darkspirit:~$ dig A _tcp.dev.terrax.net @dev.h.terrax.net +dnssec
;; Got bad packet: FORMERR
461 bytes
60 9f 80 00 00 01 00 00 00 04 00 01 04 5f 74 63          `............_tc
70 03 64 65 76 06 74 65 72 72 61 78 03 6e 65 74          p.dev.terrax.net
00 00 01 00 01 c0 11 00 2f 00 01 00 00 02 58 00          ......../.....X.
26 04 5f 34 34 33 04 5f 74 63 70 03 64 65 76 06          &._443._tcp.dev.
74 65 72 72 61 78 03 6e 65 74 00 01 01 40 00 07          terrax.net...@..
22 01 80 08 00 00 80 c0 11 00 2e 00 01 00 00 02          "...............
58 00 82 00 2f 0e 03 00 00 02 58 5b ef 43 e3 5a          X.../.....X[.C.Z
0f 61 e3 15 e0 03 64 65 76 06 74 65 72 72 61 78          .a....dev.terrax
03 6e 65 74 00 ed 68 85 3d b5 37 83 c4 37 08 e6          .net..h.=.7..7..
5a 2b 2c 82 6f 29 57 50 e9 54 86 72 23 b6 4c d4          Z+,.o)WP.T.r#.L.
66 d1 e1 30 0f fc de 5e 6b 57 b3 c5 bc 3d 1c 42          f..0...^kW...=.B
97 b3 6f ba d7 55 28 60 cf 4b a1 78 73 bc 27 3b          ..o..U(`.K.xs.';
f0 65 b0 5c 6e be 55 8e 36 f5 d1 d4 54 a8 e5 d5          .e.\n.U.6...T...
07 1e ee a5 4e c6 63 0a fc 3b fc e9 86 aa 36 c7          ....N.c..;....6.
18 e1 61 e2 c7 c0 11 00 06 00 01 00 00 02 58 00          ..a...........X.
33 03 64 65 76 01 68 06 74 65 72 72 61 78 03 6e          3.dev.h.terrax.n
65 74 00 0a 68 6f 73 74 6d 61 73 74 65 72 c0 f7          et..hostmaster..
0c 05 de 12 00 00 02 58 00 00 02 58 00 00 02 58          .......X...X...X
00 00 02 58 c0 11 00 2e 00 01 00 00 02 58 00 82          ...X.........X..
00 06 0e 03 00 00 02 58 5b ef 43 e3 5a 0f 61 e3          .......X[.C.Z.a.
15 e0 03 64 65 76 06 74 65 72 72 61 78 03 6e 65          ...dev.terrax.ne
74 00 1e 0b a7 38 a0 53 fb a2 50 ea 74 42 79 3b          t....8.S..P.tBy;
f9 c4 35 45 b7 c2 03 a8 7d b3 1c 9f e1 da 53 39          ..5E....}.....S9
f8 ee c7 2a 91 83 e0 58 16 07 26 cf 28 3b 89 68          ...*...X..&.(;.h
92 29 4f d6 ea 95 04 fd f3 cd a2 c2 a9 cc 24 46          .)O...........$F
e4 fa 11 e8 c9 ad d1 a6 08 7f 88 b6 cd c0 77 6a          ..............wj
43 f5 a0 04 68 55 38 45 11 20 97 09 43 5b e8 1f          C...hU8E....C[..
b8 54 00 00 29 10 00 00 00 80 00 00 10 00 05 00          .T..)...........
04 08 0d 0e 0f 00 06 00 04 08 0d 0e 0f                   .............

  • This looks the same if I let trustdns run as root on port 53.
    This one can trigger the bug, too:
    dig DNSKEY _tcp.dev.terrax.net @dev.h.terrax.net +dnssec +tcp
    It seems to be always fine if I don't add "+dnssec" and seems to only happen with _tcp.dev.terrax.net (which isn't listed in my zone file.)

Edit: dig AXFR _tcp.dev.terrax.net @dev.h.terrax.net +tcp can also have bad packets
(Maybe a bug in "dig" on Debian Testing? How likely would that be? According to "dig" a good and bad reponse have both the same length in bytes.)

@bluejekyll
Copy link
Member Author

bluejekyll commented Nov 18, 2017

Thanks for the details. It looks like we're making good progress. unbound looks good, which is excellent. In your research into the bad-packet issue. We might want to merge (after I fix the tests) this change in, and then continue on the bad-packet in a different issue. But let's continue here for now.


bad-packet, here are some interesting things: It looks like NSEC is most likely the cause. It should only be returned with +dnssec queries enabled. I'll validate that is the case. In terms of them being correct or not (bug in dig, or not). I find this curious: In your unbound example in the first example this sequence makes it clear that trust-dns is returning NSEC records:

2017-11-17T22:21:58.121866886+00:00 INFO trust_dns_server::server::server_future:215 request: 10795 src: [2003:c4:bf23:b900:7c04:5f85:3ec0:5f31]:48766 type: Query op_code: Query dnssec: true name: _tcp.dev.terrax.net. type: A class: IN
2017-11-17T22:21:58.121908835+00:00 INFO trust_dns_server::authority::catalog:280 request: 10795 found authority: dev.terrax.net.
2017-11-17T22:21:58.121984360+00:00 INFO trust_dns_server::authority::catalog:303 request: 10795 supported_algs: 
2017-11-17T22:21:58.122041925+00:00 INFO trust_dns_server::authority::catalog:345 request: 10795 non-existent adding nsecs: 2
2017-11-17T22:21:58.122100628+00:00 INFO trust_dns_server::server::server_future:226 request: 10795 response_code: No Error answers: 0 name_servers: 4 additionals: 0
2017-11-17T22:21:58.122169023+00:00 INFO trust_dns_server::server::request_stream:115 request: 10795 sending message len: 461

This is the initial A lookup you said was undesirable from unbound. After implementing A/AAAA in the trust-dns resolver, I can understand why that might be the case, i.e. they may always lookup A first, and the prefer ipv6 only says to return AAAA if those are found.

But what's interesting is that unbound did get some NSEC's on that request. In the unbound logs, did it specify any issues with those records? This is the same query made via the dig's issued.

Can you explain the difference between the dig queries issued that succeed and the ones that failed? It looks like the first one fails, then the second succeeds. Am I reading that correctly? Specifically I see this sequence:

$ dig A _tcp.dev.terrax.net @dev.h.terrax.net +dnssec ### FAILS
...
darkspirit@darkspirit:~$ dig A _tcp.dev.terrax.net @dev.h.terrax.net +dnssec ### SUCCEEDS
...
darkspirit@darkspirit:~$ dig A _tcp.dev.terrax.net @dev.h.terrax.net +dnssec ### SUCCEEDS
...
darkspirit@darkspirit:~$ dig A _tcp.dev.terrax.net @dev.h.terrax.net +dnssec ### FAILS
...

This is strange...


I'll build a new compatibility test with trust-dns and dig to validate that locally. A badly constructed RR or packet will be annoying to track down without this.

@Darkspirit
Copy link
Contributor

Darkspirit commented Nov 19, 2017

I find this curious: In your unbound example in the first example this sequence makes it clear that trust-dns is returning NSEC records

In #286 (comment) Part B (the dig test)
trustdns also says non-existent adding nsecs: 2 (like for unbound's requests): dig shows an NSEC for dev.terrax.net.. So I assume this is correct. PowerDNS seems to do the same in #286 (comment).

But what's interesting is that unbound did get some NSEC's on that request. In the unbound logs, did it specify any issues with those records?

I don't see anything bad. There is validate(positive): sec_status_secure

This unbound log belongs to #286 (comment) Part A:

[1510957312] unbound[5576:0] debug: module config: "subnetcache validator iterator"
[1510957312] unbound[5576:0] notice: init module 0: subnet
[1510957312] unbound[5576:0] debug: subnet: option registered (8)
[1510957312] unbound[5576:0] notice: init module 1: validator
[1510957312] unbound[5576:0] notice: init module 2: iterator
[1510957312] unbound[5576:0] debug: target fetch policy for level 0 is 3
[1510957312] unbound[5576:0] debug: target fetch policy for level 1 is 2
[1510957312] unbound[5576:0] debug: target fetch policy for level 2 is 1
[1510957312] unbound[5576:0] debug: target fetch policy for level 3 is 0
[1510957312] unbound[5576:0] debug: target fetch policy for level 4 is 0
[1510957312] unbound[5576:0] debug: Reading root hints from /etc/unbound/root.hints
[1510957312] unbound[5576:0] info: DelegationPoint<.>: 13 names (0 missing), 26 addrs (0 result, 26 avail) parentNS
[1510957312] unbound[5576:0] debug: cache memory msg=66072 rrset=66072 infra=5224 val=66336 subnet=74488
[1510957312] unbound[5576:0] info: start of service (unbound 1.6.7).
[1510957317] unbound[5576:0] info: ::1 _443._tcp.dev.terrax.net. TLSA IN
[1510957317] unbound[5576:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_new
[1510957317] unbound[5576:0] info: subnet operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510957317] unbound[5576:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
[1510957317] unbound[5576:0] info: validator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510957317] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510957317] unbound[5576:0] info: resolving _443._tcp.dev.terrax.net. TLSA IN
[1510957317] unbound[5576:0] info: priming . IN NS
[1510957317] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510957317] unbound[5576:0] info: iterator operate: query . NS IN
[1510957317] unbound[5576:0] info: processQueryTargets: . NS IN
[1510957317] unbound[5576:0] info: sending query: . NS IN
[1510957317] unbound[5576:0] debug: sending to target: <.> 2001:500:a8::e#53
[1510957317] unbound[5576:0] debug: cache memory msg=66072 rrset=66072 infra=5521 val=66336 subnet=74488
[1510957317] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510957317] unbound[5576:0] info: iterator operate: query . NS IN
[1510957317] unbound[5576:0] info: response for . NS IN
[1510957317] unbound[5576:0] info: reply from <.> 2001:500:a8::e#53
[1510957317] unbound[5576:0] info: query response was ANSWER
[1510957317] unbound[5576:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
[1510957317] unbound[5576:0] info: validator operate: query . NS IN
[1510957317] unbound[5576:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_moddone
[1510957317] unbound[5576:0] info: subnet operate: query . NS IN
[1510957317] unbound[5576:0] info: priming successful for . NS IN
[1510957317] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
[1510957317] unbound[5576:0] info: iterator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510957317] unbound[5576:0] info: resolving (init part 2):  _443._tcp.dev.terrax.net. TLSA IN
[1510957317] unbound[5576:0] info: resolving (init part 3):  _443._tcp.dev.terrax.net. TLSA IN
[1510957317] unbound[5576:0] info: processQueryTargets: _443._tcp.dev.terrax.net. TLSA IN
[1510957317] unbound[5576:0] debug: removing 4 labels
[1510957317] unbound[5576:0] info: sending query: net. A IN
[1510957317] unbound[5576:0] debug: sending to target: <.> 2001:500:1::53#53
[1510957317] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510957317] unbound[5576:0] info: iterator operate: query . DNSKEY IN
[1510957317] unbound[5576:0] info: resolving . DNSKEY IN
[1510957317] unbound[5576:0] info: resolving (init part 2):  . DNSKEY IN
[1510957317] unbound[5576:0] info: resolving (init part 3):  . DNSKEY IN
[1510957317] unbound[5576:0] info: processQueryTargets: . DNSKEY IN
[1510957317] unbound[5576:0] info: sending query: . DNSKEY IN
[1510957317] unbound[5576:0] debug: sending to target: <.> 2001:500:2::c#53
[1510957317] unbound[5576:0] debug: cache memory msg=66929 rrset=73612 infra=6115 val=66336 subnet=74488
[1510957317] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510957317] unbound[5576:0] info: iterator operate: query . DNSKEY IN
[1510957317] unbound[5576:0] info: response for . DNSKEY IN
[1510957317] unbound[5576:0] info: reply from <.> 2001:500:2::c#53
[1510957317] unbound[5576:0] info: query response was ANSWER
[1510957317] unbound[5576:0] info: finishing processing for . DNSKEY IN
[1510957317] unbound[5576:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
[1510957317] unbound[5576:0] info: validator operate: query . DNSKEY IN
[1510957317] unbound[5576:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_moddone
[1510957317] unbound[5576:0] info: subnet operate: query . DNSKEY IN
[1510957317] unbound[5576:0] debug: cache memory msg=67162 rrset=74976 infra=6115 val=66336 subnet=74488
[1510957317] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510957317] unbound[5576:0] info: iterator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510957317] unbound[5576:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510957317] unbound[5576:0] info: reply from <.> 2001:500:1::53#53
[1510957317] unbound[5576:0] info: query response was REFERRAL
[1510957317] unbound[5576:0] info: processQueryTargets: _443._tcp.dev.terrax.net. TLSA IN
[1510957317] unbound[5576:0] debug: removing 3 labels
[1510957317] unbound[5576:0] info: sending query: terrax.net. A IN
[1510957317] unbound[5576:0] debug: sending to target: <net.> 2001:500:d937::30#53
[1510957317] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510957317] unbound[5576:0] info: iterator operate: query net. DNSKEY IN
[1510957317] unbound[5576:0] info: resolving net. DNSKEY IN
[1510957317] unbound[5576:0] info: resolving (init part 2):  net. DNSKEY IN
[1510957317] unbound[5576:0] info: resolving (init part 3):  net. DNSKEY IN
[1510957317] unbound[5576:0] info: processQueryTargets: net. DNSKEY IN
[1510957317] unbound[5576:0] info: sending query: net. DNSKEY IN
[1510957317] unbound[5576:0] debug: sending to target: <net.> 2001:503:a83e::2:30#53
[1510957317] unbound[5576:0] debug: cache memory msg=67162 rrset=82779 infra=6717 val=66336 subnet=74488
[1510957317] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510957317] unbound[5576:0] info: iterator operate: query net. DNSKEY IN
[1510957317] unbound[5576:0] info: response for net. DNSKEY IN
[1510957317] unbound[5576:0] info: reply from <net.> 2001:503:a83e::2:30#53
[1510957317] unbound[5576:0] info: query response was ANSWER
[1510957317] unbound[5576:0] info: finishing processing for net. DNSKEY IN
[1510957317] unbound[5576:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
[1510957317] unbound[5576:0] info: validator operate: query net. DNSKEY IN
[1510957317] unbound[5576:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_moddone
[1510957317] unbound[5576:0] info: subnet operate: query net. DNSKEY IN
[1510957317] unbound[5576:0] debug: cache memory msg=67399 rrset=83729 infra=6717 val=66336 subnet=74488
[1510957318] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510957318] unbound[5576:0] info: iterator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510957318] unbound[5576:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510957318] unbound[5576:0] info: reply from <net.> 2001:500:d937::30#53
[1510957318] unbound[5576:0] info: query response was REFERRAL
[1510957318] unbound[5576:0] info: processQueryTargets: _443._tcp.dev.terrax.net. TLSA IN
[1510957318] unbound[5576:0] info: new target gw2.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] info: new target gw1.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] debug: removing 2 labels
[1510957318] unbound[5576:0] info: sending query: dev.terrax.net. A IN
[1510957318] unbound[5576:0] debug: sending to target: <terrax.net.> 94.130.73.109#53
[1510957318] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510957318] unbound[5576:0] info: iterator operate: query gw2.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] info: resolving gw2.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] info: resolving (init part 2):  gw2.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] info: resolving (init part 3):  gw2.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] info: processQueryTargets: gw2.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] info: skipping target due to dependency cycle (harden-glue: no may fix some of the cycles) gw2.h.terrax.net. A IN
[1510957318] unbound[5576:0] info: new target gw1.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] debug: removing 1 labels
[1510957318] unbound[5576:0] info: sending query: h.terrax.net. A IN
[1510957318] unbound[5576:0] debug: sending to target: <terrax.net.> 94.130.73.109#53
[1510957318] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510957318] unbound[5576:0] info: iterator operate: query terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] info: resolving terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] info: resolving (init part 2):  terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] info: resolving (init part 3):  terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] info: processQueryTargets: terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] info: new target gw2.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] info: new target gw1.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] info: sending query: terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] debug: sending to target: <terrax.net.> 94.130.73.109#53
[1510957318] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510957318] unbound[5576:0] info: iterator operate: query gw1.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] info: resolving gw1.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] info: resolving (init part 2):  gw1.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] info: resolving (init part 3):  gw1.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] info: processQueryTargets: gw1.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] info: skipping target due to dependency cycle (harden-glue: no may fix some of the cycles) gw2.h.terrax.net. A IN
[1510957318] unbound[5576:0] info: skipping target due to dependency cycle (harden-glue: no may fix some of the cycles) gw1.h.terrax.net. A IN
[1510957318] unbound[5576:0] debug: removing 1 labels
[1510957318] unbound[5576:0] info: sending query: h.terrax.net. A IN
[1510957318] unbound[5576:0] debug: sending to target: <terrax.net.> 94.130.73.109#53
[1510957318] unbound[5576:0] debug: cache memory msg=67399 rrset=84944 infra=7025 val=66336 subnet=74488
[1510957318] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510957318] unbound[5576:0] info: iterator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510957318] unbound[5576:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510957318] unbound[5576:0] info: reply from <terrax.net.> 94.130.73.109#53
[1510957318] unbound[5576:0] info: query response was REFERRAL
[1510957318] unbound[5576:0] info: processQueryTargets: _443._tcp.dev.terrax.net. TLSA IN
[1510957318] unbound[5576:0] info: new target dev.h.terrax.net. A IN
[1510957318] unbound[5576:0] debug: removing 1 labels
[1510957318] unbound[5576:0] info: sending query: _tcp.dev.terrax.net. A IN
[1510957318] unbound[5576:0] debug: sending to target: <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510957318] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510957318] unbound[5576:0] info: iterator operate: query dev.terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] info: resolving dev.terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] info: resolving (init part 2):  dev.terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] info: resolving (init part 3):  dev.terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] info: processQueryTargets: dev.terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] info: new target dev.h.terrax.net. A IN
[1510957318] unbound[5576:0] info: sending query: dev.terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] debug: sending to target: <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510957318] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510957318] unbound[5576:0] info: iterator operate: query dev.h.terrax.net. A IN
[1510957318] unbound[5576:0] info: resolving dev.h.terrax.net. A IN
[1510957318] unbound[5576:0] info: resolving (init part 2):  dev.h.terrax.net. A IN
[1510957318] unbound[5576:0] info: resolving (init part 3):  dev.h.terrax.net. A IN
[1510957318] unbound[5576:0] info: processQueryTargets: dev.h.terrax.net. A IN
[1510957318] unbound[5576:0] info: new target gw2.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] info: new target gw1.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] debug: removing 1 labels
[1510957318] unbound[5576:0] info: sending query: h.terrax.net. A IN
[1510957318] unbound[5576:0] debug: sending to target: <terrax.net.> 94.130.76.133#53
[1510957318] unbound[5576:0] debug: cache memory msg=67399 rrset=86022 infra=7645 val=66336 subnet=74488
[1510957318] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510957318] unbound[5576:0] info: iterator operate: query gw1.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] info: response for gw1.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] info: reply from <terrax.net.> 94.130.73.109#53
[1510957318] unbound[5576:0] info: query response was nodata ANSWER
[1510957318] unbound[5576:0] info: processQueryTargets: gw1.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] info: sending query: gw1.h.terrax.net. A IN
[1510957318] unbound[5576:0] debug: sending to target: <terrax.net.> 94.130.76.133#53
[1510957318] unbound[5576:0] debug: cache memory msg=67669 rrset=86880 infra=7645 val=66336 subnet=74488
[1510957318] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510957318] unbound[5576:0] info: iterator operate: query gw2.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] info: response for gw2.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] info: reply from <terrax.net.> 94.130.73.109#53
[1510957318] unbound[5576:0] info: query response was nodata ANSWER
[1510957318] unbound[5576:0] info: processQueryTargets: gw2.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] info: sending query: gw2.h.terrax.net. A IN
[1510957318] unbound[5576:0] debug: sending to target: <terrax.net.> 94.130.76.133#53
[1510957318] unbound[5576:0] debug: cache memory msg=67669 rrset=86880 infra=7645 val=66336 subnet=74488
[1510957318] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510957318] unbound[5576:0] info: iterator operate: query terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] info: response for terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] info: reply from <terrax.net.> 94.130.73.109#53
[1510957318] unbound[5576:0] info: query response was ANSWER
[1510957318] unbound[5576:0] info: finishing processing for terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
[1510957318] unbound[5576:0] info: validator operate: query terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_moddone
[1510957318] unbound[5576:0] info: subnet operate: query terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] debug: cache memory msg=67913 rrset=87488 infra=7645 val=66336 subnet=74488
[1510957318] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510957318] unbound[5576:0] info: iterator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510957318] unbound[5576:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510957318] unbound[5576:0] info: reply from <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510957318] unbound[5576:0] info: query response was nodata ANSWER
[1510957318] unbound[5576:0] info: processQueryTargets: _443._tcp.dev.terrax.net. TLSA IN
[1510957318] unbound[5576:0] info: sending query: _443._tcp.dev.terrax.net. A IN
[1510957318] unbound[5576:0] debug: sending to target: <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510957318] unbound[5576:0] debug: cache memory msg=68190 rrset=88367 infra=7645 val=66336 subnet=74488
[1510957318] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510957318] unbound[5576:0] info: iterator operate: query dev.terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] info: response for dev.terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] info: reply from <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510957318] unbound[5576:0] info: query response was ANSWER
[1510957318] unbound[5576:0] info: finishing processing for dev.terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
[1510957318] unbound[5576:0] info: validator operate: query dev.terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_moddone
[1510957318] unbound[5576:0] info: subnet operate: query dev.terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] debug: cache memory msg=68462 rrset=89013 infra=7645 val=66336 subnet=74488
[1510957318] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510957318] unbound[5576:0] info: iterator operate: query dev.h.terrax.net. A IN
[1510957318] unbound[5576:0] info: response for dev.h.terrax.net. A IN
[1510957318] unbound[5576:0] info: reply from <terrax.net.> 94.130.76.133#53
[1510957318] unbound[5576:0] info: query response was nodata ANSWER
[1510957318] unbound[5576:0] info: processQueryTargets: dev.h.terrax.net. A IN
[1510957318] unbound[5576:0] info: sending query: dev.h.terrax.net. A IN
[1510957318] unbound[5576:0] debug: sending to target: <terrax.net.> 94.130.73.109#53
[1510957318] unbound[5576:0] debug: cache memory msg=68462 rrset=89013 infra=7645 val=66336 subnet=74488
[1510957318] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510957318] unbound[5576:0] info: iterator operate: query gw1.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] info: response for gw1.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] info: reply from <terrax.net.> 94.130.76.133#53
[1510957318] unbound[5576:0] info: query response was ANSWER
[1510957318] unbound[5576:0] info: processQueryTargets: gw1.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] info: sending query: gw1.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] debug: sending to target: <terrax.net.> 94.130.73.109#53
[1510957318] unbound[5576:0] debug: cache memory msg=68712 rrset=89165 infra=7645 val=66336 subnet=74488
[1510957318] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510957318] unbound[5576:0] info: iterator operate: query gw2.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] info: response for gw2.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] info: reply from <terrax.net.> 94.130.76.133#53
[1510957318] unbound[5576:0] info: query response was ANSWER
[1510957318] unbound[5576:0] info: processQueryTargets: gw2.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] info: sending query: gw2.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] debug: sending to target: <terrax.net.> 94.130.73.109#53
[1510957318] unbound[5576:0] debug: cache memory msg=68962 rrset=89317 infra=7645 val=66336 subnet=74488
[1510957318] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510957318] unbound[5576:0] info: iterator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510957318] unbound[5576:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510957318] unbound[5576:0] info: reply from <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510957318] unbound[5576:0] info: query response was nodata ANSWER
[1510957318] unbound[5576:0] info: processQueryTargets: _443._tcp.dev.terrax.net. TLSA IN
[1510957318] unbound[5576:0] info: sending query: _443._tcp.dev.terrax.net. TLSA IN
[1510957318] unbound[5576:0] debug: sending to target: <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510957318] unbound[5576:0] debug: cache memory msg=69244 rrset=89745 infra=7645 val=66336 subnet=74488
[1510957318] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510957318] unbound[5576:0] info: iterator operate: query gw1.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] info: response for gw1.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] info: reply from <terrax.net.> 94.130.73.109#53
[1510957318] unbound[5576:0] info: query response was ANSWER
[1510957318] unbound[5576:0] info: finishing processing for gw1.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
[1510957318] unbound[5576:0] info: validator operate: query gw1.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_moddone
[1510957318] unbound[5576:0] info: subnet operate: query gw1.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] debug: cache memory msg=69494 rrset=90149 infra=7645 val=66336 subnet=74488
[1510957318] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510957318] unbound[5576:0] info: iterator operate: query dev.h.terrax.net. A IN
[1510957318] unbound[5576:0] info: response for dev.h.terrax.net. A IN
[1510957318] unbound[5576:0] info: reply from <terrax.net.> 94.130.73.109#53
[1510957318] unbound[5576:0] info: query response was nodata ANSWER
[1510957318] unbound[5576:0] info: finishing processing for dev.h.terrax.net. A IN
[1510957318] unbound[5576:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
[1510957318] unbound[5576:0] info: validator operate: query dev.h.terrax.net. A IN
[1510957318] unbound[5576:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_moddone
[1510957318] unbound[5576:0] info: subnet operate: query dev.h.terrax.net. A IN
[1510957318] unbound[5576:0] debug: cache memory msg=69768 rrset=90563 infra=7645 val=66336 subnet=74488
[1510957318] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510957318] unbound[5576:0] info: iterator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510957318] unbound[5576:0] info: response for _443._tcp.dev.terrax.net. TLSA IN
[1510957318] unbound[5576:0] info: reply from <dev.terrax.net.> 2a01:4f8:c0c:2c12::50#53
[1510957318] unbound[5576:0] info: query response was ANSWER
[1510957318] unbound[5576:0] info: finishing processing for _443._tcp.dev.terrax.net. TLSA IN
[1510957318] unbound[5576:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
[1510957318] unbound[5576:0] info: validator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510957318] unbound[5576:0] info: prime trust anchor
[1510957318] unbound[5576:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_pass
[1510957318] unbound[5576:0] info: subnet operate: query . DNSKEY IN
[1510957318] unbound[5576:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
[1510957318] unbound[5576:0] info: validator operate: query . DNSKEY IN
[1510957318] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510957318] unbound[5576:0] info: resolving . DNSKEY IN
[1510957318] unbound[5576:0] info: finishing processing for . DNSKEY IN
[1510957318] unbound[5576:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
[1510957318] unbound[5576:0] info: validator operate: query . DNSKEY IN
[1510957318] unbound[5576:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1510957318] unbound[5576:0] info: subnet operate: query . DNSKEY IN
[1510957318] unbound[5576:0] info: validate keys with anchor(DS): sec_status_secure
[1510957318] unbound[5576:0] info: Successfully primed trust anchor . DNSKEY IN
[1510957318] unbound[5576:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_pass
[1510957318] unbound[5576:0] info: subnet operate: query _ta-4a5c-4f66. NULL IN
[1510957318] unbound[5576:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
[1510957318] unbound[5576:0] info: validator operate: query _ta-4a5c-4f66. NULL IN
[1510957318] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510957318] unbound[5576:0] info: resolving _ta-4a5c-4f66. NULL IN
[1510957318] unbound[5576:0] info: resolving (init part 2):  _ta-4a5c-4f66. NULL IN
[1510957318] unbound[5576:0] info: resolving (init part 3):  _ta-4a5c-4f66. NULL IN
[1510957318] unbound[5576:0] info: processQueryTargets: _ta-4a5c-4f66. NULL IN
[1510957318] unbound[5576:0] info: sending query: _ta-4a5c-4f66. A IN
[1510957318] unbound[5576:0] debug: sending to target: <.> 2001:503:c27::2:30#53
[1510957318] unbound[5576:0] debug: validator[module 1] operate: extstate:module_wait_subquery event:module_event_pass
[1510957318] unbound[5576:0] info: validator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510957318] unbound[5576:0] info: validated DS net. DS IN
[1510957318] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510957318] unbound[5576:0] info: iterator operate: query . DNSKEY IN
[1510957318] unbound[5576:0] info: resolving . DNSKEY IN
[1510957318] unbound[5576:0] info: finishing processing for . DNSKEY IN
[1510957318] unbound[5576:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
[1510957318] unbound[5576:0] info: validator operate: query . DNSKEY IN
[1510957318] unbound[5576:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_moddone
[1510957318] unbound[5576:0] info: subnet operate: query . DNSKEY IN
[1510957318] unbound[5576:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_pass
[1510957318] unbound[5576:0] info: subnet operate: query net. DNSKEY IN
[1510957318] unbound[5576:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
[1510957318] unbound[5576:0] info: validator operate: query net. DNSKEY IN
[1510957318] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510957318] unbound[5576:0] info: resolving net. DNSKEY IN
[1510957318] unbound[5576:0] info: finishing processing for net. DNSKEY IN
[1510957318] unbound[5576:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
[1510957318] unbound[5576:0] info: validator operate: query net. DNSKEY IN
[1510957318] unbound[5576:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1510957318] unbound[5576:0] info: subnet operate: query net. DNSKEY IN
[1510957318] unbound[5576:0] info: validated DNSKEY net. DNSKEY IN
[1510957318] unbound[5576:0] debug: validator[module 1] operate: extstate:module_wait_subquery event:module_event_pass
[1510957318] unbound[5576:0] info: validator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510957318] unbound[5576:0] info: validated DS terrax.net. DS IN
[1510957318] unbound[5576:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_pass
[1510957318] unbound[5576:0] info: subnet operate: query terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
[1510957318] unbound[5576:0] info: validator operate: query terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510957318] unbound[5576:0] info: resolving terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] info: finishing processing for terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
[1510957318] unbound[5576:0] info: validator operate: query terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1510957318] unbound[5576:0] info: subnet operate: query terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] info: validated DNSKEY terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] debug: validator[module 1] operate: extstate:module_wait_subquery event:module_event_pass
[1510957318] unbound[5576:0] info: validator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510957318] unbound[5576:0] info: validated DS dev.terrax.net. DS IN
[1510957318] unbound[5576:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_pass
[1510957318] unbound[5576:0] info: subnet operate: query dev.terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
[1510957318] unbound[5576:0] info: validator operate: query dev.terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1510957318] unbound[5576:0] info: resolving dev.terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] info: finishing processing for dev.terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
[1510957318] unbound[5576:0] info: validator operate: query dev.terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1510957318] unbound[5576:0] info: subnet operate: query dev.terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] info: validated DNSKEY dev.terrax.net. DNSKEY IN
[1510957318] unbound[5576:0] debug: validator[module 1] operate: extstate:module_wait_subquery event:module_event_pass
[1510957318] unbound[5576:0] info: validator operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510957318] unbound[5576:0] info: validate(positive): sec_status_secure
[1510957318] unbound[5576:0] info: validation success _443._tcp.dev.terrax.net. TLSA IN
[1510957318] unbound[5576:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1510957318] unbound[5576:0] info: subnet operate: query _443._tcp.dev.terrax.net. TLSA IN
[1510957318] unbound[5576:0] debug: cache memory msg=70050 rrset=91030 infra=7942 val=69876 subnet=74488
[1510957318] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510957318] unbound[5576:0] info: iterator operate: query gw2.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] info: response for gw2.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] info: reply from <terrax.net.> 94.130.73.109#53
[1510957318] unbound[5576:0] info: query response was ANSWER
[1510957318] unbound[5576:0] info: finishing processing for gw2.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
[1510957318] unbound[5576:0] info: validator operate: query gw2.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_moddone
[1510957318] unbound[5576:0] info: subnet operate: query gw2.h.terrax.net. AAAA IN
[1510957318] unbound[5576:0] debug: cache memory msg=70300 rrset=91434 infra=7942 val=69876 subnet=74488
[1510957318] unbound[5576:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1510957318] unbound[5576:0] info: iterator operate: query _ta-4a5c-4f66. NULL IN
[1510957318] unbound[5576:0] info: response for _ta-4a5c-4f66. NULL IN
[1510957318] unbound[5576:0] info: reply from <.> 2001:503:c27::2:30#53
[1510957318] unbound[5576:0] info: query response was NXDOMAIN ANSWER
[1510957318] unbound[5576:0] info: finishing processing for _ta-4a5c-4f66. NULL IN
[1510957318] unbound[5576:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
[1510957318] unbound[5576:0] info: validator operate: query _ta-4a5c-4f66. NULL IN
[1510957318] unbound[5576:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1510957318] unbound[5576:0] info: subnet operate: query _ta-4a5c-4f66. NULL IN
[1510957318] unbound[5576:0] debug: cache memory msg=70571 rrset=92552 infra=7942 val=69876 subnet=74488
[1510957323] unbound[5576:0] info: service stopped (unbound 1.6.7).
[1510957323] unbound[5576:0] info: server stats for thread 0: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting
[1510957323] unbound[5576:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
[1510957323] unbound[5576:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 1 recursion replies sent, 0 replies dropped, 0 states jostled out
[1510957323] unbound[5576:0] info: average recursion processing time 0.420119 sec
[1510957323] unbound[5576:0] info: histogram of recursion processing times
[1510957323] unbound[5576:0] info: [25%]=0 median[50%]=0 [75%]=0
[1510957323] unbound[5576:0] info: lower(secs) upper(secs) recursions
[1510957323] unbound[5576:0] info:    0.262144    0.524288 1
[1510957323] unbound[5576:0] debug: cache memory msg=66072 rrset=66072 infra=7942 val=69876 subnet=74488
[1510957323] unbound[5576:0] debug: switching log to stderr

Can you explain the difference between the dig queries issued that succeed and the ones that failed? It looks like the first one fails, then the second succeeds. Am I reading that correctly? Specifically I see this sequence:

I just executed the same dig command multiple times, behind one another. Some results were good, some were bad.
good:

;; MSG SIZE  rcvd: 461

bad:

;; Got bad packet: FORMERR
461 bytes

Edit: dig AXFR _tcp.dev.terrax.net @dev.h.terrax.net +tcp can also have bad packets

= The same here: Some results were good, some were bad. So UDP (EDNS?) shouldn't be the cause(?).
They can also be good and bad:
dig AXFR lol-this-doesnt-exist.dev.terrax.net @dev.h.terrax.net +tcp
dig AXFR dev.terrax.net @dev.h.terrax.net +tcp
dig ANY dev.terrax.net @dev.h.terrax.net +tcp

@Darkspirit
Copy link
Contributor

Darkspirit commented Nov 19, 2017

Maybe I found something. (Or it's something completely different.)

dig ANY dev.terrax.net @dev.h.terrax.net +tcp can be sometimes good, sometimes bad.

dig via unbound

$ dig ANY dev.terrax.net

; <<>> DiG 9.10.6-Debian <<>> ANY dev.terrax.net
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 64837
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 4096
;; QUESTION SECTION:
;dev.terrax.net.                        IN      ANY

;; Query time: 0 msec
;; SERVER: ::1#53(::1)
;; WHEN: Sun Nov 19 03:06:54 CET 2017
;; MSG SIZE  rcvd: 43

unbound

[1511057273] unbound[29341:0] info: resolving dev.terrax.net. ANY IN
[1511057273] unbound[29341:0] info: finishing processing for dev.terrax.net. ANY IN
[1511057273] unbound[29341:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
[1511057273] unbound[29341:0] info: validator operate: query dev.terrax.net. ANY IN
[1511057273] unbound[29341:0] debug: rrset failed to verify due to a lack of signatures
[1511057273] unbound[29341:0] info: validator: response has failed ANSWER rrset: dev.terrax.net. NS IN
[1511057273] unbound[29341:0] info: Validate: message contains bad rrsets
[1511057273] unbound[29341:0] debug: iterator[module 2] operate: extstate:module_finished event:module_event_pass

@bluejekyll
Copy link
Member Author

bluejekyll commented Nov 19, 2017

In #286 (comment) Part B (the dig test)
trustdns also says non-existent adding nsecs: 2 (like for unbound's requests): dig shows an NSEC for dev.terrax.net.. So I assume this is correct. PowerDNS seems to do the same in #286 (comment).

Yup, this is what I expect to see. The 2 nsec records should be 1 NSEC and 1 RRSIG for it's signature. What's strange is that you get success and failure, same number of bytes.

Maybe I found something.

Well, it does show that unbound is also getting something from trust-dns it's not expecting. I'm trying to reproduce.


I've finally gotten this reproduced. I should be able to track this down now.

@bluejekyll
Copy link
Member Author

bluejekyll commented Nov 19, 2017

Ok, the only difference I've found so far is the order of the DAU and DHU fields supported algorithms. I'm going to review the RFC, and see if there's a defined order on these fields, and also order them consistently to test...


I've tracked down the issue. It's not related to the DAU/DHU fields. It looks like it's in the name servers section. Possibly a bug related to the interaction of canonical name form vs. non-canonical as it relates to label compression.

@bluejekyll
Copy link
Member Author

bluejekyll commented Nov 19, 2017

Ok, I finally tracked this down, for posterity, it's the NSEC record encoding:

NSEC: NSEC {
    next_domain_name: Name {
        is_fqdn: true,
        labels: [
            "_443",
            "_tcp",
            "example",
            "com"
        ]
    },
    type_bit_maps: [
        CAA,
        NS,
        SOA,
        MX,
        TXT,
        AAAA,
        DNSSEC(
            DNSKEY
        )
    ]
}
NSEC BYTES: 04 5f 34 34 33 04 5f 74 63 70 07 65 78 61 6d 70 6c 65 03 63 6f 6d 00 01 01 40 00 07 22 01 80 08 00 00 80
NSEC STRS : .  .  4  4  3  .  .  t  c  p  .  e  x  a  m  p  l  e  .  c  o  m  .  .  .  .  .  .  .  .  .  .  .  .  .

vs.

NSEC: NSEC {
    next_domain_name: Name {
        is_fqdn: true,
        labels: [
            "_443",
            "_tcp",
            "example",
            "com"
        ]
    },
    type_bit_maps: [
        NS,
        SOA,
        MX,
        TXT,
        AAAA,
        DNSSEC(
            DNSKEY
        ),
        CAA
    ]
}
NSEC BYTES: 04 5f 34 34 33 04 5f 74 63 70 07 65 78 61 6d 70 6c 65 03 63 6f 6d 00 00 07 22 01 80 08 00 00 80 01 01 40
NSEC STRS : .  .  4  4  3  .  .  t  c  p  .  e  x  a  m  p  l  e  .  c  o  m  .  .  .  .  .  .  .  .  .  .  .  .  .

trust-dns has no problem parsing these differences correctly. But there must be something about the order effecting some of the other parsers out there. It's nice to finally have tracked this down where this is coming from. I'm working on a fix.


Ok, I have a fix locally, but I need to cleanup a ton of debug code. It's too bad that other systems expect a stable order on this stuff, but not unexpected. The implementation details are here: https://tools.ietf.org/html/rfc4034#section-4.1.2

Specifically: Blocks are present in the NSEC RR RDATA in increasing numerical order.

The way that I'm calculating that is not necessarily the most efficient, by using a HashMap such that order doesn't matter. Switching to a BTreeMap fixes the issue, the critical section is here:

https://github.com/bluejekyll/trust-dns/blob/9b3d1cee86b79e1432a14298ac54648125351f6f/proto/src/rr/dnssec/rdata/nsec3.rs#L417

and it's subsequently encoded here:

https://github.com/bluejekyll/trust-dns/blob/9b3d1cee86b79e1432a14298ac54648125351f6f/proto/src/rr/dnssec/rdata/nsec3.rs#L439-L446

I won't have time to clean this up right now. I'll try and get something published later today.

@bluejekyll
Copy link
Member Author

Thanks for your patience and help in resolving this, @Darkspirit!

@bluejekyll
Copy link
Member Author

Ok, @Darkspirit, this recent change should fix the issue we were seeing (Got delayed on getting this in).

@Darkspirit
Copy link
Contributor

All issues are fixed. Thank you! 🎉

@bluejekyll
Copy link
Member Author

Great news! I’ll merge into master after double checking the code a Little’s later.

@bluejekyll bluejekyll merged commit c916255 into master Nov 21, 2017
@bluejekyll bluejekyll deleted the fix_nxdomain branch March 30, 2018 17:16
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

[Server] ResponseCode for NSEC on non-existent RecordType should be NoError
2 participants