You are not logged in.

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

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

[SOLVED] 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.

Last edited by aclindsa (2019-12-04 18:40:58)

Offline

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

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

Re: [SOLVED] 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: 412
Website

Re: [SOLVED] 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: 30
Website

Re: [SOLVED] 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: 34

Re: [SOLVED] 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: 287

Re: [SOLVED] 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: 30
Website

Re: [SOLVED] 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: 30
Website

Re: [SOLVED] 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

#9 2019-12-04 15:38:22

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

Re: [SOLVED] dhcpcd Intermittently Fails

@rsmarples Any further ideas? I'm still seeing this with a fully-updated system as of today.

Offline

#10 2019-12-04 16:29:37

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

Re: [SOLVED] dhcpcd Intermittently Fails

Do you have two dhcpcd instances running? One via netctl and one via systemd dhcpcd service? Try removing your dhcp setup from netctl or disabling any dhcpcd service.

Offline

#11 2019-12-04 18:40:08

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

Re: [SOLVED] dhcpcd Intermittently Fails

Interesting - My netctl config file was at /etc/netctl/ethernet-dhcp, and I somehow had ended up with two systemctl services enabled: both "netctl@ethernet-dhcp.service" and "netctl@ethernet\\x2ddhcp.service". It appears that "netctl@ethernet\\x2ddhcp.service" is the proper way to do this (escaping the dash in the netctl config file's name). I am still unsure exactly how I ended up with two of these units, or why they started causing issues only recently. I know that I did not modify the netctl or sysctl networking configuration around the time that I began observing this issue. Removing "netctl@ethernet-dhcp.service" does appear to have solved my issue. Thanks for your help!

For my own curiosity - why would having these two enabled have manifested itself as the error message that it did?

Offline

#12 2019-12-04 23:53:11

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

Re: [SOLVED] dhcpcd Intermittently Fails

Well, any errors from eloop_start can only be raised if the selected polling method fails.
On a modern Linux, this would be epoll_wait(2).

The man page says this:

       EINVAL epfd is not an epoll file descriptor, or maxevents is less
              than or equal to zero.

dhcpcd's eloop has a check here: https://roy.marples.name/cgit/dhcpcd.gi … oop.c#n931
So we know maxevents must be greater than zero.
So that means that a file descriptor dhcpcd obtained has been invalidated.

I have no idea how that can happen. The fact that this is intermittent is worrying also.
Currently, my best guess is that the kernel ran out of some resource and invalidated the fd entirely or the man page missed some other reasons for error.

Offline

Board footer

Powered by FluxBB