Reduce debug logging by moving protocol level debug log

behind -vv or by deleting unneeded output.
While here reword some debug output to make it more useful.
(There is more to be done here.)

3 files changed, 177 insertions, 129 deletions

diff --git a/sbin/dhcpleased/dhcpleased.c b/sbin/dhcpleased/dhcpleased.c
index d2c936aab03..a71fcbedbd7 100644
--- a/sbin/dhcpleased/dhcpleased.c
+++ b/sbin/dhcpleased/dhcpleased.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: dhcpleased.c,v 1.6 2021/03/02 12:03:50 florian Exp $	*/
+/*	$OpenBSD: dhcpleased.c,v 1.7 2021/03/07 18:39:11 florian Exp $	*/
 
 /*
  * Copyright (c) 2017, 2021 Florian Obser <florian@openbsd.org>
@@ -407,7 +407,6 @@ main_dispatch_frontend(int fd, short event, void *bula)
 
 		switch (imsg.hdr.type) {
 		case IMSG_OPEN_BPFSOCK:
-			log_debug("IMSG_OPEN_BPFSOCK");
 			if (IMSG_DATA_SIZE(imsg) != sizeof(if_index))
 				fatalx("%s: IMSG_OPEN_BPFSOCK wrong length: "
 				    "%lu", __func__, IMSG_DATA_SIZE(imsg));
@@ -627,8 +626,6 @@ configure_interface(struct imsg_configure_interface *imsg)
 	    IF_NAMESIZE];
 	char			 tmpl[] = _PATH_LEASE"XXXXXXXXXX";
 
-	log_debug("%s", __func__);
-
 	memset(&ifaliasreq, 0, sizeof(ifaliasreq));
 
 	if_name = if_indextoname(imsg->if_index, ifaliasreq.ifra_name);
@@ -638,6 +635,8 @@ configure_interface(struct imsg_configure_interface *imsg)
 		return;
 	}
 
+	log_debug("%s %s", __func__, if_name);
+
 	if (getifaddrs(&ifap) != 0)
 		fatal("getifaddrs");
 
@@ -712,7 +711,7 @@ configure_interface(struct imsg_configure_interface *imsg)
 	}
 
 	shutdown(udpsock, SHUT_RD);
-	log_debug("%s: udpsock: %d", __func__, udpsock);
+
 	main_imsg_compose_frontend(IMSG_UDPSOCK, udpsock,
 	    &imsg->if_index, sizeof(imsg->if_index));
 
@@ -772,8 +771,6 @@ deconfigure_interface(struct imsg_configure_interface *imsg)
 	struct ifaliasreq	 ifaliasreq;
 	struct sockaddr_in	*req_sin_addr;
 
-	log_debug("%s", __func__);
-
 	memset(&ifaliasreq, 0, sizeof(ifaliasreq));
 
 	if (imsg->router.s_addr != INADDR_ANY)
@@ -785,6 +782,8 @@ deconfigure_interface(struct imsg_configure_interface *imsg)
 		return;
 	}
 
+	log_debug("%s %s", __func__, ifaliasreq.ifra_name);
+
 	req_sin_addr = (struct sockaddr_in *)&ifaliasreq.ifra_addr;
 	req_sin_addr->sin_family = AF_INET;
 	req_sin_addr->sin_len = sizeof(*req_sin_addr);
@@ -906,9 +905,7 @@ open_bpfsock(uint32_t if_index)
 	int		 bpfsock;
 	char		 ifname[IF_NAMESIZE];
 
-	log_debug("%s: %d", __func__, if_index);
-
-	if (if_indextoname(if_index, ifname) == 0) {
+	if (if_indextoname(if_index, ifname) == NULL) {
 		log_warnx("%s: cannot find interface %d", __func__, if_index);
 		return;
 	}
@@ -975,7 +972,7 @@ read_lease_file(struct imsg_ifinfo *imsg_ifinfo)
 
 	memset(imsg_ifinfo->lease, 0, sizeof(imsg_ifinfo->lease));
 
-	if (if_indextoname(imsg_ifinfo->if_index, if_name) == 0) {
+	if (if_indextoname(imsg_ifinfo->if_index, if_name) == NULL) {
 		log_warnx("%s: cannot find interface %d", __func__,
 		    imsg_ifinfo->if_index);
 		return;
diff --git a/sbin/dhcpleased/engine.c b/sbin/dhcpleased/engine.c
index 91063b386f9..fbe7a78780f 100644
--- a/sbin/dhcpleased/engine.c
+++ b/sbin/dhcpleased/engine.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: engine.c,v 1.8 2021/03/07 16:22:01 florian Exp $	*/
+/*	$OpenBSD: engine.c,v 1.9 2021/03/07 18:39:11 florian Exp $	*/
 
 /*
  * Copyright (c) 2017, 2021 Florian Obser <florian@openbsd.org>
@@ -137,6 +137,8 @@ void			 send_rdns_withdraw(struct dhcpleased_iface *);
 void			 parse_lease(struct dhcpleased_iface *,
 			     struct imsg_ifinfo *);
 int			 engine_imsg_compose_main(int, pid_t, void *, uint16_t);
+void			 log_dhcp_hdr(struct dhcp_hdr *);
+const char		*dhcp_message_type2str(uint8_t);
 
 static struct imsgev	*iev_frontend;
 static struct imsgev	*iev_main;
@@ -495,6 +497,7 @@ engine_showinfo_ctl(struct imsg *imsg, uint32_t if_index)
 	}
 }
 #endif	/* SMALL */
