mir/bind
2
0
Fork 0
mirror of https://gitlab.isc.org/isc-projects/bind9 synced 2025-09-05 09:05:40 +00:00
Code Issues Releases Wiki Activity

[master] add better servfail logging

Browse Source 
3937.	[func]		Added some debug logging to better indicate the
			conditions causing SERVFAILs when resolving.
			[RT #35538]
This commit is contained in:
Evan Hunt
2014-08-28 22:37:55 -07:00
parent d46855caed
commit f5c24a7f48
3 changed files with 377 additions and 107 deletions
Download Patch File Download Diff File Expand all files Collapse all files

205
lib/dns/resolver.c
View File

@@ -80,11 +80,13 @@
DNS_LOGMODULE_RESOLVER, \
ISC_LOG_DEBUG(3), \
"res %p: %s", (r), (m))
#define FCTXTRACE(m) isc_log_write(dns_lctx, \
#define FCTXTRACE(m) \
isc_log_write(dns_lctx, \
DNS_LOGCATEGORY_RESOLVER, \
DNS_LOGMODULE_RESOLVER, \
ISC_LOG_DEBUG(3), \
"fctx %p(%s): %s", fctx, fctx->info, (m))
"fctx %p(%s): %s", \
fctx, fctx->info, (m))
#define FCTXTRACE2(m1, m2) \
isc_log_write(dns_lctx, \
DNS_LOGCATEGORY_RESOLVER, \
@@ -92,6 +94,22 @@
ISC_LOG_DEBUG(3), \
"fctx %p(%s): %s %s", \
fctx, fctx->info, (m1), (m2))
#define FCTXTRACE3(m, res) \
isc_log_write(dns_lctx, \
DNS_LOGCATEGORY_RESOLVER, \
DNS_LOGMODULE_RESOLVER, \
ISC_LOG_DEBUG(3), \
"fctx %p(%s): [result: %s] %s", \
fctx, fctx->info, \
isc_result_totext(res), (m))
#define FCTXTRACE4(m1, m2, res) \
isc_log_write(dns_lctx, \
DNS_LOGCATEGORY_RESOLVER, \
DNS_LOGMODULE_RESOLVER, \
ISC_LOG_DEBUG(3), \
"fctx %p(%s): [result: %s] %s %s", \
fctx, fctx->info, \
isc_result_totext(res), (m1), (m2))
#define FTRACE(m) isc_log_write(dns_lctx, \
DNS_LOGCATEGORY_RESOLVER, \
DNS_LOGMODULE_RESOLVER, \
@@ -1268,6 +1286,9 @@ process_sendevent(resquery_t *query, isc_event_t *event) {
case ISC_R_NOPERM:
case ISC_R_ADDRNOTAVAIL:
case ISC_R_CONNREFUSED:
FCTXTRACE3("query canceled in sendevent(): "
"no route to host; no response",
sevent->result);
/*
* No route to remote.
@@ -1279,6 +1300,10 @@ process_sendevent(resquery_t *query, isc_event_t *event) {
break;
default:
FCTXTRACE3("query canceled in sendevent() due to "
"unexpected event result; responding",
sevent->result);
fctx_cancelquery(&query, NULL, NULL, ISC_FALSE);
break;
}
@@ -2359,6 +2384,9 @@ resquery_connected(isc_task_t *task, isc_event_t *event) {
isc_interval_set(&interval, 20, 0);
result = fctx_startidletimer(query->fctx, &interval);
if (result != ISC_R_SUCCESS) {
FCTXTRACE("query canceled: idle timer failed; "
"responding");
fctx_cancelquery(&query, NULL, NULL, ISC_FALSE);
fctx_done(fctx, result, __LINE__);
break;
@@ -2395,6 +2423,9 @@ resquery_connected(isc_task_t *task, isc_event_t *event) {
result = resquery_send(query);
if (result != ISC_R_SUCCESS) {
FCTXTRACE("query canceled: "
"resquery_send() failed; responding");
fctx_cancelquery(&query, NULL, NULL, ISC_FALSE);
fctx_done(fctx, result, __LINE__);
}
@@ -2406,6 +2437,10 @@ resquery_connected(isc_task_t *task, isc_event_t *event) {
case ISC_R_NOPERM:
case ISC_R_ADDRNOTAVAIL:
case ISC_R_CONNECTIONRESET:
FCTXTRACE3("query canceled in connected(): "
"no route to host; no response",
sevent->result);
/*
* No route to remote.
*/
@@ -2415,6 +2450,10 @@ resquery_connected(isc_task_t *task, isc_event_t *event) {
break;
default:
FCTXTRACE3("query canceled in connected() due to "
"unexpected event result; responding",
sevent->result);
isc_socket_detach(&query->tcpsocket);
fctx_cancelquery(&query, NULL, NULL, ISC_FALSE);
break;
@@ -2495,11 +2534,12 @@ fctx_finddone(isc_task_t *task, isc_event_t *event) {
isc_event_free(&event);
dns_adb_destroyfind(&find);
if (want_try)
if (want_try) {
fctx_try(fctx, ISC_TRUE, ISC_FALSE);
else if (want_done)
} else if (want_done) {
FCTXTRACE("fetch failed in finddone(); return ISC_R_FAILURE");
fctx_done(fctx, ISC_R_FAILURE, __LINE__);
else if (destroy) {
} else if (destroy) {
fctx_destroy(fctx);
if (bucket_empty)
empty_bucket(res);
@@ -3479,6 +3519,7 @@ fctx_timeout(isc_task_t *task, isc_event_t *event) {
fctx->timeouts++;
fctx->timeout = ISC_TRUE;
/*
* We could cancel the running queries here, or we could let
* them keep going. Since we normally use separate sockets for
@@ -3490,10 +3531,13 @@ fctx_timeout(isc_task_t *task, isc_event_t *event) {
*/
query = ISC_LIST_HEAD(fctx->queries);
if (query != NULL &&
isc_time_compare(&tevent->due, &query->start) >= 0) {
isc_time_compare(&tevent->due, &query->start) >= 0)
{
FCTXTRACE("query timed out; no response");
fctx_cancelquery(&query, NULL, NULL, ISC_TRUE);
}
fctx->attributes &= ~FCTX_ATTR_ADDRWAIT;
/*
* Our timer has triggered. Reestablish the fctx lifetime
* timer.
@@ -3777,7 +3821,6 @@ fctx_create(dns_resolver_t *res, dns_name_t *name, dns_rdatatype_t type,
unsigned int findoptions = 0;
char buf[DNS_NAME_FORMATSIZE + DNS_RDATATYPE_FORMATSIZE];
char typebuf[DNS_RDATATYPE_FORMATSIZE];
dns_name_t suffix;
isc_mem_t *mctx;
/*
@@ -3789,6 +3832,11 @@ fctx_create(dns_resolver_t *res, dns_name_t *name, dns_rdatatype_t type,
fctx = isc_mem_get(mctx, sizeof(*fctx));
if (fctx == NULL)
return (ISC_R_NOMEMORY);
/*
* Make fctx->info point to a copy of a formatted string
* "name/type".
*/
dns_name_format(name, buf, sizeof(buf));
dns_rdatatype_format(type, typebuf, sizeof(typebuf));
strcat(buf, "/"); /* checked */
@@ -3798,6 +3846,7 @@ fctx_create(dns_resolver_t *res, dns_name_t *name, dns_rdatatype_t type,
result = ISC_R_NOMEMORY;
goto cleanup_fetch;
}
FCTXTRACE("create");
dns_name_init(&fctx->name, NULL);
result = dns_name_dup(name, mctx, &fctx->name);
@@ -3870,10 +3919,12 @@ fctx_create(dns_resolver_t *res, dns_name_t *name, dns_rdatatype_t type,
dns_forwarders_t *forwarders = NULL;
unsigned int labels;
dns_name_t *fwdname = name;
dns_name_t suffix;
/*
* DS records are found in the parent server.
* Strip label to get the correct forwarder (if any).
* DS records are found in the parent server. Strip one
* leading label from the name (to be used in finding
* the forwarder).
*/
if (dns_rdatatype_atparent(fctx->type) &&
dns_name_countlabels(name) > 1) {
@@ -3882,6 +3933,8 @@ fctx_create(dns_resolver_t *res, dns_name_t *name, dns_rdatatype_t type,
dns_name_getlabelsequence(name, 1, labels - 1, &suffix);
fwdname = &suffix;
}
/* Find the forwarder for this name. */
dns_fixedname_init(&fixed);
domain = dns_fixedname_name(&fixed);
result = dns_fwdtable_find2(fctx->res->view->fwdtable, fwdname,
@@ -7170,6 +7223,7 @@ resquery_response(isc_task_t *task, isc_event_t *event) {
if (fctx->res->exiting) {
result = ISC_R_SHUTTINGDOWN;
FCTXTRACE("resolver shutting down");
goto done;
}
@@ -7224,6 +7278,7 @@ resquery_response(isc_task_t *task, isc_event_t *event) {
no_response = ISC_TRUE;
}
}
FCTXTRACE3("dispatcher failure", devent->result);
goto done;
}
@@ -7231,14 +7286,18 @@ resquery_response(isc_task_t *task, isc_event_t *event) {
if (query->tsig != NULL) {
result = dns_message_setquerytsig(message, query->tsig);
if (result != ISC_R_SUCCESS)
if (result != ISC_R_SUCCESS) {
FCTXTRACE3("unable to set query tsig", result);
goto done;
}
}
if (query->tsigkey) {
result = dns_message_settsigkey(message, query->tsigkey);
if (result != ISC_R_SUCCESS)
if (result != ISC_R_SUCCESS) {
FCTXTRACE3("unable to set tsig key", result);
goto done;
}
}
if ((options & DNS_FETCHOPT_TCP) == 0) {
@@ -7250,6 +7309,7 @@ resquery_response(isc_task_t *task, isc_event_t *event) {
}
result = dns_message_parse(message, &devent->buffer, 0);
if (result != ISC_R_SUCCESS) {
FCTXTRACE3("message failed to parse", result);
switch (result) {
case ISC_R_UNEXPECTEDEND:
if (!message->question_ok ||
@@ -7338,6 +7398,7 @@ resquery_response(isc_task_t *task, isc_event_t *event) {
*/
resend = ISC_TRUE;
/* XXXMPA log it */
FCTXTRACE("bad sit");
goto done;
}
#endif
@@ -7348,8 +7409,10 @@ resquery_response(isc_task_t *task, isc_event_t *event) {
* returns success anyway.
*/
result = dns_message_checksig(message, fctx->res->view);
if (result != ISC_R_SUCCESS)
if (result != ISC_R_SUCCESS) {
FCTXTRACE3("signature check failed", result);
goto done;
}
/*
* The dispatcher should ensure we only get responses with QR set.
@@ -7453,6 +7516,7 @@ resquery_response(isc_task_t *task, isc_event_t *event) {
options |= DNS_FETCHOPT_TCP;
resend = ISC_TRUE;
}
FCTXTRACE3("message truncated", result);
goto done;
}
@@ -7463,6 +7527,7 @@ resquery_response(isc_task_t *task, isc_event_t *event) {
/* XXXRTH Log */
broken_server = DNS_R_UNEXPECTEDOPCODE;
keep_trying = ISC_TRUE;
FCTXTRACE("invalid message opcode");
goto done;
}
@@ -7497,6 +7562,8 @@ resquery_response(isc_task_t *task, isc_event_t *event) {
*/
if (message->rcode != dns_rcode_noerror &&
message->rcode != dns_rcode_nxdomain) {
isc_buffer_t b;
char code[64];
#ifdef ISC_PLATFORM_USESIT
unsigned char sit[64];
@@ -7623,6 +7690,11 @@ resquery_response(isc_task_t *task, isc_event_t *event) {
INSIST(broken_server != ISC_R_SUCCESS);
keep_trying = ISC_TRUE;
}
isc_buffer_init(&b, code, sizeof(code) - 1);
dns_rcode_totext(fctx->rmessage->rcode, &b);
code[isc_buffer_usedlength(&b)] = '\0';
FCTXTRACE2("remote server broken: returned ", code);
goto done;
}
@@ -7634,6 +7706,7 @@ resquery_response(isc_task_t *task, isc_event_t *event) {
/* XXXRTH Log */
if (result == DNS_R_FORMERR)
keep_trying = ISC_TRUE;
FCTXTRACE3("response did not match question", result);
goto done;
}
@@ -7654,6 +7727,7 @@ resquery_response(isc_task_t *task, isc_event_t *event) {
isc_result_totext(result));
broken_server = DNS_R_LAME;
keep_trying = ISC_TRUE;
FCTXTRACE("lame server");
goto done;
}
@@ -7706,22 +7780,32 @@ resquery_response(isc_task_t *task, isc_event_t *event) {
*/
if ((message->flags & DNS_MESSAGEFLAG_AA) != 0 ||
ISFORWARDER(query->addrinfo))
{
result = answer_response(fctx);
else if (iscname(fctx) &&
if (result != ISC_R_SUCCESS)
FCTXTRACE3("answer_response (AA/fwd)", result);
} else if (iscname(fctx) &&
fctx->type != dns_rdatatype_any &&
fctx->type != dns_rdatatype_cname) {
fctx->type != dns_rdatatype_cname)
{
/*
* A BIND8 server could return a non-authoritative
* answer when a CNAME is followed. We should treat
* it as a valid answer.
*/
result = answer_response(fctx);
if (result != ISC_R_SUCCESS)
FCTXTRACE3("answer_response (!ANY/!CNAME)",
result);
} else if (fctx->type != dns_rdatatype_ns &&
!betterreferral(fctx)) {
/*
* Lame response !!!.
*/
result = answer_response(fctx);
if (result != ISC_R_SUCCESS)
FCTXTRACE("answer_response (!NS)");
FCTXTRACE3("answer_response (!NS)", result);
} else {
if (fctx->type == dns_rdatatype_ns) {
/*
@@ -7734,6 +7818,9 @@ resquery_response(isc_task_t *task, isc_event_t *event) {
*/
result = noanswer_response(fctx, NULL,
LOOK_FOR_NS_IN_ANSWER);
if (result != ISC_R_SUCCESS)
FCTXTRACE3("noanswer_response (NS)",
result);
} else {
/*
* Some other servers may still somehow include
@@ -7749,6 +7836,8 @@ resquery_response(isc_task_t *task, isc_event_t *event) {
*/
result = noanswer_response(fctx, NULL,
LOOK_FOR_GLUE_IN_ANSWER);
if (result != ISC_R_SUCCESS)
FCTXTRACE3("noanswer_response", result);
}
if (result != DNS_R_DELEGATION) {
/*
@@ -7813,6 +7902,7 @@ resquery_response(isc_task_t *task, isc_event_t *event) {
*/
if (result == DNS_R_FORMERR)
keep_trying = ISC_TRUE;
FCTXTRACE3("noanswer_response", result);
goto done;
}
} else {
@@ -7822,6 +7912,7 @@ resquery_response(isc_task_t *task, isc_event_t *event) {
/* XXXRTH Log */
broken_server = DNS_R_UNEXPECTEDRCODE;
keep_trying = ISC_TRUE;
FCTXTRACE("broken server: unexpected rcode");
goto done;
}
@@ -7836,8 +7927,10 @@ resquery_response(isc_task_t *task, isc_event_t *event) {
*/
if (WANTCACHE(fctx)) {
result = cache_message(fctx, query->addrinfo, now);
if (result != ISC_R_SUCCESS)
if (result != ISC_R_SUCCESS) {
FCTXTRACE3("cache_message complete", result);
goto done;
}
}
/*
@@ -7855,6 +7948,8 @@ resquery_response(isc_task_t *task, isc_event_t *event) {
* Cache any negative cache entries in the message.
*/
result = ncache_message(fctx, query->addrinfo, covers, now);
if (result != ISC_R_SUCCESS)
FCTXTRACE3("ncache_message complete", result);
}
done:
@@ -7864,6 +7959,10 @@ resquery_response(isc_task_t *task, isc_event_t *event) {
*/
addrinfo = query->addrinfo;
FCTXTRACE4("query canceled in response(); ",
no_response ? "no response" : "responding",
result);
/*
* Cancel the query.
*
@@ -8616,6 +8715,10 @@ log_fetch(dns_name_t *name, dns_rdatatype_t type) {
char typebuf[DNS_RDATATYPE_FORMATSIZE];
int level = ISC_LOG_DEBUG(1);
/*
* If there's no chance of logging it, don't render (format) the
* name and RDATA type (further below), and return early.
*/
if (! isc_log_wouldlog(dns_lctx, level))
return;
@@ -9022,6 +9125,11 @@ dns_resolver_flushbadcache(dns_resolver_t *resolver, dns_name_t *name) {
unsigned int i;
dns_badcache_t *bad, *prev, *next;
/*
* Drop all entries that match the name, and also all expired
* entries from the badcache.
*/
REQUIRE(VALID_RESOLVER(resolver));
LOCK(&resolver->lock);
@@ -9066,6 +9174,8 @@ dns_resolver_flushbadnames(dns_resolver_t *resolver, dns_name_t *name) {
isc_time_t now;
isc_result_t result;
/* Drop all expired entries from the badcache. */
REQUIRE(VALID_RESOLVER(resolver));
REQUIRE(name != NULL);
@@ -9105,6 +9215,13 @@ resizehash(dns_resolver_t *resolver, isc_time_t *now, isc_boolean_t grow) {
dns_badcache_t **new, *bad, *next;
unsigned int i;
/*
* The number of buckets in the hashtable is modified in this
* function. Afterwards, all the entries are remapped into the
* corresponding new slot. Rehashing (hash computation) is
* unnecessary as the hash values had been saved.
*/
if (grow)
newsize = resolver->badhash * 2 + 1;
else
@@ -9115,6 +9232,13 @@ resizehash(dns_resolver_t *resolver, isc_time_t *now, isc_boolean_t grow) {
if (new == NULL)
return;
memset(new, 0, sizeof(*resolver->badcache) * newsize);
/*
* Because the hashtable implements a simple modulus mapping
* from hash to bucket (no extendible hashing is used), every
* name in the hashtable has to be remapped to its new slot.
* Entries that have expired (time) are dropped.
*/
for (i = 0; i < resolver->badhash; i++) {
for (bad = resolver->badcache[i]; bad != NULL; bad = next) {
next = bad->next;
@@ -9143,6 +9267,18 @@ dns_resolver_addbadcache(dns_resolver_t *resolver, dns_name_t *name,
unsigned int i, hashval;
dns_badcache_t *bad, *prev, *next;
/*
* The badcache is implemented as a hashtable keyed on the name,
* and each bucket slot points to a linked list (separate
* chaining).
*
* To avoid long list chains, if the number of entries in the
* hashtable goes over number-of-buckets * 8, the
* number-of-buckets is doubled. Similarly, if the number of
* entries goes below number-of-buckets * 2, the number-of-buckets
* is halved. See resizehash().
*/
REQUIRE(VALID_RESOLVER(resolver));
LOCK(&resolver->lock);
@@ -9167,6 +9303,7 @@ dns_resolver_addbadcache(dns_resolver_t *resolver, dns_name_t *name,
next = bad->next;
if (bad->type == type && dns_name_equal(name, &bad->name))
break;
/* Drop expired entries when walking the chain. */
if (isc_time_compare(&bad->expire, &now) < 0) {
if (prev == NULL)
resolver->badcache[i] = bad->next;
@@ -9179,6 +9316,12 @@ dns_resolver_addbadcache(dns_resolver_t *resolver, dns_name_t *name,
prev = bad;
}
if (bad == NULL) {
/*
* Insert the name into the badcache hashtable at the
* head of the linked list at the appropriate slot. The
* name data follows right after the allocation for the
* linked list node.
*/
isc_buffer_t buffer;
bad = isc_mem_get(resolver->mctx, sizeof(*bad) + name->length);
if (bad == NULL)
@@ -9337,6 +9480,12 @@ dns_resolver_disable_algorithm(dns_resolver_t *resolver, dns_name_t *name,
isc_result_t result;
dns_rbtnode_t *node = NULL;
/*
* Whether an algorithm is disabled (or not) is stored in a
* per-name bitfield that is stored as the node data of an
* RBT.
*/
REQUIRE(VALID_RESOLVER(resolver));
if (alg > 255)
return (ISC_R_RANGE);
@@ -9358,7 +9507,17 @@ dns_resolver_disable_algorithm(dns_resolver_t *resolver, dns_name_t *name,
if (result == ISC_R_SUCCESS || result == ISC_R_EXISTS) {
algorithms = node->data;
/*
* If algorithms is set, algorithms[0] contains its
* length.
*/
if (algorithms == NULL || len > *algorithms) {
/*
* If no bitfield exists in the node data, or if
* it is not long enough, allocate a new
* bitfield and copy the old (smaller) bitfield
* into it if one exists.
*/
new = isc_mem_get(resolver->mctx, len);
if (new == NULL) {
result = ISC_R_NOMEMORY;
@@ -9368,8 +9527,10 @@ dns_resolver_disable_algorithm(dns_resolver_t *resolver, dns_name_t *name,
if (algorithms != NULL)
memmove(new, algorithms, *algorithms);
new[len-1] |= mask;
/* new[0] should contain the length of new. */
*new = len;
node->data = new;
/* Free the older bitfield. */
if (algorithms != NULL)
isc_mem_put(resolver->mctx, algorithms,
*algorithms);
@@ -9451,6 +9612,11 @@ dns_resolver_disable_ds_digest(dns_resolver_t *resolver, dns_name_t *name,
isc_result_t result;
dns_rbtnode_t *node = NULL;
/*
* Whether a digest is disabled (or not) is stored in a per-name
* bitfield that is stored as the node data of an RBT.
*/
REQUIRE(VALID_RESOLVER(resolver));
if (digest_type > 255)
return (ISC_R_RANGE);
@@ -9472,7 +9638,14 @@ dns_resolver_disable_ds_digest(dns_resolver_t *resolver, dns_name_t *name,
if (result == ISC_R_SUCCESS || result == ISC_R_EXISTS) {
digests = node->data;
/* If digests is set, digests[0] contains its length. */
if (digests == NULL || len > *digests) {
/*
* If no bitfield exists in the node data, or if
* it is not long enough, allocate a new
* bitfield and copy the old (smaller) bitfield
* into it if one exists.
*/
new = isc_mem_get(resolver->mctx, len);
if (new == NULL) {
result = ISC_R_NOMEMORY;
@@ -9482,8 +9655,10 @@ dns_resolver_disable_ds_digest(dns_resolver_t *resolver, dns_name_t *name,
if (digests != NULL)
memmove(new, digests, *digests);
new[len-1] |= mask;
/* new[0] should contain the length of new. */
*new = len;
node->data = new;
/* Free the older bitfield. */
if (digests != NULL)
isc_mem_put(resolver->mctx, digests,
*digests);