From 23f2ab45432f6976d957053d1b343509bcc9a936 Mon Sep 17 00:00:00 2001 From: Evan Hunt Date: Fri, 8 May 2020 12:39:16 -0700 Subject: [PATCH 1/3] add "dig +qid" option to set QID to desired value --- bin/dig/dig.c | 18 ++++++++++++++++++ bin/dig/dig.rst | 4 ++++ bin/dig/dighost.c | 9 +++++++++ bin/dig/dighost.h | 6 +++++- bin/dig/nslookup.c | 2 ++ 5 files changed, 38 insertions(+), 1 deletion(-) diff --git a/bin/dig/dig.c b/bin/dig/dig.c index e53ad5e29b..d3fc299bf5 100644 --- a/bin/dig/dig.c +++ b/bin/dig/dig.c @@ -1489,6 +1489,24 @@ plus_option(char *option, bool is_batchfile, dig_lookup_t *lookup) { break; case 'q': switch (cmd[1]) { + case 'i': /* qid */ + FULLCHECK("qid"); + if (!state) { + lookup->setqid = false; + lookup->qid = 0; + break; + } + if (value == NULL) { + goto need_value; + } + result = parse_uint(&num, value, MAXQID, "qid"); + if (result != ISC_R_SUCCESS) { + warn("Couldn't parse qid"); + goto exit_or_usage; + } + lookup->setqid = true; + lookup->qid = num; + break; case 'r': /* qr */ FULLCHECK("qr"); lookup->qr = state; diff --git a/bin/dig/dig.rst b/bin/dig/dig.rst index 3c899ceebc..b14c7e751c 100644 --- a/bin/dig/dig.rst +++ b/bin/dig/dig.rst @@ -426,6 +426,10 @@ abbreviation is unambiguous; for example, ``+cd`` is equivalent to mandatory. Responses to padded queries may also be padded, but only if the query uses TCP or DNS COOKIE. +``+qid=value`` + + Specify the query ID to use when sending queries. + ``+[no]qr`` Toggles the display of the query message as it is sent. By default, the query is not printed. diff --git a/bin/dig/dighost.c b/bin/dig/dighost.c index 0384d7ccad..a12ff40019 100644 --- a/bin/dig/dighost.c +++ b/bin/dig/dighost.c @@ -677,6 +677,8 @@ make_empty_lookup(void) { looknew->tcflag = false; looknew->print_unknown_format = false; looknew->zflag = false; + looknew->setqid = false; + looknew->qid = 0; looknew->ns_search_only = false; looknew->origin = NULL; looknew->tsigctx = NULL; @@ -820,6 +822,8 @@ clone_lookup(dig_lookup_t *lookold, bool servers) { looknew->tcflag = lookold->tcflag; looknew->print_unknown_format = lookold->print_unknown_format; looknew->zflag = lookold->zflag; + looknew->setqid = lookold->setqid; + looknew->qid = lookold->qid; looknew->ns_search_only = lookold->ns_search_only; looknew->tcp_mode = lookold->tcp_mode; looknew->tcp_mode_set = lookold->tcp_mode_set; @@ -2298,6 +2302,11 @@ setup_lookup(dig_lookup_t *lookup) { lookup->sendmsg->flags |= 0x0040U; } + if (lookup->setqid) { + debug("set QID"); + lookup->sendmsg->id = lookup->qid; + } + dns_message_addname(lookup->sendmsg, lookup->name, DNS_SECTION_QUESTION); diff --git a/bin/dig/dighost.h b/bin/dig/dighost.h index 9b482ce3de..15585d460a 100644 --- a/bin/dig/dighost.h +++ b/bin/dig/dighost.h @@ -60,6 +60,8 @@ #define MAXPORT 0xffff /*% Max serial number */ #define MAXSERIAL 0xffffffff +/*% Max query ID */ +#define MAXQID 0xffff /*% Default TCP Timeout */ #define TCP_TIMEOUT 10 @@ -108,9 +110,10 @@ struct dig_lookup { tcp_keepalive, header_only, ednsneg, mapped, print_unknown_format, multiline, nottl, noclass, onesoa, use_usec, nocrypto, ttlunits, idnin, idnout, expandaaaa, qr, - accept_reply_unexpected_src; /*% print replies from + accept_reply_unexpected_src, /*% print replies from * unexpected * sources. */ + setqid; /*% use a speciied query ID */ char textname[MXNAME]; /*% Name we're going to be * looking up */ char cmdline[MXNAME]; @@ -157,6 +160,7 @@ struct dig_lookup { dns_opcode_t opcode; int rrcomments; unsigned int eoferr; + uint16_t qid; }; /*% The dig_query structure */ diff --git a/bin/dig/nslookup.c b/bin/dig/nslookup.c index 17d8515268..08ee5e36d9 100644 --- a/bin/dig/nslookup.c +++ b/bin/dig/nslookup.c @@ -788,6 +788,8 @@ addlookup(char *opt) { lookup->aaonly = aaonly; lookup->retries = tries; lookup->udpsize = 0; + lookup->setqid = false; + lookup->qid = 0; lookup->comments = comments; if (lookup->rdtype == dns_rdatatype_any && !tcpmode_set) { lookup->tcp_mode = true; From 249184e03e1de07cfdc10e28a43ebb1989ebf450 Mon Sep 17 00:00:00 2001 From: Evan Hunt Date: Fri, 15 May 2020 16:37:44 -0700 Subject: [PATCH 2/3] add a quick-and-dirty method of debugging a single query when built with "configure --enable-singletrace", named will produce detailed query logging at the highest debug level for any query with query ID zero. this enables monitoring of the progress of a single query by specifying the QID using "dig +qid=0". the "client" logging category should be set to a low severity level to suppress logging of other queries. (the chance of another query using QID=0 at the same time is only 1 in 2^16.) "--enable-singletrace" turns on "--enable-querytrace" as well, so if the logging severity is not lowered, all other queries will be logged verbosely as well. compiling with either of these options will impair query performance; they should only be turned on when testing or troubleshooting. --- configure.ac | 64 ++++++++++++++++++++++++++----------- lib/isc/include/isc/log.h | 8 +++++ lib/isc/log.c | 34 ++++++++++++++------ lib/isc/win32/libisc.def.in | 1 + lib/ns/client.c | 11 +++++++ 5 files changed, 90 insertions(+), 28 deletions(-) diff --git a/configure.ac b/configure.ac index dd075e65f2..2a5a9b4c51 100644 --- a/configure.ac +++ b/configure.ac @@ -185,12 +185,12 @@ AS_IF([test -z "$PKG_CONFIG"], AC_ARG_ENABLE(buffer_useinline, AS_HELP_STRING([--enable-buffer-useinline], - [define ISC_BUFFER_USEINLINE when compiling + [define ISC_BUFFER_USEINLINE when compiling [default=yes]]), if test yes = "${enable}" then AC_DEFINE([ISC_BUFFER_USEINLINE], [1], - [Define if you want to use inline buffers]) + [Define if you want to use inline buffers]) fi, AC_DEFINE([ISC_BUFFER_USEINLINE], [1])) @@ -228,7 +228,7 @@ AS_IF([test "$enable_fuzzing" = "afl"], AC_ARG_ENABLE(mutex_atomics, AS_HELP_STRING([--enable-mutex-atomics], - [emulate atomics by mutex-locked variables, useful for debugging + [emulate atomics by mutex-locked variables, useful for debugging [default=no]]), [], [enable_mutex_atomics=no]) @@ -236,15 +236,15 @@ AC_ARG_ENABLE(mutex_atomics, AC_MSG_CHECKING([whether to emulate atomics with mutexes]) case "$enable_mutex_atomics" in yes) - AC_MSG_RESULT(yes) - AC_DEFINE(ISC_MUTEX_ATOMICS, 1, [Define to emulate atomic variables with mutexes.]) - ;; + AC_MSG_RESULT(yes) + AC_DEFINE(ISC_MUTEX_ATOMICS, 1, [Define to emulate atomic variables with mutexes.]) + ;; no) - AC_MSG_RESULT(no) - ;; + AC_MSG_RESULT(no) + ;; *) - AC_MSG_ERROR("--enable-mutex-atomics requires yes or no") - ;; + AC_MSG_ERROR("--enable-mutex-atomics requires yes or no") + ;; esac # @@ -895,10 +895,10 @@ AC_ARG_WITH([zlib], AS_CASE([$with_zlib], [no],[], [auto],[PKG_CHECK_MODULES([ZLIB], [zlib], - [AC_DEFINE([HAVE_ZLIB], [1], [Use zlib library])], - [:])], + [AC_DEFINE([HAVE_ZLIB], [1], [Use zlib library])], + [:])], [yes],[PKG_CHECK_MODULES([ZLIB], [zlib], - [AC_DEFINE([HAVE_ZLIB], [1], [Use zlib library])])], + [AC_DEFINE([HAVE_ZLIB], [1], [Use zlib library])])], [AC_MSG_ERROR([Specifying zlib installation path is not supported, adjust PKG_CONFIG_PATH instead])]) AC_SUBST([ZLIB_CFLAGS]) AC_SUBST([ZLIB_LIBS]) @@ -1420,13 +1420,35 @@ AS_CASE([$with_tuning], AC_MSG_NOTICE(using default system tuning)]) # -# was --enable-querytrace specified? +# was --enable-querytrace or --enable-singletrace specified? # +AC_ARG_ENABLE([singletrace], + AS_HELP_STRING([--enable-singletrace], + [enable single-query trace logging + [default=no]]), + enable_singletrace="$enableval", enable_singletrace="no") + +AC_MSG_CHECKING([whether to enable single-query trace logging]) +case "$enable_singletrace" in +yes) + enable_querytrace=yes + AC_MSG_RESULT(yes) + AC_DEFINE(WANT_SINGLETRACE, 1, [Define to enable single-query tracing.]) + ;; +no) + AC_MSG_RESULT(no) + ;; +*) + AC_MSG_ERROR("--enable-singletrace requires yes or no") + ;; +esac + AC_ARG_ENABLE(querytrace, AS_HELP_STRING([--enable-querytrace], [enable very verbose query trace logging [default=no]]), - enable_querytrace="$enableval", enable_querytrace="no") + enable_querytrace="$enableval", + enable_querytrace="$enable_singletrace") AC_MSG_CHECKING([whether to enable query trace logging]) case "$enable_querytrace" in @@ -1435,10 +1457,12 @@ yes) AC_DEFINE(WANT_QUERYTRACE, 1, [Define to enable very verbose query trace logging.]) ;; no) + AS_IF([test "$enable_singletrace" = "yes"], + [AC_MSG_ERROR([--enable-singletrace requires --enable-querytrace])]) AC_MSG_RESULT(no) ;; *) - AC_MSG_ERROR("--enable-querytrace requires yes or no") + AC_MSG_ERROR("--enable-querytrace requires yes or no (not $enable_querytrace)") ;; esac @@ -1701,6 +1725,8 @@ report() { echo " Allow 'fixed' rrset-order (--enable-fixed-rrset)" test "yes" = "$enable_querytrace" && \ echo " Very verbose query trace logging (--enable-querytrace)" + test "yes" = "$enable_singletrace" && \ + echo " Single-query trace logging (--enable-singletrace)" test -z "$HAVE_CMOCKA" || echo " CMocka Unit Testing Framework (--with-cmocka)" test "auto" = "$validation_default" && echo " DNSSEC validation active by default (--enable-auto-validation)" @@ -1726,7 +1752,7 @@ report() { test "no" = "$with_dlz_stub" || \ echo " Stub (--with-dlz-stub)" test "$with_dlz_bdb $with_dlz_ldap $with_dlz_mysql $with_dlz_odbc $with_dlz_postgres $with_dlz_filesystem $with_dlz_stub" = "no no no no no no no" && \ - echo " None" + echo " None" echo "-------------------------------------------------------------------------------" @@ -1752,6 +1778,8 @@ report() { test "yes" = "$enable_querytrace" || \ echo " Very verbose query trace logging (--enable-querytrace)" + test "yes" = "$enable_singletrace" || \ + echo " Single-query trace logging (--enable-singletrace)" test "no" = "$with_cmocka" && echo " CMocka Unit Testing Framework (--with-cmocka)" @@ -1775,7 +1803,7 @@ report() { echo "LDFLAGS: $LDFLAGS" if test "X$ac_unrecognized_opts" != "X"; then - echo "-------------------------------------------------------------------------------" + echo "-------------------------------------------------------------------------------" echo "Unrecognized options:" echo " $ac_unrecognized_opts" fi diff --git a/lib/isc/include/isc/log.h b/lib/isc/include/isc/log.h index ac8b3d8672..e5a6f04d20 100644 --- a/lib/isc/include/isc/log.h +++ b/lib/isc/include/isc/log.h @@ -841,6 +841,14 @@ isc_logfile_roll(isc_logfile_t *file); *\li file is not NULL. */ +void +isc_log_setforcelog(bool v); +/*%< + * Turn forced logging on/off for the current thread. This can be used to + * temporarily increase the debug level to maximum for the duration of + * a single task event. + */ + ISC_LANG_ENDDECLS #endif /* ISC_LOG_H */ diff --git a/lib/isc/log.c b/lib/isc/log.c index fcf387e94e..d03343c371 100644 --- a/lib/isc/log.c +++ b/lib/isc/log.c @@ -31,6 +31,7 @@ #include #include #include +#include #include #include @@ -45,6 +46,8 @@ #define RDUNLOCK(lp) RWUNLOCK(lp, isc_rwlocktype_read); #define WRUNLOCK(lp) RWUNLOCK(lp, isc_rwlocktype_write); +static thread_local bool forcelog = false; + /* * XXXDCL make dynamic? */ @@ -1453,6 +1456,9 @@ isc_log_wouldlog(isc_log_t *lctx, int level) { if (lctx == NULL) { return (false); } + if (forcelog) { + return (true); + } int highest_level = atomic_load_acquire(&lctx->highest_level); if (level <= highest_level) { @@ -1484,6 +1490,7 @@ isc_log_doit(isc_log_t *lctx, isc_logcategory_t *category, bool printcategory, printmodule, printlevel, buffered; isc_logchannel_t *channel; isc_logchannellist_t *category_channels; + int_fast32_t dlevel; isc_result_t result; REQUIRE(lctx == NULL || VALID_CONTEXT(lctx)); @@ -1566,18 +1573,20 @@ isc_log_doit(isc_log_t *lctx, isc_logcategory_t *category, channel = category_channels->channel; category_channels = ISC_LIST_NEXT(category_channels, link); - int_fast32_t dlevel = atomic_load_acquire(&lctx->debug_level); - if (((channel->flags & ISC_LOG_DEBUGONLY) != 0) && dlevel == 0) - { - continue; - } - - if (channel->level == ISC_LOG_DYNAMIC) { - if (dlevel < level) { + if (!forcelog) { + dlevel = atomic_load_acquire(&lctx->debug_level); + if (((channel->flags & ISC_LOG_DEBUGONLY) != 0) && + dlevel == 0) { + continue; + } + + if (channel->level == ISC_LOG_DYNAMIC) { + if (dlevel < level) { + continue; + } + } else if (channel->level < level) { continue; } - } else if (channel->level < level) { - continue; } if ((channel->flags & ISC_LOG_PRINTTIME) != 0 && @@ -1862,3 +1871,8 @@ unlock: UNLOCK(&lctx->lock); RDUNLOCK(&lctx->lcfg_rwl); } + +void +isc_log_setforcelog(bool v) { + forcelog = v; +} diff --git a/lib/isc/win32/libisc.def.in b/lib/isc/win32/libisc.def.in index 7b47b79c26..681b730731 100644 --- a/lib/isc/win32/libisc.def.in +++ b/lib/isc/win32/libisc.def.in @@ -344,6 +344,7 @@ isc_log_registermodules isc_log_setcontext isc_log_setdebuglevel isc_log_setduplicateinterval +isc_log_setforcelog isc_log_settag isc_log_usechannel isc_log_vwrite diff --git a/lib/ns/client.c b/lib/ns/client.c index 14f9618b07..8a959b229e 100644 --- a/lib/ns/client.c +++ b/lib/ns/client.c @@ -17,6 +17,7 @@ #include #include #include +#include #include #include #include @@ -1596,6 +1597,10 @@ ns__client_reset_cb(void *client0) { client->state = NS_CLIENTSTATE_READY; INSIST(client->recursionquota == NULL); + +#ifdef WANT_SINGLETRACE + isc_log_setforcelog(false); +#endif /* WANT_SINGLETRACE */ } void @@ -1787,6 +1792,12 @@ ns__client_request(isc_nmhandle_t *handle, isc_region_t *region, void *arg) { return; } +#ifdef WANT_SINGLETRACE + if (id == 0) { + isc_log_setforcelog(true); + } +#endif /* WANT_SINGLETRACE */ + /* * The client object handles requests, not responses. * If this is a UDP response, forward it to the dispatcher. From d09c4ad4027f10745e7ae62c667913574b5951ad Mon Sep 17 00:00:00 2001 From: Evan Hunt Date: Fri, 15 May 2020 16:34:09 -0700 Subject: [PATCH 3/3] CHANGES, README, release note --- CHANGES | 5 +++++ README.md | 7 +++++-- doc/notes/notes-current.rst | 3 +++ 3 files changed, 13 insertions(+), 2 deletions(-) diff --git a/CHANGES b/CHANGES index f68af14357..eef4ebcfd8 100644 --- a/CHANGES +++ b/CHANGES @@ -1,3 +1,8 @@ +5419. [func] "dig +qid=" sets the query ID to an arbitrary + value. "configure --enable-singletrace" allows + trace logging of a single query when QID is set to 0. + [GL #1851] + 5418. [bug] delv failed to parse deprecated trusted-keys style trust anchors. [GL #1860] diff --git a/README.md b/README.md index 6d921fd85d..c01a88c542 100644 --- a/README.md +++ b/README.md @@ -268,8 +268,11 @@ configure command line. By default, fixed rrset-order is disabled to reduce memory footprint. The `--enable-querytrace` option causes `named` to log every step of -processing every query. This should only be enabled when debugging, because -it has a significant negative impact on query performance. +processing every query. The `--enable-singletrace` option turns on the +same verbose tracing, but allows an individual query to be separately +traced by setting its query ID to 0. These options should only be enabled +when debugging, because they have a significant negative impact on query +performance. `make install` will install `named` and the various BIND 9 libraries. By default, installation is into /usr/local, but this can be changed with the diff --git a/doc/notes/notes-current.rst b/doc/notes/notes-current.rst index 35bfeb40ca..46d61fd32d 100644 --- a/doc/notes/notes-current.rst +++ b/doc/notes/notes-current.rst @@ -97,6 +97,9 @@ Feature Changes consistency. Log messages are emitted for streams with inconsistent message IDs. [GL #1674] +- ``dig +qid=`` allows the user to specify a particular query ID + for testing purposes. [GL #1851] + Bug Fixes ~~~~~~~~~