Network | DHCP server starts before WiFi adapter is ready

StephanStS commented 1 year ago

Required Information

DietPi version | cat /boot/dietpi/.version
- G_DIETPI_VERSION_CORE=8
- G_DIETPI_VERSION_SUB=19
- G_DIETPI_VERSION_RC=1
- G_GITBRANCH='master'
- G_GITOWNER='MichaIng'
- G_LIVE_PATCH_STATUS[0]='applied'
- G_LIVE_PATCH_STATUS[1]='applied'
Distro version | bookworm
Kernel version | 5.15.93-sunxi64 #23.02.2 SMP Fri Feb 17 23:48:38 UTC 2023 aarch64 GNU/Linux
SBC model | NanoPi NEO Plus2 (aarch64)
Power supply used | Bestek power tower USB power output
SD card used | Samsung Evo 32 GB

Additional Information (if applicable)

Software title | WiFi-Hotspot
Was the software title installed freshly or updated/migrated? freshly installation
Can this issue be replicated on a fresh installation of DietPi? yes
Bug report ID | fcbb8aa5-7c79-4274-a704-3337899b0879

Steps to reproduce

Base DietPi installation with
- AUTO_SETUP_INSTALL_SOFTWARE_ID=3
- AUTO_SETUP_INSTALL_SOFTWARE_ID=60
Start dietpi-config
Choose "7 : Network Options: Adapters"
Choose "WiFi : Available | [On] | Disconnected"
Choose "Apply : Save all changes and restart networking"

Expected behaviour

Networking restart should take place

Actual behaviour

Error message

┌──────────────────────────────────────────────────┤ DietPi-Config ├───────────────────────────────────────────────────┐
│  - Command: systemctl start hostapd isc-dhcp-server                                                                  │
│  - Exit code: 1                                                                                                      │
│  - DietPi version: v8.19.1 (MichaIng/master) | HW_MODEL: 57 | HW_ARCH: 3 | DISTRO: 7                                 │
│  - Image creator: DietPi Core Team                                                                                   │
│  - Pre-image: Armbian                                                                                                │
│  - Error log:                                                                                                        │
│ Job for isc-dhcp-server.service failed because the control process exited with error code.                           │
│ See "systemctl status isc-dhcp-server.service" and "journalctl -xeu isc-dhcp-server.service" for details.            │
│                                                                                                                      │
│                         Retry          : Re-run the last command that failed                                         │
│                         Open subshell  : Open a subshell to investigate or solve the issue                           │
│                         Send report    : Uploads bugreport containing system info to DietPi                          │
│                                        ●─ Devs only ──────────────────────────────────────●                          │
│                         Change command : Adjust and rerun the command                                                │
│                                                                                                                      │
│                                                                                                                      │
│                                  <Ok>                                      <Exit>                                    │
│                                                                                                                      │
└──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘

Extra detail

A reboot helps to show up WiFi : Available | [On] | WiFi Hotspot Mode

Joulinar commented 1 year ago

Was this a new installation of Hotspot? At least on my experience isc-dhcp-server require a reboot to get function.

StephanStS commented 1 year ago

Was this a new installation of Hotspot? At least on my experience isc-dhcp-server require a reboot to get function.

Yes it was a new installation.

MichaIng commented 1 year ago

What do service logs say?

journalctl -u isc-dhcp-server

StephanStS commented 12 months ago

@MichaIng: My next examinations gave the following which could help to localize the problem.

I did these steps

Installation of WiFi-Hotspot on a fresh dietpi system
isc-dhcp-server.service is active (running) directly after the installation
WiFi-Hotspot works
reboot
isc-dhcp-server.service has failed (Result: exit-code) WiFi-Hotspot does not work (the client does not get any IP address)
systemctl restart isc-dhcp-server.service
isc-dhcp-server.service is active (running)
WiFi-Hotspot works

Output of steps 5. - 7.:

After reboot:

root@blocker:~# systemctl status isc-dhcp-server.service 
× isc-dhcp-server.service - LSB: DHCP server
     Loaded: loaded (/etc/init.d/isc-dhcp-server; generated)
     Active: failed (Result: exit-code) since Fri 2023-07-28 12:54:18 CEST; 31s ago
       Docs: man:systemd-sysv-generator(8)
    Process: 537 ExecStart=/etc/init.d/isc-dhcp-server start (code=exited, status=1/FAILURE)
        CPU: 220ms

