You are not logged in.

#1 2019-11-06 11:00:23

aclindsa
Member
Registered: 2011-01-29
Posts: 28
Website

dhcpcd Intermittently Fails

I have an issue where dhcpcd seems to intermittently fail to daemonize after receiving the initial dhcp lease, which results in my dhcp lease expiring about a day after I reboot. Here is the output from `journalctl` which I believe is causing the problem (notice the 'eloop_start: Invalid argument'):

Nov 05 09:53:44 hostname dhcpcd[3753]: dhcpcd exited
Nov 05 09:53:44 hostname dhcpcd[3753]: main: eloop_start: Invalid argument
Nov 05 09:53:44 hostname dhcpcd[2159]: forked to background, child pid 3753
Nov 05 09:53:44 hostname dhcpcd[2159]: eno1: adding default route via 192.168.1.1
Nov 05 09:53:44 hostname dhcpcd[2159]: eno1: adding route to 192.168.1.0/24
Nov 05 09:53:44 hostname dhcpcd[2159]: eno1: leased 192.168.1.114 for 86400 seconds

I am using netctl and have the following in /etc/netctl/ethernet-dhcp:

Description='A basic dhcp ethernet connection'
Interface=eno1
Connection=ethernet

I see the following line in the output of `systemctl`, so it appears to be properly enabled:

netctl@ethernet\x2ddhcp.service           loaded active exited    A basic dhcp ethernet conn

I first noticed this on October 26th, and had been using dhcpcd 7.2.2-1 since June 25th without problem. I upgraded to 8.1.1-1 on October 30th with no change in the behavior.

Any ideas? I'm not sure where to go next to debug this issue.

Offline

#2 2019-11-06 13:26:46

TCBear
Member
Registered: 2016-01-22
Posts: 33

Re: dhcpcd Intermittently Fails

I've been having the same problem with dhcpd. There are bug reports, and this one discusses upcoming fixes in the next version.
https://bugs.archlinux.org/task/64398?p … ing=dhcpcd

Last edited by TCBear (2019-11-06 13:30:55)

Offline

#3 2019-11-06 13:46:01

CarbonChauvinist
Member
Registered: 2012-06-16
Posts: 149

Re: dhcpcd Intermittently Fails

Does using dhclient instead provide better/more-consistent results?


"the wind-blown way, wanna win? don't play"

Offline

#4 2019-11-06 14:37:24

aclindsa
Member
Registered: 2011-01-29
Posts: 28
Website

Re: dhcpcd Intermittently Fails

TCBear wrote:

I've been having the same problem with dhcpd. There are bug reports, and this one discusses upcoming fixes in the next version.
https://bugs.archlinux.org/task/64398?p … ing=dhcpcd

Thanks for pointing me to those. It is interesting that dhcpcd goes into a loop for them, but in my case dhcpcd exits. Have you seen reports of others seeing dhcpcd exit as well? I'm a little skeptical that this is the same problem.

Offline

#5 2019-11-06 15:20:40

TCBear
Member
Registered: 2016-01-22
Posts: 33

Re: dhcpcd Intermittently Fails

I'm sorry. I should have also posted this link.
https://bugs.archlinux.org/task/64366?p … ing=dhcpcd

Offline

#6 2019-11-06 18:19:51

rsmarples
Member
Registered: 2009-05-12
Posts: 222

Re: dhcpcd Intermittently Fails

Hi! I'm upstream for dhcpcd and I'll try to help.

aclindsa wrote:

I have an issue where dhcpcd seems to intermittently fail to daemonize after receiving the initial dhcp lease, which results in my dhcp lease expiring about a day after I reboot. Here is the output from `journalctl` which I believe is causing the problem (notice the 'eloop_start: Invalid argument'):

Nov 05 09:53:44 hostname dhcpcd[3753]: dhcpcd exited
Nov 05 09:53:44 hostname dhcpcd[3753]: main: eloop_start: Invalid argument
Nov 05 09:53:44 hostname dhcpcd[2159]: forked to background, child pid 3753
Nov 05 09:53:44 hostname dhcpcd[2159]: eno1: adding default route via 192.168.1.1
Nov 05 09:53:44 hostname dhcpcd[2159]: eno1: adding route to 192.168.1.0/24
Nov 05 09:53:44 hostname dhcpcd[2159]: eno1: leased 192.168.1.114 for 86400 seconds

