- Fix #969: [FR] distinguish Do53, DoT and DoH in the logs.

daemon/worker.c

@@ -1967,11 +1967,15 @@ send_reply_rc:
 			qinfo.qname = qinfo.local_alias->rrset->rk.dname;
 			log_reply_info(NO_VERBOSE, &qinfo,
 				&repinfo->client_addr, repinfo->client_addrlen,
-				tv, 1, c->buffer);
+				tv, 1, c->buffer,
+				(worker->env.cfg->log_destaddr?(void*)repinfo->c->socket->addr->ai_addr:NULL),
+				c->type);
 		} else {
 			log_reply_info(NO_VERBOSE, &qinfo,
 				&repinfo->client_addr, repinfo->client_addrlen,
-				tv, 1, c->buffer);
+				tv, 1, c->buffer,
+				(worker->env.cfg->log_destaddr?(void*)repinfo->c->socket->addr->ai_addr:NULL),
+				c->type);
 		}
 	}
 #ifdef USE_DNSCRYPT

doc/Changelog

@@ -1,5 +1,6 @@
 5 December 2023: Wouter
 	- Merge #971: fix 'WARNING: Message has 41 extra bytes at end'.
+	- Fix #969: [FR] distinguish Do53, DoT and DoH in the logs.
 
 27 November 2023: Yorgos
 	- Merge #968: Replace the obsolescent fgrep with grep -F in tests.

doc/example.conf.in

@@ -441,6 +441,9 @@ server:
 	# filtering log-queries and log-replies from the log.
 	# log-tag-queryreply: no
 
+	# log with destination address, port and type for log-replies.
+	# log-destaddr: no
+
 	# log the local-zone actions, like local-zone type inform is enabled
 	# also for the other local zone types.
 	# log-local-actions: no

doc/unbound.conf.5.in

@@ -913,6 +913,11 @@ Prints the word 'query' and 'reply' with log\-queries and log\-replies.
 This makes filtering logs easier.  The default is off (for backwards
 compatibility).
 .TP
+.B log\-destaddr: \fI<yes or no>
+Prints the destination address, port and type in the log\-replies output.
+This disambiguates what type of traffic, eg. udp or tcp, and to what local
+port the traffic was sent to.
+.TP
 .B log\-local\-actions: \fI<yes or no>
 Print log lines to inform about local zone actions.  These lines are like the
 local\-zone type inform prints out, but they are also printed for the other

services/mesh.c

@@ -69,6 +69,12 @@
 #include "edns-subnet/subnetmod.h"
 #include "edns-subnet/edns-subnet.h"
 #endif
+#ifdef HAVE_SYS_TYPES_H
+#  include <sys/types.h>
+#endif
+#ifdef HAVE_NETDB_H
+#include <netdb.h>
+#endif
 
 /**
  * Compare two response-ip client info entries for the purpose of mesh state
@@ -1429,7 +1435,9 @@ mesh_send_reply(struct mesh_state* m, int rcode, struct reply_info* rep,
 	if(m->s.env->cfg->log_replies) {
 		log_reply_info(NO_VERBOSE, &m->s.qinfo,
 			&r->query_reply.client_addr,
-			r->query_reply.client_addrlen, duration, 0, r_buffer);
+			r->query_reply.client_addrlen, duration, 0, r_buffer,
+			(m->s.env->cfg->log_destaddr?(void*)r->query_reply.c->socket->addr->ai_addr:NULL),
+			r->query_reply.c->type);
 	}
 }
 

util/config_file.c

@@ -142,6 +142,7 @@ config_create(void)
 	cfg->log_tag_queryreply = 0;
 	cfg->log_local_actions = 0;
 	cfg->log_servfail = 0;
+	cfg->log_destaddr = 0;
 #ifndef USE_WINSOCK
 #  ifdef USE_MINI_EVENT
 	/* select max 1024 sockets */
