DietPi
DietPi copied to clipboard
MichaIng
Network | DHCP server starts before WiFi adapter is ready
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
Was this a new installation of Hotspot? At least on my experience isc-dhcp-server require a reboot to get function.
Was this a new installation of Hotspot? At least on my experience
isc-dhcp-serverrequire a reboot to get function.
Yes it was a new installation.
@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:~#
Can you reboot the system and share the whole service log, not just status messages
journalctl -u isc-dhcp-server
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:~#
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.
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.
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).
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 [email protected] override to assure that if [email protected] finishes completely before network-online.target. But [email protected] 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?
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.
Collecting some info for myself from our video chat:
ifup@wlan0starts 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 ato the start of the DHCP server service, suddenly it worked, and we were able to repeatedly replicate the case that a simpleip acall for some strange reasons fixes the DHCP server start.
Test with the actual NEO Plus2 image:
- When starting
dietpi-configall seems well. It displaysWiFi : Available | [On] | WiFi Hotspot Mode - DietPi-HotSpot is visible as the SSID
- A connection to the hostspot is working, DHCP address of 192.168.42.10 is retreived as expected
So, now all is working as expected. Close this issue.