Jul 28 12:54:16 blocker dhcpd[551]: bugs on either our web page at www.isc.org or in the README file
Jul 28 12:54:16 blocker dhcpd[551]: before submitting a bug.  These pages explain the proper
Jul 28 12:54:16 blocker dhcpd[551]: process and the information we find helpful for debugging.
Jul 28 12:54:16 blocker dhcpd[551]: 
Jul 28 12:54:16 blocker dhcpd[551]: exiting.
Jul 28 12:54:18 blocker isc-dhcp-server[537]: Starting ISC DHCPv4 server: dhcpdcheck syslog for diagnostics. ... failed!
Jul 28 12:54:18 blocker isc-dhcp-server[537]:  failed!
Jul 28 12:54:18 blocker systemd[1]: isc-dhcp-server.service: Control process exited, code=exited, status=1/FAILURE
Jul 28 12:54:18 blocker systemd[1]: isc-dhcp-server.service: Failed with result 'exit-code'.
Jul 28 12:54:18 blocker systemd[1]: Failed to start isc-dhcp-server.service - LSB: DHCP server.

Then restart the service and view the status:

root@blocker:~# systemctl restart isc-dhcp-server.service 
root@blocker:~# systemctl status isc-dhcp-server.service 
● isc-dhcp-server.service - LSB: DHCP server
     Loaded: loaded (/etc/init.d/isc-dhcp-server; generated)
     Active: active (running) since Fri 2023-07-28 12:59:03 CEST; 2s ago
       Docs: man:systemd-sysv-generator(8)
    Process: 1130 ExecStart=/etc/init.d/isc-dhcp-server start (code=exited, status=0/SUCCESS)
      Tasks: 1 (limit: 905)
     Memory: 2.5M
        CPU: 192ms
     CGroup: /system.slice/isc-dhcp-server.service
             └─1142 /usr/sbin/dhcpd -4 -q -cf /etc/dhcp/dhcpd.conf wlan0

Jul 28 12:59:01 blocker systemd[1]: Starting isc-dhcp-server.service - LSB: DHCP server...
Jul 28 12:59:01 blocker isc-dhcp-server[1130]: Launching IPv4 server only.
Jul 28 12:59:01 blocker dhcpd[1142]: Wrote 1 leases to leases file.
Jul 28 12:59:01 blocker dhcpd[1142]: Server starting service.
Jul 28 12:59:03 blocker isc-dhcp-server[1130]: Starting ISC DHCPv4 server: dhcpd.
Jul 28 12:59:03 blocker systemd[1]: Started isc-dhcp-server.service - LSB: DHCP server.
root@blocker:~#

Joulinar commented 12 months ago

Can you reboot the system and share the whole service log, not just status messages

journalctl -u isc-dhcp-server

StephanStS commented 12 months ago

Yes, for sure:

root@blocker:~# journalctl -u isc-dhcp-server.service
Jul 28 21:31:21 blocker systemd[1]: Starting isc-dhcp-server.service - LSB: DHCP server...
Jul 28 21:31:21 blocker isc-dhcp-server[541]: Launching IPv4 server only.
Jul 28 21:31:21 blocker dhcpd[555]: Wrote 1 leases to leases file.
Jul 28 21:31:21 blocker dhcpd[555]:
Jul 28 21:31:21 blocker dhcpd[555]: No subnet declaration for wlan0 (no IPv4 addresses).
Jul 28 21:31:21 blocker dhcpd[555]: ** Ignoring requests on wlan0.  If this is not what
Jul 28 21:31:21 blocker dhcpd[555]:    you want, please write a subnet declaration
Jul 28 21:31:21 blocker dhcpd[555]:    in your dhcpd.conf file for the network segment
Jul 28 21:31:21 blocker dhcpd[555]:    to which interface wlan0 is attached. **
Jul 28 21:31:21 blocker dhcpd[555]:
Jul 28 21:31:21 blocker dhcpd[555]:
Jul 28 21:31:21 blocker dhcpd[555]: Not configured to listen on any interfaces!
Jul 28 21:31:21 blocker dhcpd[555]:
Jul 28 21:31:21 blocker dhcpd[555]: If you think you have received this message due to a bug rather
Jul 28 21:31:21 blocker dhcpd[555]: than a configuration issue please read the section on submitting
Jul 28 21:31:21 blocker dhcpd[555]: bugs on either our web page at www.isc.org or in the README file
Jul 28 21:31:21 blocker dhcpd[555]: before submitting a bug.  These pages explain the proper
Jul 28 21:31:21 blocker dhcpd[555]: process and the information we find helpful for debugging.
Jul 28 21:31:21 blocker dhcpd[555]:
Jul 28 21:31:21 blocker dhcpd[555]: exiting.
Jul 28 21:31:23 blocker isc-dhcp-server[541]: Starting ISC DHCPv4 server: dhcpdcheck syslog for diagnostics. ... failed!
Jul 28 21:31:23 blocker isc-dhcp-server[541]:  failed!
Jul 28 21:31:23 blocker systemd[1]: isc-dhcp-server.service: Control process exited, code=exited, status=1/FAILURE
Jul 28 21:31:23 blocker systemd[1]: isc-dhcp-server.service: Failed with result 'exit-code'.
Jul 28 21:31:23 blocker systemd[1]: Failed to start isc-dhcp-server.service - LSB: DHCP server.
root@blocker:~#

