Improve fetch limit logging

When initially hitting the `fetches-per-zone` value, a log message
is being generated for the event of dropping the first fetch, then
any further log events occur only when another fetch is being dropped
and 60 seconds have been passed since the last logged message.

That logic isn't ideal because when the counter of the outstanding
fetches reaches zero, the structure holding the counters' values will
get deleted, and the information about the dropped fetches accumulated
during the last minute will not be logged.

Improve the fcount_logspill() function to makie sure that the final
values are getting logged before the counter object gets destroyed.

diff --git a/lib/dns/resolver.c b/lib/dns/resolver.c
index 7fa7040aa2c3abbe4d485fc8dba939c7785b6443..8001b649a9a22671fba141afaa6ff8d92af7af14 100644 (file)
--- a/lib/dns/resolver.c
+++ b/lib/dns/resolver.c
@@ -1566,7 +1566,7 @@ fctx_cancelqueries(fetchctx_t *fctx, bool no_response, bool age_untried) {
 }
 
 static void
-fcount_logspill(fetchctx_t *fctx, fctxcount_t *counter) {
+fcount_logspill(fetchctx_t *fctx, fctxcount_t *counter, bool final) {
        char dbuf[DNS_NAME_FORMATSIZE];
        isc_stdtime_t now;
 
@@ -1574,18 +1574,33 @@ fcount_logspill(fetchctx_t *fctx, fctxcount_t *counter) {
                return;
        }
 
+       /* Do not log a message if there were no dropped fetches. */
+       if (counter->dropped == 0) {
+               return;
+       }
+
+       /* Do not log the cumulative message if the previous log is recent. */
        isc_stdtime_get(&now);
-       if (counter->logged > now - 60) {
+       if (!final && counter->logged > now - 60) {
                return;
        }
 
        dns_name_format(fctx->domain, dbuf, sizeof(dbuf));
 
-       isc_log_write(dns_lctx, DNS_LOGCATEGORY_SPILL, DNS_LOGMODULE_RESOLVER,
-                     ISC_LOG_INFO,
-                     "too many simultaneous fetches for %s "
-                     "(allowed %d spilled %d)",
-                     dbuf, counter->allowed, counter->dropped);
+       if (!final) {
+               isc_log_write(dns_lctx, DNS_LOGCATEGORY_SPILL,
+                             DNS_LOGMODULE_RESOLVER, ISC_LOG_INFO,
+                             "too many simultaneous fetches for %s "
+                             "(allowed %d spilled %d)",
+                             dbuf, counter->allowed, counter->dropped);
+       } else {
+               isc_log_write(dns_lctx, DNS_LOGCATEGORY_SPILL,
+                             DNS_LOGMODULE_RESOLVER, ISC_LOG_INFO,
+                             "fetch counters for %s now being discarded "
+                             "(allowed %d spilled %d; cumulative since "
+                             "initial trigger event)",
+                             dbuf, counter->allowed, counter->dropped);
+       }
 
        counter->logged = now;
 }
@@ -1653,7 +1668,7 @@ fcount_incr(fetchctx_t *fctx, bool force) {
                uint_fast32_t spill = atomic_load_acquire(&res->zspill);
                if (!force && spill != 0 && counter->count >= spill) {
                        counter->dropped++;
-                       fcount_logspill(fctx, counter);
+                       fcount_logspill(fctx, counter, false);
                        result = ISC_R_QUOTA;
                } else {
                        counter->count++;
@@ -1696,6 +1711,7 @@ fcount_decr(fetchctx_t *fctx) {
                fctx->zbucket = NULL;
 
                if (counter->count == 0) {
+                       fcount_logspill(fctx, counter, true);
                        ISC_LIST_UNLINK(zbucket->list, counter, link);
                        isc_mem_put(fctx->res->mctx, counter, sizeof(*counter));
                }