From 1c8e51d6e0ae428bb2e277e4f8dff79b6eab3874 Mon Sep 17 00:00:00 2001
From: Peter Qiu <zqiu@chromium.org>
Date: Thu, 10 Jun 2021 17:52:03 +0000
Subject: [PATCH 12/19] Improve debugability

Increase log level for certain log messages and add more log messages
to improve debugability.

Author: Paul Stewart <pstew@chromium.org>
Author: mukesh agrawal <quiche@chromium.org>
Reviewed-on: https://gerrit.chromium.org/gerrit/42622
Reviewed-on: https://chromium-review.googlesource.com/185511
Reviewed-on: https://chromium-review.googlesource.com/186593
Reviewed-on: https://chromium-review.googlesource.com/206143
Reviewed-on: https://gerrit.chromium.org/gerrit/24835
---
 src/arp.c  |  2 +-
 src/dhcp.c | 22 +++++++++++++++++-----
 src/if.c   |  7 +++++++
 3 files changed, 25 insertions(+), 6 deletions(-)

diff --git a/src/arp.c b/src/arp.c
index f3b2e8ad..c07e0f6c 100644
--- a/src/arp.c
+++ b/src/arp.c
@@ -296,7 +296,7 @@ arp_probe1(void *arg)
 		tv.tv_nsec = 0;
 		eloop_timeout_add_tv(ifp->ctx->eloop, &tv, arp_probed, astate);
 	}
-	logdebugx("%s: ARP probing %s (%d of %d), next in %0.1f seconds",
+	loginfox("%s: ARP probing %s (%d of %d), next in %0.1f seconds",
 	    ifp->name, inet_ntoa(astate->addr),
 	    astate->probes ? astate->probes : PROBE_NUM, PROBE_NUM,
 	    timespec_to_double(&tv));
diff --git a/src/dhcp.c b/src/dhcp.c
index d0bb26e5..c03c0904 100644
--- a/src/dhcp.c
+++ b/src/dhcp.c
@@ -1835,7 +1835,7 @@ send_message(struct interface *ifp, uint8_t type,
 		/* No carrier? Don't bother sending the packet. */
 		if (ifp->carrier <= LINK_DOWN)
 			return;
-		logdebugx("%s: sending %s with xid 0x%x",
+		loginfox("%s: sending %s with xid 0x%x",
 		    ifp->name,
 		    ifo->options & DHCPCD_BOOTP ? "BOOTP" : get_dhcp_op(type),
 		    state->xid);
@@ -1855,7 +1855,7 @@ send_message(struct interface *ifp, uint8_t type,
 		 * However, we do need to advance the timeout. */
 		if (ifp->carrier <= LINK_DOWN)
 			goto fail;
-		logdebugx("%s: sending %s (xid 0x%x), next in %0.1f seconds",
+		loginfox("%s: sending %s (xid 0x%x), next in %0.1f seconds",
 		    ifp->name,
 		    ifo->options & DHCPCD_BOOTP ? "BOOTP" : get_dhcp_op(type),
 		    state->xid,
@@ -1996,6 +1996,8 @@ dhcp_request(void *arg)
 	struct dhcp_state *state = D_STATE(ifp);
 
 	rpc_signal_status("Request");
+	loginfox("%s: requesting lease of %s",
+		 ifp->name, inet_ntoa(state->lease.addr));
 	state->state = DHS_REQUEST;
 	state->nak_receive_count = 0;
 	send_request(ifp);
@@ -2085,8 +2087,8 @@ dhcp_startrenew(void *arg)
 	eloop_timeout_delete(ifp->ctx->eloop, dhcp_startrenew, ifp);
 
 	lease = &state->lease;
-	logdebugx("%s: renewing lease of %s", ifp->name,
-	    inet_ntoa(lease->addr));
+	loginfox("%s: renewing lease of %s", ifp->name,
+		 inet_ntoa(lease->addr));
 	state->state = DHS_RENEW;
 	state->nak_receive_count = 0;
 	dhcp_new_xid(ifp);
@@ -2829,6 +2831,7 @@ dhcp_inform(struct interface *ifp)
 	ifo = ifp->options;
 
 	rpc_signal_status("Inform");
+	loginfox("%s: informing peers of local address", ifp->name);
 	state->state = DHS_INFORM;
 	free(state->offer);
 	state->offer = NULL;
@@ -3354,6 +3357,9 @@ dhcp_handledhcp(struct interface *ifp, struct bootp *bootp, size_t bootp_len,
 		return;
 	}
 
+	loginfox("%s: received %s with xid 0x%x",
+		 ifp->name, get_dhcp_op(type), state->xid);
+
 #ifdef AUTH
 	/* Authenticate the message */
 	auth = get_option(ifp->ctx, bootp, bootp_len,
@@ -3640,7 +3646,7 @@ dhcp_handledhcp(struct interface *ifp, struct bootp *bootp, size_t bootp_len,
 
 rapidcommit:
 		if (!(ifo->options & DHCPCD_INFORM))
-			LOGDHCP(logdebugx, "acknowledged");
+			LOGDHCP(loginfox, "acknowledged");
 		else
 		    ifo->options &= ~DHCPCD_STATIC;
 	}
@@ -3697,6 +3703,8 @@ valid_udp_packet(void *data, size_t data_len, struct in_addr *from,
 	uint16_t bytes;
 
 	if (data_len < sizeof(p->ip)) {
+		logwarnx("packet shorter than an ip header "
+			 "(len=%zd)", data_len);
 		if (from)
 			from->s_addr = INADDR_ANY;
 		errno = ERANGE;
@@ -3706,6 +3714,7 @@ valid_udp_packet(void *data, size_t data_len, struct in_addr *from,
 	if (from)
 		from->s_addr = p->ip.ip_src.s_addr;
 	if (checksum(&p->ip, sizeof(p->ip)) != 0) {
+		logwarnx("packet failed ip header checksum");
 		errno = EINVAL;
 		return -1;
 	}
@@ -3718,6 +3727,8 @@ valid_udp_packet(void *data, size_t data_len, struct in_addr *from,
 	}
 	/* Check we don't go beyond the payload */
 	if (bytes > data_len) {
+		logwarnx("packet appears truncated "
+			 "(len=%zd, ip_len=%hu)", data_len, bytes);
 		errno = ENOBUFS;
 		return -1;
 	}
@@ -3739,6 +3750,7 @@ valid_udp_packet(void *data, size_t data_len, struct in_addr *from,
 		p->ip.ip_ttl = 0;
 		p->ip.ip_sum = 0;
 		if (udpsum && checksum(p, bytes) != udpsum) {
+			logwarnx("packet failed udp checksum");
 			errno = EINVAL;
 			return -1;
 		}
diff --git a/src/if.c b/src/if.c
index 643fc546..ad7baa84 100644
--- a/src/if.c
+++ b/src/if.c
@@ -630,6 +630,13 @@ if_discover(struct dhcpcd_ctx *ctx, struct ifaddrs **ifaddrs,
 		TAILQ_INSERT_TAIL(ifs, ifp, next);
 	}
 
+	if (!ifs) {
+		loginfox("%s: no matching interfaces", __func__);
+		for (ifa = *ifaddrs; ifa; ifa = ifa->ifa_next) {
+			loginfox("%s: considered %s", __func__, ifa->ifa_name);
+		}
+	}
+
 #ifdef IFLR_ACTIVE
 	close(link_fd);
 #endif
-- 
2.33.0.800.g4c38ced690-goog