MichaIng commented 12 months ago

Jul 28 21:31:21 blocker dhcpd[555]: No subnet declaration for wlan0 (no IPv4 addresses).

Can you show the config files:

cat /etc/dhcp/dhcpd.conf
cat /etc/default/isc-dhcp-server
cat /etc/network/interfaces

But actually, if the subnet declaration in dhcpd.conf would be really missing, a restart shouldn't solve it.

StephanStS commented 12 months ago

For me, the config files seemed to be o.k.:

root@blocker:~# cat /etc/dhcp/dhcpd.conf
authoritative;
#default-lease-time 43200;
#max-lease-time 86400;

subnet 192.168.42.0 netmask 255.255.255.0 {
        range 192.168.42.10 192.168.42.250;
        option broadcast-address 192.168.42.255;
        option routers 192.168.42.1;
        option domain-name "local";
        option domain-name-servers 9.9.9.9, 149.112.112.112;
}

root@blocker:~# cat /etc/default/isc-dhcp-server
INTERFACESv4="wlan0"

root@blocker:~# cat /etc/network/interfaces
# Location: /etc/network/interfaces
# Please modify network settings via: dietpi-config
# Or create your own drop-ins in: /etc/network/interfaces.d/

# Drop-in configs
source interfaces.d/*

# Ethernet
allow-hotplug eth0
iface eth0 inet dhcp
address 192.168.0.100
netmask 255.255.255.0
gateway 192.168.0.1
#dns-nameservers 9.9.9.9 149.112.112.112

# WiFi
allow-hotplug wlan0
iface wlan0 inet static
address 192.168.42.1
netmask 255.255.255.0
#gateway 192.168.0.1
#dns-nameservers 9.9.9.9 149.112.112.112
wireless-power off

# iptables NAT rules
up iptables-restore < /etc/iptables.ipv4.nat
up ip6tables-restore < /etc/iptables.ipv6.nat

I rather assume a init.d timing/procedure problem, because a restart of the isc-dhcp-server solved the issue.

StephanStS commented 12 months ago

One more thing: The WiFi adapter is an USB one. Maybe its initialization causes a timing issue. I will do the same test with a NanoPi NEO Plus 2 and a Pi 4 (both with onboard WiFi).

MichaIng commented 12 months ago

Looks all good indeed. USB vs onboard WiFi should not make a difference, as the allow-hotplug implementation explicitly starts the related service ifup@wlan0 once it has been detected by the system, instead of as part of the fixed boot schedule. This is the reason we use this, so the system never tries to bring up an interface if the related adapter has not been detected yet by the kernel or simply is not attached.

Ah, but ... this applies for the ifup part only, not for the DHCP server or hostapd. Actually this makes pretty much sense: In case of late detected USB adapters, the DHCP server can be started before the interface has been setup. It comes with After=network-online.target, and we added an ifup@.service override to assure that if ifup@.service finishes completely before network-online.target. But ifup@wlan0.service is created/loaded only after the adapter has been detected (reasonably), which theoretically can happen after all targets have been reached already, or at least after the ordering/schedule of the related targets/services is fixed.

Are you able to see the network adapter detection in dmesg -T, and whether the timestamp is before or after the DHCP server start?

StephanStS commented 11 months ago

Finally, testing with a Pi4 (onboard WiFi), NanoPi NEO2 (WiFi USB stick), NanoPi NEO Plus 2 (onboard WiFi), ZeroPi (WiFi USB Stick), Pi3A+ (onboard WiFi) and two different WiFi USB sticks, the problem seem to stick with my Ralink RT5572 Wireless Adapter with two antennas.

USB device

lsusb gives Bus 003 Device 002: ID 148f:5572 Ralink Technology, Corp. RT5572 Wireless Adapter

dmesg

dmesg -T gives

[Mo Jul 31 04:14:04 2023] usb 3-1: New USB device found, idVendor=148f, idProduct=5572, bcdDevice= 1.01
[Mo Jul 31 04:14:04 2023] usb 3-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[Mo Jul 31 04:14:04 2023] usb 3-1: Product: 802.11 n WLAN
[Mo Jul 31 04:14:04 2023] usb 3-1: Manufacturer: Ralink
[Mo Jul 31 04:14:04 2023] usb 3-1: SerialNumber: 1.0

...

[Mo Jul 31 04:14:10 2023] usb 3-1: reset high-speed USB device number 2 using ehci-platform
[Mo Jul 31 04:14:10 2023] ieee80211 phy0: rt2x00_set_rt: Info - RT chipset 5592, rev 0222 detected
[Mo Jul 31 04:14:11 2023] ieee80211 phy0: rt2x00_set_rf: Info - RF chipset 000f detected
[Mo Jul 31 04:14:11 2023] ieee80211 phy0: Selected rate control algorithm 'minstrel_ht'
[Mo Jul 31 04:14:11 2023] usbcore: registered new interface driver rt2800usb
[Mo Jul 31 04:14:12 2023] ieee80211 phy0: rt2x00lib_request_firmware: Info - Loading firmware file 'rt2870.bin'
[Mo Jul 31 04:14:12 2023] ieee80211 phy0: rt2x00lib_request_firmware: Info - Firmware detected - version: 0.36

...

[Mo Jul 31 04:14:19 2023] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[Mo Jul 31 04:14:26 2023] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready

journalctl

journalctl -u isc-dhcp-server.service shows that the dhcp server is initialized in the same time range

Jul 31 04:14:18 dietpi systemd[1]: Starting isc-dhcp-server.service - LSB: DHCP server...
Jul 31 04:14:18 dietpi isc-dhcp-server[562]: Launching IPv4 server only.

...

Jul 31 04:14:19 dietpi dhcpd[577]: exiting.
Jul 31 04:14:21 dietpi isc-dhcp-server[562]: Starting ISC DHCPv4 server: dhcpdcheck syslog for diagnostics. ... failed!
Jul 31 04:14:21 dietpi isc-dhcp-server[562]:  failed!
Jul 31 04:14:21 dietpi systemd[1]: isc-dhcp-server.service: Control process exited, code=exited, status=1/FAILURE
Jul 31 04:14:21 dietpi systemd[1]: isc-dhcp-server.service: Failed with result 'exit-code'.
Jul 31 04:14:21 dietpi systemd[1]: Failed to start isc-dhcp-server.service - LSB: DHCP server.

Comparison to working USB WiFi device

The malfunctioning USB device loads the firmware file 'rt2870.bin' (see dmesg output above). A different working USB device loads the firmware file ' rtlwifi/rtl8192cufw_TMSC.bin' (this is a RTL8192CU 802.11n WLAN Adapter).

Next steps?

Shall we go on with this examination or kick off the malfunctioning USB device? I could also get an additional USB WiFi adapter and do tests with it.

MichaIng commented 11 months ago

Collecting some info for myself from our video chat:

ifup@wlan0 starts and finishes several seconds before the DHCP server starts, so an IP address should be assigned already and the interface completely up.
When we wanted to debug the case and added an ip a to the start of the DHCP server service, suddenly it worked, and we were able to repeatedly replicate the case that a simple ip a call for some strange reasons fixes the DHCP server start.

MichaIng / DietPi