Wifi randomly pulls a second 169 IP, causing all internet connections to fail post-boot

[Drakonas]

Over the last week a few of us have been hammering at what is causing these weird wifi-related failures on boot at random. When they occur, the MiSTer gets an IP, even gets the time when you don't have an RTC board, and SAMBA/SSH connections work, but anything attempting to get an internet connection after that fails. Even nslookup google.com 8.8.8.8 fails with a timeout to the DNS.

What we have found are the following:

• The issue seems to stem from the commits around April 2022. This commit may be the underlying culprit, but it is unsure how.
• The issue will occur if the wlan0 interface exists when dhcpcd and ifup start up. Normally the interface does not exist until further in the boot process, but for mine it is there early (within a few seconds), so dhcpcd pulls an initial IP when its process is started.
• On my MiSTer, a second udev fires, causing a second lease to be called, and it obtains a 169 IP address, while the previous lease still has a correct local IP that is reachable. This does not fire automatically for most other people, but forcefully firing it does reproduce the issue: udevadm trigger /sys/class/net/wlan0 --action add
• Wifi seems to initiate for me very early, before the filesystem is mounted as r/w. This is not the case for most others. I am using a TP-Link Archer T3U Plus adapter (Amazon link). It is uncertain that this plays a factor in the issue at all. The random loss of internet occurs with the adapter from Porkchop as well, but it is uncertain that it is the same exact issue.
• Resetting the router does often fix the issue, but only shortly. Otherwise, you'll find the issue fixed after cold rebooting the MiSTer 6-10 times, and then it returns a number of days later again, requiring another count of excessive reboots to fix.
• dhcpcd fails to write the lease file to /var/lib/dhcpcd/interface-ssid.lease because the dhcpcd directory does not exist and it states the filesystem is read-only, which is the truth because it fires before the remount to r/w occurs. Considering I do not have an RTC addon (and the system time defaults to 1/1/1979), this means that the lease is about 40 years old once the time is pulled from NTP servers, which is most likely expired. It is uncertain if this causes it to pull a second lease.
• dhcpcd will also fail to write the duid to /var/lib/dhcpcd/duid, since it is a read-only filesystem at the time it runs.
• dhcpcd is outdated on the MiSTer. It is uncertain if updating it can be the fix. Possibly BusyBox needs work.
• The issue occurs with multiple of my own routers/modems, so the issue shouldn't be related to the router. The udev command is reproducible even on reputable routers.
• The DUID problem appears to cause some routers(mine) to give a new/different lease on every boot. Additionally it appears the r/o filesystem lease problem causes the system to trigger the IPV4LL behavior because if I move the lease directory to /media/fat/something with a symlink I can use the udevadm command multiple times and it just uses the existing lease.
• This second lease seems to load under udhcpd and not dhcpcd. It is probably best to only use one and not both. This may be causing issues.
• Depending on timing, the DUID can be static, but with my MiSTer it pulls it too early, and fails to keep it.
• The wifi initiating early is most likely caused by the wlan0 interface loading within the first few seconds of booting. On working MiSTers, it seems to not load the wlan0 interface for a while longer, which allows the system to work normally.
• Running rm /sbin/udhcpc causes ifup to use dhcpcd, and then the rc script starts another copy. It seems the priority for the startup script is to load udhcpc before dhcpcd. It would probably be best to only use dhcpcd. If udhcpd is wanted instead, eth0 does not load since it is not in the interfaces config file, so it would need to be added there.

Possible methods to fix (doing multiple is not a bad idea):

• Seemingly the beest way to fix could be to use wpa_supplicant hook scripts (/usr/share/dhcpcd/hooks/10-wpa_supplicant), but it is broken with the MiSTer's wpa_supplicant implementation. wpa_supplicant would need to be fixed. This would allow using dhcpcd.conf to address anything related to network issues. And have ifupdown just do loopback.
• Find what's causing the interface to exist on boot. This alone should fix the issue, but it is a bit of a dirty fix.
• Fixing write-permissions on boot, so dhcpcd can write the lease/duid files properly. Another dirty fix, but should address the issue.
• Fix it so only dhcpcd or udhcpd run, and not have a possibility of both. I recommend doing this regardless of other methods.

