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.

(cherry picked from commit 039871ceb767088205563965f7aae622a3f77082)

diff --git a/lib/dns/resolver.c b/lib/dns/resolver.c
index e8213c855f918143bdb1278b246eb35eccd35058..88830084204737c3500d9ea95f497eca7cea9fb2 100644 (file)
--- a/lib/dns/resolver.c
+++ b/lib/dns/resolver.c
@@ -1561,7 +1561,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;
 
@@ -1569,18 +1569,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;
 }
@@ -1626,7 +1641,7 @@ fcount_incr(fetchctx_t *fctx, bool force) {
                uint_fast32_t spill = atomic_load_acquire(&fctx->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++;
@@ -1670,6 +1685,7 @@ fcount_decr(fetchctx_t *fctx) {
                fctx->dbucketnum = RES_NOBUCKET;
 
                if (counter->count == 0) {
+                       fcount_logspill(fctx, counter, true);
                        ISC_LIST_UNLINK(dbucket->list, counter, link);
                        isc_mem_put(fctx->res->mctx, counter, sizeof(*counter));
                }