Re: dhcpcd "misses" IPv4 renew, starts requesting every minute
Jeff Kletsky
Thu May 21 00:38:14 2020
On 5/20/20 2:05 PM, Roy Marples wrote:
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
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: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
jeff@front-xen:~/build/dhcpcd$ May 20 15:59:13 systemd[1]: Started DHCP
Client Daemon.
May 20 15:59:14 dhcpcd[4635]: enp0s0f0: rebinding lease of <IPv4
assigned addr>
May 20 15:59:14 dhcpcd[4635]: enp0s0f0: leased <IPv4 addr> for 5711 seconds
May 20 15:59:14 dhcpcd[4635]: enp0s0f0: adding route to <IPv4 assigned
net>/21
May 20 15:59:14 dhcpcd[4635]: enp0s0f0: adding default route <IPv4
assigned router>
May 20 15:59:15 dhcpcd[4635]: enp0s0f0: Router Advertisement from
fe80::201:5cff:fe65:bc46
May 20 15:59:15 dhcpcd[4635]: enp0s0f0: adding route to
2001:558:4000:18::/64 via fe80::201:5cff:fe65:bc46
May 20 15:59:15 dhcpcd[4635]: enp0s0f0: adding route to
2001:558:5027:7d::/64 via fe80::201:5cff:fe65:bc46
May 20 15:59:15 dhcpcd[4635]: enp0s0f0: adding route to
2001:558:6045:17::/64 via fe80::201:5cff:fe65:bc46
May 20 15:59:15 dhcpcd[4635]: enp0s0f0: adding route to
2001:558:8046:87::/64 via fe80::201:5cff:fe65:bc46
May 20 15:59:15 dhcpcd[4635]: enp0s0f0: adding default route via
fe80::201:5cff:fe65:bc46
$ systemctl cat dhcpcd.service
# /usr/local/etc/dhcpcd/dhcpcd.service
[Unit]
Description=DHCP Client Daemon
Wants=network.target
Documentation=man:dhcpcd(8)
[Service]
Type=forking
ExecStart=/usr/local/sbin/dhcpcd
Restart=always
[Install]
WantedBy=multi-user.target
diff-ed against the file from the Debian Buster deb for dhcpcd5 (7.1.0-2)
dhcpcd-package/extracted$ diff lib/systemd/system/dhcpcd.service
/usr/local/etc/dhcpcd/dhcpcd.service
8c8
< ExecStart=/usr/sbin/dhcpcd
---
> ExecStart=/usr/local/sbin/dhcpcd
$ systemctl status dhcpcd.service
* dhcpcd.service - DHCP Client Daemon
Loaded: loaded (/usr/local/etc/dhcpcd/dhcpcd.service; linked; vendor
preset: enabled)
Active: active (running) since Wed 2020-05-20 15:59:13 PDT; 19min ago
Docs: man:dhcpcd(8)
Process: 4625 ExecStart=/usr/local/sbin/dhcpcd (code=exited,
status=0/SUCCESS)
Main PID: 4635 (dhcpcd)
Tasks: 4 (limit: 472)
Memory: 1.3M
CGroup: /system.slice/dhcpcd.service
|-4635 dhcpcd: [master] [ip4] [ip6]
|-4636 dhcpcd: [privileged actioneer]
|-4637 dhcpcd: [network proxy]
`-4645 dhcpcd: [BPF ARP] enp0s0f0
$ pgrep -a dhcp
4635 dhcpcd: [master] [ip4] [ip6]
4636 dhcpcd: [privileged actioneer]
4637 dhcpcd: [network proxy]
4645 dhcpcd: [BPF ARP] enp0s0f0
/etc/group shows "root" as group 0
Archive administrator: postmaster@marples.name