Keep experiencing disconnect loops from the WiFi on different plattforms (RPI, WLANPI, Debian)

[torstefan]

Hey,

I wonder if you have any suggestions regarding an issue i keep experiencing.

At an random interwall running the wiperf test, my system gets disconnected from the wifi and is unable to reestablish connection. Most often the connection issue can last up to the time wiperf reboots the machine. After reboot, the system is able to reconnect.

I also see that the wlan0 is getting a second IP.

From the WLC logs I see that the controller disconnects the client after a while since it does not recive an dhcp request. This is what leads me to think that maybe the dhclient has crashed, and the wpa_supplicant is somehow unable to start up a new dhclient.

I get the same result on different systems. RPI rasbian, WLANPI image2, Debian 10.9, All with the lasted software.

I wonder if anyone else experiences this? Or have any tips to get my systems stable.

Kind regards,
Tor Stefan

Mar 31 05:53:55 snorty-svg systemd[1]: Started Time & Date Service.
Mar 31 05:54:35 snorty-svg dhclient[21319]: Internet Systems Consortium DHCP Client 4.4.1
Mar 31 05:54:35 snorty-svg dhclient[21319]: Copyright 2004-2018 Internet Systems Consortium.
Mar 31 05:54:35 snorty-svg dhclient[21319]: All rights reserved.
Mar 31 05:54:35 snorty-svg dhclient[21319]: For info, please visit https://www.isc.org/software/dhcp/
Mar 31 05:54:35 snorty-svg dhclient[21319]:
Mar 31 05:54:35 snorty-svg dhclient[21319]: Listening on LPF/wlx200db0323c9f/20:0d:b0:32:3c:9f
Mar 31 05:54:35 snorty-svg dhclient[21319]: Sending on LPF/wlx200db0323c9f/20:0d:b0:32:3c:9f
Mar 31 05:54:35 snorty-svg dhclient[21319]: Sending on Socket/fallback
Mar 31 05:54:35 snorty-svg dhclient[21319]: DHCPDISCOVER on wlx200db0323c9f to 255.255.255.255 port 67 interval 3
Mar 31 05:54:35 snorty-svg dhclient[21319]: DHCPOFFER of 10.92.123.226 from 192.0.2.1
Mar 31 05:54:35 snorty-svg dhclient[21319]: DHCPREQUEST for 10.92.123.226 on wlx200db0323c9f to 255.255.255.255 port 67
Mar 31 05:54:35 snorty-svg dhclient[21319]: DHCPACK of 10.92.123.226 from 192.0.2.1
Mar 31 05:55:05 snorty-svg systemd[1]: systemd-timedated.service: Succeeded.
Mar 31 05:55:19 snorty-svg wpa_supplicant[596]: wlp2s0: Reject scan trigger since one is already pending
Mar 31 05:56:03 snorty-svg dbus-daemon[591]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.1697' (uid=0 pid=21374 comm="/usr/bin/timedatectl status ")
Mar 31 05:56:03 snorty-svg systemd[1]: Starting Time & Date Service...
Mar 31 05:56:03 snorty-svg dbus-daemon[591]: [system] Successfully activated service 'org.freedesktop.timedate1'
Mar 31 05:56:03 snorty-svg systemd[1]: Started Time & Date Service.
Mar 31 05:56:33 snorty-svg systemd[1]: systemd-timedated.service: Succeeded.
Mar 31 05:58:55 snorty-svg dbus-daemon[591]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.1699' (uid=0 pid=21492 comm="/usr/bin/timedatectl status ")
Mar 31 05:58:55 snorty-svg systemd[1]: Starting Time & Date Service...
Mar 31 05:58:55 snorty-svg dbus-daemon[591]: [system] Successfully activated service 'org.freedesktop.timedate1'
Mar 31 05:58:55 snorty-svg systemd[1]: Started Time & Date Service.
Mar 31 05:59:35 snorty-svg dhclient[21603]: Internet Systems Consortium DHCP Client 4.4.1
Mar 31 05:59:35 snorty-svg dhclient[21603]: Copyright 2004-2018 Internet Systems Consortium.
Mar 31 05:59:35 snorty-svg dhclient[21603]: All rights reserved.
Mar 31 05:59:35 snorty-svg dhclient[21603]: For info, please visit https://www.isc.org/software/dhcp/
Mar 31 05:59:35 snorty-svg dhclient[21603]:
Mar 31 05:59:35 snorty-svg dhclient[21603]: Listening on LPF/wlx200db0323c9f/20:0d:b0:32:3c:9f
Mar 31 05:59:35 snorty-svg dhclient[21603]: Sending on LPF/wlx200db0323c9f/20:0d:b0:32:3c:9f
Mar 31 05:59:35 snorty-svg dhclient[21603]: Sending on Socket/fallback
Mar 31 05:59:35 snorty-svg dhclient[21603]: DHCPDISCOVER on wlx200db0323c9f to 255.255.255.255 port 67 interval 7
Mar 31 05:59:35 snorty-svg dhclient[21603]: DHCPOFFER of 10.92.123.226 from 192.0.2.1
Mar 31 05:59:35 snorty-svg dhclient[21603]: DHCPREQUEST for 10.92.123.226 on wlx200db0323c9f to 255.255.255.255 port 67
Mar 31 05:59:35 snorty-svg dhclient[21603]: DHCPACK of 10.92.123.226 from 192.0.2.1
Mar 31 06:00:05 snorty-svg systemd[1]: systemd-timedated.service: Succeeded.
Mar 31 06:00:35 snorty-svg wpa_supplicant[596]: wlp2s0: Reject scan trigger since one is already pending
Mar 31 06:01:03 snorty-svg dbus-daemon[591]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.1720' (uid=0 pid=21656 comm="/usr/bin/timedatectl status ")
Mar 31 06:01:03 snorty-svg systemd[1]: Starting Time & Date Service...
Mar 31 06:01:03 snorty-svg dbus-daemon[591]: [system] Successfully activated service 'org.freedesktop.timedate1'
Mar 31 06:01:03 snorty-svg systemd[1]: Started Time & Date Service.
Mar 31 06:01:33 snorty-svg systemd[1]: systemd-timedated.service: Succeeded.
Mar 31 06:01:39 snorty-svg wpa_supplicant[596]: wlx200db0323c9f: CTRL-EVENT-DISCONNECTED bssid=6c:41:0e:44:0f:4b reason=1
Mar 31 06:01:39 snorty-svg wpa_supplicant[596]: dbus: wpa_dbus_property_changed: no property SessionLength in object /fi/w1/wpa_supplicant1/Interfaces/1
Mar 31 06:01:39 snorty-svg wpa_supplicant[596]: wlx200db0323c9f: CTRL-EVENT-ASSOC-REJECT status_code=1
Mar 31 06:01:39 snorty-svg wpa_supplicant[596]: wlp2s0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
Mar 31 06:01:43 snorty-svg wpa_supplicant[596]: wlx200db0323c9f: Trying to associate with 6c:41:0e:44:48:4b (SSID='psk.xyz.net' freq=5180 MHz)
Mar 31 06:01:43 snorty-svg wpa_supplicant[596]: wlx200db0323c9f: Associated with 6c:41:0e:44:48:4b
Mar 31 06:01:43 snorty-svg wpa_supplicant[596]: wlx200db0323c9f: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Mar 31 06:01:43 snorty-svg wpa_supplicant[596]: wlx200db0323c9f: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=NO
Mar 31 06:01:44 snorty-svg wpa_supplicant[596]: wlx200db0323c9f: WPA: Key negotiation completed with 6c:41:0e:44:48:4b [PTK=CCMP GTK=CCMP]
Mar 31 06:01:44 snorty-svg wpa_supplicant[596]: wlx200db0323c9f: CTRL-EVENT-CONNECTED - Connection to 6c:41:0e:44:48:4b completed [id=0 id_str=]
Mar 31 06:01:44 snorty-svg wpa_supplicant[596]: bgscan simple: Failed to enable signal strength monitoring
Mar 31 06:02:10 snorty-svg wpa_supplicant[596]: wlx200db0323c9f: CTRL-EVENT-DISCONNECTED bssid=6c:41:0e:44:48:4b reason=1
Mar 31 06:02:10 snorty-svg wpa_supplicant[596]: dbus: wpa_dbus_property_changed: no property SessionLength in object /fi/w1/wpa_supplicant1/Interfaces/1
Mar 31 06:02:10 snorty-svg wpa_supplicant[596]: wlx200db0323c9f: CTRL-EVENT-ASSOC-REJECT status_code=1
Mar 31 06:02:10 snorty-svg wpa_supplicant[596]: wlp2s0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
Mar 31 06:02:11 snorty-svg wpa_supplicant[596]: wlx200db0323c9f: Trying to associate with 6c:41:0e:44:0f:4b (SSID='psk.xyz.net' freq=5200 MHz)
Mar 31 06:02:11 snorty-svg wpa_supplicant[596]: wlx200db0323c9f: Associated with 6c:41:0e:44:0f:4b
Mar 31 06:02:11 snorty-svg wpa_supplicant[596]: wlx200db0323c9f: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Mar 31 06:02:11 snorty-svg wpa_supplicant[596]: wlx200db0323c9f: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=NO
Mar 31 06:02:12 snorty-svg wpa_supplicant[596]: wlx200db0323c9f: WPA: Key negotiation completed with 6c:41:0e:44:0f:4b [PTK=CCMP GTK=CCMP]
Mar 31 06:02:12 snorty-svg wpa_supplicant[596]: wlx200db0323c9f: CTRL-EVENT-CONNECTED - Connection to 6c:41:0e:44:0f:4b completed [id=0 id_str=]
Mar 31 06:02:12 snorty-svg wpa_supplicant[596]: bgscan simple: Failed to enable signal strength monitoring
Mar 31 06:02:38 snorty-svg wpa_supplicant[596]: wlx200db0323c9f: CTRL-EVENT-DISCONNECTED bssid=6c:41:0e:44:0f:4b reason=1
Mar 31 06:02:38 snorty-svg wpa_supplicant[596]: dbus: wpa_dbus_property_changed: no property SessionLength in object /fi/w1/wpa_supplicant1/Interfaces/1
Mar 31 06:02:38 snorty-svg wpa_supplicant[596]: wlx200db0323c9f: CTRL-EVENT-ASSOC-REJECT status_code=1
Mar 31 06:02:38 snorty-svg wpa_supplicant[596]: wlp2s0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
Mar 31 06:02:40 snorty-svg wpa_supplicant[596]: wlx200db0323c9f: Trying to associate with 6c:41:0e:44:48:4b (SSID='psk.xyz.net' freq=5180 MHz)
Mar 31 06:02:40 snorty-svg wpa_supplicant[596]: wlx200db0323c9f: Associated with 6c:41:0e:44:48:4b
Mar 31 06:02:40 snorty-svg wpa_supplicant[596]: wlx200db0323c9f: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Mar 31 06:02:40 snorty-svg wpa_supplicant[596]: wlx200db0323c9f: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=NO

wpa_supplicant.conf

ap_scan=1
country=NO

#######################################################################################

NOTE: to use the templates below, remove the hash symbols at the start of each line

#######################################################################################

WPA2 PSK Network sample (highest priority - joined first)

network={
ssid="psk.ihelse.net"
psk="secret"
priority=10
}

[wifinigel]

Hi Stefan,

Are you able to check if NetworkManager is running on your platforms? That can cause some very strange issues in this area if it is installed and running. I advise it is not installed as it clashes with using the /etc/network/interfaces file to activate wpa supplicant etc.

If not, I will need to see a copy of the /var/log/wiperf_agent.log and /var/log/wiperf_cron.log files if possible to see if I can diagnose what is happening (mail to [email protected]).

Thanks

Nigel.