I've got a little problem with dhcpcd and I don't know if you can help me

[Thimbles809]

My struggles are detailed here.
morrownr/USB-WiFi#200 (comment)
I've got a raspberry pi dhcp server doing dynamic dns using isc-dhcpd-4.4.1 and BIND 9.16.37-Debian (Extended Support Version). I've got two raspberry pi clients running dhcpcd 8.1.2 as AP's for wireless clients. The dhcpcd client is bound to the bridge interface for the wifi with a uniquely generated MAC from any of the installed network interfaces. These are the changes I've made to my /etc/dhcpcd.conf
# fallback to static profile on eth0
denyinterfaces eth0 wlx*
interface br0
ipv4
dhcp
ipv4only
noipv4ll
noipv6
But the behavior was there before I made any changes.
These are the changes I've made to my /etc/systemd/system/dhcpcd.service file in order to correct the behavior:
ExecStart=/usr/sbin/dhcpcd --master --waitip=4 --timeout 10 -d
Restart=no
but with no long term success.
What seems to be happening is that during start up, or when there are many clients attempting to renew leases, the client doesn't appear to wait for the dhcp server to answer its requests and generates mass requests which then generates a failure... and then a successful renew.
The result has been syslog's on both my AP's and my router getting filled with dhcp traffic take neither client or server are handling efficiently once the pattern starts.
When I stop and start the dhcpcd daemon, it seems to resolve the behavior on both sides so I'm a bit stuck on how to resolve this without a kludge.
Can you help me understand what may be causing this behavior and how I can fix it?

[rsmarples]

Can you post a log example of this please?
You might want to add this to the top of dhcpcd.conf

debug
logfile /var/log/dhcpcd.log

Restart dhcpcd and you then get a nice logged debug you can post here.

Also, dhcpcd-8.1.2 is quite old an unsupported by me anyway. Can you test with dhcpcd-9.5.0?

[Thimbles809]

