dhcpcd-discuss

Home Other Lists Thread Index Date Index Search
Thread Prev Thread Next Date Prev Date Next Thread Index Date Index

Re: dhcpcd "misses" IPv4 renew, starts requesting every minute

Roy Marples

Thu May 21 01:06:54 2020
On 21/05/2020 00:38, Jeff Kletsky wrote:
I can't say that I'm either an expert with or a fan of systemd, especially after running FreeBSD since 4.4 or so. 

I definitely appreciate the help on this!
It appears I successfully enabled chroot, though I neglected to copy over the DUID, so my IPv6 changed. (Later copying in the duid file to the chroot and restarting resulted in the previous IPv6 IA_NA and IA_PD.) 

dhcpcd-9.1.x (or the master branch as is) won't need that.
All files will reside outside the chroot.



dhcpcd:x:65:65::/srv/dhcpcd/chroot:/usr/sbin/nologin
dhcpcd:*:18402:0:99999:7:::

dhcpcd:x:65:
dhcpcd:!::

65:65 happens to be consistent with FreeBSD's _dhcp user:grup.
/srv/dhcpcd/chroot seemed to be vaguely in line with a non-expert's read of the (Linux?) Filesystem Hierarchy Standard
The patch did not cleanly apply to master, so I patched dhcpcd-9.0.2 (same point as my previous build) 

./configure --prefix=/usr/local --sysconfdir=/usr/local/etc/dhcpcd --rundir=/run


