If we hit a cache internal error, log the entry we failed to remove.

This is code which should never run, but if it does,
we now log information useful for debugging.
This commit is contained in:
Simon Kelley
2022-12-22 23:19:05 +00:00
parent e6841ea2e0
commit 43a2a66531

View File

@@ -28,6 +28,7 @@ static int bignames_left, hash_size;
static void make_non_terminals(struct crec *source); static void make_non_terminals(struct crec *source);
static struct crec *really_insert(char *name, union all_addr *addr, unsigned short class, static struct crec *really_insert(char *name, union all_addr *addr, unsigned short class,
time_t now, unsigned long ttl, unsigned int flags); time_t now, unsigned long ttl, unsigned int flags);
static void dump_cache_entry(struct crec *cache, time_t now);
/* type->string mapping: this is also used by the name-hash function as a mixing table. */ /* type->string mapping: this is also used by the name-hash function as a mixing table. */
/* taken from https://www.iana.org/assignments/dns-parameters/dns-parameters.xhtml */ /* taken from https://www.iana.org/assignments/dns-parameters/dns-parameters.xhtml */
@@ -594,7 +595,7 @@ static struct crec *really_insert(char *name, union all_addr *addr, unsigned sho
struct crec *new, *target_crec = NULL; struct crec *new, *target_crec = NULL;
union bigname *big_name = NULL; union bigname *big_name = NULL;
int freed_all = (flags & F_REVERSE); int freed_all = (flags & F_REVERSE);
int free_avail = 0; struct crec *free_avail = NULL;
unsigned int target_uid; unsigned int target_uid;
/* if previous insertion failed give up now. */ /* if previous insertion failed give up now. */
@@ -658,6 +659,8 @@ static struct crec *really_insert(char *name, union all_addr *addr, unsigned sho
if (!warned) if (!warned)
{ {
my_syslog(LOG_ERR, _("Internal error in cache.")); my_syslog(LOG_ERR, _("Internal error in cache."));
/* Log the entry we tried to delete. */
dump_cache_entry(free_avail, now);
warned = 1; warned = 1;
} }
insert_error = 1; insert_error = 1;
@@ -667,7 +670,7 @@ static struct crec *really_insert(char *name, union all_addr *addr, unsigned sho
if (freed_all) if (freed_all)
{ {
/* For DNSSEC records, uid holds class. */ /* For DNSSEC records, uid holds class. */
free_avail = 1; /* Must be free space now. */ free_avail = new; /* Must be free space now. */
/* condition valid when stale-caching */ /* condition valid when stale-caching */
if (difftime(now, new->ttd) < 0) if (difftime(now, new->ttd) < 0)
@@ -1760,63 +1763,20 @@ static char *sanitise(char *name)
return name; return name;
} }
static void dump_cache_entry(struct crec *cache, time_t now)
void dump_cache(time_t now)
{ {
struct server *serv, *serv1; (void)now;
static char *buff = NULL;
my_syslog(LOG_INFO, _("time %lu"), (unsigned long)now); char *p, *t = " ";
my_syslog(LOG_INFO, _("cache size %d, %d/%d cache insertions re-used unexpired cache entries."), char *a = daemon->addrbuff, *n = cache_get_name(cache);
daemon->cachesize, daemon->metrics[METRIC_DNS_CACHE_LIVE_FREED], daemon->metrics[METRIC_DNS_CACHE_INSERTED]);
my_syslog(LOG_INFO, _("queries forwarded %u, queries answered locally %u"),
daemon->metrics[METRIC_DNS_QUERIES_FORWARDED], daemon->metrics[METRIC_DNS_LOCAL_ANSWERED]);
if (daemon->cache_max_expiry != 0)
my_syslog(LOG_INFO, _("queries answered from stale cache %u"), daemon->metrics[METRIC_DNS_STALE_ANSWERED]);
#ifdef HAVE_AUTH
my_syslog(LOG_INFO, _("queries for authoritative zones %u"), daemon->metrics[METRIC_DNS_AUTH_ANSWERED]);
#endif
blockdata_report(); /* String length is limited below */
if (!buff && !(buff = whine_malloc(150)))
return;
/* sum counts from different records for same server */ p = buff;
for (serv = daemon->servers; serv; serv = serv->next)
serv->flags &= ~SERV_MARK;
for (serv = daemon->servers; serv; serv = serv->next)
if (!(serv->flags & SERV_MARK))
{
int port;
unsigned int queries = 0, failed_queries = 0, nxdomain_replies = 0, retrys = 0;
unsigned int sigma_latency = 0, count_latency = 0;
for (serv1 = serv; serv1; serv1 = serv1->next)
if (!(serv1->flags & SERV_MARK) && sockaddr_isequal(&serv->addr, &serv1->addr))
{
serv1->flags |= SERV_MARK;
queries += serv1->queries;
failed_queries += serv1->failed_queries;
nxdomain_replies += serv1->nxdomain_replies;
retrys += serv1->retrys;
sigma_latency += serv1->query_latency;
count_latency++;
}
port = prettyprint_addr(&serv->addr, daemon->addrbuff);
my_syslog(LOG_INFO, _("server %s#%d: queries sent %u, retried %u, failed %u, nxdomain replies %u, avg. latency %ums"),
daemon->addrbuff, port, queries, retrys, failed_queries, nxdomain_replies, sigma_latency/count_latency);
}
if (option_bool(OPT_DEBUG) || option_bool(OPT_LOG))
{
struct crec *cache ;
int i;
my_syslog(LOG_INFO, "Host Address Flags Expires Source");
my_syslog(LOG_INFO, "------------------------------ ---------------------------------------- ---------- ------------------------ ------------");
for (i=0; i<hash_size; i++)
for (cache = hash_table[i]; cache; cache = cache->hash_next)
{
char *t = " ";
char *a = daemon->addrbuff, *p = daemon->namebuff, *n = cache_get_name(cache);
*a = 0; *a = 0;
if (strlen(n) == 0 && !(cache->flags & F_REVERSE)) if (strlen(n) == 0 && !(cache->flags & F_REVERSE))
n = "<Root>"; n = "<Root>";
@@ -1887,10 +1847,65 @@ void dump_cache(time_t now)
p += sprintf(p, "%-24.24s", cache->flags & F_IMMORTAL ? "" : ctime(&(cache->ttd))); p += sprintf(p, "%-24.24s", cache->flags & F_IMMORTAL ? "" : ctime(&(cache->ttd)));
#endif #endif
if(cache->flags & (F_HOSTS | F_CONFIG) && cache->uid > 0) if(cache->flags & (F_HOSTS | F_CONFIG) && cache->uid > 0)
p += sprintf(p, " %s", record_source(cache->uid)); p += sprintf(p, " %-40.40s", record_source(cache->uid));
my_syslog(LOG_INFO, "%s", daemon->namebuff); my_syslog(LOG_INFO, "%s", buff);
} }
void dump_cache(time_t now)
{
struct server *serv, *serv1;
my_syslog(LOG_INFO, _("time %lu"), (unsigned long)now);
my_syslog(LOG_INFO, _("cache size %d, %d/%d cache insertions re-used unexpired cache entries."),
daemon->cachesize, daemon->metrics[METRIC_DNS_CACHE_LIVE_FREED], daemon->metrics[METRIC_DNS_CACHE_INSERTED]);
my_syslog(LOG_INFO, _("queries forwarded %u, queries answered locally %u"),
daemon->metrics[METRIC_DNS_QUERIES_FORWARDED], daemon->metrics[METRIC_DNS_LOCAL_ANSWERED]);
if (daemon->cache_max_expiry != 0)
my_syslog(LOG_INFO, _("queries answered from stale cache %u"), daemon->metrics[METRIC_DNS_STALE_ANSWERED]);
#ifdef HAVE_AUTH
my_syslog(LOG_INFO, _("queries for authoritative zones %u"), daemon->metrics[METRIC_DNS_AUTH_ANSWERED]);
#endif
blockdata_report();
/* sum counts from different records for same server */
for (serv = daemon->servers; serv; serv = serv->next)
serv->flags &= ~SERV_MARK;
for (serv = daemon->servers; serv; serv = serv->next)
if (!(serv->flags & SERV_MARK))
{
int port;
unsigned int queries = 0, failed_queries = 0, nxdomain_replies = 0, retrys = 0;
unsigned int sigma_latency = 0, count_latency = 0;
for (serv1 = serv; serv1; serv1 = serv1->next)
if (!(serv1->flags & SERV_MARK) && sockaddr_isequal(&serv->addr, &serv1->addr))
{
serv1->flags |= SERV_MARK;
queries += serv1->queries;
failed_queries += serv1->failed_queries;
nxdomain_replies += serv1->nxdomain_replies;
retrys += serv1->retrys;
sigma_latency += serv1->query_latency;
count_latency++;
}
port = prettyprint_addr(&serv->addr, daemon->addrbuff);
my_syslog(LOG_INFO, _("server %s#%d: queries sent %u, retried %u, failed %u, nxdomain replies %u, avg. latency %ums"),
daemon->addrbuff, port, queries, retrys, failed_queries, nxdomain_replies, sigma_latency/count_latency);
}
if (option_bool(OPT_DEBUG) || option_bool(OPT_LOG))
{
struct crec *cache;
int i;
my_syslog(LOG_INFO, "Host Address Flags Expires Source");
my_syslog(LOG_INFO, "------------------------------ ---------------------------------------- ---------- ------------------------ ------------");
for (i=0; i<hash_size; i++)
for (cache = hash_table[i]; cache; cache = cache->hash_next)
dump_cache_entry(cache, now);
} }
} }