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)
This commit is contained in:
Aram Sargsyan 2022-07-19 13:57:48 +00:00
parent 8801d2668e
commit 47e4ef0696

View file

@ -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));
}