[v9_9] expanded query trace logging

4300.	[cleanup]	Added new querytrace logging. [RT #41155]
This commit is contained in:
Evan Hunt 2016-01-22 14:33:50 -08:00
parent 7b7d845166
commit 70280057b4
3 changed files with 73 additions and 8 deletions

View file

@ -1,3 +1,5 @@
4300. [cleanup] Added new querytrace logging. [RT #41155]
4299. [bug] Check that exactly totallen bytes are read when
reading a RRset from raw files in both single read
and incremental modes. [RT #41402]

View file

@ -46,6 +46,7 @@ struct ns_query {
isc_boolean_t timerset;
dns_name_t * qname;
dns_name_t * origqname;
dns_rdatatype_t qtype;
unsigned int dboptions;
unsigned int fetchoptions;
dns_db_t * gluedb;

View file

@ -26,6 +26,7 @@
#include <isc/print.h>
#include <isc/serial.h>
#include <isc/stats.h>
#include <isc/thread.h>
#include <isc/util.h>
#include <dns/adb.h>
@ -123,20 +124,29 @@ client_trace(ns_client_t *client, int level, const char *message) {
if (client != NULL && client->query.qname != NULL) {
if (isc_log_wouldlog(ns_g_lctx, level)) {
char qbuf[DNS_NAME_FORMATSIZE];
char tbuf[DNS_RDATATYPE_FORMATSIZE];
dns_name_format(client->query.qname,
qbuf, sizeof(qbuf));
dns_rdatatype_format(client->query.qtype,
tbuf, sizeof(tbuf));
isc_log_write(ns_g_lctx,
NS_LOGCATEGORY_CLIENT,
NS_LOGMODULE_QUERY,
level, "client %p (%s): %s",
client, qbuf, message);
NS_LOGMODULE_QUERY, level,
"query client=%p thread=0x%lx "
"(%s/%s): %s",
client,
(unsigned long) isc_thread_self(),
qbuf, tbuf, message);
}
} else {
isc_log_write(ns_g_lctx,
NS_LOGCATEGORY_CLIENT,
NS_LOGMODULE_QUERY,
level, "client %p (<unknown-name>): %s",
client, message);
NS_LOGMODULE_QUERY, level,
"query client=%p thread=0x%lx "
"(<unknown-query>): %s",
client,
(unsigned long) isc_thread_self(),
message);
}
}
#define CTRACE(l,m) client_trace(client, l, m)
@ -332,6 +342,8 @@ query_reset(ns_client_t *client, isc_boolean_t everything) {
isc_buffer_t *dbuf, *dbuf_next;
ns_dbversion_t *dbversion, *dbversion_next;
CTRACE(ISC_LOG_DEBUG(3), "query_reset");
/*%
* Reset the query state of a client to its default state.
*/
@ -5667,6 +5679,10 @@ query_find(ns_client_t *client, dns_fetchevent_t *event, dns_rdatatype_t qtype)
isc_boolean_t associated;
dns_section_t section;
dns_ttl_t ttl;
#ifdef WANT_QUERYTRACE
char mbuf[BUFSIZ];
char qbuf[DNS_NAME_FORMATSIZE];
#endif
CTRACE(ISC_LOG_DEBUG(3), "query_find");
@ -5701,6 +5717,25 @@ query_find(ns_client_t *client, dns_fetchevent_t *event, dns_rdatatype_t qtype)
dns_clientinfomethods_init(&cm, ns_client_sourceip);
dns_clientinfo_init(&ci, client);
#ifdef WANT_QUERYTRACE
if (client->query.origqname != NULL)
dns_name_format(client->query.origqname, qbuf,
sizeof(qbuf));
else
snprintf(qbuf, sizeof(qbuf), "<unset>");
snprintf(mbuf, sizeof(mbuf) - 1,
"client attr:0x%x, query attr:0x%X, restarts:%d, "
"origqname:%s, timer:%d, authdb:%d, referral:%d",
client->attributes,
client->query.attributes,
client->query.restarts, qbuf,
(int) client->query.timerset,
(int) client->query.authdbset,
(int) client->query.isreferral);
CTRACE(ISC_LOG_DEBUG(3), mbuf);
#endif
if (event != NULL) {
/*
* We're returning from recursion. Restore the query context
@ -5710,7 +5745,33 @@ query_find(ns_client_t *client, dns_fetchevent_t *event, dns_rdatatype_t qtype)
rpz_st = client->query.rpz_st;
if (rpz_st != NULL &&
(rpz_st->state & DNS_RPZ_RECURSING) != 0) {
(rpz_st->state & DNS_RPZ_RECURSING) != 0)
{
CTRACE(ISC_LOG_DEBUG(3), "resume from RPZ recursion");
#ifdef WANT_QUERYTRACE
{
char rbuf[DNS_NAME_FORMATSIZE] = "<unset>";
char fbuf[DNS_NAME_FORMATSIZE] = "<unset>";
if (rpz_st->qname != NULL)
dns_name_format(rpz_st->qname,
qbuf, sizeof(qbuf));
else
snprintf(qbuf, sizeof(qbuf),
"<unset>");
if (rpz_st->r_name != NULL)
dns_name_format(rpz_st->r_name,
rbuf, sizeof(rbuf));
if (rpz_st->fname != NULL)
dns_name_format(rpz_st->fname,
fbuf, sizeof(fbuf));
snprintf(mbuf, sizeof(mbuf) - 1,
"rpz qname %s, rname:%s, fname:%s",
qbuf, rbuf, fbuf);
CTRACE(ISC_LOG_DEBUG(3), mbuf);
}
#endif
is_zone = rpz_st->q.is_zone;
authoritative = rpz_st->q.authoritative;
zone = rpz_st->q.zone;
@ -5740,6 +5801,7 @@ query_find(ns_client_t *client, dns_fetchevent_t *event, dns_rdatatype_t qtype)
rdataset = event->rdataset;
sigrdataset = event->sigrdataset;
}
INSIST(rdataset != NULL);
if (qtype == dns_rdatatype_rrsig || qtype == dns_rdatatype_sig)
type = dns_rdatatype_any;
@ -7844,7 +7906,7 @@ ns_query_start(ns_client_t *client) {
*/
rdataset = ISC_LIST_HEAD(client->query.qname->list);
INSIST(rdataset != NULL);
qtype = rdataset->type;
client->query.qtype = qtype = rdataset->type;
dns_rdatatypestats_increment(ns_g_server->rcvquerystats, qtype);
if (dns_rdatatype_ismeta(qtype)) {