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

@@ -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

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.