dhcpcd-discuss

On 5/20/20 5:06 PM, Roy Marples wrote:
> On 21/05/2020 00:38, Jeff Kletsky wrote:
> [...]
> 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 :)


Thanks, moved to master

commit 93082d4c (HEAD -> master, tag: build-2020-05-20_1716, 
marples/master, debug-2020-05)
Author: Roy Marples <roy@xxxxxxxxxxxx>
Date:   Wed May 20 21:43:20 2020 +0100

    privsep: Log the user chrooting as


/usr/local/etc/dhcpcd$ git diff HEAD^
diff --git a/dhcpcd.service b/dhcpcd.service
index 0b21f99..abc1e6a 100644
--- a/dhcpcd.service
+++ b/dhcpcd.service
@@ -7,6 +7,8 @@ Documentation=man:dhcpcd(8)
 Type=forking
 ExecStart=/usr/local/sbin/dhcpcd
 Restart=always
+StandardOutput=null
+StandardError=null

 [Install]
 WantedBy=multi-user.target



/usr/local/etc/dhcpcd$ sudo systemctl daemon-reload


(tail -F /var/log/daemon.log in background; now with high-res timestamps 
being logged)

/usr/local/etc/dhcpcd$ sudo systemctl restart dhcpcd.service
2020-05-20T17:22:36.868602-07:00 systemd[1]: Stopping DHCP Client Daemon...
2020-05-20T17:22:36.871107-07:00 dhcpcd[6777]: received SIGTERM, stopping
2020-05-20T17:22:36.871354-07:00 dhcpcd[6777]: enp0s0f0: removing interface
2020-05-20T17:22:36.875321-07:00 dhcpcd[6778]: process 6778 unexpectedly 
terminating on signal 15
2020-05-20T17:22:36.875510-07:00 dhcpcd[6777]: main: control_stop: 
Transport endpoint is not connected
2020-05-20T17:22:36.875660-07:00 dhcpcd[6777]: ps_dostop: Connection refused
2020-05-20T17:22:36.875803-07:00 dhcpcd[6777]: ps_dostop: Transport 
endpoint is not connected
2020-05-20T17:22:36.875952-07:00 dhcpcd[6777]: dhcpcd exited
2020-05-20T17:22:36.878033-07:00 systemd[1]: dhcpcd.service: Succeeded.
2020-05-20T17:22:36.878483-07:00 systemd[1]: Stopped DHCP Client Daemon.
2020-05-20T17:22:36.881031-07:00 systemd[1]: Starting DHCP Client Daemon...
2020-05-20T17:22:36.893402-07:00 dhcpcd[8278]: main: control_open: 
Connection refused
2020-05-20T17:22:36.893883-07:00 dhcpcd[8278]: dhcpcd-9.0.2 starting
2020-05-20T17:22:36.927151-07:00 dhcpcd[8288]: DUID 00:04:<my duid>
2020-05-20T17:22:36.928107-07:00 dhcpcd[8288]: controlgroup: root: not found
2020-05-20T17:22:36.932829-07:00 dhcpcd[8288]: enp0s0f0: IAID ca:aa:bb:cc
2020-05-20T17:22:36.933003-07:00 dhcpcd[8288]: enp0s0f0: IA type 3 IAID 
00:00:00:01
2020-05-20T17:22:36.933157-07:00 dhcpcd[8288]: enp0s0f0: IA type 25 IAID 
b9:dd:ee:ff
2020-05-20T17:22:36.934800-07:00 dhcpcd[8288]: enp0s0f0: soliciting a 
DHCPv6 lease
2020-05-20T17:22:36.935019-07:00 dhcpcd[8288]: enp0s0f0: cannot delegate 
to enp2s0.46: No such device or address
2020-05-20T17:22:37.510681-07:00 dhcpcd[8288]: enp0s0f0: soliciting an 
IPv6 router
2020-05-20T17:22:37.954913-07:00 dhcpcd[8288]: enp0s0f0: ADV <IA_NA 
addr>/128 from fe80::201:5cff:fe65:bc46
2020-05-20T17:22:37.971212-07:00 dhcpcd[8288]: enp0s0f0: REPLY6 received 
from fe80::201:5cff:fe65:bc46
2020-05-20T17:22:37.971647-07:00 dhcpcd[8288]: enp0s0f0: adding address 
<IA_NA addr>/128
2020-05-20T17:22:37.971981-07:00 dhcpcd[8288]: enp0s0f0: renew in 3600, 
rebind in 5760, expire in 7200 seconds
2020-05-20T17:22:37.972322-07:00 dhcpcd[8288]: lo: adding reject route 
to <IA_PD>::/60
2020-05-20T17:22:37.972684-07:00 dhcpcd[8288]: enp0s0f0: delegated 
prefix <IA_PD>::/60
2020-05-20T17:22:37.976081-07:00 systemd[1]: Started DHCP Client Daemon.
/usr/local/etc/dhcpcd$ 2020-05-20T17:22:38.169218-07:00 dhcpcd[8288]: 
enp0s0f0: soliciting a DHCP lease
2020-05-20T17:22:38.233781-07:00 dhcpcd[8288]: enp0s0f0: offered <IPv4 
addr> from 76.96.19.203
2020-05-20T17:22:38.271126-07:00 dhcpcd[8288]: enp0s0f0: leased <IPv4 
addr> for 5431 seconds
2020-05-20T17:22:38.272247-07:00 dhcpcd[8288]: enp0s0f0: adding route to 
<IPv4 net>/21
2020-05-20T17:22:38.272420-07:00 dhcpcd[8288]: enp0s0f0: adding default 
route via <IPv4 router>
2020-05-20T17:22:38.356999-07:00 dhcpcd[8288]: enp0s0f0: Router 
Advertisement from fe80::201:5cff:fe65:bc46
2020-05-20T17:22:38.357960-07:00 dhcpcd[8288]: enp0s0f0: adding route to 
2001:558:4000:18::/64 via fe80::201:5cff:fe65:bc46
2020-05-20T17:22:38.358137-07:00 dhcpcd[8288]: enp0s0f0: adding route to 
2001:558:5027:7d::/64 via fe80::201:5cff:fe65:bc46
2020-05-20T17:22:38.358293-07:00 dhcpcd[8288]: enp0s0f0: adding route to 
2001:558:6045:17::/64 via fe80::201:5cff:fe65:bc46
2020-05-20T17:22:38.358458-07:00 dhcpcd[8288]: enp0s0f0: adding route to 
2001:558:8046:87::/64 via fe80::201:5cff:fe65:bc46
2020-05-20T17:22:38.358603-07:00 dhcpcd[8288]: enp0s0f0: adding default 
route via fe80::201:5cff:fe65:bc46

