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.

diff --git a/configure.ac b/configure.ac
index dd075e65f297723f2d5c5efe9a7115d0d218e6a7..2a5a9b4c51437d79f3364e965557778c3a29c91c 100644 (file)
--- 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 ac8b3d86727b90f5fe0fe373f1a9cc4b0ae14aa9..e5a6f04d20624b1ce04802d7e6a826162859ad60 100644 (file)
--- 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 fcf387e94e7e49335b1881540bb22885cfd25eb9..d03343c371b218ec25ff1681e1153c4907525d84 100644 (file)
--- a/lib/isc/log.c
+++ b/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 (!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) {
+                       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 7b47b79c2607bc086a6b558a4232bea304b12bac..681b730731bf53bf56e543c1a1d89014239e1b47 100644 (file)
--- 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 14f9618b07249bd1fa4d372ef28d40957cce407d..8a959b229e7e1160977be207327d771850f75809 100644 (file)
--- a/lib/ns/client.c
+++ b/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.