[Solved] DHCPcd says it gets a lease and then uses an IPv4LL

[ManDay]

I start `dhcpcd`, which depends on in `iwd` with OpenRC, and there a ca. 50-50 chance that it either works flawlessly or uses a linklocal address for the next minutes until it spontaneously reconfigures. /var/log/messages says:

Code: Select all

Mar  9 16:24:16 air dhcpcd[21407]: dev: loaded udev
Mar  9 16:24:16 air kernel: ath10k_pci 0000:03:00.0: unsupported HTC service id: 1536
Mar  9 16:24:17 air dhcpcd[21407]: no interfaces have a carrier
Mar  9 16:24:17 air dhcpcd[21407]: forked to background, child pid 21425
Mar  9 16:24:17 air dhcpcd[21425]: enp2s0: waiting for carrier
Mar  9 16:24:17 air dhcpcd[21425]: wlp3s0: waiting for carrier
Mar  9 16:24:17 air kernel: wlp3s0: authenticate with c8:3a:35:13:73:b8
Mar  9 16:24:18 air kernel: wlp3s0: send auth to c8:3a:35:13:73:b8 (try 1/3)
Mar  9 16:24:18 air kernel: wlp3s0: authenticated
Mar  9 16:24:18 air kernel: wlp3s0: associate with c8:3a:35:13:73:b8 (try 1/3)
Mar  9 16:24:18 air kernel: wlp3s0: RX AssocResp from c8:3a:35:13:73:b8 (capab=0x411 status=0 aid=4)
Mar  9 16:24:18 air kernel: wlp3s0: associated
Mar  9 16:24:18 air dhcpcd[21425]: wlp3s0: carrier acquired
Mar  9 16:24:18 air kernel: IPv6: ADDRCONF(NETDEV_CHANGE): wlp3s0: link becomes ready
Mar  9 16:24:18 air dhcpcd[21425]: wlp3s0: connected to Access Point `Todorovi'
Mar  9 16:24:18 air dhcpcd[21425]: DUID 00:01:00:01:1e:db:b3:2b:30:65:ec:9f:09:ab
Mar  9 16:24:18 air dhcpcd[21425]: wlp3s0: IAID 28:29:4d:fb
Mar  9 16:24:18 air dhcpcd[21425]: wlp3s0: rebinding lease of 192.168.0.104
Mar  9 16:24:20 air ntpd[1640]: Listen normally on 13 wlp3s0 192.168.0.104:123
Mar  9 16:24:20 air ntpd[1640]: Listen normally on 14 wlp3s0 [fe80::caff:28ff:fe29:4dfb%5]:123
Mar  9 16:24:23 air dhcpcd[21425]: wlp3s0: probing for an IPv4LL address
Mar  9 16:24:23 air dhcpcd[21425]: wlp3s0: DHCP lease expired
Mar  9 16:24:23 air dhcpcd[21425]: wlp3s0: soliciting a DHCP lease
Mar  9 16:24:24 air dhcpcd[21425]: wlp3s0: offered 192.168.0.104 from 192.168.0.1
Mar  9 16:24:24 air ntpd[1640]: Deleting interface #13 wlp3s0, 192.168.0.104#123, interface stats: received=0, sent=0, dropped=0, active_time=4 secs
Mar  9 16:24:28 air dhcpcd[21425]: wlp3s0: using IPv4LL address 169.254.222.17
Mar  9 16:24:28 air dhcpcd[21425]: wlp3s0: adding route to 169.254.0.0/16
Mar  9 16:24:28 air dhcpcd[21425]: wlp3s0: adding default route
Mar  9 16:24:29 air ntpd[1640]: Listen normally on 15 wlp3s0 169.254.222.17:123
Mar  9 16:28:36 air dhcpcd[21425]: wlp3s0: probing address 192.168.0.104/24
Mar  9 16:28:41 air dhcpcd[21425]: wlp3s0: leased 192.168.0.104 for 86400 seconds
Mar  9 16:28:41 air dhcpcd[21425]: wlp3s0: adding route to 192.168.0.0/24
Mar  9 16:28:41 air dhcpcd[21425]: wlp3s0: changing default route via 192.168.0.1
Mar  9 16:28:41 air dhcpcd[21425]: wlp3s0: deleting route to 169.254.0.0/16
Mar  9 16:28:41 air dhcpcd[21425]: wlp3s0: pid 21425 deleted default route via 192.168.0.1
Mar  9 16:28:42 air ntpd[1640]: Listen normally on 16 wlp3s0 192.168.0.104:123
Mar  9 16:28:42 air ntpd[1640]: Deleting interface #15 wlp3s0, 169.254.222.17#123, interface stats: received=0, sent=0, dropped=0, active_time=253 secs

Does anyone know why this is happening or how to fix it?

[turtles]

Turn off IP4LL I think yo just lines at the end of /etc/dhcpcd.conf

Code: Select all

noipv4ll

or noarp
see man /etc/dhcpcd.conf for more info

[UberLord]

I start `dhcpcd`, which depends on in `iwd` with OpenRC, and there a ca. 50-50 chance that it either works flawlessly or uses a linklocal address for the next minutes until it spontaneously reconfigures. /var/log/messages says:

Code: Select all

Mar  9 16:28:41 air dhcpcd[21425]: wlp3s0: adding route to 192.168.0.0/24
Mar  9 16:28:41 air dhcpcd[21425]: wlp3s0: changing default route via 192.168.0.1
Mar  9 16:28:41 air dhcpcd[21425]: wlp3s0: deleting route to 169.254.0.0/16
Mar  9 16:28:41 air dhcpcd[21425]: wlp3s0: pid 21425 deleted default route via 192.168.0.1

Does anyone know why this is happening or how to fix it?

Looks like a bug in dhcpcd.
What version is that please? If dhcpcd-8, can you test dhcpcd-9 please?

[ManDay]

turtles: Thanks, I'll try that.
UberLord: I've updated to 9.4.0::gentoo and it still happens. (I've also removed ntpd but that didn't seem to matter):

Code: Select all

Mar 10 13:31:33 air dhcpcd[5247]: main: control_open: Connection refused
Mar 10 13:31:33 air dhcpcd[5247]: dhcpcd-9.4.0 starting
Mar 10 13:31:33 air dhcpcd[5249]: dev: loaded udev
Mar 10 13:31:33 air dhcpcd[5249]: DUID 00:01:00:01:1e:db:b3:2b:30:65:ec:9f:09:ab
Mar 10 13:31:33 air kernel: ath10k_pci 0000:03:00.0: unsupported HTC service id: 1536
Mar 10 13:31:33 air dhcpcd[5249]: no interfaces have a carrier
Mar 10 13:31:33 air dhcpcd[5249]: enp2s0: waiting for carrier
Mar 10 13:31:33 air dhcpcd[5249]: wlp3s0: waiting for carrier
Mar 10 13:31:34 air kernel: wlp3s0: authenticate with c8:3a:35:13:73:b8
Mar 10 13:31:34 air kernel: wlp3s0: send auth to c8:3a:35:13:73:b8 (try 1/3)
Mar 10 13:31:34 air kernel: wlp3s0: send auth to c8:3a:35:13:73:b8 (try 2/3)
Mar 10 13:31:34 air kernel: wlp3s0: authenticated
Mar 10 13:31:34 air kernel: wlp3s0: associate with c8:3a:35:13:73:b8 (try 1/3)
Mar 10 13:31:34 air kernel: wlp3s0: RX AssocResp from c8:3a:35:13:73:b8 (capab=0x411 status=0 aid=5)
Mar 10 13:31:34 air kernel: wlp3s0: associated
Mar 10 13:31:34 air dhcpcd[5249]: wlp3s0: carrier acquired
Mar 10 13:31:34 air dhcpcd[5249]: wlp3s0: connected to Access Point: Todorovi
Mar 10 13:31:34 air kernel: IPv6: ADDRCONF(NETDEV_CHANGE): wlp3s0: link becomes ready
Mar 10 13:31:34 air dhcpcd[5249]: wlp3s0: IAID 28:29:4d:fb
Mar 10 13:31:36 air dhcpcd[5249]: wlp3s0: rebinding lease of 192.168.0.104
Mar 10 13:31:41 air dhcpcd[5249]: wlp3s0: probing for an IPv4LL address
Mar 10 13:31:41 air dhcpcd[5249]: wlp3s0: DHCP lease expired
Mar 10 13:31:41 air dhcpcd[5249]: wlp3s0: soliciting a DHCP lease
Mar 10 13:31:42 air dhcpcd[5249]: wlp3s0: offered 192.168.0.104 from 192.168.0.1
Mar 10 13:31:46 air dhcpcd[5249]: wlp3s0: probing for an IPv4LL address
Mar 10 13:31:51 air dhcpcd[5249]: wlp3s0: using IPv4LL address 169.254.222.17
Mar 10 13:31:51 air dhcpcd[5249]: wlp3s0: adding route to 169.254.0.0/16
Mar 10 13:31:51 air dhcpcd[5249]: wlp3s0: adding default route
Mar 10 13:31:53 air dhcpcd[5249]: wlp3s0: probing address 192.168.0.104/24
Mar 10 13:31:59 air dhcpcd[5249]: wlp3s0: leased 192.168.0.104 for 86400 seconds
Mar 10 13:31:59 air dhcpcd[5249]: wlp3s0: adding route to 192.168.0.0/24
Mar 10 13:31:59 air dhcpcd[5249]: wlp3s0: changing default route via 192.168.0.1
Mar 10 13:31:59 air dhcpcd[5249]: wlp3s0: deleting route to 169.254.0.0/16

[UberLord]

That log looks ok to me - the key part is that the older version was deleting it's own default route here

Code: Select all

dhcpcd[21425]: wlp3s0: pid 21425 deleted default route via 192.168.0.1

What you are seeing is that for some reason your DHCP server is not responding to the initial REBIND request.
When this happens dhcpcd starts IPv4LL and resquests a new lease.
What we now see is that it takes 11 seconds for the DHCP server to respond to the REQUEST we got from the DISCOVER.
IPv4LL takes less than 11 seconds, so this wins.

In a nutshell your DHCP server is very very slow or something is dropping packets or DHCP packets.
I had a bad experience of Ubiquiti wireless AP firmware dropping DHCP packets a few months ago and had to use beta firmware to work around it.

The key takeaway is that dhcpcd is doing the best it can and the real issue is in your infrastructure.

[ManDay]

Oh I see. I misinterpreted the log pessimistically, although it only took a couple of seconds for setup to complete successfully. Thanks very much!

[UberLord]

As turtles said, if you cannot use IPv4LL then disable it in dhcpcd.conf and dhcpcd will then only fork once it gets a DHCP lease.

[ManDay]

I still occasionally have this problem. Less often now, I think, but the logs still look like it get a lease which doesn't supersede IPv4LL (this time, I think, I'm not misinterpreting it). The version of dhcpcd is 9.3.4:

Code: Select all

Mar 25 13:04:31 air dhcpcd[5497]: main: control_open: Connection refused
Mar 25 13:04:31 air dhcpcd[5497]: dhcpcd-9.3.4 starting
Mar 25 13:04:31 air dhcpcd[5499]: dev: loaded udev
Mar 25 13:04:31 air dhcpcd[5499]: DUID 00:01:00:01:1e:db:b3:2b:30:65:ec:9f:09:bb
Mar 25 13:04:31 air kernel: ath10k_pci 0000:03:00.0: unsupported HTC service id: 1536
Mar 25 13:04:31 air dhcpcd[5499]: no interfaces have a carrier
Mar 25 13:04:31 air dhcpcd[5499]: enp2s0: waiting for carrier
Mar 25 13:04:31 air dhcpcd[5499]: wlp3s0: waiting for carrier
Mar 25 13:04:32 air kernel: wlp3s0: authenticate with c8:3a:35:13:73:b8
Mar 25 13:04:32 air kernel: wlp3s0: send auth to c8:3a:35:13:73:b8 (try 1/3)
Mar 25 13:04:32 air kernel: wlp3s0: authenticated
Mar 25 13:04:32 air kernel: wlp3s0: associate with c8:3a:35:13:73:b8 (try 1/3)
Mar 25 13:04:32 air kernel: wlp3s0: RX AssocResp from c8:3a:35:13:73:b8 (capab=0x411 status=0 aid=4)
Mar 25 13:04:32 air kernel: wlp3s0: associated
Mar 25 13:04:32 air dhcpcd[5499]: wlp3s0: carrier acquired
Mar 25 13:04:32 air dhcpcd[5499]: wlp3s0: connected to Access Point: Todorovi
Mar 25 13:04:32 air kernel: IPv6: ADDRCONF(NETDEV_CHANGE): wlp3s0: link becomes ready
Mar 25 13:04:32 air dhcpcd[5499]: wlp3s0: IAID 28:29:4d:fb
Mar 25 13:04:34 air dhcpcd[5499]: wlp3s0: rebinding lease of 192.168.0.104
Mar 25 13:04:39 air dhcpcd[5499]: wlp3s0: probing for an IPv4LL address
Mar 25 13:04:39 air dhcpcd[5499]: wlp3s0: DHCP lease expired
Mar 25 13:04:39 air dhcpcd[5499]: wlp3s0: soliciting a DHCP lease
Mar 25 13:04:44 air dhcpcd[5499]: wlp3s0: probing for an IPv4LL address
Mar 25 13:04:44 air dhcpcd[5499]: wlp3s0: offered 192.168.0.104 from 192.168.0.1
Mar 25 13:04:48 air dhcpcd[5499]: wlp3s0: using IPv4LL address 169.254.222.17
Mar 25 13:04:48 air dhcpcd[5499]: wlp3s0: adding route to 169.254.0.0/16
Mar 25 13:04:48 air dhcpcd[5499]: wlp3s0: adding default route

[turtles]

post your dhcpcd.conf

[ManDay]

Code: Select all

hostname
ipv4only
nohook resolv.conf
duid
timeout 90
persistent
option rapid_commit
option domain_name_servers, domain_name, domain_search, host_name
option classless_static_routes
option ntp_servers
option interface_mtu
define 81 embed fqdn
embed byte flags
embed byte flags
embed byte rcode1
embed byte rcode2
embed domain fqdn

[turtles]

Add
noipv4ll
to the end of the file

[ManDay]

Sorry, I should have been clearer: I understand that would "solve" my problem, but it should also work with IPv4LL enabled, no?

[UberLord]

Because the DHCP lease expires, getting a new one is a 4 step process

client sends discover -> server replies with an address - > client requests address - > server acknowledges the address
Unless you have `noarp` in your config, dhcpcd will then spent several seconds ensuring the address is not in use by someone else.

Because your DHCP server is slow, dhcpcd is also handling IPv4LL at the same time.
It's not superceeding DHCP at all, but working alongside.

Once dhcpcd binds the address, it will remove the IPv4LL address. But it needs to go through all the above steps which could take upto 11 seconds or so on a bad day with high randomisation values.

For reference here are the two lines where the DHCP process above starts and stops.

Code: Select all

wlp3s0: soliciting a DHCP lease
wlp3s0: leased 192.168.0.104 for 86400 seconds

According to your most recent log, you got the IPv4LL address at step 2/4 above.

There really is nothing wrong with dhcpcd here.
What is wrong is the length of time between dhcpcd sending a request and your DHCP server replying.
You should investigate that really. tcpdump is your friend here, especially if you can run that on the DHCP server as well.

[Tony0945]

Ah! I see from Uberlord's response that the DHCP server seems to be at fault. Are you using your router for DHCP? I'm using DNSmasq on a separate computer but you can use it on your computer or indeed establish a fixed ip address.
What is your router model? I went to DNSmasq because my ISP's DNS, in a word, sucked. I went the further step to using DNSMasq for DHCP because it gave me more flexibility over the router.

[ManDay]

Thanks. Just to be clear: The IPv4LL address did not stay around for mere seconds (in the above case with log), but I did not get a LAN address for several minutes, after which point I got tired of waiting and restarted.

So, from what you say I understand the server sent the offer (step 2), my requesting the address (step 3) happend but does not actually show up in the log, and the server for some reason never got around to acknowledge the address (step 4), so dhcpcd stuck with the LL address. Is that about right?

I will try (knowing that nothing's wrong on my end), but I suspect in that case desactivating IPv4LL will not help, if the server does not comply with step 4.

(no idea what the router is and I don't have access to it either; it's some ISP provided box and it's not my network, either)

[UberLord]

Thanks. Just to be clear: The IPv4LL address did not stay around for mere seconds (in the above case with log), but I did not get a LAN address for several minutes, after which point I got tired of waiting and restarted.

So, from what you say I understand the server sent the offer (step 2), my requesting the address (step 3) happend but does not actually show up in the log, and the server for some reason never got around to acknowledge the address (step 4), so dhcpcd stuck with the LL address. Is that about right?

I will try (knowing that nothing's wrong on my end), but I suspect in that case desactivating IPv4LL will not help, if the server does not comply with step 4.

Correct.
It will just take a long time to get an address via DHCP.

(no idea what the router is and I don't have access to it either; it's some ISP provided box and it's not my network, either)

Well, I would speak with the network owner about the issue

If it's a crappy router you could try swapping duid for clientid in dhcpcd.conf or removing both altogether.
If that works then then answer is simple - it's a crappy router that doesn't respect RFC's.

[turtles]

Agreed
having dealt with many crappy internet connections,
I keep IP4LL disabled unless I am trying to use it, that forces me to dig into the other issues.

It never forwards anything to the internet and gives you system a false sense of connection.
https://tools.ietf.org/html/rfc3927#section-2.7

Run some tcpdump commands and we'll see whats going on.
Probably on the edge of WIFI range?
Or if its wired could be a bad cable or NIC.

[ManDay]

I will try what you said. Since the update to >=dhcpcd-9 the problem occurs rarely, though, so it's kind of difficult to analyze (with tcpdump or changing settings).