dhcpcd-discuss

Hi Jeff

Comments inline below

On 20/05/2020 18:58, Jeff Kletsky wrote:
> I'm seeing some strange behavior with dhcpcd built from tag 9.0.2 and Comcast 
> DOCSIS transport with modem in bridged/transparent mode.
>
> While the initial IPv4 rebind succeeds, later rebind attempts seem to not be 
> acknowledged by dhcpcd. DHCP ACK packets from each rebind attempt can be seen 
> coming from the Comcast DHCP server with wireshark.
>
> It may be due to the IP address of the DHCP server "changing" between the 
> initial Request/ACK (fro the IP address which answered 255.255.255.255) and that 
> used at rebind attempt (consistent with the Option 54 DHCP Server Identifier in 
> that initial ACK).
>
> How can I further diagnose this or resolve this?
>
> (I'd prefer not to resolve it without restarting dhcpcd every hour)

I would like to resolve this as well :)
So far this seems to be a systemd only issue and it's been reported by Arch 
Linux users for a while now.
It's almost the next thing on my list to look at .... I don't have any systemd 
machines.


> TIA,
>
> Jeff
>
>
> In detail:
>
>
> Built and running on Debian 10 (Buster) commit 92a4102b (HEAD, tag: 
> dhcpcd-9.0.2, tag: build-2020-05-02)
>
> I restarted dhcpcd this morning and it appears to properly rebind the existing 
> leases
>
> May 20 07:11:38 systemd[1]: Stopping DHCP Client Daemon...
> May 20 07:11:38 dhcpcd[658]: received SIGTERM, stopping
> May 20 07:11:38 dhcpcd[658]: enp0s0f0: removing interface
> May 20 07:11:38 dhcpcd[658]: dhcpcd exited
> May 20 07:11:38 systemd[1]: dhcpcd.service: Succeeded.
> May 20 07:11:38 systemd[1]: Stopped DHCP Client Daemon.
> May 20 07:11:38 systemd[1]: Starting DHCP Client Daemon...
> May 20 07:11:38 dhcpcd[17134]: dhcpcd-9.0.2 starting
> May 20 07:11:38 dhcpcd[17134]: dhcpcd-9.0.2 starting

This is the main cause for concern - why the double log entry?

> May 20 07:11:38 dhcpcd[17134]: no such user dhcpcd
> May 20 07:11:38 dhcpcd[17134]: no such user dhcpcd

Again, a double log entry.
The default compile for dhcpcd is with privsep enabled.
Please add the dhcpcd user and give it a sensible home directory - I use 
/var/chroot/dhcpcd on NetBSD.

> May 20 07:11:38 dhcpcd[17134]: DUID <redacted>
> May 20 07:11:38 dhcpcd[17134]: enp0s0f0: IAID <redacted>
> May 20 07:11:38 dhcpcd[17134]: enp0s0f0: IA type 3 IAID 00:00:00:01
> May 20 07:11:38 dhcpcd[17134]: enp0s0f0: IA type 25 IAID <redacted>
> May 20 07:11:38 dhcpcd[17134]: enp0s0f0: rebinding prior DHCPv6 lease
> May 20 07:11:38 dhcpcd[17134]: enp0s0f0: cannot delegate to <redacted>: No such 
> device or address
> May 20 07:11:38 dhcpcd[17136]: DUID<redacted>
> May 20 07:11:38 dhcpcd[17136]: enp0s0f0: IAID <redacted>
> May 20 07:11:38 dhcpcd[17136]: enp0s0f0: IA type 3 IAID 00:00:00:01
> May 20 07:11:38 dhcpcd[17136]: enp0s0f0: IA type 25 IAID <redacted>
> May 20 07:11:38 dhcpcd[17136]: enp0s0f0: rebinding prior DHCPv6 lease
> May 20 07:11:38 dhcpcd[17136]: enp0s0f0: cannot delegate to <redacted>: No such 
> device or address

