I very often use my L5 as hotspot AP for my laptop, the L5 is using data mobile to connect to Internet. Enabling is simple from Settings -> Wi-Fi. I often encounter the problem, that after a short moment Settings falls back, saying no WLAN adapter would be there. I have to reenable Hotspot again, sometimes two times, and then it works fine without any hick-up for hours,
Any ideas?
This happens to me also, quite often. Just like you describe it, for me also it works a very short time, a few seconds maybe, then breaks. Then it can work for hours on next attempt. Probably a bug, maybe in the kernel.
I totally confirm this behavior. I use the hotspot quite often, and it see this often as well.
I created an issue for this.
I use the Redpine WiFi module. What do you use?
I use redpine_91x, firmware version 1.2.20.0
Same here.
Well done!
As a side note: Release 2.6.1 available (#1) Ā· Issues Ā· Librem5 / firmware-rs9116-nonfree Ā· GitLab
I captured /var/log/messages (FreeBSD) and /var/log/syslog (PureOS) of the relevant time window and attached them to the issue. The interesting parts are:
FreeBSD:
$ grep 'Trying to associate with 88:da:1a:7c:30:1c' messages.1
May 18 20:29:38 c720-1400094 wpa_supplicant[329]: wlan0: Trying to associate with 88:da:1a:7c:30:1c (SSID='pureos' freq=2412 MHz)
May 18 20:29:53 c720-1400094 wpa_supplicant[329]: wlan0: Trying to associate with 88:da:1a:7c:30:1c (SSID='pureos' freq=2412 MHz)
May 18 20:30:38 c720-1400094 wpa_supplicant[329]: wlan0: Trying to associate with 88:da:1a:7c:30:1c (SSID='pureos' freq=2412 MHz)
PureOS:
$ grep 'Started Wi-Fi' syslog
May 18 20:28:37 pureos NetworkManager[600]: <info> [1716056917.7965] device (wlan0): Activation: (wifi) Stage 2 of 5 (Device Configure) successful. Started Wi-Fi Hotspot "pureos"
May 18 20:29:06 pureos NetworkManager[600]: <info> [1716056946.7785] device (wlan0): Activation: (wifi) Stage 2 of 5 (Device Configure) successful. Started Wi-Fi Hotspot "pureos"
May 18 20:30:20 pureos NetworkManager[600]: <info> [1716057020.5766] device (wlan0): Activation: (wifi) Stage 2 of 5 (Device Configure) successful. Started Wi-Fi Hotspot "pureos"
I.e. PureOSā NetworkManager started three times the hotspot and only with the 3rd time FreeBSD could associate succsessful.
Did you do: change the operation mode to dev_oper_mode=14?
I still have dev_oper_mode=5:
$ cat /etc/modprobe.d/librem5-devkit.conf | grep dev_oper_mode
options rsi_sdio dev_oper_mode=5
options redpine_91x dev_oper_mode=5 rsi_zone_enabled=1 antenna_diversity=1 wlan_rf_power_mode=0x00
I have the same values like you.
Here is a link to the meaning of the dev_oper_mode.
Snippet from that file:
5 - Wi-Fi station + BT classic mode
...
14 - Wi-Fi AP + BT dual mode
But, I do want to use my L5 mostly in station mode and sometimes (once a night) in AP mode.
Is there somewhere an exact technical explanation about what the different config values in the driver(?) mean?
Maybe itās not a bug in the kernel, but in the GUI of settings. I have here a case from yesterday evening: I started hotspot exact at 20:51:00 and from my feeling at 20:51:02 the GUI jumped back to a page āNo WLAN adapterā. There is nothing as error visible between 20:51:00 and 20:51:06, at 20:51:06 I toggled the WLAN kill switch to bring back the interface WLAN:
May 20 20:50:57 pureos wpa_supplicant[650]: wlan0: Reject scan trigger since one is already pending
May 20 20:51:00 pureos NetworkManager[600]: <info> [1716231060.6046] audit: op="connection-update" uuid="6fe12c3f-01b3-4584-a633-81c867e81356" name="Hotspot" args="connection.timestamp" pid=8086 uid=1000 result="success"
May 20 20:51:00 pureos NetworkManager[600]: <info> [1716231060.6432] device (wlan0): Activation: starting connection 'Hotspot' (6fe12c3f-01b3-4584-a633-81c867e81356)
May 20 20:51:00 pureos NetworkManager[600]: <info> [1716231060.6435] audit: op="connection-activate" uuid="6fe12c3f-01b3-4584-a633-81c867e81356" name="Hotspot" pid=8086 uid=1000 result="success"
May 20 20:51:00 pureos NetworkManager[600]: <info> [1716231060.6439] device (wlan0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
May 20 20:51:00 pureos kernel: [119859.009118] redpine_91x: <==== Interface DOWN ====>
May 20 20:51:00 pureos kernel: [119859.011620] redpine_91x: <==== Interface UP ====>
May 20 20:51:00 pureos kernel: [119859.013205] redpine_91x: rsi_mac80211_bss_info_changed: Change of ERP INFO: 0
May 20 20:51:00 pureos kernel: [119859.013229] redpine_91x: rsi_mac80211_bss_info_changed: Sending vap updates....
May 20 20:51:00 pureos NetworkManager[600]: <info> [1716231060.6909] device (wlan0): set-hw-addr: reset MAC address to 88:DA:1A:7C:30:1C (preserve)
May 20 20:51:00 pureos systemd-networkd[398]: wlan0: Link DOWN
May 20 20:51:00 pureos systemd-networkd[398]: wlan0: Link UP
May 20 20:51:00 pureos NetworkManager[600]: <info> [1716231060.6991] device (wlan0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
May 20 20:51:00 pureos NetworkManager[600]: <info> [1716231060.7091] device (wlan0): Activation: (wifi) access point 'Hotspot' has security, but secrets are required.
May 20 20:51:00 pureos NetworkManager[600]: <info> [1716231060.7093] device (wlan0): state change: config -> need-auth (reason 'none', sys-iface-state: 'managed')
May 20 20:51:00 pureos NetworkManager[600]: <info> [1716231060.7292] device (wlan0): state change: need-auth -> prepare (reason 'none', sys-iface-state: 'managed')
May 20 20:51:00 pureos NetworkManager[600]: <info> [1716231060.7396] device (wlan0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
May 20 20:51:00 pureos NetworkManager[600]: <info> [1716231060.7413] device (wlan0): Activation: (wifi) connection 'Hotspot' has security, and secrets exist. No new secrets needed.
May 20 20:51:00 pureos NetworkManager[600]: <info> [1716231060.7418] Config: added 'ssid' value 'pureos'
May 20 20:51:00 pureos NetworkManager[600]: <info> [1716231060.7419] Config: added 'mode' value '2'
May 20 20:51:00 pureos NetworkManager[600]: <info> [1716231060.7419] Config: added 'frequency' value '2412'
May 20 20:51:00 pureos NetworkManager[600]: <info> [1716231060.7420] Config: added 'key_mgmt' value 'WPA-PSK'
May 20 20:51:00 pureos NetworkManager[600]: <info> [1716231060.7420] Config: added 'psk' value '<hidden>'
May 20 20:51:00 pureos NetworkManager[600]: <info> [1716231060.7421] Config: added 'proto' value 'RSN'
May 20 20:51:00 pureos NetworkManager[600]: <info> [1716231060.7421] Config: added 'pairwise' value 'CCMP'
May 20 20:51:00 pureos NetworkManager[600]: <info> [1716231060.7421] Config: added 'group' value 'CCMP'
May 20 20:51:00 pureos wpa_supplicant[650]: Note: nl80211 driver interface is not designed to be used with ap_scan=2; this can result in connection failures
May 20 20:51:00 pureos NetworkManager[600]: <info> [1716231060.7814] device (wlan0): supplicant interface state: disconnected -> inactive
May 20 20:51:00 pureos NetworkManager[600]: <info> [1716231060.7815] device (p2p-dev-wlan0): supplicant management interface state: disconnected -> inactive
May 20 20:51:00 pureos wpa_supplicant[650]: Using interface wlan0 with hwaddr 88:da:1a:7c:30:1c and ssid "pureos"
May 20 20:51:00 pureos kernel: [119859.129102] redpine_91x: rsi_mac80211_bss_info_changed: Change of ERP INFO: 0
May 20 20:51:00 pureos kernel: [119859.129124] redpine_91x: rsi_mac80211_bss_info_changed: Sending vap updates....
May 20 20:51:00 pureos kernel: [119859.130175] redpine_91x: rsi_interrupt_handler: ==> FIRMWARE Assert <==
May 20 20:51:00 pureos kernel: [119859.130213] redpine_91x: rsi_interrupt_handler: Firmware Status is 0xa4
May 20 20:51:00 pureos kernel: [119859.133826] redpine_91x: rsi_core_xmit: FSM state not open
May 20 20:51:00 pureos kernel: [119859.133864] redpine_91x: rsi_core_xmit: Failed to queue packet
May 20 20:51:00 pureos systemd-networkd[398]: wlan0: Gained carrier
May 20 20:51:00 pureos wpa_supplicant[650]: wlan0: interface state UNINITIALIZED->ENABLED
May 20 20:51:00 pureos wpa_supplicant[650]: wlan0: AP-ENABLED
May 20 20:51:00 pureos wpa_supplicant[650]: wlan0: CTRL-EVENT-CONNECTED - Connection to 88:da:1a:7c:30:1c completed [id=0 id_str=]
May 20 20:51:00 pureos NetworkManager[600]: <info> [1716231060.8429] device (wlan0): supplicant interface state: inactive -> completed
May 20 20:51:00 pureos NetworkManager[600]: <info> [1716231060.8430] device (wlan0): Activation: (wifi) Stage 2 of 5 (Device Configure) successful. Started Wi-Fi Hotspot "pureos"
May 20 20:51:00 pureos NetworkManager[600]: <info> [1716231060.8431] device (p2p-dev-wlan0): supplicant management interface state: inactive -> completed
May 20 20:51:00 pureos NetworkManager[600]: <info> [1716231060.8435] device (wlan0): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
May 20 20:51:00 pureos avahi-daemon[595]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::2eaa:7213:dd1a:76c7.
May 20 20:51:00 pureos avahi-daemon[595]: New relevant interface wlan0.IPv6 for mDNS.
May 20 20:51:00 pureos avahi-daemon[595]: Registering new address record for fe80::2eaa:7213:dd1a:76c7 on wlan0.*.
May 20 20:51:00 pureos avahi-daemon[595]: Joining mDNS multicast group on interface wlan0.IPv4 with address 10.42.0.1.
May 20 20:51:00 pureos avahi-daemon[595]: New relevant interface wlan0.IPv4 for mDNS.
May 20 20:51:00 pureos avahi-daemon[595]: Registering new address record for 10.42.0.1 on wlan0.IPv4.
May 20 20:51:00 pureos NetworkManager[600]: <info> [1716231060.9511] Executing: /usr/sbin/iptables --table filter --insert INPUT --in-interface wlan0 --protocol tcp --destination-port 53 --jump ACCEPT
May 20 20:51:00 pureos NetworkManager[600]: <info> [1716231060.9645] Executing: /usr/sbin/iptables --table filter --insert INPUT --in-interface wlan0 --protocol udp --destination-port 53 --jump ACCEPT
May 20 20:51:00 pureos NetworkManager[600]: <info> [1716231060.9741] Executing: /usr/sbin/iptables --table filter --insert INPUT --in-interface wlan0 --protocol tcp --destination-port 67 --jump ACCEPT
May 20 20:51:00 pureos NetworkManager[600]: <info> [1716231060.9864] Executing: /usr/sbin/iptables --table filter --insert INPUT --in-interface wlan0 --protocol udp --destination-port 67 --jump ACCEPT
May 20 20:51:00 pureos NetworkManager[600]: <info> [1716231060.9961] Executing: /usr/sbin/iptables --table filter --insert FORWARD --in-interface wlan0 --jump REJECT
May 20 20:51:01 pureos NetworkManager[600]: <info> [1716231061.0085] Executing: /usr/sbin/iptables --table filter --insert FORWARD --out-interface wlan0 --jump REJECT
May 20 20:51:01 pureos NetworkManager[600]: <info> [1716231061.0174] Executing: /usr/sbin/iptables --table filter --insert FORWARD --in-interface wlan0 --out-interface wlan0 --jump ACCEPT
May 20 20:51:01 pureos NetworkManager[600]: <info> [1716231061.0296] Executing: /usr/sbin/iptables --table filter --insert FORWARD --source 10.42.0.0/255.255.255.0 --in-interface wlan0 --jump ACCEPT
May 20 20:51:01 pureos NetworkManager[600]: <info> [1716231061.0378] Executing: /usr/sbin/iptables --table filter --insert FORWARD --destination 10.42.0.0/255.255.255.0 --out-interface wlan0 --match state --state ESTABLISHED,RELATED --jump ACCEPT
May 20 20:51:01 pureos NetworkManager[600]: <info> [1716231061.0469] Executing: /usr/sbin/iptables --table nat --insert POSTROUTING --source 10.42.0.0/255.255.255.0 ! --destination 10.42.0.0/255.255.255.0 --jump MASQUERADE
May 20 20:51:01 pureos NetworkManager[600]: <info> [1716231061.0582] dnsmasq-manager: starting dnsmasq...
May 20 20:51:01 pureos NetworkManager[600]: <info> [1716231061.0640] device (wlan0): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
May 20 20:51:01 pureos dbus-daemon[597]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.9' (uid=0 pid=600 comm="/usr/sbin/NetworkManager --no-daemon ")
May 20 20:51:01 pureos dnsmasq[30313]: started, version 2.85 cachesize 150
May 20 20:51:01 pureos dnsmasq[30313]: compile time options: IPv6 GNU-getopt DBus no-UBus i18n IDN2 DHCP DHCPv6 no-Lua TFTP conntrack ipset auth cryptohash DNSSEC loop-detect inotify dumpfile
May 20 20:51:01 pureos dnsmasq[30313]: chown of PID file /run/nm-dnsmasq-wlan0.pid failed: Operation not permitted
May 20 20:51:01 pureos dnsmasq-dhcp[30313]: DHCP, IP range 10.42.0.10 -- 10.42.0.254, lease time 1h
May 20 20:51:01 pureos dnsmasq[30313]: reading /etc/resolv.conf
May 20 20:51:01 pureos dnsmasq[30313]: using nameserver 2a02:3018:0:40ff::aaaa#53
May 20 20:51:01 pureos dnsmasq[30313]: using nameserver 2a02:3018:0:40ff::bbbb#53
May 20 20:51:01 pureos dnsmasq[30313]: cleared cache
May 20 20:51:01 pureos systemd[1]: Starting Network Manager Script Dispatcher Service...
May 20 20:51:01 pureos dbus-daemon[597]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
May 20 20:51:01 pureos systemd[1]: Started Network Manager Script Dispatcher Service.
May 20 20:51:01 pureos NetworkManager[600]: <info> [1716231061.1472] device (wlan0): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
May 20 20:51:01 pureos NetworkManager[600]: <info> [1716231061.1481] device (wlan0): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
May 20 20:51:01 pureos NetworkManager[600]: <info> [1716231061.1541] device (wlan0): Activation: successful, device activated.
May 20 20:51:02 pureos systemd-networkd[398]: wlan0: Gained IPv6LL
May 20 20:51:06 pureos wpa_supplicant[650]: rfkill: WLAN hard blocked
May 20 20:51:06 pureos kernel: [119864.534976] redpine_91x: <==== Interface DOWN ====>
May 20 20:51:06 pureos NetworkManager[600]: <info> [1716231066.1911] manager: rfkill: Wi-Fi now disabled by radio killswitch
I searched the web how to get more debug log for gnome-control-center and did this modification:
purism@pureos:~$ grep 'Exec=' /usr/share/applications/gnome-control-center.desktop
# Exec=gnome-control-center
Exec=/home/purism/gnome-control-center
purism@pureos:~$ cat /home/purism/gnome-control-center
#!/bin/sh
export G_MESSAGES_DEBUG=all
/usr/bin/gnome-control-center
This gives tons of log lines in journal:
purism@pureos:~$ sudo journalctl --since -10m | grep gnome-control-c
May 21 13:46:29 pureos gnome-control-c[10269]: Initializing object storage
May 21 13:46:29 pureos gnome-control-c[10269]: _g_io_module_get_default: Found default implementation gvfs (GDaemonVfs) for āgio-vfsā
May 21 13:46:29 pureos gnome-control-c[10269]: gtk_style_context_add_provider_for_screen: assertion 'GDK_IS_SCREEN (screen)' failed
May 21 13:46:29 pureos gnome-control-c[10269]: _g_io_module_get_default: Found default implementation dconf (DConfSettingsBackend) for āgsettings-backendā
...
I moved on May 30 to a new L5 with a SparkWLAN Wifi card. Since then the hotspot does not fall back again to normal Wifi. See here for other observations related to this change: FOSDEM 2024 talk by Sebastian Krzyszkowiak about USB suspend/resume bug affecting Librem 5 - #29 by guru