That looks like a totally new error to me. I would guess that the polling mechanism is broken.

The output from journalctl is all messed up - you have log from a process before it forked?
Usless.

Can you add this to /etc/dhcpcd.conf please and then restart it?

debug
/var/log/dhcpcd.log

Hopefully that will give more information.

Offline

#7 2019-11-06 18:42:25

aclindsa
Member
Registered: 2011-01-29
Posts: 28
Website

Re: dhcpcd Intermittently Fails

I've added the debug logging to my `/etc/dhcpcd.conf`. From a clean boot, I see this in /var/log/dhcpcd.log:

Nov 06 13:27:04 [2157]: dhcpcd-8.1.1 starting
Nov 06 13:27:04 [2157]: eno1: executing `/usr/lib/dhcpcd/dhcpcd-run-hooks' PREINIT
Nov 06 13:27:04 [2157]: eno1: executing `/usr/lib/dhcpcd/dhcpcd-run-hooks' CARRIER
Nov 06 13:27:04 [2157]: DUID 00:04:00:00:00:00:00:00:00:00:00:00:ac:1f:6b:ad:02:04
Nov 06 13:27:04 [2157]: eno1: IAID 6b:ad:02:04
Nov 06 13:27:04 [2157]: eno1: delaying IPv4 for 0.6 seconds
Nov 06 13:27:05 [2157]: eno1: reading lease `/var/lib/dhcpcd/eno1.lease'
Nov 06 13:27:05 [2157]: eno1: rebinding lease of 192.168.1.114
Nov 06 13:27:05 [2157]: eno1: sending REQUEST (xid 0x3c8bbad), next in 3.4 seconds
Nov 06 13:27:05 [2157]: eno1: acknowledged 192.168.1.114 from 192.168.1.1
Nov 06 13:27:05 [2157]: eno1: probing address 192.168.1.114/24
Nov 06 13:27:05 [2157]: eno1: probing for 192.168.1.114
Nov 06 13:27:05 [2157]: eno1: ARP probing 192.168.1.114 (1 of 3), next in 1.3 seconds
Nov 06 13:27:06 [2157]: eno1: ARP probing 192.168.1.114 (2 of 3), next in 1.3 seconds
Nov 06 13:27:06 [2157]: docker0: new hardware address: 6e:ab:e2:b5:fe:f6
Nov 06 13:27:07 [2157]: veth47f3722: new hardware address: 1a:6b:47:2c:a3:9a
Nov 06 13:27:07 [2157]: veth19fbac9: new hardware address: aa:ff:01:2b:87:3a
Nov 06 13:27:07 [2157]: eno1: ARP probing 192.168.1.114 (3 of 3), next in 2.0 seconds
Nov 06 13:27:09 [2157]: eno1: DAD completed for 192.168.1.114
Nov 06 13:27:09 [2157]: eno1: leased 192.168.1.114 for 86400 seconds
Nov 06 13:27:09 [2157]: eno1: renew in 43200 seconds, rebind in 75600 seconds
Nov 06 13:27:09 [2157]: eno1: writing lease `/var/lib/dhcpcd/eno1.lease'
Nov 06 13:27:09 [2157]: eno1: adding IP address 192.168.1.114/24 broadcast 192.168.1.255
Nov 06 13:27:09 [2157]: eno1: adding route to 192.168.1.0/24
Nov 06 13:27:09 [2157]: eno1: adding default route via 192.168.1.1
Nov 06 13:27:09 [2157]: eno1: ARP announcing 192.168.1.114 (1 of 2), next in 2.0 seconds
Nov 06 13:27:09 [2157]: eno1: executing `/usr/lib/dhcpcd/dhcpcd-run-hooks' BOUND
Nov 06 13:27:09 [2157]: forking to background
Nov 06 13:27:09 [2157]: forked to background, child pid 3781
Nov 06 13:27:09 [3781]: main: eloop_start: Invalid argument
Nov 06 13:27:09 [3781]: dhcpcd exited

Interestingly, if I run `sudo netctl restart ethernet-dhcp` to restart dhcpcd, it seems to work normally:

Nov 06 13:31:50 [7284]: dhcpcd-8.1.1 starting
Nov 06 13:31:50 [7284]: eno1: executing `/usr/lib/dhcpcd/dhcpcd-run-hooks' PREINIT
Nov 06 13:31:50 [7284]: eno1: executing `/usr/lib/dhcpcd/dhcpcd-run-hooks' CARRIER
Nov 06 13:31:50 [7284]: DUID 00:04:00:00:00:00:00:00:00:00:00:00:ac:1f:6b:ad:02:04
Nov 06 13:31:50 [7284]: eno1: IAID 6b:ad:02:04
Nov 06 13:31:50 [7284]: eno1: delaying IPv4 for 0.8 seconds
Nov 06 13:31:50 [7284]: eno1: reading lease `/var/lib/dhcpcd/eno1.lease'
Nov 06 13:31:50 [7284]: eno1: rebinding lease of 192.168.1.114
Nov 06 13:31:50 [7284]: eno1: sending REQUEST (xid 0x118a4f1e), next in 4.5 seconds
Nov 06 13:31:50 [7284]: eno1: acknowledged 192.168.1.114 from 192.168.1.1
Nov 06 13:31:50 [7284]: eno1: probing address 192.168.1.114/24
Nov 06 13:31:50 [7284]: eno1: probing for 192.168.1.114
Nov 06 13:31:50 [7284]: eno1: ARP probing 192.168.1.114 (1 of 3), next in 2.0 seconds
Nov 06 13:31:52 [7284]: eno1: ARP probing 192.168.1.114 (2 of 3), next in 1.9 seconds
Nov 06 13:31:54 [7284]: eno1: ARP probing 192.168.1.114 (3 of 3), next in 2.0 seconds
Nov 06 13:31:56 [7284]: eno1: DAD completed for 192.168.1.114
Nov 06 13:31:56 [7284]: eno1: leased 192.168.1.114 for 86400 seconds
Nov 06 13:31:56 [7284]: eno1: renew in 43200 seconds, rebind in 75600 seconds
Nov 06 13:31:56 [7284]: eno1: writing lease `/var/lib/dhcpcd/eno1.lease'
Nov 06 13:31:56 [7284]: eno1: adding IP address 192.168.1.114/24 broadcast 192.168.1.255
Nov 06 13:31:56 [7284]: eno1: adding route to 192.168.1.0/24
Nov 06 13:31:56 [7284]: eno1: adding default route via 192.168.1.1
Nov 06 13:31:56 [7284]: eno1: ARP announcing 192.168.1.114 (1 of 2), next in 2.0 seconds
Nov 06 13:31:56 [7284]: eno1: executing `/usr/lib/dhcpcd/dhcpcd-run-hooks' BOUND
Nov 06 13:31:56 [7284]: forking to background
Nov 06 13:31:56 [7284]: forked to background, child pid 7328
Nov 06 13:31:58 [7328]: eno1: ARP announcing 192.168.1.114 (2 of 2)

I've rebooted several times and run `sudo netctl restart ethernet-dhcp` several times. The former seems to always fail and the latter seems to always succeed. I'm a little worried that systemctl is somehow calling dhcpcd differently than I am when I use netctl itself - what's the best way to ensure it's being called consistently between the two invocations? Anything else you'd like me to gather and report back on?

Offline

#8 2019-11-06 18:55:07

aclindsa
Member
Registered: 2011-01-29
Posts: 28
Website

Re: dhcpcd Intermittently Fails

rsmarples wrote:

The output from journalctl is all messed up - you have log from a process before it forked?

FYI, I think I was using `journalctl -r`, so time is inverted (top line is the youngest) in my original log paste. I guess that's not obvious when the timestamp doesn't have enough resolution to tell which end is up...

Offline

Board footer

Powered by FluxBB