NEWS

@@ -3,7 +3,8 @@ Knot Resolver 5.4.1 (2021-0m-dd)
 
 Bugfixes
 --------
-- fix build without doh2 support (!1197)
+- fix build without doh2 support after 5.4.0 (!1197)
+- fix policy.DEBUG* logging and -V/--version after 5.4.0 (!1199)
 
 
 Knot Resolver 5.4.0 (2021-07-29)

daemon/engine.c

@@ -241,7 +241,7 @@ static int l_log_groups(lua_State *L)
 	// get
 	lua_newtable(L);
 	int i = 1;
-	for (int grp = LOG_GRP_SYSTEM; grp <= LOG_GRP_DEVEL; grp++) {
+	for (enum kr_log_group grp = LOG_GRP_SYSTEM; grp < LOG_GRP_REQDBG; grp++) {
 		const char *name = kr_log_grp2name(grp);
 		if (kr_fails_assert(name))
 			continue;

daemon/lua/kres-gen-29.lua

@@ -11,7 +11,7 @@ struct timeval {
 };
 
 typedef struct knot_dump_style knot_dump_style_t;
-extern const knot_dump_style_t KNOT_DUMP_STYLE_DEFAULT;
+extern const knot_dump_style_t KR_DUMP_STYLE_DEFAULT;
 struct kr_cdb_api {};
 struct lru {};
 typedef enum {KNOT_ANSWER, KNOT_AUTHORITY, KNOT_ADDITIONAL} knot_section_t;
@@ -307,7 +307,7 @@ struct kr_server_selection {
 	struct local_state *local_state;
 };
 typedef int kr_log_level_t;
-enum kr_log_group {LOG_GRP_UNKNOWN = -1, LOG_GRP_SYSTEM = 1, LOG_GRP_CACHE, LOG_GRP_IO, LOG_GRP_NETWORK, LOG_GRP_TA, LOG_GRP_TLS, LOG_GRP_GNUTLS, LOG_GRP_TLSCLIENT, LOG_GRP_XDP, LOG_GRP_ZIMPORT, LOG_GRP_ZSCANNER, LOG_GRP_DOH, LOG_GRP_DNSSEC, LOG_GRP_HINT, LOG_GRP_PLAN, LOG_GRP_ITERATOR, LOG_GRP_VALIDATOR, LOG_GRP_RESOLVER, LOG_GRP_SELECTION, LOG_GRP_ZCUT, LOG_GRP_COOKIES, LOG_GRP_STATISTICS, LOG_GRP_REBIND, LOG_GRP_WORKER, LOG_GRP_POLICY, LOG_GRP_TASENTINEL, LOG_GRP_TASIGNALING, LOG_GRP_TAUPDATE, LOG_GRP_DAF, LOG_GRP_DETECTTIMEJUMP, LOG_GRP_DETECTTIMESKEW, LOG_GRP_GRAPHITE, LOG_GRP_PREFILL, LOG_GRP_PRIMING, LOG_GRP_SRVSTALE, LOG_GRP_WATCHDOG, LOG_GRP_NSID, LOG_GRP_DNSTAP, LOG_GRP_TESTS, LOG_GRP_DOTAUTH, LOG_GRP_HTTP, LOG_GRP_CONTROL, LOG_GRP_MODULE, LOG_GRP_DEVEL};
+enum kr_log_group {LOG_GRP_UNKNOWN = -1, LOG_GRP_SYSTEM = 1, LOG_GRP_CACHE, LOG_GRP_IO, LOG_GRP_NETWORK, LOG_GRP_TA, LOG_GRP_TLS, LOG_GRP_GNUTLS, LOG_GRP_TLSCLIENT, LOG_GRP_XDP, LOG_GRP_ZIMPORT, LOG_GRP_ZSCANNER, LOG_GRP_DOH, LOG_GRP_DNSSEC, LOG_GRP_HINT, LOG_GRP_PLAN, LOG_GRP_ITERATOR, LOG_GRP_VALIDATOR, LOG_GRP_RESOLVER, LOG_GRP_SELECTION, LOG_GRP_ZCUT, LOG_GRP_COOKIES, LOG_GRP_STATISTICS, LOG_GRP_REBIND, LOG_GRP_WORKER, LOG_GRP_POLICY, LOG_GRP_TASENTINEL, LOG_GRP_TASIGNALING, LOG_GRP_TAUPDATE, LOG_GRP_DAF, LOG_GRP_DETECTTIMEJUMP, LOG_GRP_DETECTTIMESKEW, LOG_GRP_GRAPHITE, LOG_GRP_PREFILL, LOG_GRP_PRIMING, LOG_GRP_SRVSTALE, LOG_GRP_WATCHDOG, LOG_GRP_NSID, LOG_GRP_DNSTAP, LOG_GRP_TESTS, LOG_GRP_DOTAUTH, LOG_GRP_HTTP, LOG_GRP_CONTROL, LOG_GRP_MODULE, LOG_GRP_DEVEL, LOG_GRP_REQDBG};
 
 kr_layer_t kr_layer_t_static;
 _Bool kr_dbg_assertion_abort;

daemon/lua/kres-gen-31.lua

@@ -11,7 +11,7 @@ struct timeval {
 };
 
 typedef struct knot_dump_style knot_dump_style_t;
-extern const knot_dump_style_t KNOT_DUMP_STYLE_DEFAULT;
+extern const knot_dump_style_t KR_DUMP_STYLE_DEFAULT;
 struct kr_cdb_api {};
 struct lru {};
 typedef enum {KNOT_ANSWER, KNOT_AUTHORITY, KNOT_ADDITIONAL} knot_section_t;
@@ -307,7 +307,7 @@ struct kr_server_selection {
 	struct local_state *local_state;
 };
 typedef int kr_log_level_t;
-enum kr_log_group {LOG_GRP_UNKNOWN = -1, LOG_GRP_SYSTEM = 1, LOG_GRP_CACHE, LOG_GRP_IO, LOG_GRP_NETWORK, LOG_GRP_TA, LOG_GRP_TLS, LOG_GRP_GNUTLS, LOG_GRP_TLSCLIENT, LOG_GRP_XDP, LOG_GRP_ZIMPORT, LOG_GRP_ZSCANNER, LOG_GRP_DOH, LOG_GRP_DNSSEC, LOG_GRP_HINT, LOG_GRP_PLAN, LOG_GRP_ITERATOR, LOG_GRP_VALIDATOR, LOG_GRP_RESOLVER, LOG_GRP_SELECTION, LOG_GRP_ZCUT, LOG_GRP_COOKIES, LOG_GRP_STATISTICS, LOG_GRP_REBIND, LOG_GRP_WORKER, LOG_GRP_POLICY, LOG_GRP_TASENTINEL, LOG_GRP_TASIGNALING, LOG_GRP_TAUPDATE, LOG_GRP_DAF, LOG_GRP_DETECTTIMEJUMP, LOG_GRP_DETECTTIMESKEW, LOG_GRP_GRAPHITE, LOG_GRP_PREFILL, LOG_GRP_PRIMING, LOG_GRP_SRVSTALE, LOG_GRP_WATCHDOG, LOG_GRP_NSID, LOG_GRP_DNSTAP, LOG_GRP_TESTS, LOG_GRP_DOTAUTH, LOG_GRP_HTTP, LOG_GRP_CONTROL, LOG_GRP_MODULE, LOG_GRP_DEVEL};
+enum kr_log_group {LOG_GRP_UNKNOWN = -1, LOG_GRP_SYSTEM = 1, LOG_GRP_CACHE, LOG_GRP_IO, LOG_GRP_NETWORK, LOG_GRP_TA, LOG_GRP_TLS, LOG_GRP_GNUTLS, LOG_GRP_TLSCLIENT, LOG_GRP_XDP, LOG_GRP_ZIMPORT, LOG_GRP_ZSCANNER, LOG_GRP_DOH, LOG_GRP_DNSSEC, LOG_GRP_HINT, LOG_GRP_PLAN, LOG_GRP_ITERATOR, LOG_GRP_VALIDATOR, LOG_GRP_RESOLVER, LOG_GRP_SELECTION, LOG_GRP_ZCUT, LOG_GRP_COOKIES, LOG_GRP_STATISTICS, LOG_GRP_REBIND, LOG_GRP_WORKER, LOG_GRP_POLICY, LOG_GRP_TASENTINEL, LOG_GRP_TASIGNALING, LOG_GRP_TAUPDATE, LOG_GRP_DAF, LOG_GRP_DETECTTIMEJUMP, LOG_GRP_DETECTTIMESKEW, LOG_GRP_GRAPHITE, LOG_GRP_PREFILL, LOG_GRP_PRIMING, LOG_GRP_SRVSTALE, LOG_GRP_WATCHDOG, LOG_GRP_NSID, LOG_GRP_DNSTAP, LOG_GRP_TESTS, LOG_GRP_DOTAUTH, LOG_GRP_HTTP, LOG_GRP_CONTROL, LOG_GRP_MODULE, LOG_GRP_DEVEL, LOG_GRP_REQDBG};
 
 kr_layer_t kr_layer_t_static;
 _Bool kr_dbg_assertion_abort;

daemon/lua/kres-gen.sh

@@ -64,7 +64,7 @@ EOF
 
 printf "
 typedef struct knot_dump_style knot_dump_style_t;
-extern const knot_dump_style_t KNOT_DUMP_STYLE_DEFAULT;
+extern const knot_dump_style_t KR_DUMP_STYLE_DEFAULT;
 struct kr_cdb_api {};
 struct lru {};
 "

daemon/lua/kres.lua

@@ -395,7 +395,7 @@ ffi.metatype( knot_rrset_t, {
 			if rr:rdcount() > 0 then
 				local ret
 				if i ~= nil then
-					ret = knot.knot_rrset_txt_dump_data(rr, i, rrset_buf, rrset_buflen, knot.KNOT_DUMP_STYLE_DEFAULT)
+					ret = knot.knot_rrset_txt_dump_data(rr, i, rrset_buf, rrset_buflen, C.KR_DUMP_STYLE_DEFAULT)
 				else
 					ret = -1
 				end
@@ -412,7 +412,7 @@ ffi.metatype( knot_rrset_t, {
 			local size = ffi.new('size_t[1]', { bufsize }) -- one size_t = bufsize
 
 			local ret = knot.knot_rrset_txt_dump(rr, dump, size,
-							style or knot.KNOT_DUMP_STYLE_DEFAULT)
+							style or C.KR_DUMP_STYLE_DEFAULT)
 			local result = nil
 			if ret >= 0 then
 				result = ffi.string(dump[0], ret)
@@ -428,7 +428,7 @@ ffi.metatype( knot_rrset_t, {
 			ffi.gc(dump, C.free)
 
 			local ret = knot.knot_rrset_txt_dump_data(rr, i, dump, 1024,
-							knot.KNOT_DUMP_STYLE_DEFAULT)
+							C.KR_DUMP_STYLE_DEFAULT)
 			if ret >= 0 then
 				local out = {}
 				out.owner = dname2str(rr:owner())
@@ -797,15 +797,15 @@ ffi.metatype( kr_request_t, {
 			assert(ffi.istype(kr_request_t, req))
 			local buf = {}
 			if #req.answ_selected ~= 0 then
-				table.insert(buf, string.format('[%05d.00][dbg ] selected rrsets from answer sections:\n', req.uid))
+				table.insert(buf, ';; selected from ANSWER sections:\n')
 				table.insert(buf, tostring(req.answ_selected))
 			end
 			if #req.auth_selected ~= 0 then
-				table.insert(buf, string.format('[%05d.00][dbg ] selected rrsets from authority sections:\n', req.uid))
+				table.insert(buf, ';; selected from AUTHORITY sections:\n')
 				table.insert(buf, tostring(req.auth_selected))
 			end
 			if #req.add_selected ~= 0 then
-				table.insert(buf, string.format('[%05d.00][dbg ] selected rrsets from additional sections:\n', req.uid))
+				table.insert(buf, ';; selected from ADDITIONAL sections:\n')
 				table.insert(buf, tostring(req.add_selected))
 			end
 			return table.concat(buf, '')

daemon/lua/sandbox.lua.in

@@ -31,7 +31,8 @@ local function curr_file() return debug.getinfo(4,'S').source end
 local function curr_line() return debug.getinfo(4,'l').currentline end
 
 local function log_fmt(grp, level, fmt, ...)
-	ffi.C.kr_log_fmt(grp, level, 'CODE_FILE='..curr_file(), 'CODE_LINE='..curr_line(), '',
+	ffi.C.kr_log_fmt(grp, level,
+			'CODE_FILE='..curr_file(), 'CODE_LINE='..curr_line(), 'CODE_FUNC=',
 			'[%-6s] %s\n', ffi.C.kr_log_grp2name(grp), string.format(fmt, ...))
 end
 

daemon/main.c

@@ -265,7 +265,7 @@ static int parse_args(int argc, char **argv, struct args *args)
 			args->quiet = true;
 			break;
 		case 'V':
-			kr_log_info(SYSTEM, "%s, version %s\n", "Knot Resolver", PACKAGE_VERSION);
+			printf("Knot Resolver, version %s\n", PACKAGE_VERSION);
 			return EXIT_SUCCESS;
 		case 'h':
 		case '?':
@@ -406,6 +406,7 @@ static void drop_capabilities(void)
 
 int main(int argc, char **argv)
 {
+	kr_log_group_reset();
 	if (setvbuf(stdout, NULL, _IONBF, 0) || setvbuf(stderr, NULL, _IONBF, 0)) {
 		kr_log_error(SYSTEM, "failed to to set output buffering (ignored): %s\n",
 				strerror(errno));

doc/config-logging-monitoring.rst

@@ -14,7 +14,8 @@ in ``syslog.h``. It is possible change logging level using
 
 Logging level ``notice`` is set after start by default,
 so logs from Knot Resolver should contain only couple lines a day.
-For debugging purposes it is possible to use the very verbose ``debug`` level.
+For debugging purposes it is possible to use the very verbose ``debug`` level,
+but that is generally not usable unless restricted in some way (see below).
 
 In addition to levels, logging is also divided into the
 :ref:`groups <config_log_groups>`. All groups
@@ -22,6 +23,11 @@ are logged by default, but you can enable ``debug`` level for selected groups us
 :func:`log_groups` function. Other groups are logged to the log level
 set by :func:`log_level`.
 
+It is also possible to enable ``debug`` logging level for particular requests,
+with :ref:`policies <mod-policy-logging>` or as :ref:`an HTTP service <mod-http-trace>`.
+
+Less verbose logging for DNSSEC validation errors can be enabled by using :ref:`mod-bogus_log` module.
+
 .. py:function:: log_level([level])
 
   :param: string ``'crit'``, ``'err'``, ``'warning'``, ``'notice'``,
@@ -67,10 +73,6 @@ set by :func:`log_level`.
      log_groups()              -- list active log groups
      log_groups({})            -- remove all log groups
 
-It is also possible to enable ``debug`` logging level for *a single request*, see chapter :ref:`mod-http-trace`.
-
-Less verbose logging for DNSSEC validation errors can be enabled using :ref:`mod-bogus_log` module.
-
 Various statistics for monitoring purposes are available in :ref:`mod-stats` module, including export to central systems like Graphite, Metronome, InfluxDB, or Prometheus format.
 
 Resolver :ref:`mod-watchdog` is tool to detect and recover from potential bugs that cause the resolver to stop responding properly to queries.

lib/log.c

@@ -81,6 +81,7 @@ const log_group_names_t log_group_names[] = {
 	GRP_NAME_ITEM(LOG_GRP_CONTROL),
 	GRP_NAME_ITEM(LOG_GRP_MODULE),
 	GRP_NAME_ITEM(LOG_GRP_DEVEL),
+	GRP_NAME_ITEM(LOG_GRP_REQDBG),
 	{ NULL, LOG_GRP_UNKNOWN },
 };
 
@@ -237,6 +238,7 @@ void kr_log_group_reset()
 {
 	bool had_gnutls = kr_log_group_is_set(LOG_GRP_GNUTLS);
 	kr_log_groups = 0;
+	kr_log_group_add(LOG_GRP_REQDBG);
 	if (had_gnutls)
 		kr_gnutls_log_level_set();
 }
@@ -272,15 +274,15 @@ static void kr_vlog_req(
 	struct mempool *mp = mp_new(512);
 
 	const uint32_t req_uid = req ? req->uid : 0;
-	char *msg = mp_printf(mp, "[%05u.%02u] %*s",
-				req_uid, qry_uid, indent, "");
+	char *msg = mp_printf(mp, "[%-6s][%05u.%02u] %*s",
+				tag, req_uid, qry_uid, indent, "");
 
 	msg = mp_vprintf_append(mp, msg, fmt, args);
 
 	if (req_has_trace_log(req))
 		req->trace_log(req, msg);
 
-	kr_log_fmt(group, LOG_DEBUG, SD_JOURNAL_METADATA, "[%-6s]%s", tag, msg);
+	kr_log_fmt(group, LOG_DEBUG, SD_JOURNAL_METADATA, "%s", msg);
 
 	mp_delete(mp);
 }

lib/log.h

@@ -77,8 +77,9 @@ enum kr_log_group {
 	LOG_GRP_HTTP,
 	LOG_GRP_CONTROL,
 	LOG_GRP_MODULE,
+	LOG_GRP_DEVEL,
 	/* ^^ Add new log groups above ^^. */
-	LOG_GRP_DEVEL,  /* Must be last entry in enum! */
+	LOG_GRP_REQDBG, /* Must be first non-displayed entry in enum! */
 };
 
 /**
@@ -129,6 +130,7 @@ enum kr_log_group {
 #define LOG_GRP_CONTROL_TAG		"contrl"	/**< ``contrl``: TTY control sockets*/
 #define LOG_GRP_MODULE_TAG		"module"	/**< ``module``: suitable for user-defined modules */
 #define LOG_GRP_DEVEL_TAG		"devel"		/**< ``devel``: for development purposes */
+#define LOG_GRP_REQDBG_TAG		"reqdbg"	/**< ``reqdbg``: debug logs enabled by policy actions */
 ///@}
 
 KR_EXPORT
@@ -181,10 +183,6 @@ kr_log_level_t kr_log_name2level(const char *name);
 	kr_log_fmt(LOG_GRP_ ## grp, LOG_INFO, SD_JOURNAL_METADATA, \
 			"[%-6s] " fmt, LOG_GRP_ ## grp ## _TAG, ## __VA_ARGS__)
 
-#define kr_log_warning(grp, fmt, ...) \
-	kr_log_fmt(LOG_GRP_ ## grp, LOG_WARNING, SD_JOURNAL_METADATA, \
-			"[%-6s] " fmt, LOG_GRP_ ## grp ## _TAG, ## __VA_ARGS__)
-
 #define kr_log_notice(grp, fmt, ...) \
 	kr_log_fmt(LOG_GRP_ ## grp, LOG_NOTICE, SD_JOURNAL_METADATA, \
 			"[%-6s] " fmt, LOG_GRP_ ## grp ## _TAG, ## __VA_ARGS__)
@@ -192,6 +190,10 @@ kr_log_level_t kr_log_name2level(const char *name);
 /** Levels less severe than ``notice`` are not logged by default. */
 #define LOG_DEFAULT_LEVEL	LOG_NOTICE
 
+#define kr_log_warning(grp, fmt, ...) \
+	kr_log_fmt(LOG_GRP_ ## grp, LOG_WARNING, SD_JOURNAL_METADATA, \
+			"[%-6s] " fmt, LOG_GRP_ ## grp ## _TAG, ## __VA_ARGS__)
+
 /** Significant error.  The process continues, except for configuration errors during startup. */
 #define kr_log_error(grp, fmt, ...) \
 	kr_log_fmt(LOG_GRP_ ## grp, LOG_ERR, SD_JOURNAL_METADATA, \
@@ -261,6 +263,11 @@ bool kr_log_is_debug_fun(enum kr_log_group group, const struct kr_request *req);
 
 /* Helpers "internal" to log.* */
 
+/** @internal
+ *
+ * If you don't have location, pass ("CODE_FILE=", "CODE_LINE=", "CODE_FUNC=")
+ * Others than systemd don't utilize these metadata.
+ */
 KR_EXPORT KR_PRINTF(6)
 void kr_log_fmt(enum kr_log_group group, kr_log_level_t level, const char *file, const char *line,
 		const char *func, const char *fmt, ...);

lib/utils.c

@@ -1010,6 +1010,10 @@ char *kr_pkt_text(const knot_pkt_t *pkt)
 	return result;
 }
 
+const knot_dump_style_t KR_DUMP_STYLE_DEFAULT = { /* almost all = false, */
+	.show_ttl = true,
+};
+
 char *kr_rrset_text(const knot_rrset_t *rr)
 {
 	if (!rr) {
@@ -1019,7 +1023,7 @@ char *kr_rrset_text(const knot_rrset_t *rr)
 	/* Note: knot_rrset_txt_dump will double the size until the rrset fits */
 	size_t bufsize = 128;
 	char *buf = malloc(bufsize);
-	int ret = knot_rrset_txt_dump(rr, &buf, &bufsize, &KNOT_DUMP_STYLE_DEFAULT);
+	int ret = knot_rrset_txt_dump(rr, &buf, &bufsize, &KR_DUMP_STYLE_DEFAULT);
 	if (ret < 0) {
 		free(buf);
 		return NULL;

lib/utils.h

@@ -401,6 +401,11 @@ int kr_ranked_rrarray_set_wire(ranked_rr_array_t *array, bool to_wire,
 			       uint32_t qry_uid, bool check_dups,
 			       bool (*extraCheck)(const ranked_rr_array_entry_t *));
 
+
+/** Style used by the kr_*_text() functions. */
+KR_EXPORT extern
+const knot_dump_style_t KR_DUMP_STYLE_DEFAULT;
+
 /**
  * @return Newly allocated string representation of packet.
  * Caller has to free() returned string.

modules/bogus_log/README.rst

@@ -5,7 +5,7 @@
 DNSSEC validation failure logging
 =================================
 
-This module adds error message for each DNSSEC validation failure.
+This module logs a message for each DNSSEC validation failure (on ``notice`` :func:`level <log_level>`).
 It is meant to provide hint to operators which queries should be
 investigated using diagnostic tools like DNSViz_.
 
@@ -19,7 +19,7 @@ Example of error message logged by this module:
 
 .. code-block:: none
 
-        DNSSEC validation failure dnssec-failed.org. DNSKEY
+        [dnssec] validation failure: dnssec-failed.org. DNSKEY
 
 .. _DNSViz: http://dnsviz.net/
 
@@ -28,15 +28,17 @@ List of most frequent queries which fail as DNSSEC bogus can be obtained at run-
 .. code-block:: lua
 
       > bogus_log.frequent()
-      [1] => {
-          [type] => DNSKEY
-          [count] => 1
-          [name] => dnssec-failed.org.
-      }
-      [2] => {
-          [type] => DNSKEY
-          [count] => 13
-          [name] => rhybar.cz.
+      {
+          {
+              ['count'] = 1,
+              ['name'] = 'dnssec-failed.org.',
+              ['type'] = 'DNSKEY',
+          },
+          {
+              ['count'] = 13,
+              ['name'] = 'rhybar.cz.',
+              ['type'] = 'DNSKEY',
+          },
       }
 
 Please note that in future this module might be replaced

modules/bogus_log/bogus_log.c

@@ -38,7 +38,7 @@ static int consume(kr_layer_t *ctx, knot_pkt_t *pkt)
 	auto_free char *qname_text = kr_dname_text(knot_pkt_qname(pkt));
 	auto_free char *qtype_text = kr_rrtype_text(knot_pkt_qtype(pkt));
 
-	kr_log_error(DNSSEC, "DNSSEC validation failure %s %s\n", qname_text, qtype_text);
+	kr_log_notice(DNSSEC, "validation failure: %s %s\n", qname_text, qtype_text);
 
 	/* log of most frequent bogus queries */
 	uint16_t type = knot_pkt_qtype(pkt);

modules/http/trace.rst

@@ -10,8 +10,8 @@ Using query policies
 
 Query policies :any:`policy.DEBUG_ALWAYS`, :any:`policy.DEBUG_CACHE_MISS` or
 :any:`policy.DEBUG_IF` can be used to enable debug-level logging for selected
-subdomains or queries matching specific conditions. Please refer to their
-documentation for usage.
+subdomains or queries matching specific conditions. Please refer to
+:ref:`mod-policy-logging` for more information.
 
 Using HTTP module
 -----------------

modules/policy/README.rst

@@ -201,49 +201,54 @@ Following actions act on request and then processing continue until first non-ch
 
    Set and/or clear some flags for the query.  There can be multiple flags to set/clear.  You can just pass a single flag name (string) or a set of names. Flag names correspond to :c:type:`kr_qflags` structure.  Use only if you know what you are doing.
 
-.. py:attribute:: QTRACE
 
-   Pretty-print DNS response packets from authoritative servers into debug logs for the query and its sub-queries.  It's useful for debugging weird DNS servers.
-   Note that debug-level logs are off by default; see :func:`log_level`.
+.. _mod-policy-logging:
 
-   .. code-block:: lua
+Actions for extra logging
+^^^^^^^^^^^^^^^^^^^^^^^^^
 
-      -- log answers from all authoritative servers involved in resolving
-      -- requests for example.net. and its subdomains
-      policy.add(policy.suffix(policy.QTRACE, policy.todnames({'example.net'})))
+These are also "chain" actions, i.e. they don't stop processing the policy rule list.
+Similarly to other actions, they apply during whole processing of the client's request,
+i.e. including any sub-queries.
 
-.. py:attribute:: REQTRACE
+The log lines from these policy actions are tagged by extra ``[reqdbg]`` prefix,
+and they are produced regardless of your :func:`log_level()` setting.
+They are marked as ``debug`` level, so e.g. with journalctl command you can use ``-p info`` to skip them.
 
-   Pretty-print DNS requests from clients into the verbose log. It's useful for debugging weird DNS clients.
-   Debug-level logging must be enabled for this policy to be effective; see :func:`log_level`.
-   It makes most sense together with :ref:`mod-view` (enabling per-client)
-   and probably with verbose logging those request (e.g. ``DEBUG_ALWAYS``).
+.. warning::  Beware of producing too much logs.
+
+   These actions are not suitable for use on a large fraction of resolver's requests.
+   The extra logs have significant performance impact and might also overload your logging system
+   (or get rate-limited by it).
+   You can use `Filters`_ to further limit on which requests this happens.
 
 .. py:attribute:: DEBUG_ALWAYS
 
-   Enable extra verbose logging for all requests, including cache hits. See caveats for :func:`policy.DEBUG_IF`.
+   Print debug-level logging for this request.
+   That also includes messages from client (:any:`REQTRACE`), upstream servers (:any:`QTRACE`), and stats about interesting records at the end.
 
-.. py:data:: DEBUG_CACHE_MISS
+   .. code-block:: lua
 
-   Enable extra verbose logging but print logs only for requests which required information which was not available locally (i.e. requests which forced resolver to communicate over network). Intended usage is for debugging problems with remote servers. This action typically produces less logs than :any:`policy.DEBUG_ALWAYS` but all caveats from :func:`policy.DEBUG_IF` apply as well.
+      -- debug requests that ask for flaky.example.net or below
+      policy.add(policy.suffix(policy.DEBUG_ALWAYS,
+          policy.todnames({'flaky.example.net'})))
 
-   .. code-block:: lua
+.. py:attribute:: DEBUG_CACHE_MISS
 
-      policy.add(policy.suffix(
-          policy.DEBUG_CACHE_MISS,
-          policy.todnames({'example.com.'})))
+   Same as :any:`DEBUG_ALWAYS` but only if the request required information which was not available locally, i.e. requests which forced resolver to ask upstream server(s).
+   Intended usage is for debugging problems with remote servers.
 
 .. py:function:: DEBUG_IF(test_function)
 
-   :param test_function: Function with single argument of type :c:type:`kr_request` which returns ``true`` if debug logs for a given request should be generated and ``false`` otherwise.
+   :param test_function: Function with single argument of type :c:type:`kr_request` which returns ``true`` if debug logs for that request should be generated and ``false`` otherwise.
 
-   Enable extra verbose logging but print logs only for requests which match condition specified by ``test_function``. This allows to fine-tune which requests should be printed.
+   Same as :any:`DEBUG_ALWAYS` but only logs if the test_function says so.
 
-   .. warning:: Logging on debug level has significant performance impact on resolver and might also overload you logging system because one request can easily generate tens of kilobytes of logs. Always use appropriate `Filters`_ to limit number of requests triggering this action to a minimum!
+   .. note:: ``test_function`` is evaluated only when request is finished.
+        As a result all debug logs this request must be collected,
+        and at the end they get either printed or thrown away.
 
-   .. note:: ``test_function`` is evaluated only when request is finished. As a result debug logs for all requests must be collected until request is finished because it is not possible to know beforehand how ``test_function`` at the end evaluates given request. When a request is finalized logs are either printed or thrown away.
-
-   Example usage which gathers verbose logs for all requests in subtree ``dnssec-failed.org.`` and prints debug logs for all requests finished with states different than ``kres.DONE`` (most importantly ``kres.FAIL``, see :c:type:`kr_layer_state`).
+   Example usage which gathers verbose logs for all requests in subtree ``dnssec-failed.org.`` and prints debug logs for those finishing in a different state than ``kres.DONE`` (most importantly ``kres.FAIL``, see :c:type:`kr_layer_state`).
 
    .. code-block:: lua
 
@@ -253,6 +258,21 @@ Following actions act on request and then processing continue until first non-ch
                           end),
           policy.todnames({'dnssec-failed.org.'})))
 
+.. py:attribute:: QTRACE
+
+   Pretty-print DNS responses from upstream servers (or cache) into logs.
+   It's useful for debugging weird DNS servers.
+
+   If you do not use ``QTRACE`` in combination with ``DEBUG*``,
+   you additionally need either ``log_groups({'iterat'})`` (possibly with other groups)
+   or ``log_level('debug')`` to see the output in logs.
+
+.. py:attribute:: REQTRACE
+
+   Pretty-print DNS requests from clients into the verbose log. It's useful for debugging weird DNS clients.
+   It makes most sense together with :ref:`mod-view` (enabling per-client)
+   and probably with verbose logging those request (e.g. use :any:`DEBUG_ALWAYS` instead).
+
 
 Custom actions
 ^^^^^^^^^^^^^^

modules/policy/policy.lua

@@ -2,6 +2,9 @@
 local kres = require('kres')
 local ffi = require('ffi')
 
+local LOG_GRP_POLICY_TAG = ffi.string(ffi.C.kr_log_grp2name(ffi.C.LOG_GRP_POLICY))
+local LOG_GRP_REQDBG_TAG = ffi.string(ffi.C.kr_log_grp2name(ffi.C.LOG_GRP_REQDBG))
+
 local todname = kres.str2dname -- not available during module load otherwise
 
 -- Counter of unique rules
@@ -643,31 +646,39 @@ end
 
 local debug_logline_cb = ffi.cast('trace_log_f', function (_, msg)
 	jit.off(true, true) -- JIT for (C -> lua)^2 nesting isn't allowed
-	-- msg typically ends with newline
-	log_debug(ffi.C.LOG_GRP_POLICY, "%s", msg)
+	ffi.C.kr_log_fmt(
+		ffi.C.LOG_GRP_REQDBG, -- but the original [group] tag also remains in the string
+		LOG_DEBUG,
+		'CODE_FILE=policy.lua', 'CODE_LINE=', 'CODE_FUNC=policy.DEBUG_ALWAYS', -- no meaningful locations
+		'[%-6s]%s', LOG_GRP_REQDBG_TAG, msg) -- msg should end with newline already
 end)
 ffi.gc(debug_logline_cb, free_cb)
 
+-- LOG_DEBUG without log_trace and without code locations
+local function log_notrace(req, fmt, ...)
+	ffi.C.kr_log_fmt(ffi.C.LOG_GRP_REQDBG, LOG_DEBUG,
+		'CODE_FILE=policy.lua', 'CODE_LINE=', 'CODE_FUNC=', -- no meaningful locations
+		'%s', string.format( -- convert in lua, as integers in C varargs would pass as double
+			'[%-6s][%-6s][%05u.00] ' .. fmt,
+			LOG_GRP_REQDBG_TAG, LOG_GRP_POLICY_TAG, req.uid, ...)
+	)
+end
+
 local debug_logfinish_cb = ffi.cast('trace_callback_f', function (req)
 	jit.off(true, true) -- JIT for (C -> lua)^2 nesting isn't allowed
-	log_req(req, 0, 0, ffi.C.LOG_GRP_POLICY,
-		'following rrsets were marked as interesting:\n' ..
+	log_notrace(req, 'following rrsets were marked as interesting:\n%s\n',
 		req:selected_tostring())
 	if req.answer ~= nil then
-		log_req(req, 0, 0, ffi.C.LOG_GRP_POLICY,
-			'answer packet:\n' .. tostring(req.answer))
+		log_notrace(req, 'answer packet:\n%s\n', req.answer)
 	else
-		log_req(req, 0, 0, ffi.C.LOG_GRP_POLICY,
-			'answer packet DROPPED\n')
+		log_notrace(req, 'answer packet DROPPED\n')
 	end
 end)
 ffi.gc(debug_logfinish_cb, free_cb)
 
 -- log request packet
 function policy.REQTRACE(_, req)
-	log_req(req, 0, 0, ffi.C.LOG_GRP_POLICY,
-		'request packet:\n%s',
-		tostring(req.qsource.packet))
+	log_notrace(req, 'request packet:\n%s', req.qsource.packet)
 end
 
 function policy.DEBUG_ALWAYS(state, req)
@@ -691,8 +702,13 @@ function policy.DEBUG_IF(test)
 		jit.off(true, true) -- JIT for (C -> lua)^2 nesting isn't allowed
 		if test(cbreq) then
 			debug_logfinish_cb(cbreq)  -- unconditional version
+
 			local stash = cbreq:vars()['policy_debug_stash']
-			io.write(table.concat(stash, ''))
+			for _, line in ipairs(stash) do -- don't want one huge entry
+				ffi.C.kr_log_fmt(ffi.C.LOG_GRP_REQDBG, LOG_DEBUG,
+					'CODE_FILE=policy.lua', 'CODE_LINE=', 'CODE_FUNC=', -- no meaningful locations
+					'[%-6s]%s', LOG_GRP_REQDBG_TAG, line)
+			end
 		end
 	end)
 	ffi.gc(debug_finish_cb, function (func) func:free() end)