Cleanup query logging.

Debug log level 1 gives us basic query progress, level 2 writes out
packages.
looks good to otto

2 files changed, 35 insertions, 27 deletions

diff --git a/sbin/unwind/frontend.c b/sbin/unwind/frontend.c
index 3ce0fe2ad5c..7dd88d73fab 100644
--- a/sbin/unwind/frontend.c
+++ b/sbin/unwind/frontend.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: frontend.c,v 1.44 2019/12/03 16:14:00 florian Exp $	*/
+/*	$OpenBSD: frontend.c,v 1.45 2019/12/03 16:17:48 florian Exp $	*/
 
 /*
  * Copyright (c) 2018 Florian Obser <florian@openbsd.org>
@@ -548,7 +548,7 @@ udp_receive(int fd, short events, void *arg)
 	struct bl_node		 find;
 	ssize_t			 len, dname_len;
 	int			 ret;
-	char			*str_from, *str;
+	char			*str;
 	char			 dname[LDNS_MAX_DOMAINLEN + 1];
 
 	memset(&qinfo, 0, sizeof(qinfo));
@@ -580,10 +580,10 @@ udp_receive(int fd, short events, void *arg)
 	sldns_buffer_write(pq->qbuf, udpev->query, len);
 	sldns_buffer_flip(pq->qbuf);
 
-	str_from = ip_port((struct sockaddr *)&udpev->from);
-	log_debug("query from %s", str_from);
-	if ((str = sldns_wire2str_pkt(udpev->query, len)) != NULL) {
-		log_debug("%s", str);
+	if (log_getverbose() & OPT_VERBOSE2 && (str =
+	    sldns_wire2str_pkt(udpev->query, len)) != NULL) {
+		log_debug("from: %s\n%s", ip_port((struct sockaddr *)
+		    &udpev->from), str);
 		free(str);
 	}
 
@@ -606,8 +606,9 @@ udp_receive(int fd, short events, void *arg)
 	}
 	dname_str(qinfo.qname, dname);
 
-	log_debug("%s: query_info_parse, qname_len: %ld dname[%ld]: %s",
-	    __func__, qinfo.qname_len, dname_len, dname);
+	log_debug("%s: %s %s %s ?", ip_port((struct sockaddr *)&udpev->from),
+	    dname, sldns_wire2str_class(qinfo.qclass),
+	    sldns_wire2str_type(qinfo.qtype));
 
 	find.domain = dname;
 	if (RB_FIND(bl_tree, &bl_head, &find) != NULL) {
@@ -684,7 +685,7 @@ chaos_answer(struct pending_query *pq)
 {
 	struct sldns_buffer	 buf, *pkt = &buf;
 	size_t			 size, len;
-	char			*name = "unwind", *str;
+	char			*name = "unwind";
 
 	len = strlen(name);
 	size = sldns_buffer_capacity(pq->qbuf) + COMPRESSED_RR_SIZE + 1 + len;
@@ -722,11 +723,6 @@ chaos_answer(struct pending_query *pq)
 	sldns_buffer_write_u16(pkt, 1 + len);		/* RDLENGTH */
 	sldns_buffer_write_u8(pkt, len);		/* length octed */
 	sldns_buffer_write(pkt, name, len);
-
-	if ((str = sldns_wire2str_pkt(pq->answer, pq->answer_len)) != NULL) {
-		log_debug("%s: %s", __func__, str);
-		free(str);
-	}
 }
 
 int
@@ -774,10 +770,9 @@ void
 send_answer(struct pending_query *pq)
 {
 	ssize_t	 len;
+	char	*str;
 	uint8_t	*answer;
 
-	log_debug("result for %s", ip_port((struct sockaddr*)&pq->from));
-
 	answer = pq->answer;
 	len = pq->answer_len;
 
@@ -811,6 +806,13 @@ send_answer(struct pending_query *pq)
 		}
 	}
 
+	if (log_getverbose() & OPT_VERBOSE2 && (str =
+	    sldns_wire2str_pkt(answer, len)) != NULL) {
+		log_debug("to: %s\n%s",
+		    ip_port((struct sockaddr *)&pq->from),str);
+		free(str);
+	}
+
 	if(sendto(pq->fd, answer, len, 0, (struct sockaddr *)&pq->from,
 	    pq->from.ss_len) == -1)
 		log_warn("sendto");