Any thoughts as to what may be directly causing this is welcome. I'd like to get to the bottom of this, as various users besides me have reported this happening at random with their MiSTer. We are using the latest Mr. Fusion images as far as I know.

I have attached my syslog for review.

/var/log/messages

[sorgelig]

To fix the problem, need to have this problem. Generally speaking 99% of time i use wired connection and it's hard for me to work on this issue. I'm not very much in Linux specifics, so don't treat me as a master here :)
If you can offer a working solution, then go on.

[sorgelig]

there is kind of race condition in boot sequence. I was trying to fix it when i was working on Bluetooth. But it seems impossible to fix it especially when more USB devices are connected. You may try to play with etc/init.d/* scripts sequence - may be it will help.

[Drakonas]

there is kind of race condition in boot sequence. I was trying to fix it when i was working on Bluetooth. But it seems impossible to fix it especially when more USB devices are connected. You may try to play with etc/init.d/* scripts sequence - may be it will help.

It's hard to really see what's going on without access to the buildroot scripts. These don't seem to be public. Do you know where these are located for the project?

[birdybro]

It occurs for me too with this adapter --> https://www.amazon.com/gp/product/B08D72GSMS/ combined with this router+ap --> https://www.amazon.com/dp/B08DTF7KGC/ref=twister_B09P4Q7JK4

I just have to run ip addr flush dev wlan0 and it comes back with one address. It also doesn't come back between boots and it is definitely related to the dhcp lease time, because it will only come back after my dhcp lease has expired I've noticed (or joined a different network). It also occurred at my parents house with a totally different router+ap.

[zakk4223]

There's multiple things going on:

1. the root filesystem is read-only so dhcpcd can't write a lease or duid file to /var/db/dhcpcd

1a) for some users the wlan0 device is available when dhcpcd first starts. It negotiates a lease but can't write any state to disk. Then for some reason it also receives a udev 'add' event for wlan0. Due to the fact there's no lease state written it tries to refresh/rediscover a dhcp lease. For some users this fails (I suspect the router is applying "protection"). When it fails dhcpcd falls back to a self assigned IP and deletes the route/dns for the 'good' lease. Or at least inserts a higher priority route to nowhere.

I unfortunately cannot debug this one because my wlan0 interface is not available when dhcpcd launches, so it only tries to get a lease once due to udev add event. I've seen Drakonas' logs and their wlan0 device is detected a full 2 seconds before mine so I suspect this is just due to variations in USB setups (hub, other devices etc).

Either /var/db/dhcpcd needs to be writeable or dhcpcd needs to use a different database directory. You can symlink /var/db/dhcpcd to /media/fat/dhcpcd and it will work. Or you could recompile dhcpcd and set DBDIR to /media/fat/dhcpcd (configure --dbdir=/media/fat/dhcpcd)

2. udhcpc is still being run for wlan0 which means there are two dhcp clients running on those interfaces with possibly unpredictable results.

If you change /etc/network/interfaces so the line like 'iface wlan0 inet dhcp' is instead 'iface wlan0 inet manual' the ifup script won't try to invoke a dhcp client, but will still invoke the pre-up scripts for wpa_supplicant. Then dhcpcd will handle the dhcp lease when it runs.

[sorgelig]

Nothing to do with buildroot. Boot scripts are in image and can be read/tweaked.
For debug purpose root fs can be mounted in read/write at boot (by uncommenting the line in inittab). If it will fix the problem then need to check which directory needs to be mounted as rw (as tmpfs).

[prenetic]

I have what seems to be the same or at least a very similar problem, outlined in greater detail in this thread on the Mister FPGA forums:

https://misterfpga.org/viewtopic.php?p=58198#p58198
https://misterfpga.org/viewtopic.php?p=58210#p58210
https://misterfpga.org/viewtopic.php?p=58274#p58274

Essentially two leases are allocated to the MiSTer on Wi-Fi (haven't tested whether this happens wired as well). Same MAC address, but one is registered without a hostname and a vendor ID of "udhcp", the other with the "MiSTer" hostname but no vendor ID (from dhcpc). When the device comes up, there is a brief moment of connectivity, followed by 10-20 seconds of disruption, and then connectivity again. You can't see both addresses with ifconfig, but you CAN see both with ip address. The flags differ too, with the udhcpc address showing perpetual validity (doesn't seem to respect the DHCP lease time).

Looking at the DHCP datagrams it's more clear -- the udhcpc requests come in with the MAC address (DUID) as the client identifier, but the dhcpc request comes in with the MAC address (DUID) PLUS an IAID as the client identifier. In the eyes of the DHCP server, these each require a unique IP address despite having the same base MAC address.

For testing/as a workaround, I changed the following option from duid to clientid which causes dhcpc to only send the MAC address as part of the DHCP request, so now the client identifiers between udhcpc and dhcpc match and only one lease is provided as confirmed by logs on my DHCP server (dnsmasq on my router).

# Use the hardware address of the interface for the Client ID.
clientid
# or
# Use the same DUID + IAID as set in DHCPv6 for DHCPv4 ClientID as per RFC4361.
# Some non-RFC compliant DHCP servers do not reply with this set.
# In this case, comment out duid and enable clientid above.
#duid

So given the behavior I think we're running into the same thing here. I'm under the impression that when the choice was made to transition to dhcpc from udhcpc, the latter wasn't fully disabled in the base image and the two DHCP clients are conflicting and causing issues -- so +1 to sticking to one or the other regardless of any other fixes.

Separately, if people are still running into new IP addresses every startup/polluting DHCP pools even after disabling one of the two DHCP clients, then the config change above should take care of that problem since the MAC address shouldn't be changing every boot. There's really no reason to include IAID as part of the client identifier for the case of MiSTer as far as I can tell (though it shouldn't be cycling with every boot anyway), and it is typically omitted for compatibility purposes for IPv4 anyway.

[Drakonas]

# Use the hardware address of the interface for the Client ID.
clientid
# or
# Use the same DUID + IAID as set in DHCPv6 for DHCPv4 ClientID as per RFC4361.
# Some non-RFC compliant DHCP servers do not reply with this set.
# In this case, comment out duid and enable clientid above.
#duid

To clarify, what file is this change supposed to occur? I assume /etc/dhcpcd.conf

[prenetic]

# Use the hardware address of the interface for the Client ID.
clientid
# or
# Use the same DUID + IAID as set in DHCPv6 for DHCPv4 ClientID as per RFC4361.
# Some non-RFC compliant DHCP servers do not reply with this set.
# In this case, comment out duid and enable clientid above.
#duid

To clarify, what file is this change supposed to occur? I assume /etc/dhcpcd.conf

Yep, that's the one. Sorry I forgot to include that here.

[Akuma-Git]

That's because ifup/ifdown are hardcoded to use udhcpc. Try renaming /usr/sbin/udhcpc to /usr/sbin/_udhcpc.

[Drakonas]

That's because ifup/ifdown are hardcoded to use udhcpc. Try renaming /usr/sbin/udhcpc to /usr/sbin/_udhcpc.

Why is this then? It seems, based on this, that two separate DHCP clients can (or maybe always?) load on startup, given the right scenario. Does Busybox handle both for the MiSTer setup? Pretty sure that fixing this should really warrant a change having everything hardcoded for one DHCP client, instead of requiring dirty workarounds

Also, please see Zakk's statements a couple months ago in this issue. There is more to the issue than two DHCP daemons. @Akuma-Git

[Akuma-Git]

Why is this then?

Because udhcpc, ifup, ifdown are busybox components.

It seems, based on this, that two separate DHCP clients can (or maybe always?) load on startup, given the right scenario.

Correct

Does Busybox handle both for the MiSTer setup? Pretty sure that fixing this should really warrant a change having everything hardcoded for one DHCP client, instead of requiring dirty workarounds

Idk, afaict the dhcpcd package is unnecessary

Also, please see Zakk's statements a couple months ago in this issue. There is more to the issue than two DHCP daemons.

Correct, this is due to configuration errors resulting in some fighting between:

• udev
• busybox (ifup/ifdown/udhcpc)
• network
• dhcpcd

[prenetic]

Idk, afaict the dhcpcd package is unnecessary

I'm curious what sparked this change as it seems like it was an intentional choice to switch to dhcpc. Possibly @sorgelig can provide more context, if there was originally an issue with udhcpc that can be addressed here.

[sorgelig]

because udhcpc didn't work well.
I will re-check it. Make sure your solution works with Ethernet connection too.

[prenetic]

Via wired Ethernet without the dhcpcd.conf client identifier change (duid) -- datagrams include IAID of 04050607:

dnsmasq DHCP logs

user@router1:~$ tail -f -n 0 /var/log/dnsmasq.log | grep -i 02:03:04:05:06:07
Aug 17 16:27:14 dnsmasq-dhcp[32608]: DHCPDISCOVER(bond0.10) 02:03:04:05:06:07
Aug 17 16:27:14 dnsmasq-dhcp[32608]: DHCPOFFER(bond0.10) 192.168.10.212 02:03:04:05:06:07
Aug 17 16:27:14 dnsmasq-dhcp[32608]: DHCPREQUEST(bond0.10) 192.168.10.212 02:03:04:05:06:07
Aug 17 16:27:14 dnsmasq-dhcp[32608]: DHCPACK(bond0.10) 192.168.10.212 02:03:04:05:06:07 MiSTer

dnsmasq DHCP lease

02:03:04:05:06:07 192.168.10.212 MiSTer ff:04:05:06:07:00:03:00:01:02:03:04:05:06:07

Datagram contents

Option: (61) Client identifier
    Length: 15
    IAID: 04050607
    DUID Type: link-layer address (3)
    Hardware type: Ethernet (1)
    Link layer address: 02:03:04:05:06:07

Active IP addresses

2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc mq state UP group default qlen 1000
    link/ether 02:03:04:05:06:07 brd ff:ff:ff:ff:ff:ff
    inet 192.168.10.212/24 brd 192.168.10.255 scope global dynamic noprefixroute eth0
       valid_lft 82688sec preferred_lft 71888sec

Via wired Ethernet with the dhcpcd.conf client identifier change (clientid) -- datagrams do not include IAID:

dnsmasq DHCP logs

user@router:~$ tail -f -n 0 /var/log/dnsmasq.log | grep -i 02:03:04:05:06:07
Aug 17 16:11:22 dnsmasq-dhcp[30909]: DHCPDISCOVER(bond0.10) 02:03:04:05:06:07
Aug 17 16:11:22 dnsmasq-dhcp[30909]: DHCPOFFER(bond0.10) 192.168.10.211 02:03:04:05:06:07
Aug 17 16:11:22 dnsmasq-dhcp[30909]: DHCPREQUEST(bond0.10) 192.168.10.211 02:03:04:05:06:07
Aug 17 16:11:22 dnsmasq-dhcp[30909]: DHCPACK(bond0.10) 192.168.10.211 02:03:04:05:06:07 MiSTer

dnsmasq DHCP lease

02:03:04:05:06:07 192.168.10.211 MiSTer 01:02:03:04:05:06:07

Datagram contents

Option: (61) Client identifier
    Length: 7
    Hardware type: Ethernet (0x01)
    Client MAC address: MS-NLB-PhysServer-03_04:05:06:07 (02:03:04:05:06:07)

Active IP addresses

2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc mq state UP group default qlen 1000
    link/ether 02:03:04:05:06:07 brd ff:ff:ff:ff:ff:ff
    inet 192.168.10.211/24 brd 192.168.10.255 scope global dynamic noprefixroute eth0
       valid_lft 86327sec preferred_lft 75527sec

Regardless of which configuration I'm only seeing one set of requests show up from dhcpc -- nothing comes in from udhcpc over wired Ethernet from what I can tell. This seems to indicate the udhcp/duplicate lease issue is limited to Wi-Fi (and possibly USB wired Ethernet adapters as well), and that this change doesn't appear to have any negative impact for wired Ethernet other than temporarily creating a second lease when changing the IAID behavior which you can see above. The second lease in this case should expire gracefully as the two aren't tied up at the same time like they are via Wi-Fi.

@Drakonas while this certainly isn't a long-term fix, does the change to dhcpc.conf I mentioned above take care of the second/169.x.x.x address issue you were seeing via Wi-Fi? Wondering if your DHCP server just isn't handling the IPv4 IAID that's going out through dhcpc and fails, that's known behavior for some vendors.