malmond / rpms / unbound

Forked from rpms/unbound 3 years ago
Clone

Blame SOURCES/unbound-1.7.3-additional-logging.patch

d9cda3
diff --git a/daemon/worker.c b/daemon/worker.c
d9cda3
index 44a989a..3acecc1 100644
d9cda3
--- a/daemon/worker.c
d9cda3
+++ b/daemon/worker.c
d9cda3
@@ -1193,7 +1193,7 @@ worker_handle_request(struct comm_point* c, void* arg, int error,
d9cda3
 	if(worker->env.cfg->log_queries) {
d9cda3
 		char ip[128];
d9cda3
 		addr_to_str(&repinfo->addr, repinfo->addrlen, ip, sizeof(ip));
d9cda3
-		log_nametypeclass(0, ip, qinfo.qname, qinfo.qtype, qinfo.qclass);
d9cda3
+		log_query_in(ip, qinfo.qname, qinfo.qtype, qinfo.qclass);
d9cda3
 	}
d9cda3
 	if(qinfo.qtype == LDNS_RR_TYPE_AXFR || 
d9cda3
 		qinfo.qtype == LDNS_RR_TYPE_IXFR) {
d9cda3
diff --git a/doc/Changelog b/doc/Changelog
d9cda3
index 3d05ae5..bb74461 100644
d9cda3
--- a/doc/Changelog
d9cda3
+++ b/doc/Changelog
d9cda3
@@ -1,3 +1,15 @@
d9cda3
+30 November 2018: Wouter
d9cda3
+	- log-tag-queryreply: yes in unbound.conf tags the log-queries and
d9cda3
+	  log-replies in the log file for easier log filter maintenance.
d9cda3
+
d9cda3
+21 August 2018: Wouter
d9cda3
+	- log-local-actions: yes option for unbound.conf that logs all the
d9cda3
+	  local zone actions, a patch from Saksham Manchanda (Secure64).
d9cda3
+
d9cda3
+17 August 2018: Wouter
d9cda3
+	- log-servfail: yes prints log lines that say why queries are
d9cda3
+	  returning SERVFAIL to clients.
d9cda3
+
d9cda3
 19 June 2018: Wouter
d9cda3
 	- Fix for unbound-control on Windows and set TCP socket parameters
d9cda3
 	  more closely.
d9cda3
diff --git a/doc/example.conf.in b/doc/example.conf.in
d9cda3
index be83bda..aa06cee 100644
d9cda3
--- a/doc/example.conf.in
d9cda3
+++ b/doc/example.conf.in
d9cda3
@@ -309,6 +309,17 @@ server:
d9cda3
 	# timetoresolve, fromcache and responsesize.
d9cda3
 	# log-replies: no
d9cda3
 
d9cda3
+	# log with tag 'query' and 'reply' instead of 'info' for
d9cda3
+	# filtering log-queries and log-replies from the log.
d9cda3
+	# log-tag-queryreply: no
d9cda3
+
d9cda3
+	# log the local-zone actions, like local-zone type inform is enabled
d9cda3
+	# also for the other local zone types.
d9cda3
+	# log-local-actions: no
d9cda3
+
d9cda3
+	# print log lines that say why queries return SERVFAIL to clients.
d9cda3
+	# log-servfail: no
d9cda3
+
d9cda3
 	# the pid file. Can be an absolute path outside of chroot/work dir.
d9cda3
 	# pidfile: "@UNBOUND_PIDFILE@"
d9cda3
 
d9cda3
diff --git a/doc/unbound.conf.5.in b/doc/unbound.conf.5.in
d9cda3
index 9167a5a..b73bc70 100644
d9cda3
--- a/doc/unbound.conf.5.in
d9cda3
+++ b/doc/unbound.conf.5.in
d9cda3
@@ -618,6 +618,21 @@ Default is no.  Note that it takes time to print these
d9cda3
 lines which makes the server (significantly) slower.  Odd (nonprintable)
d9cda3
 characters in names are printed as '?'.
d9cda3
 .TP
d9cda3
+.B log\-tag\-queryreply: \fI<yes or no>
d9cda3
+Prints the word 'query' and 'reply' with log\-queries and log\-replies.
d9cda3
+This makes filtering logs easier.  The default is off (for backwards
d9cda3
+compatibility).
d9cda3
+.TP
d9cda3
+.B log\-local\-actions: \fI<yes or no>
d9cda3
+Print log lines to inform about local zone actions.  These lines are like the
d9cda3
+local\-zone type inform prints out, but they are also printed for the other
d9cda3
+types of local zones.
d9cda3
+.TP
d9cda3
+.B log\-servfail: \fI<yes or no>
d9cda3
+Print log lines that say why queries return SERVFAIL to clients.
d9cda3
+This is separate from the verbosity debug logs, much smaller, and printed
d9cda3
+at the error level, not the info level of debug info from verbosity.
d9cda3
+.TP
d9cda3
 .B pidfile: \fI<filename>
d9cda3
 The process id is written to the file. Default is "@UNBOUND_PIDFILE@".
d9cda3
 So,
d9cda3
diff --git a/services/localzone.c b/services/localzone.c
d9cda3
index 0f60817..a85619b 100644
d9cda3
--- a/services/localzone.c
d9cda3
+++ b/services/localzone.c
d9cda3
@@ -1459,7 +1459,7 @@ lz_inform_print(struct local_zone* z, struct query_info* qinfo,
d9cda3
 	uint16_t port = ntohs(((struct sockaddr_in*)&repinfo->addr)->sin_port);
d9cda3
 	dname_str(z->name, zname);
d9cda3
 	addr_to_str(&repinfo->addr, repinfo->addrlen, ip, sizeof(ip));
d9cda3
-	snprintf(txt, sizeof(txt), "%s inform %s@%u", zname, ip,
d9cda3
+	snprintf(txt, sizeof(txt), "%s %s %s@%u", zname, local_zone_type2str(z->type), ip,
d9cda3
 		(unsigned)port);
d9cda3
 	log_nametypeclass(0, txt, qinfo->qname, qinfo->qtype, qinfo->qclass);
d9cda3
 }
d9cda3
@@ -1576,7 +1576,8 @@ local_zones_answer(struct local_zones* zones, struct module_env* env,
d9cda3
 			z->override_tree, &tag, tagname, num_tags);
d9cda3
 		lock_rw_unlock(&zones->lock);
d9cda3
 	}
d9cda3
-	if((lzt == local_zone_inform || lzt == local_zone_inform_deny)
d9cda3
+	if((env->cfg->log_local_actions ||
d9cda3
+		lzt == local_zone_inform || lzt == local_zone_inform_deny)
d9cda3
 		&& repinfo)
d9cda3
 		lz_inform_print(z, qinfo, repinfo);
d9cda3
 
d9cda3
diff --git a/services/mesh.c b/services/mesh.c
d9cda3
index 41aba74..55c1947 100644
d9cda3
--- a/services/mesh.c
d9cda3
+++ b/services/mesh.c
d9cda3
@@ -977,7 +977,7 @@ mesh_do_callback(struct mesh_state* m, int rcode, struct reply_info* rep,
d9cda3
 		rcode = LDNS_RCODE_SERVFAIL;
d9cda3
 	if(!rcode && (rep->security == sec_status_bogus ||
d9cda3
 		rep->security == sec_status_secure_sentinel_fail)) {
d9cda3
-		if(!(reason = errinf_to_str(&m->s)))
d9cda3
+		if(!(reason = errinf_to_str_bogus(&m->s)))
d9cda3
 			rcode = LDNS_RCODE_SERVFAIL;
d9cda3
 	}
d9cda3
 	/* send the reply */
d9cda3
@@ -1148,6 +1148,15 @@ void mesh_query_done(struct mesh_state* mstate)
d9cda3
 	struct mesh_cb* c;
d9cda3
 	struct reply_info* rep = (mstate->s.return_msg?
d9cda3
 		mstate->s.return_msg->rep:NULL);
d9cda3
+	if((mstate->s.return_rcode == LDNS_RCODE_SERVFAIL ||
d9cda3
+		(rep && FLAGS_GET_RCODE(rep->flags) == LDNS_RCODE_SERVFAIL))
d9cda3
+		&& mstate->s.env->cfg->log_servfail
d9cda3
+		&& !mstate->s.env->cfg->val_log_squelch) {
d9cda3
+			char* err = errinf_to_str_servfail(&mstate->s);
d9cda3
+			if(err)
d9cda3
+				log_err("%s", err);
d9cda3
+			free(err);
d9cda3
+	}
d9cda3
 	for(r = mstate->reply_list; r; r = r->next) {
d9cda3
 		/* if a response-ip address block has been stored the
d9cda3
 		 *  information should be logged for each client. */
d9cda3
diff --git a/util/config_file.c b/util/config_file.c
d9cda3
index b061760..68a0a15 100644
d9cda3
--- a/util/config_file.c
d9cda3
+++ b/util/config_file.c
d9cda3
@@ -115,6 +115,9 @@ config_create(void)
d9cda3
 	cfg->log_time_ascii = 0;
d9cda3
 	cfg->log_queries = 0;
d9cda3
 	cfg->log_replies = 0;
d9cda3
+	cfg->log_tag_queryreply = 0;
d9cda3
+	cfg->log_local_actions = 0;
d9cda3
+	cfg->log_servfail = 0;
d9cda3
 #ifndef USE_WINSOCK
d9cda3
 #  ifdef USE_MINI_EVENT
d9cda3
 	/* select max 1024 sockets */
d9cda3
@@ -540,6 +543,9 @@ int config_set_option(struct config_file* cfg, const char* opt,
d9cda3
 	else S_YNO("val-log-squelch:", val_log_squelch)
d9cda3
 	else S_YNO("log-queries:", log_queries)
d9cda3
 	else S_YNO("log-replies:", log_replies)
d9cda3
+	else S_YNO("log-tag-queryreply:", log_tag_queryreply)
d9cda3
+	else S_YNO("log-local-actions:", log_local_actions)
d9cda3
+	else S_YNO("log-servfail:", log_servfail)
d9cda3
 	else S_YNO("val-permissive-mode:", val_permissive_mode)
d9cda3
 	else S_YNO("aggressive-nsec:", aggressive_nsec)
d9cda3
 	else S_YNO("ignore-cd-flag:", ignore_cd)
d9cda3
@@ -893,6 +899,9 @@ config_get_option(struct config_file* cfg, const char* opt,
d9cda3
 	else O_STR(opt, "logfile", logfile)
d9cda3
 	else O_YNO(opt, "log-queries", log_queries)
d9cda3
 	else O_YNO(opt, "log-replies", log_replies)
d9cda3
+	else O_YNO(opt, "log-tag-queryreply", log_tag_queryreply)
d9cda3
+	else O_YNO(opt, "log-local-actions", log_local_actions)
d9cda3
+	else O_YNO(opt, "log-servfail", log_servfail)
d9cda3
 	else O_STR(opt, "pidfile", pidfile)
d9cda3
 	else O_YNO(opt, "hide-identity", hide_identity)
d9cda3
 	else O_YNO(opt, "hide-version", hide_version)
d9cda3
@@ -1845,6 +1854,7 @@ config_apply(struct config_file* config)
d9cda3
 	EDNS_ADVERTISED_SIZE = (uint16_t)config->edns_buffer_size;
d9cda3
 	MINIMAL_RESPONSES = config->minimal_responses;
d9cda3
 	RRSET_ROUNDROBIN = config->rrset_roundrobin;
d9cda3
+	LOG_TAG_QUERYREPLY = config->log_tag_queryreply;
d9cda3
 	log_set_time_asc(config->log_time_ascii);
d9cda3
 	autr_permit_small_holddown = config->permit_small_holddown;
d9cda3
 }
d9cda3
@@ -2220,7 +2230,7 @@ void errinf_origin(struct module_qstate* qstate, struct sock_list *origin)
d9cda3
 	}
d9cda3
 }
d9cda3
 
d9cda3
-char* errinf_to_str(struct module_qstate* qstate)
d9cda3
+char* errinf_to_str_bogus(struct module_qstate* qstate)
d9cda3
 {
d9cda3
 	char buf[20480];
d9cda3
 	char* p = buf;
d9cda3
@@ -2245,6 +2255,31 @@ char* errinf_to_str(struct module_qstate* qstate)
d9cda3
 	return p;
d9cda3
 }
d9cda3
 
d9cda3
+char* errinf_to_str_servfail(struct module_qstate* qstate)
d9cda3
+{
d9cda3
+    char buf[20480];
d9cda3
+    char* p = buf;
d9cda3
+    size_t left = sizeof(buf);
d9cda3
+    struct config_strlist* s;
d9cda3
+    char dname[LDNS_MAX_DOMAINLEN+1];
d9cda3
+    char t[16], c[16];
d9cda3
+    sldns_wire2str_type_buf(qstate->qinfo.qtype, t, sizeof(t));
d9cda3
+    sldns_wire2str_class_buf(qstate->qinfo.qclass, c, sizeof(c));
d9cda3
+    dname_str(qstate->qinfo.qname, dname);
d9cda3
+    snprintf(p, left, "SERVFAIL <%s %s %s>:", dname, t, c);
d9cda3
+    left -= strlen(p); p += strlen(p);
d9cda3
+    if(!qstate->errinf)
d9cda3
+        snprintf(p, left, " misc failure");
d9cda3
+    else for(s=qstate->errinf; s; s=s->next) {
d9cda3
+        snprintf(p, left, " %s", s->str);
d9cda3
+        left -= strlen(p); p += strlen(p);
d9cda3
+    }
d9cda3
+    p = strdup(buf);
d9cda3
+    if(!p)
d9cda3
+        log_err("malloc failure in errinf_to_str");
d9cda3
+    return p;
d9cda3
+}
d9cda3
+
d9cda3
 void errinf_rrset(struct module_qstate* qstate, struct ub_packed_rrset_key *rr)
d9cda3
 {
d9cda3
 	char buf[1024];
d9cda3
diff --git a/util/config_file.h b/util/config_file.h
d9cda3
index 4206eb9..1e7f402 100644
d9cda3
--- a/util/config_file.h
d9cda3
+++ b/util/config_file.h
d9cda3
@@ -268,6 +268,12 @@ struct config_file {
d9cda3
 	int log_queries;
d9cda3
 	/** log replies with one line per reply */
d9cda3
 	int log_replies;
d9cda3
+	/** tag log_queries and log_replies for filtering */
d9cda3
+	int log_tag_queryreply;
d9cda3
+	/** log every local-zone hit **/
d9cda3
+	int log_local_actions;
d9cda3
+	/** log servfails with a reason */
d9cda3
+	int log_servfail;
d9cda3
 	/** log identity to report */
d9cda3
 	char* log_identity;
d9cda3
 
d9cda3
@@ -1070,7 +1076,15 @@ void errinf_dname(struct module_qstate* qstate, const char* str,
d9cda3
  * @return string or NULL on malloc failure (already logged).
d9cda3
  *    This string is malloced and has to be freed by caller.
d9cda3
  */
d9cda3
-char* errinf_to_str(struct module_qstate* qstate);
d9cda3
+char* errinf_to_str_bogus(struct module_qstate* qstate);
d9cda3
+
d9cda3
+/**
d9cda3
+ * Create error info in string.  For other servfails.
d9cda3
+ * @param qstate: query state.
d9cda3
+ * @return string or NULL on malloc failure (already logged).
d9cda3
+ *    This string is malloced and has to be freed by caller.
d9cda3
+ */
d9cda3
+char* errinf_to_str_servfail(struct module_qstate* qstate);
d9cda3
 
d9cda3
 /**
d9cda3
  * Used during options parsing
d9cda3
diff --git a/util/configlexer.lex b/util/configlexer.lex
d9cda3
index 6124e32..9b22db1 100644
d9cda3
--- a/util/configlexer.lex
d9cda3
+++ b/util/configlexer.lex
d9cda3
@@ -366,6 +366,9 @@ log-identity{COLON}		{ YDVAR(1, VAR_LOG_IDENTITY) }
d9cda3
 log-time-ascii{COLON}		{ YDVAR(1, VAR_LOG_TIME_ASCII) }
d9cda3
 log-queries{COLON}		{ YDVAR(1, VAR_LOG_QUERIES) }
d9cda3
 log-replies{COLON}		{ YDVAR(1, VAR_LOG_REPLIES) }
d9cda3
+log-tag-queryreply{COLON}      { YDVAR(1, VAR_LOG_TAG_QUERYREPLY) }
d9cda3
+log-local-actions{COLON}       { YDVAR(1, VAR_LOG_LOCAL_ACTIONS) }
d9cda3
+log-servfail{COLON}            { YDVAR(1, VAR_LOG_SERVFAIL) }
d9cda3
 local-zone{COLON}		{ YDVAR(2, VAR_LOCAL_ZONE) }
d9cda3
 local-data{COLON}		{ YDVAR(1, VAR_LOCAL_DATA) }
d9cda3
 local-data-ptr{COLON}		{ YDVAR(1, VAR_LOCAL_DATA_PTR) }
d9cda3
diff --git a/util/configparser.y b/util/configparser.y
d9cda3
index e34665a..4b23a71 100644
d9cda3
--- a/util/configparser.y
d9cda3
+++ b/util/configparser.y
d9cda3
@@ -106,7 +106,7 @@ extern struct config_parser_state* cfg_parser;
d9cda3
 %token VAR_AUTO_TRUST_ANCHOR_FILE VAR_KEEP_MISSING VAR_ADD_HOLDDOWN 
d9cda3
 %token VAR_DEL_HOLDDOWN VAR_SO_RCVBUF VAR_EDNS_BUFFER_SIZE VAR_PREFETCH
d9cda3
 %token VAR_PREFETCH_KEY VAR_SO_SNDBUF VAR_SO_REUSEPORT VAR_HARDEN_BELOW_NXDOMAIN
d9cda3
-%token VAR_IGNORE_CD_FLAG VAR_LOG_QUERIES VAR_LOG_REPLIES
d9cda3
+%token VAR_IGNORE_CD_FLAG VAR_LOG_QUERIES VAR_LOG_REPLIES VAR_LOG_LOCAL_ACTIONS
d9cda3
 %token VAR_TCP_UPSTREAM VAR_SSL_UPSTREAM
d9cda3
 %token VAR_SSL_SERVICE_KEY VAR_SSL_SERVICE_PEM VAR_SSL_PORT VAR_FORWARD_FIRST
d9cda3
 %token VAR_STUB_SSL_UPSTREAM VAR_FORWARD_SSL_UPSTREAM VAR_TLS_CERT_BUNDLE
d9cda3
@@ -158,6 +158,8 @@ extern struct config_parser_state* cfg_parser;
d9cda3
 %token VAR_AUTH_ZONE VAR_ZONEFILE VAR_MASTER VAR_URL VAR_FOR_DOWNSTREAM
d9cda3
 %token VAR_FALLBACK_ENABLED VAR_TLS_ADDITIONAL_PORT VAR_LOW_RTT VAR_LOW_RTT_PERMIL
d9cda3
 %token VAR_ALLOW_NOTIFY VAR_TLS_WIN_CERT
d9cda3
+%token VAR_FORWARD_NO_CACHE VAR_STUB_NO_CACHE VAR_LOG_SERVFAIL
d9cda3
+%token VAR_UNKNOWN_SERVER_TIME_LIMIT VAR_LOG_TAG_QUERYREPLY
d9cda3
 
d9cda3
 %%
d9cda3
 toplevelvars: /* empty */ | toplevelvars toplevelvar ;
d9cda3
@@ -217,6 +219,7 @@ content_server: server_num_threads | server_verbosity | server_port |
d9cda3
 	server_edns_buffer_size | server_prefetch | server_prefetch_key |
d9cda3
 	server_so_sndbuf | server_harden_below_nxdomain | server_ignore_cd_flag |
d9cda3
 	server_log_queries | server_log_replies | server_tcp_upstream | server_ssl_upstream |
d9cda3
+	server_log_local_actions |
d9cda3
 	server_ssl_service_key | server_ssl_service_pem | server_ssl_port |
d9cda3
 	server_minimal_responses | server_rrset_roundrobin | server_max_udp_size |
d9cda3
 	server_so_reuseport | server_delay_close |
d9cda3
@@ -249,7 +252,9 @@ content_server: server_num_threads | server_verbosity | server_port |
d9cda3
 	server_ipsecmod_whitelist | server_ipsecmod_strict |
d9cda3
 	server_udp_upstream_without_downstream | server_aggressive_nsec |
d9cda3
 	server_tls_cert_bundle | server_tls_additional_port | server_low_rtt |
d9cda3
-	server_low_rtt_permil | server_tls_win_cert
d9cda3
+	server_low_rtt_permil | server_tls_win_cert |
d9cda3
+	server_tcp_connection_limit | server_log_servfail |
d9cda3
+	server_unknown_server_time_limit | server_log_tag_queryreply
d9cda3
 	;
d9cda3
 stubstart: VAR_STUB_ZONE
d9cda3
 	{
d9cda3
@@ -764,6 +769,33 @@ server_log_replies: VAR_LOG_REPLIES STRING_ARG
d9cda3
   	free($2);
d9cda3
   }
d9cda3
   ;
d9cda3
+server_log_tag_queryreply: VAR_LOG_TAG_QUERYREPLY STRING_ARG
d9cda3
+  {
d9cda3
+    OUTYY(("P(server_log_tag_queryreply:%s)\n", $2));
d9cda3
+    if(strcmp($2, "yes") != 0 && strcmp($2, "no") != 0)
d9cda3
+        yyerror("expected yes or no.");
d9cda3
+    else cfg_parser->cfg->log_tag_queryreply = (strcmp($2, "yes")==0);
d9cda3
+    free($2);
d9cda3
+  }
d9cda3
+  ;
d9cda3
+server_log_servfail: VAR_LOG_SERVFAIL STRING_ARG
d9cda3
+  {
d9cda3
+	OUTYY(("P(server_log_servfail:%s)\n", $2));
d9cda3
+	if(strcmp($2, "yes") != 0 && strcmp($2, "no") != 0)
d9cda3
+		yyerror("expected yes or no.");
d9cda3
+	else cfg_parser->cfg->log_servfail = (strcmp($2, "yes")==0);
d9cda3
+	free($2);
d9cda3
+  }
d9cda3
+  ;
d9cda3
+server_log_local_actions: VAR_LOG_LOCAL_ACTIONS STRING_ARG
d9cda3
+  {
d9cda3
+	OUTYY(("P(server_log_local_actions:%s)\n", $2));
d9cda3
+	if(strcmp($2, "yes") != 0 && strcmp($2, "no") != 0)
d9cda3
+		yyerror("expected yes or no.");
d9cda3
+	else cfg_parser->cfg->log_local_actions = (strcmp($2, "yes")==0);
d9cda3
+	free($2);
d9cda3
+  }
d9cda3
+  ;
d9cda3
 server_chroot: VAR_CHROOT STRING_ARG
d9cda3
 	{
d9cda3
 		OUTYY(("P(server_chroot:%s)\n", $2));
d9cda3
diff --git a/util/data/msgreply.c b/util/data/msgreply.c
d9cda3
index 772f5d1..df2131c 100644
d9cda3
--- a/util/data/msgreply.c
d9cda3
+++ b/util/data/msgreply.c
d9cda3
@@ -844,7 +844,9 @@ log_reply_info(enum verbosity_value v, struct query_info *qinf,
d9cda3
 	addr_to_str(addr, addrlen, clientip_buf, sizeof(clientip_buf));
d9cda3
 	if(rcode == LDNS_RCODE_FORMERR)
d9cda3
 	{
d9cda3
-		log_info("%s - - - %s - - - ", clientip_buf, rcode_buf);
d9cda3
+		if(LOG_TAG_QUERYREPLY)
d9cda3
+			log_reply("%s - - - %s - - - ", clientip_buf, rcode_buf);
d9cda3
+		else log_info("%s - - - %s - - - ", clientip_buf, rcode_buf);
d9cda3
 	} else {
d9cda3
 		if(qinf->qname)
d9cda3
 			dname_str(qinf->qname, qname_buf);
d9cda3
@@ -852,7 +854,11 @@ log_reply_info(enum verbosity_value v, struct query_info *qinf,
d9cda3
 		pktlen = sldns_buffer_limit(rmsg);
d9cda3
 		sldns_wire2str_type_buf(qinf->qtype, type_buf, sizeof(type_buf));
d9cda3
 		sldns_wire2str_class_buf(qinf->qclass, class_buf, sizeof(class_buf));
d9cda3
-		log_info("%s %s %s %s %s " ARG_LL "d.%6.6d %d %d",
d9cda3
+		if(LOG_TAG_QUERYREPLY)
d9cda3
+			log_reply("%s %s %s %s %s " ARG_LL "d.%6.6d %d %d",
d9cda3
+				clientip_buf, qname_buf, type_buf, class_buf,
d9cda3
+				rcode_buf, (long long)dur.tv_sec, (int)dur.tv_usec, cached, (int)pktlen);
d9cda3
+		else log_info("%s %s %s %s %s " ARG_LL "d.%6.6d %d %d",
d9cda3
 			clientip_buf, qname_buf, type_buf, class_buf,
d9cda3
 			rcode_buf, (long long)dur.tv_sec, (int)dur.tv_usec, cached, (int)pktlen);
d9cda3
 	}
d9cda3
diff --git a/util/log.c b/util/log.c
d9cda3
index 43dd572..fff4319 100644
d9cda3
--- a/util/log.c
d9cda3
+++ b/util/log.c
d9cda3
@@ -391,6 +391,24 @@ log_hex(const char* msg, void* data, size_t length)
d9cda3
 	log_hex_f(verbosity, msg, data, length);
d9cda3
 }
d9cda3
 
d9cda3
+void
d9cda3
+log_query(const char *format, ...)
d9cda3
+{
d9cda3
+	va_list args;
d9cda3
+	va_start(args, format);
d9cda3
+	log_vmsg(LOG_INFO, "query", format, args);
d9cda3
+	va_end(args);
d9cda3
+}
d9cda3
+
d9cda3
+void
d9cda3
+log_reply(const char *format, ...)
d9cda3
+{
d9cda3
+	va_list args;
d9cda3
+	va_start(args, format);
d9cda3
+	log_vmsg(LOG_INFO, "reply", format, args);
d9cda3
+	va_end(args);
d9cda3
+}
d9cda3
+
d9cda3
 void log_buf(enum verbosity_value level, const char* msg, sldns_buffer* buf)
d9cda3
 {
d9cda3
 	if(verbosity < level)
d9cda3
diff --git a/util/log.h b/util/log.h
d9cda3
index 7bc3d9e..172cd01 100644
d9cda3
--- a/util/log.h
d9cda3
+++ b/util/log.h
d9cda3
@@ -160,6 +160,20 @@ void log_warn(const char* format, ...) ATTR_FORMAT(printf, 1, 2);
d9cda3
  */
d9cda3
 void log_hex(const char* msg, void* data, size_t length);
d9cda3
 
d9cda3
+/**
d9cda3
+ * Log query.
d9cda3
+ * Pass printf formatted arguments. No trailing newline is needed.
d9cda3
+ * @param format: printf-style format string. Arguments follow.
d9cda3
+ */
d9cda3
+void log_query(const char* format, ...) ATTR_FORMAT(printf, 1, 2);
d9cda3
+
d9cda3
+/**
d9cda3
+ * Log reply.
d9cda3
+ * Pass printf formatted arguments. No trailing newline is needed.
d9cda3
+ * @param format: printf-style format string. Arguments follow.
d9cda3
+ */
d9cda3
+void log_reply(const char* format, ...) ATTR_FORMAT(printf, 1, 2);
d9cda3
+
d9cda3
 /**
d9cda3
  * Easy alternative for log_hex, takes a sldns_buffer.
d9cda3
  * @param level: verbosity level for this message, compared to global 
d9cda3
diff --git a/util/net_help.c b/util/net_help.c
d9cda3
index a193c36..617a896 100644
d9cda3
--- a/util/net_help.c
d9cda3
+++ b/util/net_help.c
d9cda3
@@ -67,6 +67,9 @@ int MINIMAL_RESPONSES = 0;
d9cda3
 /** rrset order roundrobin: default is no */
d9cda3
 int RRSET_ROUNDROBIN = 0;
d9cda3
 
d9cda3
+/** log tag queries with name instead of 'info' for filtering */
d9cda3
+int LOG_TAG_QUERYREPLY = 0;
d9cda3
+
d9cda3
 /* returns true is string addr is an ip6 specced address */
d9cda3
 int
d9cda3
 str_is_ip6(const char* str)
d9cda3
@@ -335,7 +338,7 @@ log_nametypeclass(enum verbosity_value v, const char* str, uint8_t* name,
d9cda3
 {
d9cda3
 	char buf[LDNS_MAX_DOMAINLEN+1];
d9cda3
 	char t[12], c[12];
d9cda3
-	const char *ts, *cs; 
d9cda3
+	const char *ts, *cs;
d9cda3
 	if(verbosity < v)
d9cda3
 		return;
d9cda3
 	dname_str(name, buf);
d9cda3
@@ -361,6 +364,37 @@ log_nametypeclass(enum verbosity_value v, const char* str, uint8_t* name,
d9cda3
 	log_info("%s %s %s %s", str, buf, ts, cs);
d9cda3
 }
d9cda3
 
d9cda3
+void
d9cda3
+log_query_in(const char* str, uint8_t* name, uint16_t type, uint16_t dclass)
d9cda3
+{
d9cda3
+    char buf[LDNS_MAX_DOMAINLEN+1];
d9cda3
+    char t[12], c[12];
d9cda3
+    const char *ts, *cs;
d9cda3
+    dname_str(name, buf);
d9cda3
+    if(type == LDNS_RR_TYPE_TSIG) ts = "TSIG";
d9cda3
+    else if(type == LDNS_RR_TYPE_IXFR) ts = "IXFR";
d9cda3
+    else if(type == LDNS_RR_TYPE_AXFR) ts = "AXFR";
d9cda3
+    else if(type == LDNS_RR_TYPE_MAILB) ts = "MAILB";
d9cda3
+    else if(type == LDNS_RR_TYPE_MAILA) ts = "MAILA";
d9cda3
+    else if(type == LDNS_RR_TYPE_ANY) ts = "ANY";
d9cda3
+    else if(sldns_rr_descript(type) && sldns_rr_descript(type)->_name)
d9cda3
+        ts = sldns_rr_descript(type)->_name;
d9cda3
+    else {
d9cda3
+        snprintf(t, sizeof(t), "TYPE%d", (int)type);
d9cda3
+        ts = t;
d9cda3
+    }
d9cda3
+    if(sldns_lookup_by_id(sldns_rr_classes, (int)dclass) &&
d9cda3
+        sldns_lookup_by_id(sldns_rr_classes, (int)dclass)->name)
d9cda3
+        cs = sldns_lookup_by_id(sldns_rr_classes, (int)dclass)->name;
d9cda3
+    else {
d9cda3
+        snprintf(c, sizeof(c), "CLASS%d", (int)dclass);
d9cda3
+        cs = c;
d9cda3
+    }
d9cda3
+    if(LOG_TAG_QUERYREPLY)
d9cda3
+            log_query("%s %s %s %s", str, buf, ts, cs);
d9cda3
+    else    log_info("%s %s %s %s", str, buf, ts, cs);
d9cda3
+}
d9cda3
+
d9cda3
 void log_name_addr(enum verbosity_value v, const char* str, uint8_t* zone, 
d9cda3
 	struct sockaddr_storage* addr, socklen_t addrlen)
d9cda3
 {
d9cda3
diff --git a/util/net_help.h b/util/net_help.h
d9cda3
index de2e1ac..f2e0e43 100644
d9cda3
--- a/util/net_help.h
d9cda3
+++ b/util/net_help.h
d9cda3
@@ -99,6 +99,9 @@ extern int MINIMAL_RESPONSES;
d9cda3
 /** rrset order roundrobin */
d9cda3
 extern int RRSET_ROUNDROBIN;
d9cda3
 
d9cda3
+/** log tag queries with name instead of 'info' for filtering */
d9cda3
+extern int LOG_TAG_QUERYREPLY;
d9cda3
+
d9cda3
 /**
d9cda3
  * See if string is ip4 or ip6.
d9cda3
  * @param str: IP specification.
d9cda3
@@ -235,6 +238,12 @@ void sockaddr_store_port(struct sockaddr_storage* addr, socklen_t addrlen,
d9cda3
 void log_nametypeclass(enum verbosity_value v, const char* str, 
d9cda3
 	uint8_t* name, uint16_t type, uint16_t dclass);
d9cda3
 
d9cda3
+/**
d9cda3
+ * Like log_nametypeclass, but logs with log_query for query logging
d9cda3
+ */
d9cda3
+void log_query_in(const char* str, uint8_t* name, uint16_t type,
d9cda3
+       uint16_t dclass);
d9cda3
+
d9cda3
 /**
d9cda3
  * Compare two sockaddrs. Imposes an ordering on the addresses.
d9cda3
  * Compares address and port.
d9cda3
diff --git a/validator/val_kcache.c b/validator/val_kcache.c
d9cda3
index 22070cc..e0b88b6 100644
d9cda3
--- a/validator/val_kcache.c
d9cda3
+++ b/validator/val_kcache.c
d9cda3
@@ -89,7 +89,7 @@ key_cache_insert(struct key_cache* kcache, struct key_entry_key* kkey,
d9cda3
 	if(key_entry_isbad(k) && qstate->errinf &&
d9cda3
 		qstate->env->cfg->val_log_level >= 2) {
d9cda3
 		/* on malloc failure there is simply no reason string */
d9cda3
-		key_entry_set_reason(k, errinf_to_str(qstate));
d9cda3
+		key_entry_set_reason(k, errinf_to_str_bogus(qstate));
d9cda3
 	}
d9cda3
 	key_entry_hash(k);
d9cda3
 	slabhash_insert(kcache->slab, k->entry.hash, &k->entry, 
d9cda3
diff --git a/validator/validator.c b/validator/validator.c
d9cda3
index 5777b29..2d9cc17 100644
d9cda3
--- a/validator/validator.c
d9cda3
+++ b/validator/validator.c
d9cda3
@@ -2227,13 +2227,15 @@ processFinished(struct module_qstate* qstate, struct val_qstate* vq,
d9cda3
 		vq->orig_msg->rep->ttl = ve->bogus_ttl;
d9cda3
 		vq->orig_msg->rep->prefetch_ttl = 
d9cda3
 			PREFETCH_TTL_CALC(vq->orig_msg->rep->ttl);
d9cda3
-		if(qstate->env->cfg->val_log_level >= 1 &&
d9cda3
+		if((qstate->env->cfg->val_log_level >= 1 ||
d9cda3
+			qstate->env->cfg->log_servfail) &&
d9cda3
 			!qstate->env->cfg->val_log_squelch) {
d9cda3
-			if(qstate->env->cfg->val_log_level < 2)
d9cda3
+            if(qstate->env->cfg->val_log_level < 2 &&
d9cda3
+				!qstate->env->cfg->log_servfail)
d9cda3
 				log_query_info(0, "validation failure",
d9cda3
 					&qstate->qinfo);
d9cda3
 			else {
d9cda3
-				char* err = errinf_to_str(qstate);
d9cda3
+				char* err = errinf_to_str_bogus(qstate);
d9cda3
 				if(err) log_info("%s", err);
d9cda3
 				free(err);
d9cda3
 			}
d9cda3
@@ -2332,6 +2334,7 @@ processDLVLookup(struct module_qstate* qstate, struct val_qstate* vq,
d9cda3
 
d9cda3
 	if(vq->dlv_status == dlv_error) {
d9cda3
 		verbose(VERB_QUERY, "failed DLV lookup");
d9cda3
+		errinf(qstate, "failed DLV lookup");
d9cda3
 		return val_error(qstate, id);
d9cda3
 	} else if(vq->dlv_status == dlv_success) {
d9cda3
 		uint8_t* nm;