From 70280057b44dcd97c879a04d1e59381a3398653c Mon Sep 17 00:00:00 2001 From: Evan Hunt Date: Fri, 22 Jan 2016 14:33:50 -0800 Subject: [PATCH] [v9_9] expanded query trace logging 4300. [cleanup] Added new querytrace logging. [RT #41155] --- CHANGES | 2 + bin/named/include/named/query.h | 1 + bin/named/query.c | 78 +++++++++++++++++++++++++++++---- 3 files changed, 73 insertions(+), 8 deletions(-) diff --git a/CHANGES b/CHANGES index 6525fbec31..dbfd311a2a 100644 --- a/CHANGES +++ b/CHANGES @@ -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] diff --git a/bin/named/include/named/query.h b/bin/named/include/named/query.h index 444729a98f..514bb38fbd 100644 --- a/bin/named/include/named/query.h +++ b/bin/named/include/named/query.h @@ -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; diff --git a/bin/named/query.c b/bin/named/query.c index 409f797d81..734a34b8d9 100644 --- a/bin/named/query.c +++ b/bin/named/query.c @@ -26,6 +26,7 @@ #include #include #include +#include #include #include @@ -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 (): %s", - client, message); + NS_LOGMODULE_QUERY, level, + "query client=%p thread=0x%lx " + "(): %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), ""); + + 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] = ""; + char fbuf[DNS_NAME_FORMATSIZE] = ""; + if (rpz_st->qname != NULL) + dns_name_format(rpz_st->qname, + qbuf, sizeof(qbuf)); + else + snprintf(qbuf, sizeof(qbuf), + ""); + 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)) {