Flood of "resolver priming query complete" when using DNS forwarders

Same issue as in the post below.

https://community.sophos.com/products/unified-threat-management/f/hardware-installation-up2date-licensing/104163/sophos-utm-9-510-4-released---let-s-share-experiences/380061#380061

This has been on going since the 9.510-4 build.  Found to be present in 9.510-4, -5, and now 9.6. 

How do we get this fixed??

 

  • I experience the very same as Jay Jay. Another symptom is that no DNS forwarders are displayed at the corresponding place (Network Services/DNS/Forwarders shows "Currently assigned forwarders: none"). UTM version is 9.600-5. I found in the logs when all this started on my system:

    2018:12:21-21:50:28 vm-fw named[4809]: automatic empty zone: view default: 8.B.D.0.1.0.0.2.IP6.ARPA
    2018:12:21-21:50:28 vm-fw named[4809]: automatic empty zone: view default: EMPTY.AS112.ARPA
    2018:12:21-21:50:28 vm-fw named[4809]: none:99: 'max-cache-size 90%' - setting to 3686MB (out of 4095MB)
    2018:12:21-21:50:28 vm-fw named[4809]: configuring command channel from '//etc/rndc.key'
    2018:12:21-21:50:28 vm-fw named[4809]: reloading configuration succeeded
    2018:12:21-21:50:28 vm-fw named[4809]: reloading zones succeeded
    2018:12:21-21:50:28 vm-fw named[4809]: oculus driver teardown
    2018:12:21-21:50:28 vm-fw named[4809]: [tid 4147907440]: [aptp_disconnect]: aptp socket has been disconnected
    2018:12:21-21:50:28 vm-fw named[4809]: [tid 4147907440]: [aptp_exit] APTP cleanup done
    2018:12:21-21:50:28 vm-fw named[4809]: zone 1.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.ip6.arpa/IN/no_rpz_dlz: loaded serial 1545425428
    2018:12:21-21:50:28 vm-fw named[4809]: zone 0.0.127.in-addr.arpa/IN/no_rpz_dlz: loaded serial 1545425428
    2018:12:21-21:50:28 vm-fw named[4809]: all zones loaded
    2018:12:21-21:50:28 vm-fw named[4809]: running
    2018:12:21-21:50:28 vm-fw named[4809]: zone localhost/IN/no_rpz_dlz: loaded serial 1545425428
    2018:12:21-21:50:28 vm-fw named[4809]: zone 0.0.127.in-addr.arpa/IN/default: loaded serial 1545425428
    2018:12:21-21:50:28 vm-fw named[4809]: zone 1.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.ip6.arpa/IN/default: loaded serial 1545425428
    2018:12:21-21:50:28 vm-fw named[4809]: rpz.zone:9: using RFC1035 TTL semantics
    2018:12:21-21:50:28 vm-fw named[4809]: zone rpz/IN/default: zone serial (1345588987) unchanged. zone may fail to transfer to slaves.
    2018:12:21-21:50:28 vm-fw named[4809]: rpz: (re)loading policy zone 'rpz' changed from 1 to 1 qname, 0 to 0 nsdname, 2084 to 2084 IP, 0 to 0 NSIP, 0 to 0 CLIENTIP entries
    2018:12:21-21:50:28 vm-fw named[4809]: zone rpz/IN/default: loaded serial 1345588987
    2018:12:21-21:50:28 vm-fw named[4809]: zone localhost/IN/default: loaded serial 1545425428
    2018:12:21-21:53:20 vm-fw named[4809]: [tid 4147907440]: [aptp_connect]: aptp socket connect succeeded
    2018:12:21-21:53:20 vm-fw named[4809]: resolver priming query complete
    2018:12:21-21:55:02 vm-fw named[4809]: resolver priming query complete
    2018:12:21-21:58:49 vm-fw named[4809]: resolver priming query complete
    2018:12:21-22:00:01 vm-fw named[4809]: resolver priming query complete
    2018:12:21-22:10:02 vm-fw named[4809]: resolver priming query complete
    2018:12:21-22:17:02 vm-fw named[4809]: resolver priming query complete
    2018:12:21-22:17:32 vm-fw named[4809]: resolver priming query complete
    2018:12:21-22:20:01 vm-fw named[4809]: resolver priming query complete
    2018:12:21-22:25:02 vm-fw named[4809]: resolver priming query complete
    2018:12:21-22:40:02 vm-fw named[4809]: resolver priming query complete
    2018:12:21-22:42:39 vm-fw named[4809]: resolver priming query complete
    2018:12:21-22:47:02 vm-fw named[4809]: resolver priming query complete
    2018:12:21-22:47:32 vm-fw named[4809]: resolver priming query complete
    2018:12:21-23:00:01 vm-fw named[4809]: resolver priming query complete
    2018:12:21-23:10:02 vm-fw named[4809]: resolver priming query complete
    2018:12:21-23:17:02 vm-fw named[4809]: resolver priming query complete
    2018:12:21-23:17:32 vm-fw named[4809]: resolver priming query complete
    2018:12:21-23:20:01 vm-fw named[4809]: resolver priming query complete
    2018:12:21-23:25:02 vm-fw named[4809]: resolver priming query complete
    2018:12:21-23:40:01 vm-fw named[4809]: resolver priming query complete
    2018:12:21-23:47:02 vm-fw named[4809]: resolver priming query complete
    2018:12:21-23:47:32 vm-fw named[4809]: resolver priming query complete
    2018:12:21-23:55:02 vm-fw named[4809]: resolver priming query complete
    2018:12:22-00:00:01 vm-fw named[4809]: resolver priming query complete

    On the other hand, DNS is apparently working.

  • In reply to puch:

    Considering how long this issue has been ongoing, it appears to be falling on deaf ears.

     

    @mods, can we get some help please??

  • In reply to puch:

    Szia puch,

    How does your configuration compare to DNS best practice?

    Cheers - Bob

  • In reply to BAlfson:

    Bob, so you think this error is a result of some other DNS misconfiguration? With no other changes, why is this error not present in older UTM versions?

  • In reply to Jay Jay:

    Jay, my wag is that this is a situation where the Up2Date process slightly mangled your configuration database - that seems to occur in less than 0.1% of UP2Dates, maybe less than 0.01%.  If you have a backup from before the first Up2Date to 9.510, try restoring that to see if the problem disappears.  Any luck with that?

    Cheers - Bob

  • In reply to BAlfson:

    Looking at my UTM logs I find that I am seeing the same repeating DNS Proxy log entry as Jay.  I have no other symptoms and my DNS forwarder configuration looks normal.  My logs show that this "resolver priming" entry started immediately after upgrading from 9.509-3 to 9.510-5.  I have restored a configuration from 9.509-3 but the log entries continue.  Other than this log entry my UTM is functioning perfectly.  I am currently at version 9.600-5.  I know I'm not offering any info here that solves this but thought I would share what another user is seeing.

     

    Rick

  • In reply to RickWeiss:

    Looks like this is a bug in the Bind DNS resolver.  The Bind user groups started reporting this behaviour last year.  I'm guessing we got a Bind update with the UTM upgrade to 9.510-5 which introduced the bug to UTM.  This is said to only be an annoyance in the logs and does not affect DNS performance.

     

    Rick

  • In reply to RickWeiss:

    Rick, I'd say it may affect performance.  A log entry is generated for each dns lookup.  If there are many going on at once, all this activity would surely affect performance, no?

     

    Any way to revert back to an older bind version?

  • In reply to Jay Jay:

    From what I read in the Bind user forum performance degradation did not seem to be an issue.  I see no performance issues ether and only noticed the log entries because your post made me look at my logs.  Your mileage may vary.  Also, the log entry doesn't seem to be triggered by a DNS lookup but happens regularly without lookup activity.

    The only way I know of to go back to the older Bind version is to go back to UTM version 9.509 before this Bind issue occured.

    Rick