diff --git a/sbin/unwind/resolver.c b/sbin/unwind/resolver.c
index c12628a8c88..8947a9ee30b 100644
--- a/sbin/unwind/resolver.c
+++ b/sbin/unwind/resolver.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: resolver.c,v 1.96 2019/12/03 16:17:00 florian Exp $	*/
+/*	$OpenBSD: resolver.c,v 1.97 2019/12/03 16:17:48 florian Exp $	*/
 
 /*
  * Copyright (c) 2018 Florian Obser <florian@openbsd.org>
@@ -761,7 +761,8 @@ try_next_resolver(struct running_query *rq)
 
 	if (res == NULL) {
 		evtimer_del(&rq->timer_ev); /* we are not going to find one */
-		log_debug("%s: could not find working resolver", __func__);
+		log_debug("%s: could not find (any more) working resolvers",
+		    __func__);
 		goto err;
 	}
 
@@ -770,8 +771,11 @@ try_next_resolver(struct running_query *rq)
 	timespecsub(&tp, &rq->tp, &elapsed);
 	ms = elapsed.tv_sec * 1000 + elapsed.tv_nsec / 1000000;
 
-	log_debug("%s[+%lldms]: %s[%s]", __func__, ms,
-	    uw_resolver_type_str[res->type], uw_resolver_state_str[res->state]);
+	log_debug("%s[+%lldms]: %s[%s] %s %s %s", __func__, ms,
+	    uw_resolver_type_str[res->type], uw_resolver_state_str[res->state],
+	    rq->query_imsg->qname, sldns_wire2str_class(rq->query_imsg->c),
+	    sldns_wire2str_type(rq->query_imsg->t));
+
 	if ((query_imsg = malloc(sizeof(*query_imsg))) == NULL) {
 		log_warnx("%s", __func__);
 		goto err;
@@ -930,10 +934,10 @@ resolve_done(struct uw_resolver *res, void *arg, int rcode,
 	result->answer_len = 0;
 
 	sldns_wire2str_rcode_buf(result->rcode, rcode_buf, sizeof(rcode_buf));
-	log_debug("%s[%s]: rcode: %s[%d], elapsed: %lldms, "
-	    "histogram: %lld - %lld", __func__, uw_resolver_type_str[res->type],
-	    rcode_buf, result->rcode, ms, histogram_limits[i],
-	    res->histogram[i]);
+	log_debug("%s[%s]: %s %s %s rcode: %s[%d], elapsed: %lldms", __func__,
+	    uw_resolver_type_str[res->type], query_imsg->qname,
+	    sldns_wire2str_class(query_imsg->c),
+	    sldns_wire2str_type(query_imsg->t), rcode_buf, result->rcode, ms);
 
 	if (result->rcode == LDNS_RCODE_NXDOMAIN && res->type != UW_RES_ASR) {
 		timespecsub(&tp, &last_network_change, &elapsed);
@@ -942,8 +946,9 @@ resolve_done(struct uw_resolver *res, void *arg, int rcode,
 			 * Doubt NXDOMAIN if we just switched networks,
 			 * we might be behind a captive portal.
 			 */
-			log_debug("%s: doubt NXDOMAIN from %s", __func__,
-			    uw_resolver_type_str[res->type]);
+			log_debug("%s: doubt NXDOMAIN from %s, network change "
+			    "%llds ago", __func__,
+			    uw_resolver_type_str[res->type], elapsed.tv_sec);
 			if (rq) {
 				/* search for ASR */
 				for (i = 0; i < (size_t)rq->res_pref.len; i++)
@@ -971,7 +976,8 @@ resolve_done(struct uw_resolver *res, void *arg, int rcode,
 			    "%llds ago", __func__, elapsed.tv_sec);
 	}
 
-	if ((str = sldns_wire2str_pkt(answer_packet, answer_len)) != NULL) {
+	if (log_getverbose() & OPT_VERBOSE2 && (str =
+	    sldns_wire2str_pkt(answer_packet, answer_len)) != NULL) {
 		log_debug("%s", str);
 		free(str);
 	}