So I did a sudo apt-get update full-upgrade and the latest bullseye official release is the one above.
So I did a git clone of the latest code and one configure make make install later and I'm on
dhcpcd 9.99.0
Copyright (c) 2006-2023 Roy Marples
Compiled in features: INET ARP ARPing IPv4LL INET6 DHCPv6 AUTH PRIVSEP
one sudo reboot later and suddenly my wifi AP is down. :( hostapd won't start.
The reason being is that my interface names became unpredictable.
In the tutorial here:
https://github.com/morrownr/USB-WiFi/blob/main/home/AP_Mode/Bridged_Wireless_Access_Point.md
one of the steps is to
"To enable predictable network interface names on the Raspberry Pi OS:

sudo raspi-config
Select: Advanced options > A4 Network Interface Names > Yes"
That enables the wlan0 wlan1 names to become wlxa907b7be695e based on the interfaces mac address.
Apr 12 17:49:09 yeahwifibabyyeah dhcpcd[436]: wlan1: interface added
Apr 12 17:49:09 yeahwifibabyyeah dhcpcd[436]: wlan1: executing: /libexec/dhcpcd-run-hooks PREINIT
Apr 12 17:49:09 yeahwifibabyyeah dhcpcd[436]: wlan1: executing: /libexec/dhcpcd-run-hooks NOCARRIER
Apr 12 17:49:09 yeahwifibabyyeah systemd-udevd[187]: Using default interface naming scheme 'v247'.
Apr 12 17:49:09 yeahwifibabyyeah systemd-udevd[186]: Using default interface naming scheme 'v247'.
Apr 12 17:49:09 yeahwifibabyyeah systemd-udevd[187]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Apr 12 17:49:09 yeahwifibabyyeah systemd-udevd[187]: wlan0: Failed to rename network interface 4 from 'wlan0' to 'wlxa907b7be695e': Device or resource busy
Apr 12 17:49:09 yeahwifibabyyeah systemd-udevd[187]: wlan0: Failed to process device, ignoring: Device or resource busy
Which meant hostapd couldn't find the interfaces it was supposed to be associated with.
Fixed it by changing my /etc/dhcpcd.conf file to
denyinterfaces eth* enx* wl* wlx*

and I just thought I'd post it just in case someone else ran into this problem.
I've got everything logging now, so hopefully I'll catch an error. :D

[Thimbles809]

Decided to consolidate my answers:

Caught one! At 17:54:57 I rebooted my AP.

Apr 12 17:54:57 [412]: no such user dhcpcd
Apr 12 17:54:57 [412]: dhcpcd-9.99.0 starting
Apr 12 17:54:57 [428]: spawned manager process on PID 428
Apr 12 17:54:57 [428]: DUID 00:01:00:01:2b:ca:0c:1e:20:0d:b0:c6:cb:08
Apr 12 17:54:57 [428]: lo: ignoring due to interface type and no config
Apr 12 17:54:57 [428]: br0: executing: /libexec/dhcpcd-run-hooks PREINIT
Apr 12 17:54:57 [428]: br0: executing: /libexec/dhcpcd-run-hooks NOCARRIER
Apr 12 17:54:58 [428]: br0: waiting for carrier
Apr 12 17:54:59 [428]: br0: carrier acquired
Apr 12 17:54:59 [428]: br0: executing: /libexec/dhcpcd-run-hooks CARRIER
Apr 12 17:54:59 [428]: br0: delaying IPv4 for 1.1 seconds
Apr 12 17:55:16 [428]: br0: using ClientID 01:a9:07:b7:be:69:5e
Apr 12 17:55:16 [428]: br0: reading lease: /var/db/dhcpcd/br0.lease
Apr 12 17:55:16 [428]: br0: rebinding lease of 192.168.1.4
Apr 12 17:55:16 [428]: br0: ARP announcing 192.168.1.4 (1 of 2), next in 2.0 seconds
Apr 12 17:55:16 [428]: br0: sending REQUEST (xid 0xf4f39fbe), next in 3.9 seconds
Apr 12 17:55:16 [428]: br0: acknowledged 192.168.1.4 from 192.168.1.1
Apr 12 17:55:16 [428]: br0: leased 192.168.1.4 for 7200 seconds
Apr 12 17:55:16 [428]: br0: renew in 3600 seconds, rebind in 6300 seconds
Apr 12 17:55:16 [428]: br0: writing lease: /var/db/dhcpcd/br0.lease
Apr 12 17:55:16 [428]: br0: adding IP address 192.168.1.4/24 broadcast 192.168.1.255
Apr 12 17:55:16 [428]: br0: adding route to 192.168.1.0/24
Apr 12 17:55:16 [428]: br0: adding default route via 192.168.1.1
Apr 12 17:55:16 [428]: br0: ARP announcing 192.168.1.4 (1 of 2), next in 2.0 seconds
Apr 12 17:55:16 [428]: br0: executing: /libexec/dhcpcd-run-hooks REBOOT
Apr 12 17:55:19 [428]: br0: ARP announcing 192.168.1.4 (2 of 2)
Apr 12 18:55:16 [428]: br0: renewing lease of 192.168.1.4
Apr 12 18:55:16 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 3.5 seconds
Apr 12 18:55:20 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 7.0 seconds
Apr 12 18:55:27 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 15.8 seconds
Apr 12 18:55:43 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 32.4 seconds
Apr 12 18:56:15 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 63.7 seconds
Apr 12 18:57:19 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 64.5 seconds
Apr 12 18:58:23 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 64.8 seconds
Apr 12 18:59:28 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 64.7 seconds
Apr 12 19:00:33 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 63.5 seconds
Apr 12 19:01:36 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 63.3 seconds
Apr 12 19:02:40 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 63.9 seconds
Apr 12 19:03:43 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 63.5 seconds
Apr 12 19:04:47 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 64.5 seconds
Apr 12 19:05:52 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 63.1 seconds
Apr 12 19:06:55 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 64.0 seconds
Apr 12 19:07:59 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 64.0 seconds
Apr 12 19:09:03 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 64.4 seconds
Apr 12 19:10:07 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 64.2 seconds
Apr 12 19:11:11 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 64.4 seconds
Apr 12 19:12:16 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 63.4 seconds
Apr 12 19:13:19 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 63.8 seconds
Apr 12 19:14:23 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 64.9 seconds
Apr 12 19:15:28 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 63.5 seconds
Apr 12 19:16:31 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 63.1 seconds
Apr 12 19:17:35 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 64.9 seconds
Apr 12 19:18:40 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 63.4 seconds
Apr 12 19:19:43 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 63.9 seconds
Apr 12 19:35:45 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 65.0 seconds
Apr 12 19:36:50 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 65.0 seconds
Apr 12 19:37:55 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 63.5 seconds
Apr 12 19:38:58 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 63.6 seconds
Apr 12 19:40:02 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 64.5 seconds
Apr 12 19:40:16 [428]: br0: failed to renew DHCP, rebinding
Apr 12 19:40:16 [428]: br0: expire in 900 seconds
Apr 12 19:40:16 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 3.7 seconds
Apr 12 19:40:16 [428]: br0: acknowledged 192.168.1.4 from 192.168.1.1
Apr 12 19:40:16 [428]: br0: leased 192.168.1.4 for 7200 seconds
Apr 12 19:40:16 [428]: br0: renew in 3600 seconds, rebind in 6300 seconds
Apr 12 19:40:16 [428]: br0: writing lease: /var/db/dhcpcd/br0.lease
Apr 12 19:40:16 [428]: br0: adding IP address 192.168.1.4/24 broadcast 192.168.1.255
Apr 12 19:40:16 [428]: br0: ARP announcing 192.168.1.4 (1 of 2), next in 2.0 seconds
Apr 12 19:40:16 [428]: br0: executing: /libexec/dhcpcd-run-hooks REBIND
Apr 12 19:40:18 [428]: br0: ARP announcing 192.168.1.4 (2 of 2)

Meanwhile, on the server:
Apr 12 18:55:14 dr-evil dhcpd[1163]: DHCPREQUEST for 192.168.1.4 from a9:07:b7:be:69:5e via br0
Apr 12 18:55:14 dr-evil dhcpd[1163]: DHCPACK on 192.168.1.4 to a9:07:b7:be:69:5e via br0
Apr 12 18:55:16 dr-evil dhcpd[1163]: DHCPREQUEST for 192.168.1.4 from a9:07:b7:be:69:5e via br0
Apr 12 18:55:16 dr-evil dhcpd[1163]: DHCPACK on 192.168.1.4 to a9:07:b7:be:69:5e via br0
Apr 12 18:55:20 dr-evil dhcpd[1163]: DHCPREQUEST for 192.168.1.4 from a9:07:b7:be:69:5e via br0
Apr 12 18:55:20 dr-evil dhcpd[1163]: DHCPACK on 192.168.1.4 to a9:07:b7:be:69:5e via br0
Apr 12 18:55:27 dr-evil dhcpd[1163]: DHCPREQUEST for 192.168.1.4 from a9:07:b7:be:69:5e via br0
Apr 12 18:55:27 dr-evil dhcpd[1163]: DHCPACK on 192.168.1.4 to a9:07:b7:be:69:5e via br0
Apr 12 18:55:43 dr-evil dhcpd[1163]: DHCPREQUEST for 192.168.1.4 from a9:07:b7:be:69:5e via br0
Apr 12 18:55:43 dr-evil dhcpd[1163]: DHCPACK on 192.168.1.4 to a9:07:b7:be:69:5e via br0
Apr 12 18:56:15 dr-evil dhcpd[1163]: DHCPREQUEST for 192.168.1.4 from a9:07:b7:be:69:5e via br0
Apr 12 18:56:15 dr-evil dhcpd[1163]: DHCPACK on 192.168.1.4 to a9:07:b7:be:69:5e via br0
Apr 12 18:57:19 dr-evil dhcpd[1163]: DHCPREQUEST for 192.168.1.4 from a9:07:b7:be:69:5e via br0
Apr 12 18:57:19 dr-evil dhcpd[1163]: DHCPACK on 192.168.1.4 to a9:07:b7:be:69:5e via br0
Apr 12 18:58:23 dr-evil dhcpd[1163]: DHCPREQUEST for 192.168.1.4 from a9:07:b7:be:69:5e via br0
Apr 12 18:58:23 dr-evil dhcpd[1163]: DHCPACK on 192.168.1.4 to a9:07:b7:be:69:5e via br0
Apr 12 19:00:33 dr-evil dhcpd[1163]: DHCPREQUEST for 192.168.1.4 from a9:07:b7:be:69:5e via br0
Apr 12 19:00:33 dr-evil dhcpd[1163]: DHCPACK on 192.168.1.4 to a9:07:b7:be:69:5e via br0
....for brevity....
Apr 12 19:17:35 dr-evil dhcpd[1163]: DHCPREQUEST for 192.168.1.4 from a9:07:b7:be:69:5e via br0
Apr 12 19:17:35 dr-evil dhcpd[1163]: DHCPACK on 192.168.1.4 to a9:07:b7:be:69:5e via br0
Apr 12 19:18:40 dr-evil dhcpd[1163]: DHCPREQUEST for 192.168.1.4 from a9:07:b7:be:69:5e via br0
Apr 12 19:18:40 dr-evil dhcpd[1163]: DHCPACK on 192.168.1.4 to a9:07:b7:be:69:5e via br0
Apr 12 19:19:43 dr-evil dhcpd[1163]: DHCPREQUEST for 192.168.1.4 from a9:07:b7:be:69:5e via br0
Apr 12 19:19:43 dr-evil dhcpd[1163]: DHCPACK on 192.168.1.4 to a9:07:b7:be:69:5e via br0
Apr 12 19:20:47 dr-evil dhcpd[1163]: DHCPREQUEST for 192.168.1.4 from a9:07:b7:be:69:5e via br0
Apr 12 19:20:47 dr-evil dhcpd[1163]: DHCPACK on 192.168.1.4 to a9:07:b7:be:69:5e via br0
Apr 12 19:35:45 dr-evil dhcpd[1163]: DHCPREQUEST for 192.168.1.4 from a9:07:b7:be:69:5e via br0
Apr 12 19:35:45 dr-evil dhcpd[1163]: DHCPACK on 192.168.1.4 to a9:07:b7:be:69:5e via br0
Apr 12 19:36:50 dr-evil dhcpd[1163]: DHCPREQUEST for 192.168.1.4 from a9:07:b7:be:69:5evia br0
Apr 12 19:36:50 dr-evil dhcpd[1163]: DHCPACK on 192.168.1.4 to a9:07:b7:be:69:5e via br0
Apr 12 19:37:55 dr-evil dhcpd[1163]: DHCPREQUEST for 192.168.1.4 from a9:07:b7:be:69:5e via br0
Apr 12 19:37:55 dr-evil dhcpd[1163]: DHCPACK on 192.168.1.4 to a9:07:b7:be:69:5e via br0
Apr 12 19:38:58 dr-evil dhcpd[1163]: DHCPREQUEST for 192.168.1.4 from a9:07:b7:be:69:5e via br0
Apr 12 19:38:58 dr-evil dhcpd[1163]: DHCPACK on 192.168.1.4 to a9:07:b7:be:69:5e via br0
Apr 12 19:40:02 dr-evil dhcpd[1163]: DHCPREQUEST for 192.168.1.4 from a9:07:b7:be:69:5e via br0
Apr 12 19:40:02 dr-evil dhcpd[1163]: DHCPACK on 192.168.1.4 to a9:07:b7:be:69:5e via br0
Apr 12 19:40:16 dr-evil dhcpd[1163]: DHCPREQUEST for 192.168.1.4 from a9:07:b7:be:69:5e via br0
Apr 12 19:40:16 dr-evil dhcpd[1163]: DHCPACK on 192.168.1.4 to a9:07:b7:be:69:5e via br0

PS. I set my dhcpcd.service file back to what it was by default in /usr/lib/systemd/system/dhcpcd.service before reboot:
ExecStart=/usr/sbin/dhcpcd -b -q
Restart=always

[rsmarples]

Thanks for the detailed logs!

OK, so you need to install the libudev-dev and then recompile and install dhcpcd so it gets udev support.
That allows dhcpcd to work with udev changing the interface names.

Now here is the really interesting section

Apr 12 17:55:19 [428]: br0: ARP announcing 192.168.1.4 (2 of 2) - final ARP after rebooting the AP which is good

Apr 12 18:55:16 [428]: br0: renewing lease of 192.168.1.4
Apr 12 18:55:16 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 3.5 seconds
Apr 12 18:55:20 [428]: br0: sending REQUEST (xid 0xb38a831a), next in 7.0 seconds

So this is when the renew starts, one how later. This looks perfectly normal and we can see that the replies go out to the server and the server does send a reply back again but the key point is that dhcpcd does not see it and thus it repeats until it tries to rebind and then it finally succeeds. Now, there is a technical difference between RENEW and REBIND. RENEW is always sent and received via the IP network whereas all other DHCP messages are sent and received using the BPF raw socket on the interface.

Now this scenario is perfectly fine, and it's expected when the DHCP server is not reachable via IP (common in home routers) and it's just log spam. This is the nature of DHCP sadly (DHCPv6 fixes this). However, your DHCP server is on link, so you should not be seeing this.

I need to setup a new Linux VM to test with anyway and I'll see if I can setup a bridge myself and see if there's any underlying issue with dhcpcd running directly on the bridge.

[Thimbles809]

Ah, so this my be why my sudo crontab -e
45 * * * * sudo /bin/systemctl stop dhcpcd && sudo /bin/systemctl start dhcpcd

kludge fixes this, because it's forcing a rebind instead of a renew?
Thanks for the assistance on this. It's been a bugbear for weeks now.

[rsmarples]

You shouldn't need that in your crontab. Try removing it and watch dhcpcd again - I'll bet you get the same behaviour as noted above - renew errors but rebind works.

[Thimbles809]

Yup. That's what I did to retrigger the errors. A week ago I tried this kludge and it fixed the log spam, but it didn't diagnose the problem. It's been working for a week like this, every hour at 45 after making a rebind instead of a renew.

Right after I git cloned your repository, I commented out my crontab command and set my dhcpcd.service files to default, sure enough - on the hour - it started generating renew requests.

To the average wifi client, it looks and feels like nothing is wrong.. but my syslogs are a mess and I look at those. 😡 Oooooo I hate messy syslogs. 🙃

[Thimbles809]

So I got to here:
The following NEW packages will be installed:
libudev-dev
...
Get:1 http://deb.debian.org/debian bullseye/main arm64 libudev-dev arm64 247.3-7+deb11u1 [123 kB]
...
Preparing to unpack .../libudev-dev_247.3-7+deb11u1_arm64.deb ...
Unpacking libudev-dev:arm64 (247.3-7+deb11u1) ...
Setting up libudev-dev:arm64 (247.3-7+deb11u1) ...
Processing triggers for man-db (2.9.4-2) ...
Then I configured and made from here:
./configure
configure args:
Deriving operating system from ... aarch64-unknown-linux
Configuring dhcpcd for ... linux
Found git checkout ... Adding debugging CFLAGS
...
Enabling Privilege Separation
Detecting a suitable user for dhcpcd ...
No suitable user found for Priviledge Separation!
Using compiler .. cc
...
Checking for libudev ... yes
Checking udev_monitor_filter_add_match_subsystem_devtype ... yes
Checking udev_device_get_is_initialized ... yes
...
Checking for ypbind ... not found
Assuming ypbind is Linux
SYSCONFDIR = /etc
...
PRIVSEPUSER = dhcpcd
and when I got to here:
make
for x in src hooks; do cd $x; make all || exit $?; cd ..; done
make[1]: Entering directory '/home/pi/dhcpcd/src'
Makefile:55: warning: ignoring prerequisites on suffix rule definition
cc -O2 -g -Wall -Wextra -Wundef -Wmissing-prototypes ...
...
This occurred:
/usr/bin/ld: dev.o: in function 'dev_initialised':
/home/pi/dhcpcd/src/dev.c:48: undefined reference to 'ps_root_dev_initialised'
/usr/bin/ld: dev.o: in function 'dev_listening':
/home/pi/dhcpcd/src/dev.c:63: undefined reference to 'ps_root_dev_listening'
collect2: error: ld returned 1 exit status
make[1]: *** [Makefile:73: dhcpcd] Error 1
make[1]: Leaving directory '/home/pi/dhcpcd/src'
make: *** [Makefile:24: all] Error 2
I was going to see if I could catch the error myself in some way and I thought I'd compile the udev support while at it, but it appears I need to create a dhcpcd user and then set the
#ifdef PLUGIN_DEV
flag in privsep-root.c in order to get the complier to link the two missing functions? I just don't want to get too far into the weeds here before I start making real changes on my AP.

[Thimbles809]

Right.
configure --enable-debug --with-udev
Good to know.

[Thimbles809]

A possible fix, not knowing given the size and complexity of the codebase if this a valid fix.

It seems that my server and client are triggering no obvious errors. The code in dhcp.c gets to line 1780 in function
static void
send_message(struct interface *ifp, uint8_t type,
void (*callback)(void *))
It's here that everything works well:
if (to.s_addr != INADDR_BROADCAST) {
if (dhcp_sendudp(ifp, &to, bootp, len) != -1)
goto out;
logerr("%s: dhcp_sendudp", ifp->name);
}
but it keeps generating requests because it goto's out to line 1830:
if (callback != NULL)
eloop_timeout_add_msec(ifp->ctx->eloop, RT, callback, ifp);
}
and it gets into that endless loop. So I attempted to set a terminating condition.
if (to.s_addr != INADDR_BROADCAST) {
if (dhcp_sendudp(ifp, &to, bootp, len) != -1){
callback = NULL; /*terminating condition*/
goto out;
}
logerr("%s: dhcp_sendudp", ifp->name);
}
It appears to be working, but let me know if this is a good approach.

