TTL 0: dropped msg from cache

Unbound
1

I’m using “local_unbound” on FreeBSD 10.

I have dnscrypt running on 127.0.0.2, and this seems to work fine, but I noticed my local queries which are forwarded to the local router running Asus Merlin firmware are getting giving me no answer and with verbose 5 I was able to see this error:

“TTL 0: dropped msg from cache”

Querying the server (router) directly gives a proper answer, and it is true that the TTL is “0”, is this the expected behavior?
I don’t think I have a way to change the TTL for local domain under Asus Merlin, but I could look into it, still even if this is the expected behavior is this, is there anything I can change in the config to workaround it?

thanks

Mike

2

I'm using "local_unbound" on FreeBSD 10.

I have dnscrypt running on 127.0.0.2, and this seems to work fine, but I
noticed my local queries which are forwarded to the local router running
Asus Merlin firmware are getting giving me no answer and with verbose 5 I
was able to see this error:

"TTL 0: dropped msg from cache"

Querying the server (router) directly gives a proper answer, and it is true
that the TTL is "0", is this the expected behavior?

I've personally never seen a router do that (by default), but if it really
does that than could explains why Unbound might have a problem with it.

Because 0 is an extremely low value.

I don't think I have a way to change the TTL for local domain under Asus
Merlin, but I could look into it, still even if this is the expected
behavior is this, is there anything I can change in the config to
workaround it?

Have you tried setting cache-min-ttl in Unbound to something higher than the
default 0 ? Maybe that resolves the problem.

3

Yeah it is indeed a odd issue, I’m reporting it to the dev see if its a bug.

I tried to set cache-min-ttl to 1 but I still don’t get an ip using host or drill, and see this in the log:

;; ANSWER SECTION:
yoda.geek.local. 1 IN A 10.10.50.50

;; AUTHORITY SECTION:

;; ADDITIONAL SECTION:

;; Query time: 0 msec
;; WHEN: Thu Jan 1 01:00:00 1970
;; MSG SIZE rcvd: 49

[1394727382] unbound[10696:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
[1394727382] unbound[10696:0] info: query response was ANSWER
[1394727382] unbound[10696:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE
[1394727382] unbound[10696:0] info: finishing processing for yoda.geek.local. A IN
[1394727382] unbound[10696:0] debug: mesh_run: iterator module exit state is module_finished
[1394727382] unbound[10696:0] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1394727382] unbound[10696:0] info: validator operate: query yoda.geek.local. A IN
[1394727382] unbound[10696:0] debug: validator: nextmodule returned
[1394727382] unbound[10696:0] debug: val handle processing q with state VAL_INIT_STATE
[1394727382] unbound[10696:0] debug: validator classification positive
[1394727382] unbound[10696:0] info: no signer, using yoda.geek.local. TYPE0 CLASS0
[1394727382] unbound[10696:0] debug: val handle processing q with state VAL_FINISHED_STATE
[1394727382] unbound[10696:0] debug: mesh_run: validator module exit state is module_finished
[1394727382] unbound[10696:0] debug: query took 0.002806 sec
[1394727382] unbound[10696:0] info: mesh_run: end 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 190 recursion replies sent, 0 replies dropped, 0 states jostled out
[1394727382] unbound[10696:0] info: average recursion processing time 0.159627 sec
[1394727382] unbound[10696:0] info: histogram of recursion processing times
[1394727382] unbound[10696:0] info: [25%]=0.0868352 median[50%]=0.117965 [75%]=0.214897
[1394727382] unbound[10696:0] info: lower(secs) upper(secs) recursions
[1394727382] unbound[10696:0] info: 0.001024 0.002048 8
[1394727382] unbound[10696:0] info: 0.002048 0.004096 7
[1394727382] unbound[10696:0] info: 0.065536 0.131072 100
[1394727382] unbound[10696:0] info: 0.131072 0.262144 43
[1394727382] unbound[10696:0] info: 0.262144 0.524288 27
[1394727382] unbound[10696:0] info: 0.524288 1.000000 4
[1394727382] unbound[10696:0] info: 1.000000 2.000000 1
[1394727382] unbound[10696:0] debug: cache memory msg=143211 rrset=189624 infra=3093 val=86798
[1394727382] unbound[10696:0] debug: svcd callbacks end
[1394727382] unbound[10696:0] debug: close of port 21439
[1394727382] unbound[10696:0] debug: close fd 10

4

Any TTL < 60 seconds is probably going to be a problem at some point.
We've had to force that in our app on occasion to deal with "too clever
sysadmin syndrome".

John

5

Sorry, when I said 1 I mean 1mins (60 secs), but I also just changed to 120
and get the same in the log!

6

Yeah it is indeed a odd issue, I'm reporting it to the dev see if its a bug.

I tried to set cache-min-ttl to 1 but I still don't get an ip using host or

Well, 1 second is still pretty low, but it might work.

drill, and see this in the log:

First of all, pro tip:

use dig, not host or drill.

dig @unbound-ip-address yoga.geek.local. A

And for dnssec validated data:

dig @unbound-ip-address +dnssec labs.nic.cz A

;; ANSWER SECTION:
yoda.geek.local. 1 IN A 10.10.50.50

;; AUTHORITY SECTION:

;; ADDITIONAL SECTION:

;; Query time: 0 msec
;; WHEN: Thu Jan 1 01:00:00 1970
;; MSG SIZE rcvd: 49

Second, that time/date above looks funny.

I hope this isn't the date/time on your Unbound server, because DNSSEC-validation will fail.

Third, I don't see a validation error below, but have you tried adding:

domain-insecure: "local"

in your unbound.conf ?

7

I tried “domain-insecure: “local””

And this seems to make it work

% drill +dnssec @127.0.0.1 yoda.geek.local. A
;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 31171
;; flags: qr rd ra ; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0
;; QUESTION SECTION:
;; yoda.geek.local. IN A

;; ANSWER SECTION:
yoda.geek.local. 39 IN A 10.10.50.50

;; AUTHORITY SECTION:

;; ADDITIONAL SECTION:

;; Query time: 0 msec
;; SERVER: 127.0.0.1
;; WHEN: Thu Mar 13 18:43:54 2014
;; MSG SIZE rcvd: 49

% drill -D @127.0.0.1 yoda.geek.local. A
;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 49043
;; flags: qr rd ra ; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0
;; QUESTION SECTION:
;; yoda.geek.local. IN A

;; ANSWER SECTION:
yoda.geek.local. 36 IN A 10.10.50.50

;; AUTHORITY SECTION:

;; ADDITIONAL SECTION:

;; Query time: 0 msec
;; EDNS: version 0; flags: do ; udp: 4096
;; SERVER: 127.0.0.1
;; WHEN: Thu Mar 13 18:43:57 2014
;; MSG SIZE rcvd: 60

So that is indeed odd, If i do this:

rill @127.0.0.1 yoda.geek.local. A
;; ->>HEADER<<- opcode: QUERY, rcode: SERVFAIL, id: 52645
;; flags: qr rd ra ; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0
;; QUESTION SECTION:
;; yoda.geek.local. IN A

;; ANSWER SECTION:

;; AUTHORITY SECTION:

;; ADDITIONAL SECTION:

;; Query time: 374 msec
;; SERVER: 127.0.0.1
;; WHEN: Thu Mar 13 18:40:58 2014

So its failing dnsec validation but the log doens’t show it?