From 24aa62eefd9284fb94820093f6088607d42c4249 Mon Sep 17 00:00:00 2001
From: Samuel Tan <samueltan@google.com>
Date: Thu, 13 Aug 2015 17:12:30 -0700
Subject: [PATCH] Improve debugability

Cherry-picked from
https://chromium.googlesource.com/chromiumos/overlays/chromiumos-overlay/+/
master/net-misc/dhcpcd/files/patches/dhcpcd-6.8.2-Improve-debugability.patch.

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

BUG: 22956197
Change-Id: Idec6362a13d946831c8f0837a4cfe31c2671665e

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
---
 arp.c  |  2 +-
 dhcp.c | 23 +++++++++++++++++++----
 if.c   |  8 ++++++++
 3 files changed, 28 insertions(+), 5 deletions(-)

diff --git a/arp.c b/arp.c
index 96cf40c..1db1e89 100644
--- a/arp.c
+++ b/arp.c
@@ -282,7 +282,7 @@ arp_probe1(void *arg)
 		tv.tv_nsec = 0;
 		eloop_timeout_add_tv(ifp->ctx->eloop, &tv, arp_probed, astate);
 	}
-	logger(ifp->ctx, LOG_DEBUG,
+	logger(ifp->ctx, LOG_INFO,
 	    "%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,
diff --git a/dhcp.c b/dhcp.c
index f2a5899..32bced4 100644
--- a/dhcp.c
+++ b/dhcp.c
@@ -1654,7 +1654,7 @@ send_message(struct interface *ifp, uint8_t type,
 #endif
 
 	if (!callback)
-		logger(ifp->ctx, LOG_DEBUG, "%s: sending %s with xid 0x%x",
+		logger(ifp->ctx, LOG_INFO, "%s: sending %s with xid 0x%x",
 		    ifp->name,
 		    ifo->options & DHCPCD_BOOTP ? "BOOTP" : get_dhcp_op(type),
 		    state->xid);
@@ -1670,7 +1670,7 @@ send_message(struct interface *ifp, uint8_t type,
 		tv.tv_nsec = (suseconds_t)arc4random_uniform(
 		    (DHCP_RAND_MAX - DHCP_RAND_MIN) * NSEC_PER_SEC);
 		timespecnorm(&tv);
-		logger(ifp->ctx, LOG_DEBUG,
+		logger(ifp->ctx, LOG_INFO,
 		    "%s: sending %s (xid 0x%x), next in %0.1f seconds",
 		    ifp->name,
 		    ifo->options & DHCPCD_BOOTP ? "BOOTP" : get_dhcp_op(type),
@@ -1851,6 +1851,9 @@ dhcp_request(void *arg)
 	struct interface *ifp = arg;
 	struct dhcp_state *state = D_STATE(ifp);
 
+	logger(ifp->ctx, LOG_INFO, "%s: requesting lease of %s",
+		ifp->name, inet_ntoa(state->lease.addr));
+
 	rpc_signal_status("Request");
 	state->state = DHS_REQUEST;
 	state->nak_receive_count = 0;
@@ -1886,7 +1889,7 @@ dhcp_renew(void *arg)
 	struct dhcp_lease *lease = &state->lease;
 
 	rpc_signal_status("Renew");
-	logger(ifp->ctx, LOG_DEBUG, "%s: renewing lease of %s",
+	logger(ifp->ctx, LOG_INFO, "%s: renewing lease of %s",
 	    ifp->name, inet_ntoa(lease->addr));
 	logger(ifp->ctx, LOG_DEBUG, "%s: rebind in %"PRIu32" seconds,"
 	    " expire in %"PRIu32" seconds",
@@ -2285,6 +2288,8 @@ dhcp_inform(struct interface *ifp)
 
 	state = D_STATE(ifp);
 	ifo = ifp->options;
+	logger(ifp->ctx, LOG_INFO, "%s: informing peers of local address",
+	       ifp->name);
 	if (ifp->ctx->options & DHCPCD_TEST) {
 		state->addr.s_addr = ifo->req_addr.s_addr;
 		state->net.s_addr = ifo->req_mask.s_addr;
@@ -2840,6 +2845,9 @@ dhcp_handledhcp(struct interface *ifp, struct dhcp_message **dhcpp,
 		return;
 	}
 
+	logger(ifp->ctx, LOG_INFO, "%s: received %s with xid 0x%x",
+		ifp->name, get_dhcp_op(type), state->xid);
+
 	/* Authenticate the message */
 	auth = get_option(ifp->ctx, dhcp, DHO_AUTHENTICATION, &auth_len);
 	if (auth) {
@@ -3102,7 +3110,7 @@ dhcp_handledhcp(struct interface *ifp, struct dhcp_message **dhcpp,
 		}
 
 		if (!(ifo->options & DHCPCD_INFORM))
-			log_dhcp(LOG_DEBUG, "acknowledged", ifp, dhcp, from);
+			log_dhcp(LOG_INFO, "acknowledged", ifp, dhcp, from);
 		else
 		    ifo->options &= ~DHCPCD_STATIC;
 	}
@@ -3184,6 +3192,8 @@ valid_udp_packet(const uint8_t *data, size_t data_len, struct in_addr *from,
 	uint16_t bytes, udpsum;
 
 	if (data_len < sizeof(p.ip)) {
+		syslog(LOG_WARNING, "packet short than an ip header "
+			"(len=%zd)", data_len);
 		if (from)
 			from->s_addr = INADDR_ANY;
 		errno = EINVAL;
@@ -3193,16 +3203,20 @@ valid_udp_packet(const uint8_t *data, size_t data_len, struct in_addr *from,
 	if (from)
 		from->s_addr = p.ip.ip_src.s_addr;
 	if (data_len > sizeof(p)) {
+		syslog(LOG_WARNING, "packet too long (%zd bytes)", data_len);
 		errno = EINVAL;
 		return -1;
 	}
 	if (checksum(&p.ip, sizeof(p.ip)) != 0) {
+		syslog(LOG_WARNING, "packet failed ip header checksum");
 		errno = EINVAL;
 		return -1;
 	}
 
 	bytes = ntohs(p.ip.ip_len);
 	if (data_len < bytes) {
+		syslog(LOG_WARNING, "packet appears truncated "
+			"(len=%zd, ip_len=%zd)", data_len, bytes);
 		errno = EINVAL;
 		return -1;
 	}
@@ -3219,6 +3233,7 @@ valid_udp_packet(const uint8_t *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) {
+			syslog(LOG_WARNING, "packet failed udp checksum");
 			errno = EINVAL;
 			return -1;
 		}
diff --git a/if.c b/if.c
index 683021f..ddd03ff 100644
--- a/if.c
+++ b/if.c
@@ -566,6 +566,14 @@ if_discover(struct dhcpcd_ctx *ctx, int argc, char * const *argv)
 		TAILQ_INSERT_TAIL(ifs, ifp, next);
 	}
 
+	if (!ifs) {
+		logger(ctx, LOG_INFO, "%s: no matching interfaces", __func__);
+		for (ifa = ifaddrs; ifa; ifa = ifa->ifa_next) {
+			logger(ctx, LOG_INFO, "%s: considered %s",
+			       __func__, ifa->ifa_name);
+		}
+	}
+
 	if_learnaddrs1(ctx, ifs, ifaddrs);
 	freeifaddrs(ifaddrs);
 
-- 
cgit v1.2.3