+
 void
 engine_update_iface(struct imsg_ifinfo *imsg_ifinfo)
 {
@@ -606,6 +609,7 @@ parse_dhcp(struct dhcpleased_iface *iface, struct imsg_dhcp *dhcp)
 	char			 hbuf_dst[INET_ADDRSTRLEN];
 	char			 hbuf[INET_ADDRSTRLEN];
 	char			 vis_buf[4 * 255 + 1];
+	char			 ifnamebuf[IF_NAMESIZE], *if_name;
 
 	if (bcast_mac.ether_addr_octet[0] == 0)
 		memset(bcast_mac.ether_addr_octet, 0xff, ETHER_ADDR_LEN);
@@ -637,7 +641,8 @@ parse_dhcp(struct dhcpleased_iface *iface, struct imsg_dhcp *dhcp)
 	if (rem < sizeof(*ip))
 		goto too_short;
 
-	log_debug("%s, from: %s, to: %s", __func__, from, to);
+	if (log_getverbose() > 1)
+		log_debug("%s, from: %s, to: %s", __func__, from, to);
 
 	ip = (struct ip *)p;
 
@@ -657,7 +662,7 @@ parse_dhcp(struct dhcpleased_iface *iface, struct imsg_dhcp *dhcp)
 	if (inet_ntop(AF_INET, &ip->ip_src, hbuf_src, sizeof(hbuf_src)) == NULL)
 		hbuf_src[0] = '\0';
 	if (inet_ntop(AF_INET, &ip->ip_dst, hbuf_dst, sizeof(hbuf_dst)) == NULL)
-		hbuf_src[0] = '\0';
+		hbuf_dst[0] = '\0';
 
 	if (rem < sizeof(*udp))
 		goto too_short;
@@ -667,8 +672,11 @@ parse_dhcp(struct dhcpleased_iface *iface, struct imsg_dhcp *dhcp)
 		goto too_short;
 
 	if (rem > ntohs(udp->uh_ulen)) {
-		log_debug("%s: accepting packet with %lu bytes of data after "
-		    "udp payload", __func__, rem - ntohs(udp->uh_ulen));
+		if (log_getverbose() > 1) {
+			log_debug("%s: accepting packet with %lu bytes of data"
+			    " after udp payload", __func__, rem -
+			    ntohs(udp->uh_ulen));
+		}
 		rem = ntohs(udp->uh_ulen);
 	}
 
@@ -687,9 +695,10 @@ parse_dhcp(struct dhcpleased_iface *iface, struct imsg_dhcp *dhcp)
 		return;
 	}
 