Now it gets serious.
I think it's related to the double entries above - we now have two dhcpcd 
processes trying to do the work of one.

Only one dhcpcd process can receive RENEW messages from the DHCP server.
Which one gets it ..... is random. First to read the socket I think.

Everything below looks fine or related this issue above.

Can you try using the attached patch please?
It might shed some light as to where the double log starts.

Roy

diff --git a/src/dhcpcd.c b/src/dhcpcd.c
index 0059f47b..b3ca3dc9 100644
--- a/src/dhcpcd.c
+++ b/src/dhcpcd.c
@@ -1762,6 +1762,12 @@ main(int argc, char **argv)
 	const char *siga = NULL;
 #endif
 
+	logopts = LOGERR_ERR|LOGERR_LOG|LOGERR_LOG_DATE|LOGERR_LOG_PID;
+	logsetopts(logopts);
+	logopen(NULL);
+
+	loginfox("MAIN ENTRY");
+
 	/* Test for --help and --version */
 	if (argc > 1) {
 		if (strcmp(argv[1], "--help") == 0) {
@@ -1828,7 +1834,8 @@ main(int argc, char **argv)
 #endif
 	rt_init(&ctx);
 
-	logopts = LOGERR_ERR|LOGERR_LOG|LOGERR_LOG_DATE|LOGERR_LOG_PID;
+	loginfox("CTX INIT");
+
 	i = 0;
 	while ((opt = getopt_long(argc, argv,
 	    ctx.options & DHCPCD_PRINT_PIDFILE ? NOERR_IF_OPTS : IF_OPTS,
@@ -1897,8 +1904,7 @@ main(int argc, char **argv)
 		}
 	}
 
-	logsetopts(logopts);
-	logopen(ctx.logfile);
+	loginfox("CMDLINE");
 
 	ctx.argv = argv;
 	ctx.argc = argc;
@@ -1967,6 +1973,8 @@ main(int argc, char **argv)
 	if (ctx.options & DHCPCD_DEBUG)
 		logsetopts(logopts | LOGERR_DEBUG);
 
+	loginfox("DEBUG 1");
+
 	if (!(ctx.options & (DHCPCD_TEST | DHCPCD_DUMPLEASE))) {
 printpidfile:
 		/* If we have any other args, we should run as a single dhcpcd
@@ -2005,6 +2013,8 @@ printpidfile:
 		}
 	}
 
+	loginfox("DEBUG 2");
+
 	if (chdir("/") == -1)
 		logerr("%s: chdir `/'", __func__);
 
@@ -2015,6 +2025,8 @@ printpidfile:
 		goto exit_failure;
 	}
 
+	loginfox("DEBUG 3");
+
 #ifdef USE_SIGNALS
 	/* Ignore SIGPIPE, prefer EPIPE. */
 	signal(SIGPIPE, SIG_IGN);
@@ -2032,6 +2044,8 @@ printpidfile:
 		goto exit_failure;
 	}
 
+	loginfox("DEBUG 4");
+
 	/* Test against siga instead of sig to avoid gcc
 	 * warning about a bogus potential signed overflow.
 	 * The end result will be the same. */
@@ -2077,6 +2091,8 @@ printpidfile:
 	}
 #endif
 
+	loginfox("DEBUG 5");
+
 #ifdef USE_SIGNALS
 	if (sig != 0) {
 		pid = pidfile_read(ctx.pidfile);
@@ -2111,6 +2127,8 @@ printpidfile:
 		}
 	}
 
+	loginfox("DEBUG 6");
+
 	if (!(ctx.options & DHCPCD_TEST)) {
 		/* Ensure we have the needed directories */
 		if (mkdir(RUNDIR, 0755) == -1 && errno != EEXIST)
@@ -2128,6 +2146,8 @@ printpidfile:
 	}
 #endif
 
+	loginfox("DEBUG 7");
+
 	loginfox(PACKAGE "-" VERSION " starting");
 	freopen(_PATH_DEVNULL, "r", stdin);