Re: What does "deleted from unreachable cache" mean?

[Cathy Almond]

On 19/07/12 00:49, Peter Olsson wrote:
> Hello!
>
> After my latest bind upgrade our slave server started
> occasionally writing these messages to the log:
>
> master 2a02:xxxx:xxxx:xxxx::2#53 (source ::#0) deleted from unreachable cache
>
> master 62.xxx.xxx.2#53 (source 0.0.0.0#0) deleted from unreachable cache
>
> DNS seems to work fine anyway, and all zonefiles in the slave
> seem to update like they should, so everything seems ok. But I
> would like to be certain that there is nothing to worry about,
> so I wonder what these messages mean. (I didn't find anything
> interesting in the list archives or in Google.)
>
> Both master and slave are FreeBSD, running port bind97-9.7.6.1.
>
> Thanks!
>

There'll be a new KB FAQ published on this early next week
(https://kb.isc.org/article/AA-00765). Preview is that it will say
something like this:

What does named log message "deleted from unreachable cache" mean?

An example of the messages being logged is:

02-Aug-2012 07:58:20.601 general: info: master 192.0.2.4#53 (source
192.0.2.8#0) deleted from unreachable cache

BIND maintains a cache of unreachable masters to which it refers when
handling a zone refresh. If a zone refresh fails with a specific master
(either during the query for the SOA or after querying and while
attempting a subsequent zone transfer), then this master is cached as
'unreachable' for 10 minutes.

As of versions 9.6-ESV-R6, 9.7.5, 9.8.2 and 9.9.0 onwards, the change
below implements an earlier removal of a master server from the
unreachable cache if a notify is received from it.

Note that receipt of a notify (which is a UDP packet travelling from
master to slave) doesn't guarantee that the master will be reachable
from the slave, but it does ensure quicker recovery in the situation
where a master was temporarily unavailable, for example for a reboot.

This is the relevant info from the Release Notes:

Master servers that had previously been marked as unreachable because of
failed zone transfer attempts will now be removed from the "unreachable"
list (i.e. considered reachable again) if the slave receives a NOTIFY
message from them. [RT #25960]

In the CHANGES file, it is described thus:
3204. [bug] When a master server that has been marked as
unreachable sends a NOTIFY, mark it reachable again. [RT #25960]

[Peter Olsson]

Excellent information, thanks!
However, it is worrying that the master sometimes is unreachable.
Is there some way I can make the slave server log, with timestamp,
what zone it was trying to refresh when it failed?

Thanks!

--
Peter Olsson p...@leissner.se

[Michael Hoskins (michoski)]

-----Original Message-----

From: Peter Olsson <p...@leissner.se>
Date: Thursday, August 2, 2012 10:25 AM
To: Cathy Almond <cat...@isc.org>
Cc: "bind-...@lists.isc.org" <bind-...@lists.isc.org>
Subject: Re: What does "deleted from unreachable cache" mean?

>Excellent information, thanks!

Agreed. I really appreciate the effort ISC has put into the KB.

>However, it is worrying that the master sometimes is unreachable.
>Is there some way I can make the slave server log, with timestamp,
>what zone it was trying to refresh when it failed?

Not sure if you've already tried, but do you have xfer logging enabled?

logging {

<snip>

channel audit_log {

file "/var/named/bind/named.log";
severity debug;
print-time yes;

};


<snip>

category xfer-in { audit_log; };
category xfer-out { audit_log; };
category notify { audit_log; };
category network { audit_log; };
category update { audit_log; };
// might want this to debug...
//category queries { audit_log; };

};

[Cathy Almond]

The point at which the 'unreachable' entry is cached, is logged under
category 'xfer-in' - although it doesn't actually tell you that it's
caching it. Look for messages containing text "failed to connect" or
"could not refresh".

Once the master is already in the unreachable cache, if the refresh code
checks and finds it there, then there are several messages (different
circumstances) that explain why a transfer isn't going to happen right
then - and these ones all incorporate the text "unreachable (cached)".

But yesterday, I dug further into the code that's reporting "deleted
from unreachable cache" and I'm sorry that I have to report that there
is a bug there - the code is matching the source of the notify
correctly, but may also mistakenly include and report on older cache
entries that are already "deleted".

We'll fix this. It's being tracked as bug ticket #30501.

But if you have no evidence of ongoing problems (looking at what's
logged in category xfer-in - per my suggestions above) then you can
safely ignore these messages. There will have been an issue at some
point in the past, but which is now cleared.

Apologies.

[Peter Olsson]

I will try logging, but it's good to know that it might not
be a big problem.

[J. Thomsen]

Due to a little too aggressive firewall configuration we had a lot of

"deleted from unreachable cache"

messsages in the log, but absolutely no messages logged for the reason for entering the host
into the cache, which is much more useful in tracking down the problem.

It appears to me, that there is an asymmetry here, which should be fixed.

Our logging is configured as

category queries { queryfile; };
category dnssec { dnssecfile; };
category security { securityfile; };
category notify { queryfile; };
category xfer-in { queryfile; };
category general { queryfile; };
category client { debugfile; };
category unmatched { debugfile; };
category resolver { queryfile; };
category default { queryfile; };


- Jørgen Thomsen