@@ -690,6 +691,7 @@ int config_set_option(struct config_file* cfg, const char* opt,
 	else S_YNO("log-tag-queryreply:", log_tag_queryreply)
 	else S_YNO("log-local-actions:", log_local_actions)
 	else S_YNO("log-servfail:", log_servfail)
+	else S_YNO("log-destaddr:", log_destaddr)
 	else S_YNO("val-permissive-mode:", val_permissive_mode)
 	else S_YNO("aggressive-nsec:", aggressive_nsec)
 	else S_YNO("ignore-cd-flag:", ignore_cd)
@@ -1127,6 +1129,7 @@ config_get_option(struct config_file* cfg, const char* opt,
 	else O_YNO(opt, "log-tag-queryreply", log_tag_queryreply)
 	else O_YNO(opt, "log-local-actions", log_local_actions)
 	else O_YNO(opt, "log-servfail", log_servfail)
+	else O_YNO(opt, "log-destaddr", log_destaddr)
 	else O_STR(opt, "pidfile", pidfile)
 	else O_YNO(opt, "hide-identity", hide_identity)
 	else O_YNO(opt, "hide-version", hide_version)

util/config_file.h

@@ -349,6 +349,8 @@ struct config_file {
 	int log_servfail;
 	/** log identity to report */
 	char* log_identity;
+	/** log dest addr for log_replies */
+	int log_destaddr;
 
 	/** do not report identity (id.server, hostname.bind) */
 	int hide_identity;

util/configlexer.lex

@@ -434,6 +434,7 @@ log-replies{COLON}		{ YDVAR(1, VAR_LOG_REPLIES) }
 log-tag-queryreply{COLON}	{ YDVAR(1, VAR_LOG_TAG_QUERYREPLY) }
 log-local-actions{COLON}       { YDVAR(1, VAR_LOG_LOCAL_ACTIONS) }
 log-servfail{COLON}		{ YDVAR(1, VAR_LOG_SERVFAIL) }
+log-destaddr{COLON}		{ YDVAR(1, VAR_LOG_DESTADDR) }
 local-zone{COLON}		{ YDVAR(2, VAR_LOCAL_ZONE) }
 local-data{COLON}		{ YDVAR(1, VAR_LOCAL_DATA) }
 local-data-ptr{COLON}		{ YDVAR(1, VAR_LOCAL_DATA_PTR) }

util/configparser.y

@@ -200,6 +200,7 @@ extern struct config_parser_state* cfg_parser;
 %token VAR_INTERFACE_TAG_ACTION VAR_INTERFACE_TAG_DATA
 %token VAR_PROXY_PROTOCOL_PORT VAR_STATISTICS_INHIBIT_ZERO
 %token VAR_HARDEN_UNKNOWN_ADDITIONAL VAR_DISABLE_EDNS_DO VAR_CACHEDB_NO_STORE
+%token VAR_LOG_DESTADDR
 
 %%
 toplevelvars: /* empty */ | toplevelvars toplevelvar ;
@@ -333,7 +334,8 @@ content_server: server_num_threads | server_verbosity | server_port |
 	server_tcp_reuse_timeout | server_tcp_auth_query_timeout |
 	server_interface_automatic_ports | server_ede |
 	server_proxy_protocol_port | server_statistics_inhibit_zero |
-	server_harden_unknown_additional | server_disable_edns_do
+	server_harden_unknown_additional | server_disable_edns_do |
+	server_log_destaddr
 	;
 stubstart: VAR_STUB_ZONE
 	{
@@ -1250,6 +1252,15 @@ server_log_servfail: VAR_LOG_SERVFAIL STRING_ARG
 		free($2);
 	}
 	;
+server_log_destaddr: VAR_LOG_DESTADDR STRING_ARG
+	{
+		OUTYY(("P(server_log_destaddr:%s)\n", $2));
+		if(strcmp($2, "yes") != 0 && strcmp($2, "no") != 0)
+			yyerror("expected yes or no.");
+		else cfg_parser->cfg->log_destaddr = (strcmp($2, "yes")==0);
+		free($2);
+	}
+	;
 server_log_local_actions: VAR_LOG_LOCAL_ACTIONS STRING_ARG
 	{
 		OUTYY(("P(server_log_local_actions:%s)\n", $2));

util/data/msgreply.c

@@ -918,13 +918,15 @@ log_dns_msg(const char* str, struct query_info* qinfo, struct reply_info* rep)
 void
 log_reply_info(enum verbosity_value v, struct query_info *qinf,
 	struct sockaddr_storage *addr, socklen_t addrlen, struct timeval dur,
-	int cached, struct sldns_buffer *rmsg)
+	int cached, struct sldns_buffer *rmsg, struct sockaddr_storage* daddr,
+	enum comm_point_type tp)
 {
 	char qname_buf[LDNS_MAX_DOMAINLEN+1];
 	char clientip_buf[128];
 	char rcode_buf[16];
 	char type_buf[16];
 	char class_buf[16];
+	char dest_buf[160];
 	size_t pktlen;
 	uint16_t rcode = FLAGS_GET_RCODE(sldns_buffer_read_u16_at(rmsg, 2));
 
@@ -933,11 +935,46 @@ log_reply_info(enum verbosity_value v, struct query_info *qinf,
 
 	sldns_wire2str_rcode_buf((int)rcode, rcode_buf, sizeof(rcode_buf));
 	addr_to_str(addr, addrlen, clientip_buf, sizeof(clientip_buf));
+	if(daddr) {
+		char da[128];
+		int port = 0;
+		char* comm;
+		if(daddr->ss_family == AF_INET6) {
+			struct sockaddr_in6 *d = (struct sockaddr_in6 *)daddr;
+			if(inet_ntop(d->sin6_family, &d->sin6_addr, da,
+				sizeof(*d)) == 0)
+				snprintf(dest_buf, sizeof(dest_buf),
+					"(inet_ntop_error)");
+			port = ntohs(d->sin6_port);
+		} else if(daddr->ss_family == AF_INET) {
+			struct sockaddr_in *d = (struct sockaddr_in *)daddr;
+			if(inet_ntop(d->sin_family, &d->sin_addr, da,
+				sizeof(*d)) == 0)
+				snprintf(dest_buf, sizeof(dest_buf),
+					"(inet_ntop_error)");
+			port = ntohs(d->sin_port);
+		} else {
+			snprintf(da, sizeof(da), "socket%d",
+				(int)daddr->ss_family);
+		}
+		comm = "udp";
+		if(tp == comm_tcp) comm = "tcp";
+		else if(tp == comm_tcp_accept) comm = "tcp";
+		else if(tp == comm_http) comm = "dot";
+		else if(tp == comm_local) comm = "unix";
+		else if(tp == comm_raw) comm = "raw";
+		snprintf(dest_buf, sizeof(dest_buf), " on %s %s %d",
+			comm, da, port);
+	} else {
+		dest_buf[0]=0;
+	}
 	if(rcode == LDNS_RCODE_FORMERR)
 	{
 		if(LOG_TAG_QUERYREPLY)
-			log_reply("%s - - - %s - - - ", clientip_buf, rcode_buf);
-		else	log_info("%s - - - %s - - - ", clientip_buf, rcode_buf);
+			log_reply("%s - - - %s - - -%s", clientip_buf,
+				rcode_buf, dest_buf);
+		else	log_info("%s - - - %s - - -%s", clientip_buf,
+				rcode_buf, dest_buf);
 	} else {
 		if(qinf->qname)
 			dname_str(qinf->qname, qname_buf);
@@ -946,12 +983,14 @@ log_reply_info(enum verbosity_value v, struct query_info *qinf,
 		sldns_wire2str_type_buf(qinf->qtype, type_buf, sizeof(type_buf));
 		sldns_wire2str_class_buf(qinf->qclass, class_buf, sizeof(class_buf));
 		if(LOG_TAG_QUERYREPLY)
-		     log_reply("%s %s %s %s %s " ARG_LL "d.%6.6d %d %d",
+		     log_reply("%s %s %s %s %s " ARG_LL "d.%6.6d %d %d%s",
 			clientip_buf, qname_buf, type_buf, class_buf,
-			rcode_buf, (long long)dur.tv_sec, (int)dur.tv_usec, cached, (int)pktlen);
-		else log_info("%s %s %s %s %s " ARG_LL "d.%6.6d %d %d",
+			rcode_buf, (long long)dur.tv_sec, (int)dur.tv_usec,
+			cached, (int)pktlen, dest_buf);
+		else log_info("%s %s %s %s %s " ARG_LL "d.%6.6d %d %d%s",
 			clientip_buf, qname_buf, type_buf, class_buf,
-			rcode_buf, (long long)dur.tv_sec, (int)dur.tv_usec, cached, (int)pktlen);
+			rcode_buf, (long long)dur.tv_sec, (int)dur.tv_usec,
+			cached, (int)pktlen, dest_buf);
 	}
 }
 

util/data/msgreply.h

@@ -58,6 +58,7 @@ struct msg_parse;
 struct rrset_parse;
 struct local_rrset;
 struct dns_msg;
+enum comm_point_type;
 
 /** calculate the prefetch TTL as 90% of original. Calculation
  * without numerical overflow (uin32_t) */
@@ -520,10 +521,13 @@ void log_dns_msg(const char* str, struct query_info* qinfo,
  * @param cached: whether or not the reply is coming from
  *                    the cache, or an outside network.
  * @param rmsg: sldns buffer packet.
+ * @param daddr: if not NULL, the destination address and port are logged.
+ * @param tp: type of the comm point for logging destination connection type.
  */
 void log_reply_info(enum verbosity_value v, struct query_info *qinf,
 	struct sockaddr_storage *addr, socklen_t addrlen, struct timeval dur,
-	int cached, struct sldns_buffer *rmsg);
+	int cached, struct sldns_buffer *rmsg, struct sockaddr_storage* daddr,
+	enum comm_point_type tp);
 
 /**
  * Print string with neat domain name, type, class from query info.