[Thimbles809]

This is my dhcpcd.log, with a few extra debug messages I was using to track the flow and state of the program:
Apr 18 23:37:03 [947]: sending signal USR1 to pid 918
Apr 18 23:37:03 [918]: received SIGUSR1, renewing
Apr 18 23:37:03 [918]: br0: renewing lease of 192.168.1.4
Apr 18 23:37:03 [918]: Link is up.
Apr 18 23:37:03 [918]: br0: sending REQUEST (xid 0xe90130d7), next in 3.4 seconds
Apr 18 23:37:03 [918]: sending to: 192.168.1.1
Apr 18 23:37:03 [918]: sendmsg ctx->udp_wfd success. Returned 348
Apr 18 23:37:03 [918]: br0: dhcp_sendudp success

[rsmarples]

Your approach is bad because you only send one message on the wire. This assumes that the connection to the DHCP server is fully working and we have a DHCP server. If any part of the is not good, there is not attempt to retry. That is why we have the exponential backoff.

The issue is entirely that dhcpcd is not seeing the reply sent by the DHCP server. When I get some free time next week hopefully I'll be able to test on a linux bridge.

[Thimbles809]

Okay, back to the drawing board.
In dchcpcd.c, line 1383, there's:
if (!ifp->active)
return;
To debug it, I put some message code in there:
if (!ifp->active){
logdebugx("ifp->active is not active");
return;
}
The result:
Apr 19 12:01:28 [1988]: received SIGUSR1, renewing
Apr 19 12:01:28 [1988]: ifp->active is not active
Apr 19 12:01:28 [1988]: ifp->active is not active
Apr 19 12:01:28 [1988]: Executing dhcp_renew
Apr 19 12:01:28 [1988]: br0: renewing lease of 192.168.1.4
Apr 19 12:01:28 [1988]: Link is up.
Apr 19 12:01:28 [1988]: br0: sending REQUEST (xid 0x92b33d2b), next in 4.8 seconds
Apr 19 12:01:28 [1988]: sending to: 192.168.1.1
Apr 19 12:01:28 [1988]: sendmsg ctx->udp_wfd success 348
Apr 19 12:01:28 [1988]: br0: dhcp_sendudp success
Apr 19 12:01:28 [1988]: Attempting eloop timeout.
Apr 19 12:01:28 [1988]: ifp->active is not active
Apr 19 12:01:28 [1988]: ifp->active is not active
Apr 19 12:01:33 [1988]: Link is up.
Apr 19 12:01:33 [1988]: br0: sending REQUEST (xid 0x92b33d2b), next in 7.2 seconds
Apr 19 12:01:33 [1988]: sending to: 192.168.1.1
Apr 19 12:01:33 [1988]: sendmsg ctx->udp_wfd success 348
Apr 19 12:01:33 [1988]: br0: dhcp_sendudp success
Apr 19 12:01:33 [1988]: Attempting eloop timeout.
Apr 19 12:01:40 [1988]: Link is up.
Hey, where did those "ifp->active is not active" msgs go?
Apr 19 12:01:40 [1988]: br0: sending REQUEST (xid 0x92b33d2b), next in 16.0 seconds
Apr 19 12:01:40 [1988]: sending to: 192.168.1.1
Apr 19 12:01:40 [1988]: sendmsg ctx->udp_wfd success 348
Apr 19 12:01:40 [1988]: br0: dhcp_sendudp success
Apr 19 12:01:40 [1988]: Attempting eloop timeout.
Apr 19 12:01:56 [1988]: Link is up.
Apr 19 12:01:56 [1988]: br0: sending REQUEST (xid 0x92b33d2b), next in 31.6 seconds
Apr 19 12:01:56 [1988]: sending to: 192.168.1.1
*ad nauseum*
Hopefully, this is helpful.