-	log_debug("%s: %s:%d -> %s:%d", __func__,
-	    hbuf_src, ntohs(udp->uh_sport),
-	    hbuf_dst, ntohs(udp->uh_dport));
+	if (log_getverbose() > 1) {
+		log_debug("%s: %s:%d -> %s:%d", __func__, hbuf_src,
+		    ntohs(udp->uh_sport), hbuf_dst, ntohs(udp->uh_dport));
+	}
 
 	if (ntohs(udp->uh_sport) != SERVER_PORT ||
 	    ntohs(udp->uh_dport) != CLIENT_PORT) {
@@ -707,33 +716,9 @@ parse_dhcp(struct dhcpleased_iface *iface, struct imsg_dhcp *dhcp)
 
 	dhcp_hdr->sname[DHCP_SNAME_LEN -1 ] = '\0'; /* ensure it's a string */
 	dhcp_hdr->file[DHCP_FILE_LEN -1 ] = '\0'; /* ensure it's a string */
-	log_debug("dhcp_hdr op: %s (%d)", dhcp_hdr->op == DHCP_BOOTREQUEST ?
-	    "Boot Request" : dhcp_hdr->op == DHCP_BOOTREPLY ? "Boot Reply" :
-	    "Unknown", dhcp_hdr->op);
-	log_debug("dhcp_hdr htype: %s (%d)", dhcp_hdr->htype == 1 ? "Ethernet":
-	    "Unknown", dhcp_hdr->htype);
-	log_debug("dhcp_hdr hlen: %d", dhcp_hdr->hlen);
-	log_debug("dhcp_hdr hops: %d", dhcp_hdr->hops);
-	log_debug("dhcp_hdr xid: 0x%x", dhcp_hdr->xid);
-	log_debug("dhcp_hdr secs: %u", dhcp_hdr->secs);
-	log_debug("dhcp_hdr flags: 0x%x", dhcp_hdr->flags);
-	log_debug("dhcp_hdr ciaddr: %s", inet_ntop(AF_INET, &dhcp_hdr->ciaddr,
-	    hbuf, sizeof(hbuf)));
-	log_debug("dhcp_hdr yiaddr: %s", inet_ntop(AF_INET, &dhcp_hdr->yiaddr,
-	    hbuf, sizeof(hbuf)));
-	log_debug("dhcp_hdr siaddr: %s", inet_ntop(AF_INET, &dhcp_hdr->siaddr,
-	    hbuf, sizeof(hbuf)));
-	log_debug("dhcp_hdr giaddr: %s", inet_ntop(AF_INET, &dhcp_hdr->giaddr,
-	    hbuf, sizeof(hbuf)));
-	log_debug("dhcp_hdr chaddr: %02x:%02x:%02x:%02x:%02x:%02x "
-	    "(%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x)",
-	    dhcp_hdr->chaddr[0], dhcp_hdr->chaddr[1], dhcp_hdr->chaddr[2],
-	    dhcp_hdr->chaddr[3], dhcp_hdr->chaddr[4], dhcp_hdr->chaddr[5],
-	    dhcp_hdr->chaddr[6], dhcp_hdr->chaddr[7], dhcp_hdr->chaddr[8],
-	    dhcp_hdr->chaddr[9], dhcp_hdr->chaddr[10], dhcp_hdr->chaddr[11],
-	    dhcp_hdr->chaddr[12], dhcp_hdr->chaddr[13], dhcp_hdr->chaddr[14],
-	    dhcp_hdr->chaddr[15]);
-	/* ignore sname and file, if we ever print it use strvis(3) */
+
+	if (log_getverbose() > 1)
+		log_dhcp_hdr(dhcp_hdr);
 
 	if (dhcp_hdr->op != DHCP_BOOTREPLY) {
 		log_warnx("%s: ignorning non-reply packet", __func__);
@@ -778,43 +763,20 @@ parse_dhcp(struct dhcpleased_iface *iface, struct imsg_dhcp *dhcp)
 
 		switch(dho) {
 		case DHO_PAD:
-			log_debug("DHO_PAD");
+			if (log_getverbose() > 1)
+				log_debug("DHO_PAD");
 			break;
 		case DHO_END:
-			log_debug("DHO_END");
+			if (log_getverbose() > 1)
+				log_debug("DHO_END");
 			break;
 		case DHO_DHCP_MESSAGE_TYPE:
 			if (dho_len != 1)
 				goto wrong_length;
 			dhcp_message_type = *p;
-			switch (dhcp_message_type) {
-			case DHCPDISCOVER:
-				log_debug("DHO_DHCP_MESSAGE_TYPE: DHCPDISCOVER");
-				break;
-			case DHCPOFFER:
-				log_debug("DHO_DHCP_MESSAGE_TYPE: DHCPOFFER");
-				break;
-			case DHCPREQUEST:
-				log_debug("DHO_DHCP_MESSAGE_TYPE: DHCPREQUEST");
-				break;
-			case DHCPDECLINE:
-				log_debug("DHO_DHCP_MESSAGE_TYPE: DHCPDECLINE");
-				break;
-			case DHCPACK:
-				log_debug("DHO_DHCP_MESSAGE_TYPE: DHCPACK");
-				break;
-			case DHCPNAK:
-				log_debug("DHO_DHCP_MESSAGE_TYPE: DHCPNAK");
-				break;
-			case DHCPRELEASE:
-				log_debug("DHO_DHCP_MESSAGE_TYPE: DHCPRELEASE");
-				break;
-			case DHCPINFORM:
-				log_debug("DHO_DHCP_MESSAGE_TYPE: DHCPINFORM");
-				break;
-			default:
-				log_debug("DHO_DHCP_MESSAGE_TYPE: Unknown");
-				break;
+			if (log_getverbose() > 1) {
+				log_debug("DHO_DHCP_MESSAGE_TYPE: %s",
+				    dhcp_message_type2str(dhcp_message_type));
 			}
 			p += dho_len;
 			rem -= dho_len;
@@ -824,9 +786,11 @@ parse_dhcp(struct dhcpleased_iface *iface, struct imsg_dhcp *dhcp)
 				goto wrong_length;
 			memcpy(&server_identifier, p,
 			    sizeof(server_identifier));
-			log_debug("DHO_DHCP_SERVER_IDENTIFIER: %s",
-			    inet_ntop(AF_INET, &server_identifier,
-			    hbuf, sizeof(hbuf)));
+			if (log_getverbose() > 1) {
+				log_debug("DHO_DHCP_SERVER_IDENTIFIER: %s",
+				    inet_ntop(AF_INET, &server_identifier,
+				    hbuf, sizeof(hbuf)));
+			}
 			p += dho_len;
 			rem -= dho_len;
 			break;
@@ -835,7 +799,10 @@ parse_dhcp(struct dhcpleased_iface *iface, struct imsg_dhcp *dhcp)
 				goto wrong_length;
 			memcpy(&lease_time, p, sizeof(lease_time));
 			lease_time = ntohl(lease_time);
-			log_debug("DHO_DHCP_LEASE_TIME %us", lease_time);
+			if (log_getverbose() > 1) {
+				log_debug("DHO_DHCP_LEASE_TIME %us",
+				    lease_time);
+			}
 			p += dho_len;
 			rem -= dho_len;
 			break;
@@ -843,8 +810,11 @@ parse_dhcp(struct dhcpleased_iface *iface, struct imsg_dhcp *dhcp)
 			if (dho_len != sizeof(subnet_mask))
 				goto wrong_length;
 			memcpy(&subnet_mask, p, sizeof(subnet_mask));
-			log_debug("DHO_SUBNET_MASK: %s", inet_ntop(AF_INET,
-			    &subnet_mask, hbuf, sizeof(hbuf)));
+			if (log_getverbose() > 1) {
+				log_debug("DHO_SUBNET_MASK: %s",
+				    inet_ntop(AF_INET, &subnet_mask, hbuf,
+				    sizeof(hbuf)));
+			}
 			p += dho_len;
 			rem -= dho_len;
 			break;
@@ -855,9 +825,11 @@ parse_dhcp(struct dhcpleased_iface *iface, struct imsg_dhcp *dhcp)
 				goto wrong_length;
 			/* we only use one router */
 			memcpy(&router, p, sizeof(router));
-			log_debug("DHO_ROUTER: %s (1/%lu)", inet_ntop(AF_INET,
-			    &router, hbuf, sizeof(hbuf)), dho_len /
-			    sizeof(router));
+			if (log_getverbose() > 1) {
+				log_debug("DHO_ROUTER: %s (1/%lu)",
+				    inet_ntop(AF_INET, &router, hbuf,
+				    sizeof(hbuf)), dho_len / sizeof(router));
+			}
 			p += dho_len;
 			rem -= dho_len;
 			break;
@@ -869,13 +841,15 @@ parse_dhcp(struct dhcpleased_iface *iface, struct imsg_dhcp *dhcp)
 			/* we limit ourself to 8 nameservers for proposals */
 			memcpy(&nameservers, p, MINIMUM(sizeof(nameservers),
 			    dho_len));
-			for (i = 0; i < MINIMUM(sizeof(nameservers), dho_len /
-			    sizeof(nameservers[0]));
-			     i++) {
-				log_debug("DHO_DOMAIN_NAME_SERVERS: %s "
-				    "(%lu/%lu)", inet_ntop(AF_INET,
-				    &nameservers[i], hbuf, sizeof(hbuf)), i + 1,
-				    dho_len / sizeof(nameservers[0]));
+			if (log_getverbose() > 1) {
+				for (i = 0; i < MINIMUM(sizeof(nameservers),
+				    dho_len / sizeof(nameservers[0])); i++) {
+					log_debug("DHO_DOMAIN_NAME_SERVERS: %s "
+					    "(%lu/%lu)", inet_ntop(AF_INET,
+					    &nameservers[i], hbuf,
+					    sizeof(hbuf)), i + 1,
+					    dho_len / sizeof(nameservers[0]));
+				}
 			}
 			p += dho_len;
 			rem -= dho_len;
@@ -883,8 +857,10 @@ parse_dhcp(struct dhcpleased_iface *iface, struct imsg_dhcp *dhcp)
 		case DHO_DOMAIN_NAME:
 			if ( dho_len < 1)
 				goto wrong_length;
-			strvisx(vis_buf, p, dho_len, VIS_SAFE);
-			log_debug("DHO_DOMAIN_NAME: %s", vis_buf);
+			if (log_getverbose() > 1) {
+				strvisx(vis_buf, p, dho_len, VIS_SAFE);
+				log_debug("DHO_DOMAIN_NAME: %s", vis_buf);
+			}
 			p += dho_len;
 			rem -= dho_len;
 			break;
@@ -893,7 +869,10 @@ parse_dhcp(struct dhcpleased_iface *iface, struct imsg_dhcp *dhcp)
 				goto wrong_length;
 			memcpy(&renewal_time, p, sizeof(renewal_time));
 			renewal_time = ntohl(renewal_time);
-			log_debug("DHO_DHCP_RENEWAL_TIME %us", renewal_time);
+			if (log_getverbose() > 1) {
+				log_debug("DHO_DHCP_RENEWAL_TIME %us",
+				    renewal_time);
+			}
 			p += dho_len;
 			rem -= dho_len;
 			break;
@@ -902,8 +881,10 @@ parse_dhcp(struct dhcpleased_iface *iface, struct imsg_dhcp *dhcp)
 				goto wrong_length;
 			memcpy(&rebinding_time, p, sizeof(rebinding_time));
 			rebinding_time = ntohl(rebinding_time);
-			log_debug("DHO_DHCP_REBINDING_TIME %us",
-			    rebinding_time);
+			if (log_getverbose() > 1) {
+				log_debug("DHO_DHCP_REBINDING_TIME %us",
+				    rebinding_time);
+			}
 			p += dho_len;
 			rem -= dho_len;
 			break;
@@ -925,7 +906,8 @@ parse_dhcp(struct dhcpleased_iface *iface, struct imsg_dhcp *dhcp)
 			rem -= dho_len;
 			break;
 		default:
-			log_debug("DHO_%u, len: %u", dho, dho_len);
+			if (log_getverbose() > 1)
+				log_debug("DHO_%u, len: %u", dho, dho_len);
 			p += dho_len;
 			rem -= dho_len;
 		}
@@ -941,6 +923,11 @@ parse_dhcp(struct dhcpleased_iface *iface, struct imsg_dhcp *dhcp)
 		log_warnx("%s: %lu bytes garbage data from %s", __func__, rem,
 		    from);
 
+	if_name = if_indextoname(iface->if_index, ifnamebuf);
+	log_debug("%s on %s from %s/%s to %s/%s",
+	    dhcp_message_type2str(dhcp_message_type), if_name == NULL ? "?" :
+	    if_name, from, hbuf_src, to, hbuf_dst);
+
 	switch (dhcp_message_type) {
 	case DHCPOFFER:
 		if (iface->state != IF_INIT) {
@@ -1049,6 +1036,7 @@ state_transition(struct dhcpleased_iface *iface, enum if_state new_state)
 {
 	enum if_state	 old_state = iface->state;
 	struct timespec	 now, res;
+	char		 ifnamebuf[IF_NAMESIZE], *if_name;
 
 	iface->state = new_state;
 	switch (new_state) {
@@ -1144,8 +1132,12 @@ state_transition(struct dhcpleased_iface *iface, enum if_state new_state)
 		request_dhcp_request(iface);
 		break;
 	}
-	log_debug("%s %s -> %s, timo: %lld", __func__, if_state_name[old_state],
-	    if_state_name[new_state], iface->timo.tv_sec);
+
+	if_name = if_indextoname(iface->if_index, ifnamebuf);
+	log_debug("%s[%s] %s -> %s, timo: %lld", __func__, if_name == NULL ?
+	    "?" : if_name, if_state_name[old_state], if_state_name[new_state],
+	    iface->timo.tv_sec);
+
 	if (iface->timo.tv_sec == -1) {
 		if (evtimer_pending(&iface->timer, NULL))
 			evtimer_del(&iface->timer);
@@ -1238,12 +1230,9 @@ void
 log_lease(struct dhcpleased_iface *iface, int deconfigure)
 {
 	char	 hbuf_lease[INET_ADDRSTRLEN], hbuf_server[INET_ADDRSTRLEN];
-	char	 if_name[IF_NAMESIZE];
+	char	 ifnamebuf[IF_NAMESIZE], *if_name;
 
-	memset(if_name, 0, sizeof(if_name));
-
-	if (if_indextoname(iface->if_index, if_name) == 0)
-		if_name[0] = '?';
+	if_name = if_indextoname(iface->if_index, ifnamebuf);
 	inet_ntop(AF_INET, &iface->requested_ip, hbuf_lease,
 	    sizeof(hbuf_lease));
 	inet_ntop(AF_INET, &iface->server_identifier, hbuf_server,
@@ -1252,10 +1241,10 @@ log_lease(struct dhcpleased_iface *iface, int deconfigure)
 
 	if (deconfigure)
 		log_info("deleting %s from %s (lease from %s)", hbuf_lease,
-		    if_name, hbuf_server);
+		    if_name == NULL ? "?" : if_name, hbuf_server);
 	else
 		log_info("adding %s to %s (lease from %s)", hbuf_lease,
-		    if_name, hbuf_server);
+		    if_name == NULL ? "?" : if_name, hbuf_server);
 }
 
 void
@@ -1301,12 +1290,9 @@ log_rdns(struct dhcpleased_iface *iface, int withdraw)
 {
 	int	 i;
 	char	 hbuf_rdns[INET_ADDRSTRLEN], hbuf_server[INET_ADDRSTRLEN];
-	char	 if_name[IF_NAMESIZE], *rdns_buf = NULL, *tmp_buf;
-
-	memset(if_name, 0, sizeof(if_name));
+	char	 ifnamebuf[IF_NAMESIZE], *if_name, *rdns_buf = NULL, *tmp_buf;
 
-	if (if_indextoname(iface->if_index, if_name) == 0)
-		if_name[0] = '?';
+	if_name = if_indextoname(iface->if_index, ifnamebuf);
 
 	inet_ntop(AF_INET, &iface->server_identifier, hbuf_server,
 	    sizeof(hbuf_server));
@@ -1325,12 +1311,15 @@ log_rdns(struct dhcpleased_iface *iface, int withdraw)
 	}
 
 	if (rdns_buf != NULL) {
-		if (withdraw)
+		if (withdraw) {
 			log_info("deleting nameservers%s (lease from %s on %s)",
-			    rdns_buf, hbuf_server, if_name);
-		else
+			    rdns_buf, hbuf_server, if_name == NULL ? "?" :
+			    if_name);
+		} else {
 			log_info("adding nameservers%s (lease from %s on %s)",
-			    rdns_buf, hbuf_server, if_name);
+			    rdns_buf, hbuf_server, if_name == NULL ? "?" :
+			    if_name);
+		}
 		free(rdns_buf);
 	}
 }
@@ -1390,3 +1379,62 @@ parse_lease(struct dhcpleased_iface *iface, struct imsg_ifinfo *imsg_ifinfo)
 	if (inet_pton(AF_INET, p, &iface->requested_ip) != 1)
 		iface->requested_ip.s_addr = INADDR_ANY;
 }
+
+void
+log_dhcp_hdr(struct dhcp_hdr *dhcp_hdr)
+{
+	char	 hbuf[INET_ADDRSTRLEN];
+
+	log_debug("dhcp_hdr op: %s (%d)", dhcp_hdr->op == DHCP_BOOTREQUEST ?
+	    "Boot Request" : dhcp_hdr->op == DHCP_BOOTREPLY ? "Boot Reply" :
+	    "Unknown", dhcp_hdr->op);
+	log_debug("dhcp_hdr htype: %s (%d)", dhcp_hdr->htype == 1 ? "Ethernet":
+	    "Unknown", dhcp_hdr->htype);
+	log_debug("dhcp_hdr hlen: %d", dhcp_hdr->hlen);
+	log_debug("dhcp_hdr hops: %d", dhcp_hdr->hops);
+	log_debug("dhcp_hdr xid: 0x%x", dhcp_hdr->xid);
+	log_debug("dhcp_hdr secs: %u", dhcp_hdr->secs);
+	log_debug("dhcp_hdr flags: 0x%x", dhcp_hdr->flags);
+	log_debug("dhcp_hdr ciaddr: %s", inet_ntop(AF_INET, &dhcp_hdr->ciaddr,
+	    hbuf, sizeof(hbuf)));
+	log_debug("dhcp_hdr yiaddr: %s", inet_ntop(AF_INET, &dhcp_hdr->yiaddr,
+	    hbuf, sizeof(hbuf)));
+	log_debug("dhcp_hdr siaddr: %s", inet_ntop(AF_INET, &dhcp_hdr->siaddr,
+	    hbuf, sizeof(hbuf)));
+	log_debug("dhcp_hdr giaddr: %s", inet_ntop(AF_INET, &dhcp_hdr->giaddr,
+	    hbuf, sizeof(hbuf)));
+	log_debug("dhcp_hdr chaddr: %02x:%02x:%02x:%02x:%02x:%02x "
+	    "(%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x)",
+	    dhcp_hdr->chaddr[0], dhcp_hdr->chaddr[1], dhcp_hdr->chaddr[2],
+	    dhcp_hdr->chaddr[3], dhcp_hdr->chaddr[4], dhcp_hdr->chaddr[5],
+	    dhcp_hdr->chaddr[6], dhcp_hdr->chaddr[7], dhcp_hdr->chaddr[8],
+	    dhcp_hdr->chaddr[9], dhcp_hdr->chaddr[10], dhcp_hdr->chaddr[11],
+	    dhcp_hdr->chaddr[12], dhcp_hdr->chaddr[13], dhcp_hdr->chaddr[14],
+	    dhcp_hdr->chaddr[15]);
+	/* ignore sname and file, if we ever print it use strvis(3) */
+}
+
+const char *
+dhcp_message_type2str(uint8_t dhcp_message_type)
+{
+	switch (dhcp_message_type) {
+	case DHCPDISCOVER:
+		return "DHCPDISCOVER";
+	case DHCPOFFER:
+		return "DHCPOFFER";
+	case DHCPREQUEST:
+		return "DHCPREQUEST";
+	case DHCPDECLINE:
+		return "DHCPDECLINE";
+	case DHCPACK:
+		return "DHCPACK";
+	case DHCPNAK:
+		return "DHCPNAK";
+	case DHCPRELEASE:
+		return "DHCPRELEASE";
+	case DHCPINFORM:
+		return "DHCPINFORM";
+	default:
+		return "Unknown";
+	}
+}
diff --git a/sbin/dhcpleased/frontend.c b/sbin/dhcpleased/frontend.c
index 0c5010fadf9..353082eca55 100644
--- a/sbin/dhcpleased/frontend.c
+++ b/sbin/dhcpleased/frontend.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: frontend.c,v 1.2 2021/03/02 17:39:26 claudio Exp $	*/
+/*	$OpenBSD: frontend.c,v 1.3 2021/03/07 18:39:11 florian Exp $	*/
 
 /*
  * Copyright (c) 2017, 2021 Florian Obser <florian@openbsd.org>
@@ -624,8 +624,7 @@ handle_route_message(struct rt_msghdr *rtm, struct sockaddr **rti_info)
 {
 	struct if_msghdr		*ifm;
 	int				 xflags, if_index;
-	char				 ifnamebuf[IFNAMSIZ];
-	char				*if_name;
+	char				 ifnamebuf[IF_NAMESIZE], *if_name;
 
 	switch (rtm->rtm_type) {
 	case RTM_IFINFO:
@@ -653,7 +652,8 @@ handle_route_message(struct rt_msghdr *rtm, struct sockaddr **rti_info)
 	case RTM_NEWADDR:
 		ifm = (struct if_msghdr *)rtm;
 		if_name = if_indextoname(ifm->ifm_index, ifnamebuf);
-		log_debug("RTM_NEWADDR: %s[%u]", if_name, ifm->ifm_index);
+		log_debug("RTM_NEWADDR: %s[%u]", if_name == NULL ?
+		    "?" : if_name, ifm->ifm_index);
 		update_iface(ifm->ifm_index, if_name);
 		break;
 	case RTM_PROPOSAL:
@@ -699,13 +699,13 @@ bpf_receive(int fd, short events, void *arg)
 
 	iface = (struct iface *)arg;
 
-	log_debug("%s: fd: %d", __func__, fd);
 	if ((len = read(fd, iface->bpfev.buf, BPFLEN)) == -1) {
 		log_warn("read");
 		return;
 	}
-	/* XXX len = 0 */
-	log_debug("%s: %ld", __func__, len);
+
+	if (len == 0)
+		fatal("%s len == 0", __func__);
 
 	memset(&imsg_dhcp, 0, sizeof(imsg_dhcp));
 	imsg_dhcp.if_index = iface->if_index;
@@ -818,16 +818,19 @@ void
 send_discover(struct iface *iface)
 {
 	ssize_t	 pkt_len;
+	char	 ifnamebuf[IF_NAMESIZE], *if_name;
 
 	if (!event_initialized(&iface->bpfev.ev)) {
 		iface->send_discover = 1;
 		return;
 	}
 	iface->send_discover = 0;
-	log_debug("%s", __func__);
+
+	if_name = if_indextoname(iface->if_index, ifnamebuf);
+	log_debug("DHCPDISCOVER on %s", if_name == NULL ? "?" : if_name);
+
 	pkt_len = build_packet(DHCPDISCOVER, iface->xid, &iface->hw_address,
 	    &iface->requested_ip, NULL);
-	log_debug("%s, pkt_len: %ld", __func__, pkt_len);
 	bpf_send_packet(iface, dhcp_packet, pkt_len);
 }
 
@@ -835,10 +838,13 @@ void
 send_request(struct iface *iface)
 {
 	ssize_t	 pkt_len;
+	char	 ifnamebuf[IF_NAMESIZE], *if_name;
+
+	if_name = if_indextoname(iface->if_index, ifnamebuf);
+	log_debug("DHCPREQUEST on %s", if_name == NULL ? "?" : if_name);
 
 	pkt_len = build_packet(DHCPREQUEST, iface->xid, &iface->hw_address,
 	    &iface->requested_ip, &iface->server_identifier);
-	log_debug("%s, pkt_len: %ld", __func__, pkt_len);
 	if (iface->dhcp_server.s_addr != INADDR_ANY)
 		udp_send_packet(iface, dhcp_packet, pkt_len);
 	else
@@ -850,7 +856,6 @@ udp_send_packet(struct iface *iface, uint8_t *packet, ssize_t len)
 {
 	struct sockaddr_in	to;
 
-	log_debug("%s", __func__);
 	memset(&to, 0, sizeof(to));
 	to.sin_family = AF_INET;
 	to.sin_len = sizeof(to);
@@ -960,8 +965,6 @@ set_bpfsock(int bpfsock, uint32_t if_index)
 {
 	struct iface	*iface;
 
-	log_debug("%s: %d fd: %d", __func__, if_index, bpfsock);
-
 	if ((iface = get_iface_by_id(if_index)) == NULL) {
 		/*
 		 * The interface disappeared while we were waiting for the