$ sudo systemctl restart dhcpcd.service
May 20 15:59:12 dhcpcd[2973]: received SIGTERM, stopping
May 20 15:59:12 dhcpcd[2973]: enp0s0f0: removing interface
May 20 15:59:12 systemd[1]: Stopping DHCP Client Daemon...
May 20 15:59:12 dhcpcd[2974]: process 2974 unexpectedly terminating on signal 15
May 20 15:59:12 dhcpcd[2973]: main: control_stop: Transport endpoint is not connected 
May 20 15:59:12 dhcpcd[2973]: ps_dostop: Connection refused
May 20 15:59:12 dhcpcd[2973]: ps_dostop: Transport endpoint is not connected
May 20 15:59:12 dhcpcd[2973]: dhcpcd exited
May 20 15:59:12 systemd[1]: dhcpcd.service: Succeeded.
May 20 15:59:12 systemd[1]: Stopped DHCP Client Daemon.
May 20 15:59:12 systemd[1]: Starting DHCP Client Daemon...
May 20 15:59:12 dhcpcd[4625]: MAIN ENTRY
May 20 15:59:12 dhcpcd[4625]: MAIN ENTRY
May 20 15:59:12 dhcpcd[4625]: CTX INIT
May 20 15:59:12 dhcpcd[4625]: CTX INIT
May 20 15:59:12 dhcpcd[4625]: CMDLINE
May 20 15:59:12 dhcpcd[4625]: CMDLINE
May 20 15:59:12 dhcpcd[4625]: DEBUG 1
May 20 15:59:12 dhcpcd[4625]: DEBUG 1
May 20 15:59:12 dhcpcd[4625]: DEBUG 2
May 20 15:59:12 dhcpcd[4625]: DEBUG 2
May 20 15:59:12 dhcpcd[4625]: DEBUG 3
May 20 15:59:12 dhcpcd[4625]: DEBUG 3
May 20 15:59:12 dhcpcd[4625]: DEBUG 4
May 20 15:59:12 dhcpcd[4625]: main: control_open: Connection refused
May 20 15:59:12 dhcpcd[4625]: DEBUG 5
May 20 15:59:12 dhcpcd[4625]: DEBUG 6
May 20 15:59:12 dhcpcd[4625]: DEBUG 7
May 20 15:59:12 dhcpcd[4625]: dhcpcd-9.0.2 starting
May 20 15:59:12 dhcpcd[4625]: DEBUG 4
May 20 15:59:12 dhcpcd[4625]: main: control_open: Connection refused
May 20 15:59:12 dhcpcd[4625]: DEBUG 5
May 20 15:59:12 dhcpcd[4625]: DEBUG 6
May 20 15:59:12 dhcpcd[4625]: DEBUG 7
May 20 15:59:12 dhcpcd[4625]: dhcpcd-9.0.2 starting
May 20 15:59:12 dhcpcd[4625]: controlgroup: root: not found
May 20 15:59:12 dhcpcd[4635]: controlgroup: root: not found
May 20 15:59:12 dhcpcd[4625]: DUID 00:01:00:01:26:58:6c:ef:68:05:ca:aa:bb:cc
May 20 15:59:12 dhcpcd[4625]: enp0s0f0: IAID ca:aa:bb:cc
May 20 15:59:12 dhcpcd[4625]: enp0s0f0: IA type 3 IAID 00:00:00:01
May 20 15:59:12 dhcpcd[4625]: enp0s0f0: IA type 25 IAID b9:dd:ee:ff
May 20 15:59:12 dhcpcd[4625]: enp0s0f0: rebinding prior DHCPv6 lease
May 20 15:59:12 dhcpcd[4625]: enp0s0f0: cannot delegate to enp2s0.46: No such device or address 
May 20 15:59:12 dhcpcd[4635]: DUID 00:01:00:01:26:58:6c:ef:68:05:ca:aa:bb:cc
May 20 15:59:12 dhcpcd[4635]: enp0s0f0: IAID ca:aa:bb:cc
May 20 15:59:12 dhcpcd[4635]: enp0s0f0: IA type 3 IAID 00:00:00:01
May 20 15:59:12 dhcpcd[4635]: enp0s0f0: IA type 25 IAID b9:dd:ee:ff
May 20 15:59:12 dhcpcd[4635]: enp0s0f0: rebinding prior DHCPv6 lease
May 20 15:59:12 dhcpcd[4635]: enp0s0f0: cannot delegate to <non-existent-link>: No such device or address 
May 20 15:59:12 dhcpcd[4625]: enp0s0f0: soliciting an IPv6 router
May 20 15:59:12 dhcpcd[4635]: enp0s0f0: soliciting an IPv6 router
May 20 15:59:13 dhcpcd[4625]: enp0s0f0: REPLY6 received from fe80::201:5cff:fe65:bc46 
May 20 15:59:13 dhcpcd[4625]: enp0s0f0: adding address <IA_NA addr>/128
May 20 15:59:13 dhcpcd[4635]: enp0s0f0: REPLY6 received from fe80::201:5cff:fe65:bc46 
May 20 15:59:13 dhcpcd[4635]: enp0s0f0: adding address  <IA_NA addr>/128
May 20 15:59:13 dhcpcd[4625]: enp0s0f0: renew in 1060, rebind in 1696, expire in 2120 seconds 
May 20 15:59:13 dhcpcd[4625]: lo: adding reject route to <IA_PD addr>::/60
May 20 15:59:13 dhcpcd[4625]: enp0s0f0: delegated prefix <IA_PD addr>::/60
May 20 15:59:13 dhcpcd[4635]: enp0s0f0: renew in 1060, rebind in 1696, expire in 2120 seconds 
May 20 15:59:13 dhcpcd[4635]: lo: adding reject route to <IA_PD addr>::/60
May 20 15:59:13 dhcpcd[4635]: enp0s0f0: delegated prefix <IA_PD addr>::/60
May 20 15:59:13 dhcpcd[4625]: forked to background, child pid 4635


Aha! Here's the most important detail.
Notice that pid 4625 forked to the child pid of 4635 - these are the duplicates.
So we can assume systemd is logging the console output of dhcpcd AND the syslog output. So there is no error with duplicate processes. 

Please edit your dhcpcd service file like so:
[Service]
StandardOutput=null
StandardError=null

https://www.freedesktop.org/software/systemd/man/systemd.exec.html#StandardOutput=

You can remove that patch now - the cause is known and it's not your problem.
Let's get some more logs after you've made that change please so there's less confusion :) 

Roy
Follow-Ups:
Re: dhcpcd "misses" IPv4 renew, starts requesting every minuteJeff Kletsky
References:
dhcpcd "misses" IPv4 renew, starts requesting every minuteJeff Kletsky
Re: dhcpcd "misses" IPv4 renew, starts requesting every minuteRoy Marples
Re: dhcpcd "misses" IPv4 renew, starts requesting every minuteJeff Kletsky
Archive administrator: postmaster@marples.name