[Thimbles809]

So the first two "ifp->active is not active" messages refer to the lo and eth0 interfaces,
Apr 20 10:37:35 [4483]: lo ifp->active is not active
Apr 20 10:37:35 [4483]: eth0 ifp->active is not active
THEN it goes to the br0 interface and does a successful renew:
Apr 20 10:37:35 [4483]: br0 ifp->active IS active
then it goes to the next two wlan interfaces where "ifp->active is not active".
Apr 20 10:37:35 [4483]: wlan0* ifp->active is not active
Apr 20 10:37:35 [4483]: wlan1* ifp->active is not active
Could the non functional state of one of the 3 slave interfaces to the bridge - or the lo interface - be wiping out the state of the functional interface? Is there a way of checking interfaces to see if their state is a slave and therefore requiring dhcp requests to go through the master bridge?

*no real interface names were used in this debugging

[Thimbles809]

Any news on the testing of the linux bridge? I've been working on the debugging side myself when I can, but the only results of interest I get are attempts on the slave interfaces. On service startup:
May 13 15:14:48 [13374]: dhcp_new_xid:lo state1 = D_CSTATE(ifp1) == NULL
May 13 15:14:48 [13374]: dhcp_new_xid:eth0 state1 = D_CSTATE(ifp1) == NULL
May 13 15:14:48 [13374]: dhcp_new_xid:br0 ifp == ifp1
May 13 15:14:48 [13374]: dhcp_new_xid:wlx01 state1 = D_CSTATE(ifp1) == NULL
May 13 15:14:48 [13374]: dhcp_new_xid:wlx02 state1 = D_CSTATE(ifp1) == NULL
May 13 15:14:48 [13374]: dhcp_new_xid: ifp1 == NULL
May 13 15:14:48 [13374]: dhcp_new_xid: exiting dhcp_new_xid
On sudo dhcpcd -N
May 13 15:14:57 [13393]: sending signal USR1 to pid 13374
May 13 15:14:57 [13374]: received SIGUSR1, renewing
May 13 15:14:57 [13374]: dhcpcd_ifrenew: lo ifp->active is not active
May 13 15:14:57 [13374]: dhcpcd_ifrenew: eth0 ifp->active is not active
May 13 15:14:57 [13374]: dhcpcd_ifrenew: br0 ifp->active IS active ifp->active == 2
May 13 15:14:57 [13374]: dhcpcd_ifrenew: Executing dhcp_renew for br0
May 13 15:14:57 [13374]: dhcp_startrenew: state is running
May 13 15:14:57 [13374]: dhcp_startrenew: state is DHS_BOUND
May 13 15:14:57 [13374]: dhcp_startrenew: br0: renewing lease of 192.168.1.4
May 13 15:14:57 [13374]: dhcp_new_xid:lo state1 = D_CSTATE(ifp1) == NULL
May 13 15:14:57 [13374]: dhcp_new_xid:eth0 state1 = D_CSTATE(ifp1) == NULL
May 13 15:14:57 [13374]: dhcp_new_xid:br0 ifp == ifp1
May 13 15:14:57 [13374]: dhcp_new_xid:wlx01 state1 = D_CSTATE(ifp1) == NULL
May 13 15:14:57 [13374]: dhcp_new_xid:wlx02 state1 = D_CSTATE(ifp1) == NULL
May 13 15:14:57 [13374]: dhcp_new_xid: ifp1 == NULL
May 13 15:14:57 [13374]: dhcp_new_xid: exiting dhcp_new_xid
May 13 15:14:57 [13374]: dhcp_startrenew: Attempting send_renew
May 13 15:14:57 [13374]: send_renew: Attempting send_message
May 13 15:14:57 [13374]: send_message: Link is up.
May 13 15:14:57 [13374]: send_message: br0: sending REQUEST (xid 0xe2c676cb), next in 4.5 seconds
May 13 15:14:57 [13374]: send_message: sending to: 192.168.1.1
May 13 15:14:57 [13374]: send_messaage: (to.s_addr != INADDR_BROADCAST) Attempting dhcp_sendudp
May 13 15:14:57 [13374]: dhcp_makeudppacket: sendmsg ctx->udp_wfd success 348 bytes sent.
May 13 15:14:57 [13374]: send_message: br0: dhcp_sendudp success, goto out
May 13 15:14:57 [13374]: send_message:Attempting eloop timeout.
May 13 15:14:57 [13374]: send_message:Finished eloop for br0. active = 2 hwtype= 1 carrier 1 hwaddr <br0 MACAddress> ipaddr 192.168.1.4
May 13 15:14:57 [13374]: send_renew:Finished send_message
May 13 15:14:57 [13374]: dhcp_startrenew: send_renew completed
May 13 15:14:57 [13374]: dhcpcd_ifrenew: Finished dhcp_renew for br0
May 13 15:14:57 [13374]: dhcpcd_ifrenew: wlx01 ifp->active is not active
May 13 15:14:57 [13374]: dhcpcd_ifrenew: wlx02 ifp->active is not active
May 13 15:15:01 [13374]: send_renew:Attempting send_message
May 13 15:15:01 [13374]: send_message: Link is up.
May 13 15:15:01 [13374]: send_message:br0: sending REQUEST (xid 0xe2c676cb), next in 8.4 seconds
May 13 15:15:01 [13374]: send_message:sending to: 192.168.1.1
May 13 15:15:01 [13374]: send_messaage:(to.s_addr != INADDR_BROADCAST) Attempting dhcp_sendudp
May 13 15:15:01 [13374]: dhcp_makeudppacket:sendmsg ctx->udp_wfd success 348 bytes sent.
May 13 15:15:01 [13374]: send_message:br0: dhcp_sendudp success, goto out
May 13 15:15:01 [13374]: send_message:Attempting eloop timeout.
May 13 15:15:01 [13374]: send_message:Finished eloop for br0. active = 2 hwtype= 1 carrier 1 hwaddr <br0 MACAddress> ipaddr 192.168.1.4
May 13 15:15:01 [13374]: send_renew: Finished send_message
May 13 15:15:10 [13374]: send_renew: Attempting send_message
May 13 15:15:10 [13374]: send_message: Link is up.
May 13 15:15:10 [13374]: send_message: br0: sending REQUEST (xid 0xe2c676cb), next in 16.8 seconds
May 13 15:15:10 [13374]: send_message: sending to: 192.168.1.1
May 13 15:15:10 [13374]: send_messaage:(to.s_addr != INADDR_BROADCAST) Attempting dhcp_sendudp
May 13 15:15:10 [13374]: dhcp_makeudppacket:sendmsg ctx->udp_wfd success 348 bytes sent
May 13 15:15:10 [13374]: send_message:br0: dhcp_sendudp success, goto out
May 13 15:15:10 [13374]: send_message:Attempting eloop timeout.
May 13 15:15:10 [13374]: send_message:Finished eloop for br0. active = 2 hwtype= 1 carrier 1 hwaddr <br0 MACAddress> ipaddr 192.168.1.4
May 13 15:15:10 [13374]: send_renew:Finished send_message
May 13 15:15:26 [13374]: send_renew:Attempting send_message
May 13 15:15:26 [13374]: send_message: Link is up.
May 13 15:15:26 [13374]: send_message:br0: sending REQUEST (xid 0xe2c676cb), next in 32.8 seconds
May 13 15:15:26 [13374]: send_message:sending to: 192.168.1.1
...

Anything you want me to try?