So far I see a "classic" exchange in around 100 ms, with yet another 
source IP address

:38.170302   0.0.0.0 => 255.255.255.255    DHCP Discover
:38.233330   98.207.152.1 => <my addr>    DHCP Offer
:38.234352   <my addr> => 98.207.152.1    DHCP Request
:38.270478   98.207.152.1 => <my addr>    DHCP ACK

Relay agent IP: 96.120.88.229
Option 54: 76.96.19.203
Option 51: 5431 s (1:30:31)
Option 58: 2715 s (0:45:15)
Option 59: 4752 s (1:19:12)

(45 minutes passes from original lease, 2715 seconds, to be precise)

18:07:53    <my addr> => 76.96.19.203    DHCP Request
18:07:53    76.96.19.203 => <my addr>    DHCP ACK

(no bad behavior seen at this point)

Option 51: 7200 s
Option 58: 3600 s (1 hour)
Option 59: 6300 s (1 hour 15 min)

seems to be reflected in the lease

reason=RENEW
interface=enp0s0f0
[...]
dhcp_lease_time=7200
dhcp_message_type=5
dhcp_server_identifier=76.96.19.203
dhcp_renewal_time=3600
dhcp_rebinding_time=6300
skip_hooks=resolv.conf hostname ntp.conf


I'd like to say this "proves" that the issue has been resolved somewhere 
since 9.0.2, but I'll definitely keep my eyes on both the packets and 
the logs.

(Yes, I'm willing to make further tests as well)


Thanks again for the support,


Jeff