Merge branch 'wpk-dirty-query-debuglog' into 'master'

single-query trace logging

Closes #1851

See merge request isc-projects/bind9!3545

CHANGES

@@ -1,3 +1,8 @@
+5419.	[func]		"dig +qid=<num>" 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]
 

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

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;

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.

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);
 

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 */

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;

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

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=<num>`` allows the user to specify a particular query ID
+   for testing purposes. [GL #1851]
+
 Bug Fixes
 ~~~~~~~~~
 

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 */

lib/isc/log.c

@@ -31,6 +31,7 @@
 #include <isc/stat.h>
 #include <isc/stdio.h>
 #include <isc/string.h>
+#include <isc/thread.h>
 #include <isc/time.h>
 #include <isc/util.h>
 
@@ -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;
+}

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

lib/ns/client.c

@@ -17,6 +17,7 @@
 #include <isc/formatcheck.h>
 #include <isc/fuzz.h>
 #include <isc/hmac.h>
+#include <isc/log.h>
 #include <isc/mutex.h>
 #include <isc/nonce.h>
 #include <isc/once.h>
@@ -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.