Bug 1756201

+++ This bug was initially created as a clone of Bug #1680028 +++


we are seeing this strange status  " resolver priming query complete"


[root@ns-infr ~]# uname -r
3.10.0-1062.1.2.el7.x86_64

[root@ns-infr ~]# cat /etc/redhat-release
Red Hat Enterprise Linux Server release 7.7 (Maipo)

[root@ns-infr ~]# systemctl status named -l
● named.service - Berkeley Internet Name Domain (DNS)
   Loaded: loaded (/usr/lib/systemd/system/named.service; enabled; vendor preset: disabled)
   Active: active (running) since Thu 2019-09-26 08:28:19 UTC; 3min 22s ago
  Process: 1299 ExecStart=/usr/sbin/named -u named -c ${NAMEDCONF} $OPTIONS (code=exited, status=0/SUCCESS)
  Process: 1283 ExecStartPre=/bin/bash -c if [ ! "$DISABLE_ZONE_CHECKING" == "yes" ]; then /usr/sbin/named-checkconf -z "$NAMEDCONF"; else echo "Checking of zone files is disabled"; fi (code=exited, status=0/SUCCESS)
 Main PID: 1308 (named)
   CGroup: /system.slice/named.service
           └─1308 /usr/sbin/named -u named -c /etc/named.conf

Sep 26 08:30:56 ns-infr.mitreap.org named[1308]: resolver priming query complete
Sep 26 08:31:07 ns-infr.mitreap.org named[1308]: resolver priming query complete
Sep 26 08:31:08 ns-infr.mitreap.org named[1308]: resolver priming query complete
Sep 26 08:31:13 ns-infr.mitreap.org named[1308]: resolver priming query complete
Sep 26 08:31:17 ns-infr.mitreap.org named[1308]: resolver priming query complete
Sep 26 08:31:19 ns-infr.mitreap.org named[1308]: resolver priming query complete
Sep 26 08:31:34 ns-infr.mitreap.org named[1308]: resolver priming query complete
Sep 26 08:31:38 ns-infr.mitreap.org named[1308]: resolver priming query complete
Sep 26 08:31:39 ns-infr.mitreap.org named[1308]: resolver priming query complete
Sep 26 08:31:40 ns-infr.mitreap.org named[1308]: resolver priming query complete

Description of problem:
Named seems to log
  named[XXXX]: resolver priming query complete
for almost every name lookup, or so it seems.

Version-Release number of selected component (if applicable):
bind-9.11.5-2.P1.fc29.x86_64

How reproducible:
Always

Steps to Reproduce:
1. configure and run a local recursive caching resolver

Actual results:
Lots of root priming messages in the logs

Expected results:
Very few of those, if any 

Additional info:
I run a recursive caching server, currently forward first to OpenDNS, and have these hints in named.conf:

zone "." IN {
        type hint;
        file "named.ca";
};

Just compared the named.ca file to the output of a dig query for the root servers and they are the same (except for the comments in header/footer)

What am I missing?  Attaching my (sanitized) named.conf.

--- Additional comment from Henrique Martins on 2019-03-23 14:59:33 UTC ---

Explanation of this behaviour here:
  https://kb.isc.org/docs/aa-01537.

Another ISC page:
  https://kb.isc.org/docs/aa-01309
claims:
  Fixed in 9.12.0, 9.11.3, 9.10.7 and 9.9.12, bug RT #45241 could cause named to send unnecessary and frequent priming queries.
However, I now have
  bind-9.11.5-4.P4.fc29.x86_64
and I'm still getting lots of messages logged.

Can be eliminated by querying all root servers for -tA and -tAAAA (or -tANY). I've added that to a 30m crontab for now.

--- Additional comment from Petr Menšík on 2019-09-11 11:02:31 UTC ---

Hi Henrique,

sorry for great delay. This is strange issue, but I think I read something similar on release issue notes.

Have you tried updated versions? Does this issue persist with more recent updates?

--- Additional comment from Henrique Martins on 2019-09-11 17:12:46 UTC ---

Yup, it's been a while. 
I'm now on:
  bind-9.11.10-1.fc30.x86_64

Disabled my root priming crontab job earlier today and the logs seem clean of that annoying message.

I'll report back tomorrow and if still clean, it is time to close the bug.

--- Additional comment from Henrique Martins on 2019-09-12 11:56:05 UTC ---

Seems to be fixed in the current version.
Time to close this.
Thanks