* disconnects when in AP mode
@ 2023-12-28 18:19 KeithG
2023-12-28 18:42 ` KeithG
0 siblings, 1 reply; 6+ messages in thread
From: KeithG @ 2023-12-28 18:19 UTC (permalink / raw)
To: iwd
Group,
I finally gave up on getting connman to manage scanning when iwd is in
AP mode. What I have done is listen to James who posted this a long
time ago and I just finally figured out what he was saying.
I am doing what is outlined here:
https://lore.kernel.org/linux-wireless/87k0dhdg0d.fsf@bang-olufsen.dk/
I am running this on RPis all with the brcmfmac adapters. I can get it
all working, but when connected to the RPi on its advertised AP, I can
get a connection for a bit then it disconnects, requiring a reconnect.
I am running a freshly built iwd version 2.11 with ell 0.61 on RPiOS
fully up to date on Bookworm
I get tons of this in the log: "wiphy_estimate_data_rate() failed" and
a few others but it does not seem like this is what triggers it to
disconnect. I have not been able to pinpoint anything in the log where
it disconnects.
Any help appreciated.
# uname -a
Linux runeaudio 6.1.0-rpi7-rpi-v8 #1 SMP PREEMPT Debian
1:6.1.63-1+rpt1 (2023-11-24) aarch64 GNU/Linux
this is what shows at bootup
Dec 28 11:50:45 runeaudio kernel: brcmfmac: F1 signature read
@0x18000000=0x15264345
Dec 28 11:50:45 runeaudio kernel: brcmfmac: brcmf_fw_alloc_request:
using brcm/brcmfmac43455-sdio for chip BCM4345/6
Dec 28 11:50:45 runeaudio kernel: usbcore: registered new interface
driver brcmfmac
Dec 28 11:50:45 runeaudio kernel: Bluetooth: hci0: BCM4345C0
'brcm/BCM4345C0.raspberrypi,3-model-b-plus.hcd' Patch
Dec 28 11:50:45 runeaudio kernel: brcmfmac: brcmf_c_preinit_dcmds:
Firmware: BCM4345/6 wl0: Nov 1 2021 00:37:25 version 7.45.241
(1a2f2fa CY) FWID 01-703fd60
Dec 28 11:50:48 runeaudio kernel: brcmfmac:
brcmf_cfg80211_set_power_mgmt: power save enabled
Dec 28 11:50:55 runeaudio kernel: brcmfmac:
brcmf_cfg80211_set_power_mgmt: power save disabled
Dec 28 11:51:30 runeaudio kernel: brcmfmac:
brcmf_cfg80211_set_power_mgmt: power save disabled
Dec 28 11:51:31 runeaudio kernel: brcmfmac:
brcmf_cfg80211_set_power_mgmt: power save disabled
Dec 28 11:51:40 runeaudio kernel: ieee80211 phy0: brcmf_escan_timeout:
timer expired
I get this in the log:
Dec 28 11:51:30 runeaudio iwd[1306]: No Diffie-Hellman support found,
WPS will not be available
Dec 28 11:51:30 runeaudio iwd[1306]: The following options are missing
in the kernel:
Dec 28 11:51:30 runeaudio iwd[1306]: CONFIG_KEY_DH_OPERATIONS
Dec 28 11:51:30 runeaudio iwd[1306]: Wireless daemon version 2.11
Dec 28 11:51:30 runeaudio iwd[1306]: Loaded configuration from
/etc/iwd/main.conf
Dec 28 11:51:30 runeaudio systemd[1]: Started iwd.service - Wireless service.
Dec 28 11:51:30 runeaudio iwd[1306]: Wiphy: 0, Name: phy0
Dec 28 11:51:30 runeaudio iwd[1306]: Permanent Address:
b8:27:eb:52:cc:d0
Dec 28 11:51:30 runeaudio iwd[1306]: 2.4GHz Band:
Dec 28 11:51:30 runeaudio iwd[1306]: Bitrates (non-HT):
Dec 28 11:51:30 runeaudio iwd[1306]: 1.0 Mbps
Dec 28 11:51:30 runeaudio iwd[1306]: 2.0 Mbps
Dec 28 11:51:30 runeaudio iwd[1306]: 5.5 Mbps
Dec 28 11:51:30 runeaudio iwd[1306]: 11.0 Mbps
Dec 28 11:51:30 runeaudio iwd[1306]: 6.0 Mbps
Dec 28 11:51:30 runeaudio iwd[1306]: 9.0 Mbps
Dec 28 11:51:30 runeaudio iwd[1306]: 12.0 Mbps
Dec 28 11:51:30 runeaudio iwd[1306]: 18.0 Mbps
Dec 28 11:51:30 runeaudio iwd[1306]: 24.0 Mbps
Dec 28 11:51:30 runeaudio iwd[1306]: 36.0 Mbps
Dec 28 11:51:30 runeaudio iwd[1306]: 48.0 Mbps
Dec 28 11:51:30 runeaudio iwd[1306]: 54.0 Mbps
Dec 28 11:51:30 runeaudio iwd[1306]: HT Capabilities:
Dec 28 11:51:30 runeaudio iwd[1306]: HT40
Dec 28 11:51:30 runeaudio iwd[1306]: Short GI for 20Mhz
Dec 28 11:51:30 runeaudio iwd[1306]: HT RX MCS indexes:
Dec 28 11:51:30 runeaudio iwd[1306]: 0-7
Dec 28 11:51:30 runeaudio iwd[1306]: 5GHz Band:
Dec 28 11:51:30 runeaudio iwd[1306]: Bitrates (non-HT):
Dec 28 11:51:30 runeaudio iwd[1306]: 6.0 Mbps
Dec 28 11:51:30 runeaudio iwd[1306]: 9.0 Mbps
Dec 28 11:51:30 runeaudio iwd[1306]: 12.0 Mbps
Dec 28 11:51:30 runeaudio iwd[1306]: 18.0 Mbps
Dec 28 11:51:30 runeaudio iwd[1306]: 24.0 Mbps
Dec 28 11:51:30 runeaudio iwd[1306]: 36.0 Mbps
Dec 28 11:51:30 runeaudio iwd[1306]: 48.0 Mbps
Dec 28 11:51:30 runeaudio iwd[1306]: 54.0 Mbps
Dec 28 11:51:30 runeaudio iwd[1306]: HT Capabilities:
Dec 28 11:51:30 runeaudio iwd[1306]: HT40
Dec 28 11:51:30 runeaudio iwd[1306]: Short GI for 20Mhz
Dec 28 11:51:30 runeaudio iwd[1306]: Short GI for 40Mhz
Dec 28 11:51:30 runeaudio iwd[1306]: HT RX MCS indexes:
Dec 28 11:51:30 runeaudio iwd[1306]: 0-7
Dec 28 11:51:30 runeaudio iwd[1306]: VHT Capabilities:
Dec 28 11:51:30 runeaudio iwd[1306]: Short GI for 80Mhz
Dec 28 11:51:30 runeaudio iwd[1306]: Max RX
MCS: 0-9 for NSS: 1
Dec 28 11:51:30 runeaudio iwd[1306]: Max TX
MCS: 0-9 for NSS: 1
Dec 28 11:51:30 runeaudio iwd[1306]: Ciphers: BIP-CMAC-128 CCMP-128 TKIP
Dec 28 11:51:30 runeaudio iwd[1306]: Supported iftypes: ad-hoc
station ap p2p-client p2p-go p2p-device
Dec 28 11:51:30 runeaudio iwd[1306]: Driver Flags: DefaultInterface
Dec 28 11:51:30 runeaudio iwd[1306]: Wiphy phy0 will only use the
default interface
Dec 28 11:51:30 runeaudio iwd[1306]: Could not register frame watch
type 00b0: -22
Dec 28 11:51:46 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
Dec 28 11:51:56 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
Dec 28 11:52:22 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
Dec 28 11:52:22 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
Dec 28 11:52:29 runeaudio iwd[1306]: KEY_SEQ not returned in GET_KEY reply
Dec 28 11:52:29 runeaudio iwd[1306]: 4-Way handshake failed for
ifindex: 4, reason: 15
Dec 28 11:52:39 runeaudio iwd[1306]: KEY_SEQ not returned in GET_KEY reply
Dec 28 11:52:40 runeaudio iwd[1306]: 4-Way handshake failed for
ifindex: 4, reason: 15
Dec 28 11:52:49 runeaudio iwd[1306]: KEY_SEQ not returned in GET_KEY reply
Dec 28 11:52:49 runeaudio iwd[1306]: 4-Way handshake failed for
ifindex: 4, reason: 15
Dec 28 11:53:07 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
Dec 28 11:53:35 runeaudio iwd[1306]: KEY_SEQ not returned in GET_KEY reply
Dec 28 11:54:33 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
Dec 28 11:54:33 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: disconnects when in AP mode
2023-12-28 18:19 disconnects when in AP mode KeithG
@ 2023-12-28 18:42 ` KeithG
2023-12-29 18:53 ` KeithG
0 siblings, 1 reply; 6+ messages in thread
From: KeithG @ 2023-12-28 18:42 UTC (permalink / raw)
To: iwd
I put iwd in debug mode and this is what happens at disconnect. Maybe
better for diagnostics.
If there is something else I can do to help diagnose it, please let me know
Dec 28 12:32:37 runeaudio iwd[5127]: src/netdev.c:netdev_mlme_notify()
MLME notification Del Station(20)
Dec 28 12:32:37 runeaudio iwd[5127]: src/netdev.c:netdev_mlme_notify()
MLME notification Del Station(20)
Dec 28 12:35:13 runeaudio iwd[5127]: src/netdev.c:netdev_mlme_notify()
MLME notification New Station(19)
Dec 28 12:35:13 runeaudio iwd[5127]: KEY_SEQ not returned in GET_KEY reply
Dec 28 12:35:13 runeaudio iwd[5127]: src/eapol.c:eapol_start()
Dec 28 12:35:13 runeaudio iwd[5127]:
src/eapol.c:eapol_send_ptk_1_of_4() STA: f0:42:1c:d7:da:e8 retries=0
Dec 28 12:35:13 runeaudio iwd[5127]:
src/eapol.c:eapol_handle_ptk_2_of_4() ifindex=4
Dec 28 12:35:13 runeaudio iwd[5127]:
src/eapol.c:eapol_send_ptk_3_of_4() STA: f0:42:1c:d7:da:e8 retries=0
Dec 28 12:35:13 runeaudio iwd[5127]:
src/eapol.c:eapol_ptk_3_of_4_retry() attempt 1
Dec 28 12:35:13 runeaudio iwd[5127]:
src/eapol.c:eapol_handle_ptk_4_of_4() ifindex=4
Dec 28 12:35:13 runeaudio iwd[5127]: src/netdev.c:netdev_set_tk()
ifindex=4 key_idx=0
Dec 28 12:35:13 runeaudio iwd[5127]: src/netdev.c:netdev_set_station_cb()
Dec 28 12:35:13 runeaudio iwd[5127]:
src/netdev.c:try_handshake_complete() ptk_installed: 1, gtk_installed:
1, igtk_installed: 1
Dec 28 12:35:13 runeaudio iwd[5127]:
src/netdev.c:try_handshake_complete() nhs->complete: 0
Dec 28 12:35:13 runeaudio iwd[5127]:
src/netdev.c:try_handshake_complete() Invoking handshake_event()
Dec 28 12:35:13 runeaudio iwd[5127]: src/ap.c:ap_new_rsna() STA
f0:42:1c:d7:da:e8 authenticated
Dec 28 12:35:55 runeaudio iwd[5127]: src/agent.c:agent_register()
agent register called
Dec 28 12:35:55 runeaudio iwd[5127]: src/agent.c:agent_register()
agent :1.566 path /agent/12001
Dec 28 12:35:55 runeaudio iwd[5127]: src/station.c:station_dbus_scan()
Scan called from DBus
Dec 28 12:35:55 runeaudio iwd[5127]:
src/wiphy.c:wiphy_radio_work_insert() Inserting work item 13
Dec 28 12:35:55 runeaudio iwd[5127]:
src/wiphy.c:wiphy_radio_work_next() Starting work item 13
On Thu, Dec 28, 2023 at 12:19 PM KeithG <ys3al35l@gmail.com> wrote:
>
> Group,
>
> I finally gave up on getting connman to manage scanning when iwd is in
> AP mode. What I have done is listen to James who posted this a long
> time ago and I just finally figured out what he was saying.
>
> I am doing what is outlined here:
> https://lore.kernel.org/linux-wireless/87k0dhdg0d.fsf@bang-olufsen.dk/
>
> I am running this on RPis all with the brcmfmac adapters. I can get it
> all working, but when connected to the RPi on its advertised AP, I can
> get a connection for a bit then it disconnects, requiring a reconnect.
> I am running a freshly built iwd version 2.11 with ell 0.61 on RPiOS
> fully up to date on Bookworm
>
> I get tons of this in the log: "wiphy_estimate_data_rate() failed" and
> a few others but it does not seem like this is what triggers it to
> disconnect. I have not been able to pinpoint anything in the log where
> it disconnects.
>
> Any help appreciated.
>
> # uname -a
> Linux runeaudio 6.1.0-rpi7-rpi-v8 #1 SMP PREEMPT Debian
> 1:6.1.63-1+rpt1 (2023-11-24) aarch64 GNU/Linux
>
> this is what shows at bootup
> Dec 28 11:50:45 runeaudio kernel: brcmfmac: F1 signature read
> @0x18000000=0x15264345
> Dec 28 11:50:45 runeaudio kernel: brcmfmac: brcmf_fw_alloc_request:
> using brcm/brcmfmac43455-sdio for chip BCM4345/6
> Dec 28 11:50:45 runeaudio kernel: usbcore: registered new interface
> driver brcmfmac
> Dec 28 11:50:45 runeaudio kernel: Bluetooth: hci0: BCM4345C0
> 'brcm/BCM4345C0.raspberrypi,3-model-b-plus.hcd' Patch
> Dec 28 11:50:45 runeaudio kernel: brcmfmac: brcmf_c_preinit_dcmds:
> Firmware: BCM4345/6 wl0: Nov 1 2021 00:37:25 version 7.45.241
> (1a2f2fa CY) FWID 01-703fd60
> Dec 28 11:50:48 runeaudio kernel: brcmfmac:
> brcmf_cfg80211_set_power_mgmt: power save enabled
> Dec 28 11:50:55 runeaudio kernel: brcmfmac:
> brcmf_cfg80211_set_power_mgmt: power save disabled
> Dec 28 11:51:30 runeaudio kernel: brcmfmac:
> brcmf_cfg80211_set_power_mgmt: power save disabled
> Dec 28 11:51:31 runeaudio kernel: brcmfmac:
> brcmf_cfg80211_set_power_mgmt: power save disabled
> Dec 28 11:51:40 runeaudio kernel: ieee80211 phy0: brcmf_escan_timeout:
> timer expired
>
> I get this in the log:
> Dec 28 11:51:30 runeaudio iwd[1306]: No Diffie-Hellman support found,
> WPS will not be available
> Dec 28 11:51:30 runeaudio iwd[1306]: The following options are missing
> in the kernel:
> Dec 28 11:51:30 runeaudio iwd[1306]: CONFIG_KEY_DH_OPERATIONS
> Dec 28 11:51:30 runeaudio iwd[1306]: Wireless daemon version 2.11
> Dec 28 11:51:30 runeaudio iwd[1306]: Loaded configuration from
> /etc/iwd/main.conf
> Dec 28 11:51:30 runeaudio systemd[1]: Started iwd.service - Wireless service.
> Dec 28 11:51:30 runeaudio iwd[1306]: Wiphy: 0, Name: phy0
> Dec 28 11:51:30 runeaudio iwd[1306]: Permanent Address:
> b8:27:eb:52:cc:d0
> Dec 28 11:51:30 runeaudio iwd[1306]: 2.4GHz Band:
> Dec 28 11:51:30 runeaudio iwd[1306]: Bitrates (non-HT):
> Dec 28 11:51:30 runeaudio iwd[1306]: 1.0 Mbps
> Dec 28 11:51:30 runeaudio iwd[1306]: 2.0 Mbps
> Dec 28 11:51:30 runeaudio iwd[1306]: 5.5 Mbps
> Dec 28 11:51:30 runeaudio iwd[1306]: 11.0 Mbps
> Dec 28 11:51:30 runeaudio iwd[1306]: 6.0 Mbps
> Dec 28 11:51:30 runeaudio iwd[1306]: 9.0 Mbps
> Dec 28 11:51:30 runeaudio iwd[1306]: 12.0 Mbps
> Dec 28 11:51:30 runeaudio iwd[1306]: 18.0 Mbps
> Dec 28 11:51:30 runeaudio iwd[1306]: 24.0 Mbps
> Dec 28 11:51:30 runeaudio iwd[1306]: 36.0 Mbps
> Dec 28 11:51:30 runeaudio iwd[1306]: 48.0 Mbps
> Dec 28 11:51:30 runeaudio iwd[1306]: 54.0 Mbps
> Dec 28 11:51:30 runeaudio iwd[1306]: HT Capabilities:
> Dec 28 11:51:30 runeaudio iwd[1306]: HT40
> Dec 28 11:51:30 runeaudio iwd[1306]: Short GI for 20Mhz
> Dec 28 11:51:30 runeaudio iwd[1306]: HT RX MCS indexes:
> Dec 28 11:51:30 runeaudio iwd[1306]: 0-7
> Dec 28 11:51:30 runeaudio iwd[1306]: 5GHz Band:
> Dec 28 11:51:30 runeaudio iwd[1306]: Bitrates (non-HT):
> Dec 28 11:51:30 runeaudio iwd[1306]: 6.0 Mbps
> Dec 28 11:51:30 runeaudio iwd[1306]: 9.0 Mbps
> Dec 28 11:51:30 runeaudio iwd[1306]: 12.0 Mbps
> Dec 28 11:51:30 runeaudio iwd[1306]: 18.0 Mbps
> Dec 28 11:51:30 runeaudio iwd[1306]: 24.0 Mbps
> Dec 28 11:51:30 runeaudio iwd[1306]: 36.0 Mbps
> Dec 28 11:51:30 runeaudio iwd[1306]: 48.0 Mbps
> Dec 28 11:51:30 runeaudio iwd[1306]: 54.0 Mbps
> Dec 28 11:51:30 runeaudio iwd[1306]: HT Capabilities:
> Dec 28 11:51:30 runeaudio iwd[1306]: HT40
> Dec 28 11:51:30 runeaudio iwd[1306]: Short GI for 20Mhz
> Dec 28 11:51:30 runeaudio iwd[1306]: Short GI for 40Mhz
> Dec 28 11:51:30 runeaudio iwd[1306]: HT RX MCS indexes:
> Dec 28 11:51:30 runeaudio iwd[1306]: 0-7
> Dec 28 11:51:30 runeaudio iwd[1306]: VHT Capabilities:
> Dec 28 11:51:30 runeaudio iwd[1306]: Short GI for 80Mhz
> Dec 28 11:51:30 runeaudio iwd[1306]: Max RX
> MCS: 0-9 for NSS: 1
> Dec 28 11:51:30 runeaudio iwd[1306]: Max TX
> MCS: 0-9 for NSS: 1
> Dec 28 11:51:30 runeaudio iwd[1306]: Ciphers: BIP-CMAC-128 CCMP-128 TKIP
> Dec 28 11:51:30 runeaudio iwd[1306]: Supported iftypes: ad-hoc
> station ap p2p-client p2p-go p2p-device
> Dec 28 11:51:30 runeaudio iwd[1306]: Driver Flags: DefaultInterface
> Dec 28 11:51:30 runeaudio iwd[1306]: Wiphy phy0 will only use the
> default interface
> Dec 28 11:51:30 runeaudio iwd[1306]: Could not register frame watch
> type 00b0: -22
> Dec 28 11:51:46 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
> Dec 28 11:51:56 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
> Dec 28 11:52:22 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
> Dec 28 11:52:22 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
> Dec 28 11:52:29 runeaudio iwd[1306]: KEY_SEQ not returned in GET_KEY reply
> Dec 28 11:52:29 runeaudio iwd[1306]: 4-Way handshake failed for
> ifindex: 4, reason: 15
> Dec 28 11:52:39 runeaudio iwd[1306]: KEY_SEQ not returned in GET_KEY reply
> Dec 28 11:52:40 runeaudio iwd[1306]: 4-Way handshake failed for
> ifindex: 4, reason: 15
> Dec 28 11:52:49 runeaudio iwd[1306]: KEY_SEQ not returned in GET_KEY reply
> Dec 28 11:52:49 runeaudio iwd[1306]: 4-Way handshake failed for
> ifindex: 4, reason: 15
> Dec 28 11:53:07 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
> Dec 28 11:53:35 runeaudio iwd[1306]: KEY_SEQ not returned in GET_KEY reply
> Dec 28 11:54:33 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
> Dec 28 11:54:33 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: disconnects when in AP mode
2023-12-28 18:42 ` KeithG
@ 2023-12-29 18:53 ` KeithG
2023-12-29 22:16 ` James Prestwood
2023-12-29 22:17 ` KeithG
0 siblings, 2 replies; 6+ messages in thread
From: KeithG @ 2023-12-29 18:53 UTC (permalink / raw)
To: iwd
On Thu, Dec 28, 2023 at 12:42 PM KeithG <ys3al35l@gmail.com> wrote:
>
> I put iwd in debug mode and this is what happens at disconnect. Maybe
> better for diagnostics.
> If there is something else I can do to help diagnose it, please let me know
>
> Dec 28 12:32:37 runeaudio iwd[5127]: src/netdev.c:netdev_mlme_notify()
> MLME notification Del Station(20)
> Dec 28 12:32:37 runeaudio iwd[5127]: src/netdev.c:netdev_mlme_notify()
> MLME notification Del Station(20)
> Dec 28 12:35:13 runeaudio iwd[5127]: src/netdev.c:netdev_mlme_notify()
> MLME notification New Station(19)
> Dec 28 12:35:13 runeaudio iwd[5127]: KEY_SEQ not returned in GET_KEY reply
> Dec 28 12:35:13 runeaudio iwd[5127]: src/eapol.c:eapol_start()
> Dec 28 12:35:13 runeaudio iwd[5127]:
> src/eapol.c:eapol_send_ptk_1_of_4() STA: f0:42:1c:d7:da:e8 retries=0
> Dec 28 12:35:13 runeaudio iwd[5127]:
> src/eapol.c:eapol_handle_ptk_2_of_4() ifindex=4
> Dec 28 12:35:13 runeaudio iwd[5127]:
> src/eapol.c:eapol_send_ptk_3_of_4() STA: f0:42:1c:d7:da:e8 retries=0
> Dec 28 12:35:13 runeaudio iwd[5127]:
> src/eapol.c:eapol_ptk_3_of_4_retry() attempt 1
> Dec 28 12:35:13 runeaudio iwd[5127]:
> src/eapol.c:eapol_handle_ptk_4_of_4() ifindex=4
> Dec 28 12:35:13 runeaudio iwd[5127]: src/netdev.c:netdev_set_tk()
> ifindex=4 key_idx=0
> Dec 28 12:35:13 runeaudio iwd[5127]: src/netdev.c:netdev_set_station_cb()
> Dec 28 12:35:13 runeaudio iwd[5127]:
> src/netdev.c:try_handshake_complete() ptk_installed: 1, gtk_installed:
> 1, igtk_installed: 1
> Dec 28 12:35:13 runeaudio iwd[5127]:
> src/netdev.c:try_handshake_complete() nhs->complete: 0
> Dec 28 12:35:13 runeaudio iwd[5127]:
> src/netdev.c:try_handshake_complete() Invoking handshake_event()
> Dec 28 12:35:13 runeaudio iwd[5127]: src/ap.c:ap_new_rsna() STA
> f0:42:1c:d7:da:e8 authenticated
> Dec 28 12:35:55 runeaudio iwd[5127]: src/agent.c:agent_register()
> agent register called
> Dec 28 12:35:55 runeaudio iwd[5127]: src/agent.c:agent_register()
> agent :1.566 path /agent/12001
> Dec 28 12:35:55 runeaudio iwd[5127]: src/station.c:station_dbus_scan()
> Scan called from DBus
> Dec 28 12:35:55 runeaudio iwd[5127]:
> src/wiphy.c:wiphy_radio_work_insert() Inserting work item 13
> Dec 28 12:35:55 runeaudio iwd[5127]:
> src/wiphy.c:wiphy_radio_work_next() Starting work item 13
>
> On Thu, Dec 28, 2023 at 12:19 PM KeithG <ys3al35l@gmail.com> wrote:
> >
> > Group,
> >
> > I finally gave up on getting connman to manage scanning when iwd is in
> > AP mode. What I have done is listen to James who posted this a long
> > time ago and I just finally figured out what he was saying.
> >
> > I am doing what is outlined here:
> > https://lore.kernel.org/linux-wireless/87k0dhdg0d.fsf@bang-olufsen.dk/
> >
> > I am running this on RPis all with the brcmfmac adapters. I can get it
> > all working, but when connected to the RPi on its advertised AP, I can
> > get a connection for a bit then it disconnects, requiring a reconnect.
> > I am running a freshly built iwd version 2.11 with ell 0.61 on RPiOS
> > fully up to date on Bookworm
> >
> > I get tons of this in the log: "wiphy_estimate_data_rate() failed" and
> > a few others but it does not seem like this is what triggers it to
> > disconnect. I have not been able to pinpoint anything in the log where
> > it disconnects.
> >
> > Any help appreciated.
> >
> > # uname -a
> > Linux runeaudio 6.1.0-rpi7-rpi-v8 #1 SMP PREEMPT Debian
> > 1:6.1.63-1+rpt1 (2023-11-24) aarch64 GNU/Linux
> >
> > this is what shows at bootup
> > Dec 28 11:50:45 runeaudio kernel: brcmfmac: F1 signature read
> > @0x18000000=0x15264345
> > Dec 28 11:50:45 runeaudio kernel: brcmfmac: brcmf_fw_alloc_request:
> > using brcm/brcmfmac43455-sdio for chip BCM4345/6
> > Dec 28 11:50:45 runeaudio kernel: usbcore: registered new interface
> > driver brcmfmac
> > Dec 28 11:50:45 runeaudio kernel: Bluetooth: hci0: BCM4345C0
> > 'brcm/BCM4345C0.raspberrypi,3-model-b-plus.hcd' Patch
> > Dec 28 11:50:45 runeaudio kernel: brcmfmac: brcmf_c_preinit_dcmds:
> > Firmware: BCM4345/6 wl0: Nov 1 2021 00:37:25 version 7.45.241
> > (1a2f2fa CY) FWID 01-703fd60
> > Dec 28 11:50:48 runeaudio kernel: brcmfmac:
> > brcmf_cfg80211_set_power_mgmt: power save enabled
> > Dec 28 11:50:55 runeaudio kernel: brcmfmac:
> > brcmf_cfg80211_set_power_mgmt: power save disabled
> > Dec 28 11:51:30 runeaudio kernel: brcmfmac:
> > brcmf_cfg80211_set_power_mgmt: power save disabled
> > Dec 28 11:51:31 runeaudio kernel: brcmfmac:
> > brcmf_cfg80211_set_power_mgmt: power save disabled
> > Dec 28 11:51:40 runeaudio kernel: ieee80211 phy0: brcmf_escan_timeout:
> > timer expired
> >
> > I get this in the log:
> > Dec 28 11:51:30 runeaudio iwd[1306]: No Diffie-Hellman support found,
> > WPS will not be available
> > Dec 28 11:51:30 runeaudio iwd[1306]: The following options are missing
> > in the kernel:
> > Dec 28 11:51:30 runeaudio iwd[1306]: CONFIG_KEY_DH_OPERATIONS
> > Dec 28 11:51:30 runeaudio iwd[1306]: Wireless daemon version 2.11
> > Dec 28 11:51:30 runeaudio iwd[1306]: Loaded configuration from
> > /etc/iwd/main.conf
> > Dec 28 11:51:30 runeaudio systemd[1]: Started iwd.service - Wireless service.
> > Dec 28 11:51:30 runeaudio iwd[1306]: Wiphy: 0, Name: phy0
> > Dec 28 11:51:30 runeaudio iwd[1306]: Permanent Address:
> > b8:27:eb:52:cc:d0
> > Dec 28 11:51:30 runeaudio iwd[1306]: 2.4GHz Band:
> > Dec 28 11:51:30 runeaudio iwd[1306]: Bitrates (non-HT):
> > Dec 28 11:51:30 runeaudio iwd[1306]: 1.0 Mbps
> > Dec 28 11:51:30 runeaudio iwd[1306]: 2.0 Mbps
> > Dec 28 11:51:30 runeaudio iwd[1306]: 5.5 Mbps
> > Dec 28 11:51:30 runeaudio iwd[1306]: 11.0 Mbps
> > Dec 28 11:51:30 runeaudio iwd[1306]: 6.0 Mbps
> > Dec 28 11:51:30 runeaudio iwd[1306]: 9.0 Mbps
> > Dec 28 11:51:30 runeaudio iwd[1306]: 12.0 Mbps
> > Dec 28 11:51:30 runeaudio iwd[1306]: 18.0 Mbps
> > Dec 28 11:51:30 runeaudio iwd[1306]: 24.0 Mbps
> > Dec 28 11:51:30 runeaudio iwd[1306]: 36.0 Mbps
> > Dec 28 11:51:30 runeaudio iwd[1306]: 48.0 Mbps
> > Dec 28 11:51:30 runeaudio iwd[1306]: 54.0 Mbps
> > Dec 28 11:51:30 runeaudio iwd[1306]: HT Capabilities:
> > Dec 28 11:51:30 runeaudio iwd[1306]: HT40
> > Dec 28 11:51:30 runeaudio iwd[1306]: Short GI for 20Mhz
> > Dec 28 11:51:30 runeaudio iwd[1306]: HT RX MCS indexes:
> > Dec 28 11:51:30 runeaudio iwd[1306]: 0-7
> > Dec 28 11:51:30 runeaudio iwd[1306]: 5GHz Band:
> > Dec 28 11:51:30 runeaudio iwd[1306]: Bitrates (non-HT):
> > Dec 28 11:51:30 runeaudio iwd[1306]: 6.0 Mbps
> > Dec 28 11:51:30 runeaudio iwd[1306]: 9.0 Mbps
> > Dec 28 11:51:30 runeaudio iwd[1306]: 12.0 Mbps
> > Dec 28 11:51:30 runeaudio iwd[1306]: 18.0 Mbps
> > Dec 28 11:51:30 runeaudio iwd[1306]: 24.0 Mbps
> > Dec 28 11:51:30 runeaudio iwd[1306]: 36.0 Mbps
> > Dec 28 11:51:30 runeaudio iwd[1306]: 48.0 Mbps
> > Dec 28 11:51:30 runeaudio iwd[1306]: 54.0 Mbps
> > Dec 28 11:51:30 runeaudio iwd[1306]: HT Capabilities:
> > Dec 28 11:51:30 runeaudio iwd[1306]: HT40
> > Dec 28 11:51:30 runeaudio iwd[1306]: Short GI for 20Mhz
> > Dec 28 11:51:30 runeaudio iwd[1306]: Short GI for 40Mhz
> > Dec 28 11:51:30 runeaudio iwd[1306]: HT RX MCS indexes:
> > Dec 28 11:51:30 runeaudio iwd[1306]: 0-7
> > Dec 28 11:51:30 runeaudio iwd[1306]: VHT Capabilities:
> > Dec 28 11:51:30 runeaudio iwd[1306]: Short GI for 80Mhz
> > Dec 28 11:51:30 runeaudio iwd[1306]: Max RX
> > MCS: 0-9 for NSS: 1
> > Dec 28 11:51:30 runeaudio iwd[1306]: Max TX
> > MCS: 0-9 for NSS: 1
> > Dec 28 11:51:30 runeaudio iwd[1306]: Ciphers: BIP-CMAC-128 CCMP-128 TKIP
> > Dec 28 11:51:30 runeaudio iwd[1306]: Supported iftypes: ad-hoc
> > station ap p2p-client p2p-go p2p-device
> > Dec 28 11:51:30 runeaudio iwd[1306]: Driver Flags: DefaultInterface
> > Dec 28 11:51:30 runeaudio iwd[1306]: Wiphy phy0 will only use the
> > default interface
> > Dec 28 11:51:30 runeaudio iwd[1306]: Could not register frame watch
> > type 00b0: -22
> > Dec 28 11:51:46 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
> > Dec 28 11:51:56 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
> > Dec 28 11:52:22 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
> > Dec 28 11:52:22 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
> > Dec 28 11:52:29 runeaudio iwd[1306]: KEY_SEQ not returned in GET_KEY reply
> > Dec 28 11:52:29 runeaudio iwd[1306]: 4-Way handshake failed for
> > ifindex: 4, reason: 15
> > Dec 28 11:52:39 runeaudio iwd[1306]: KEY_SEQ not returned in GET_KEY reply
> > Dec 28 11:52:40 runeaudio iwd[1306]: 4-Way handshake failed for
> > ifindex: 4, reason: 15
> > Dec 28 11:52:49 runeaudio iwd[1306]: KEY_SEQ not returned in GET_KEY reply
> > Dec 28 11:52:49 runeaudio iwd[1306]: 4-Way handshake failed for
> > ifindex: 4, reason: 15
> > Dec 28 11:53:07 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
> > Dec 28 11:53:35 runeaudio iwd[1306]: KEY_SEQ not returned in GET_KEY reply
> > Dec 28 11:54:33 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
> > Dec 28 11:54:33 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
I tried this similarly with hostapd and get similar results with
disconnects. I have connman/iwd managing eth0 and wlano and created an
ap0 virtual interface on wlan0 then start hostapd. It will come up but
repeatedly disconnects in a similar fashion. I see these disconnects
with my phone as well as with my laptop running an intel wireless
card. My next investigation is to use wpa_supplicant on wlan0 and see
if it is any more stable. After that, maybe looking for any more up to
date firmware for the brcmfmac. Could iwd scanning in the wlan0 cause
a disconnect on the virtual ap0? Any other ideas welcome.
This is a snippet of the log showing iwd and hostapd:
Dec 29 07:45:26 runeaudio iwd[19160]:
src/station.c:station_autoconnect_next() autoconnect: Trying SSID:
DemBoyz_5G
Dec 29 07:45:26 runeaudio iwd[19160]:
src/station.c:station_autoconnect_next() autoconnect:
'd8:07:b6:8e:97:7a' freq: 5785, rank: 13, strength: -8100
Dec 29 07:45:26 runeaudio iwd[19160]:
src/station.c:station_autoconnect_next() autoconnect:
network_autoconnect: No such file or directory (-2)
Dec 29 07:45:26 runeaudio iwd[19160]:
src/wiphy.c:wiphy_radio_work_done() Work item 12 done
Dec 29 07:45:30 runeaudio iwd[19160]:
src/netdev.c:netdev_mlme_notify() MLME notification Del Station(20)
Dec 29 07:45:30 runeaudio hostapd[1583]: ap0: STA f0:42:1c:d7:da:e8
IEEE 802.11: disassociated
Dec 29 07:45:30 runeaudio iwd[19160]:
src/netdev.c:netdev_mlme_notify() MLME notification Del Station(20)
Dec 29 07:45:30 runeaudio hostapd[1583]: ap0: STA f0:42:1c:d7:da:e8
IEEE 802.11: disassociated
Dec 29 07:45:49 runeaudio iwd[19160]:
src/netdev.c:netdev_mlme_notify() MLME notification New Station(19)
Dec 29 07:45:49 runeaudio hostapd[1583]: ap0: STA f0:42:1c:d7:da:e8
IEEE 802.11: associated
Dec 29 07:45:49 runeaudio hostapd[1583]: ap0: STA f0:42:1c:d7:da:e8
RADIUS: starting accounting session 28F5839359A8BF79
Dec 29 07:45:49 runeaudio hostapd[1583]: ap0: STA f0:42:1c:d7:da:e8
WPA: pairwise key handshake completed (RSN)
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: disconnects when in AP mode
2023-12-29 18:53 ` KeithG
@ 2023-12-29 22:16 ` James Prestwood
2023-12-29 22:17 ` KeithG
1 sibling, 0 replies; 6+ messages in thread
From: James Prestwood @ 2023-12-29 22:16 UTC (permalink / raw)
To: KeithG, iwd
Hi Keith,
On 12/29/23 10:53 AM, KeithG wrote:
> On Thu, Dec 28, 2023 at 12:42 PM KeithG <ys3al35l@gmail.com> wrote:
>> I put iwd in debug mode and this is what happens at disconnect. Maybe
>> better for diagnostics.
>> If there is something else I can do to help diagnose it, please let me know
>>
>> Dec 28 12:32:37 runeaudio iwd[5127]: src/netdev.c:netdev_mlme_notify()
>> MLME notification Del Station(20)
>> Dec 28 12:32:37 runeaudio iwd[5127]: src/netdev.c:netdev_mlme_notify()
>> MLME notification Del Station(20)
>> Dec 28 12:35:13 runeaudio iwd[5127]: src/netdev.c:netdev_mlme_notify()
>> MLME notification New Station(19)
>> Dec 28 12:35:13 runeaudio iwd[5127]: KEY_SEQ not returned in GET_KEY reply
>> Dec 28 12:35:13 runeaudio iwd[5127]: src/eapol.c:eapol_start()
>> Dec 28 12:35:13 runeaudio iwd[5127]:
>> src/eapol.c:eapol_send_ptk_1_of_4() STA: f0:42:1c:d7:da:e8 retries=0
>> Dec 28 12:35:13 runeaudio iwd[5127]:
>> src/eapol.c:eapol_handle_ptk_2_of_4() ifindex=4
>> Dec 28 12:35:13 runeaudio iwd[5127]:
>> src/eapol.c:eapol_send_ptk_3_of_4() STA: f0:42:1c:d7:da:e8 retries=0
>> Dec 28 12:35:13 runeaudio iwd[5127]:
>> src/eapol.c:eapol_ptk_3_of_4_retry() attempt 1
>> Dec 28 12:35:13 runeaudio iwd[5127]:
>> src/eapol.c:eapol_handle_ptk_4_of_4() ifindex=4
>> Dec 28 12:35:13 runeaudio iwd[5127]: src/netdev.c:netdev_set_tk()
>> ifindex=4 key_idx=0
>> Dec 28 12:35:13 runeaudio iwd[5127]: src/netdev.c:netdev_set_station_cb()
>> Dec 28 12:35:13 runeaudio iwd[5127]:
>> src/netdev.c:try_handshake_complete() ptk_installed: 1, gtk_installed:
>> 1, igtk_installed: 1
>> Dec 28 12:35:13 runeaudio iwd[5127]:
>> src/netdev.c:try_handshake_complete() nhs->complete: 0
>> Dec 28 12:35:13 runeaudio iwd[5127]:
>> src/netdev.c:try_handshake_complete() Invoking handshake_event()
>> Dec 28 12:35:13 runeaudio iwd[5127]: src/ap.c:ap_new_rsna() STA
>> f0:42:1c:d7:da:e8 authenticated
>> Dec 28 12:35:55 runeaudio iwd[5127]: src/agent.c:agent_register()
>> agent register called
>> Dec 28 12:35:55 runeaudio iwd[5127]: src/agent.c:agent_register()
>> agent :1.566 path /agent/12001
>> Dec 28 12:35:55 runeaudio iwd[5127]: src/station.c:station_dbus_scan()
>> Scan called from DBus
>> Dec 28 12:35:55 runeaudio iwd[5127]:
>> src/wiphy.c:wiphy_radio_work_insert() Inserting work item 13
>> Dec 28 12:35:55 runeaudio iwd[5127]:
>> src/wiphy.c:wiphy_radio_work_next() Starting work item 13
>>
>> On Thu, Dec 28, 2023 at 12:19 PM KeithG <ys3al35l@gmail.com> wrote:
>>> Group,
>>>
>>> I finally gave up on getting connman to manage scanning when iwd is in
>>> AP mode. What I have done is listen to James who posted this a long
>>> time ago and I just finally figured out what he was saying.
>>>
>>> I am doing what is outlined here:
>>> https://lore.kernel.org/linux-wireless/87k0dhdg0d.fsf@bang-olufsen.dk/
>>>
>>> I am running this on RPis all with the brcmfmac adapters. I can get it
>>> all working, but when connected to the RPi on its advertised AP, I can
>>> get a connection for a bit then it disconnects, requiring a reconnect.
>>> I am running a freshly built iwd version 2.11 with ell 0.61 on RPiOS
>>> fully up to date on Bookworm
>>>
>>> I get tons of this in the log: "wiphy_estimate_data_rate() failed" and
>>> a few others but it does not seem like this is what triggers it to
>>> disconnect. I have not been able to pinpoint anything in the log where
>>> it disconnects.
>>>
>>> Any help appreciated.
>>>
>>> # uname -a
>>> Linux runeaudio 6.1.0-rpi7-rpi-v8 #1 SMP PREEMPT Debian
>>> 1:6.1.63-1+rpt1 (2023-11-24) aarch64 GNU/Linux
>>>
>>> this is what shows at bootup
>>> Dec 28 11:50:45 runeaudio kernel: brcmfmac: F1 signature read
>>> @0x18000000=0x15264345
>>> Dec 28 11:50:45 runeaudio kernel: brcmfmac: brcmf_fw_alloc_request:
>>> using brcm/brcmfmac43455-sdio for chip BCM4345/6
>>> Dec 28 11:50:45 runeaudio kernel: usbcore: registered new interface
>>> driver brcmfmac
>>> Dec 28 11:50:45 runeaudio kernel: Bluetooth: hci0: BCM4345C0
>>> 'brcm/BCM4345C0.raspberrypi,3-model-b-plus.hcd' Patch
>>> Dec 28 11:50:45 runeaudio kernel: brcmfmac: brcmf_c_preinit_dcmds:
>>> Firmware: BCM4345/6 wl0: Nov 1 2021 00:37:25 version 7.45.241
>>> (1a2f2fa CY) FWID 01-703fd60
>>> Dec 28 11:50:48 runeaudio kernel: brcmfmac:
>>> brcmf_cfg80211_set_power_mgmt: power save enabled
>>> Dec 28 11:50:55 runeaudio kernel: brcmfmac:
>>> brcmf_cfg80211_set_power_mgmt: power save disabled
>>> Dec 28 11:51:30 runeaudio kernel: brcmfmac:
>>> brcmf_cfg80211_set_power_mgmt: power save disabled
>>> Dec 28 11:51:31 runeaudio kernel: brcmfmac:
>>> brcmf_cfg80211_set_power_mgmt: power save disabled
>>> Dec 28 11:51:40 runeaudio kernel: ieee80211 phy0: brcmf_escan_timeout:
>>> timer expired
>>>
>>> I get this in the log:
>>> Dec 28 11:51:30 runeaudio iwd[1306]: No Diffie-Hellman support found,
>>> WPS will not be available
>>> Dec 28 11:51:30 runeaudio iwd[1306]: The following options are missing
>>> in the kernel:
>>> Dec 28 11:51:30 runeaudio iwd[1306]: CONFIG_KEY_DH_OPERATIONS
>>> Dec 28 11:51:30 runeaudio iwd[1306]: Wireless daemon version 2.11
>>> Dec 28 11:51:30 runeaudio iwd[1306]: Loaded configuration from
>>> /etc/iwd/main.conf
>>> Dec 28 11:51:30 runeaudio systemd[1]: Started iwd.service - Wireless service.
>>> Dec 28 11:51:30 runeaudio iwd[1306]: Wiphy: 0, Name: phy0
>>> Dec 28 11:51:30 runeaudio iwd[1306]: Permanent Address:
>>> b8:27:eb:52:cc:d0
>>> Dec 28 11:51:30 runeaudio iwd[1306]: 2.4GHz Band:
>>> Dec 28 11:51:30 runeaudio iwd[1306]: Bitrates (non-HT):
>>> Dec 28 11:51:30 runeaudio iwd[1306]: 1.0 Mbps
>>> Dec 28 11:51:30 runeaudio iwd[1306]: 2.0 Mbps
>>> Dec 28 11:51:30 runeaudio iwd[1306]: 5.5 Mbps
>>> Dec 28 11:51:30 runeaudio iwd[1306]: 11.0 Mbps
>>> Dec 28 11:51:30 runeaudio iwd[1306]: 6.0 Mbps
>>> Dec 28 11:51:30 runeaudio iwd[1306]: 9.0 Mbps
>>> Dec 28 11:51:30 runeaudio iwd[1306]: 12.0 Mbps
>>> Dec 28 11:51:30 runeaudio iwd[1306]: 18.0 Mbps
>>> Dec 28 11:51:30 runeaudio iwd[1306]: 24.0 Mbps
>>> Dec 28 11:51:30 runeaudio iwd[1306]: 36.0 Mbps
>>> Dec 28 11:51:30 runeaudio iwd[1306]: 48.0 Mbps
>>> Dec 28 11:51:30 runeaudio iwd[1306]: 54.0 Mbps
>>> Dec 28 11:51:30 runeaudio iwd[1306]: HT Capabilities:
>>> Dec 28 11:51:30 runeaudio iwd[1306]: HT40
>>> Dec 28 11:51:30 runeaudio iwd[1306]: Short GI for 20Mhz
>>> Dec 28 11:51:30 runeaudio iwd[1306]: HT RX MCS indexes:
>>> Dec 28 11:51:30 runeaudio iwd[1306]: 0-7
>>> Dec 28 11:51:30 runeaudio iwd[1306]: 5GHz Band:
>>> Dec 28 11:51:30 runeaudio iwd[1306]: Bitrates (non-HT):
>>> Dec 28 11:51:30 runeaudio iwd[1306]: 6.0 Mbps
>>> Dec 28 11:51:30 runeaudio iwd[1306]: 9.0 Mbps
>>> Dec 28 11:51:30 runeaudio iwd[1306]: 12.0 Mbps
>>> Dec 28 11:51:30 runeaudio iwd[1306]: 18.0 Mbps
>>> Dec 28 11:51:30 runeaudio iwd[1306]: 24.0 Mbps
>>> Dec 28 11:51:30 runeaudio iwd[1306]: 36.0 Mbps
>>> Dec 28 11:51:30 runeaudio iwd[1306]: 48.0 Mbps
>>> Dec 28 11:51:30 runeaudio iwd[1306]: 54.0 Mbps
>>> Dec 28 11:51:30 runeaudio iwd[1306]: HT Capabilities:
>>> Dec 28 11:51:30 runeaudio iwd[1306]: HT40
>>> Dec 28 11:51:30 runeaudio iwd[1306]: Short GI for 20Mhz
>>> Dec 28 11:51:30 runeaudio iwd[1306]: Short GI for 40Mhz
>>> Dec 28 11:51:30 runeaudio iwd[1306]: HT RX MCS indexes:
>>> Dec 28 11:51:30 runeaudio iwd[1306]: 0-7
>>> Dec 28 11:51:30 runeaudio iwd[1306]: VHT Capabilities:
>>> Dec 28 11:51:30 runeaudio iwd[1306]: Short GI for 80Mhz
>>> Dec 28 11:51:30 runeaudio iwd[1306]: Max RX
>>> MCS: 0-9 for NSS: 1
>>> Dec 28 11:51:30 runeaudio iwd[1306]: Max TX
>>> MCS: 0-9 for NSS: 1
>>> Dec 28 11:51:30 runeaudio iwd[1306]: Ciphers: BIP-CMAC-128 CCMP-128 TKIP
>>> Dec 28 11:51:30 runeaudio iwd[1306]: Supported iftypes: ad-hoc
>>> station ap p2p-client p2p-go p2p-device
>>> Dec 28 11:51:30 runeaudio iwd[1306]: Driver Flags: DefaultInterface
>>> Dec 28 11:51:30 runeaudio iwd[1306]: Wiphy phy0 will only use the
>>> default interface
>>> Dec 28 11:51:30 runeaudio iwd[1306]: Could not register frame watch
>>> type 00b0: -22
>>> Dec 28 11:51:46 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
>>> Dec 28 11:51:56 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
>>> Dec 28 11:52:22 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
>>> Dec 28 11:52:22 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
>>> Dec 28 11:52:29 runeaudio iwd[1306]: KEY_SEQ not returned in GET_KEY reply
>>> Dec 28 11:52:29 runeaudio iwd[1306]: 4-Way handshake failed for
>>> ifindex: 4, reason: 15
>>> Dec 28 11:52:39 runeaudio iwd[1306]: KEY_SEQ not returned in GET_KEY reply
>>> Dec 28 11:52:40 runeaudio iwd[1306]: 4-Way handshake failed for
>>> ifindex: 4, reason: 15
>>> Dec 28 11:52:49 runeaudio iwd[1306]: KEY_SEQ not returned in GET_KEY reply
>>> Dec 28 11:52:49 runeaudio iwd[1306]: 4-Way handshake failed for
>>> ifindex: 4, reason: 15
>>> Dec 28 11:53:07 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
>>> Dec 28 11:53:35 runeaudio iwd[1306]: KEY_SEQ not returned in GET_KEY reply
>>> Dec 28 11:54:33 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
>>> Dec 28 11:54:33 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
> I tried this similarly with hostapd and get similar results with
> disconnects. I have connman/iwd managing eth0 and wlano and created an
> ap0 virtual interface on wlan0 then start hostapd. It will come up but
> repeatedly disconnects in a similar fashion. I see these disconnects
> with my phone as well as with my laptop running an intel wireless
> card. My next investigation is to use wpa_supplicant on wlan0 and see
> if it is any more stable. After that, maybe looking for any more up to
> date firmware for the brcmfmac. Could iwd scanning in the wlan0 cause
> a disconnect on the virtual ap0? Any other ideas welcome.
Sorry for the delay, I've been out for the holidays but could probably
find time to try AP mode out again on brcmfmac next week.
In your original email it seemed like there was a 4-way handshake
problem, but then other logs show a connection when IWD is in AP mode
and then a scan was issued after that. Without testing I'd say scanning
likely is the culprit of the disconnects. If you don't scan do clients
disconnect or stay connected indefinitely?
The problem with creating both AP and station interfaces on the same phy
is they are sharing air space. Clients expect the AP to continually send
beacons every 100ms but scanning on the station interface is likely
preventing the beacons from going out. Many cards support this interface
combination but its questionable if they support it in a usable way from
the standpoint of scanning.
As far as the connman questions as I'm sure you discovered sniffing
DBus, AP mode is a separate DBus interface. So this would need to be a
feature added to connman in order to support it.
Thanks,
James
>
> This is a snippet of the log showing iwd and hostapd:
>
> Dec 29 07:45:26 runeaudio iwd[19160]:
> src/station.c:station_autoconnect_next() autoconnect: Trying SSID:
> DemBoyz_5G
> Dec 29 07:45:26 runeaudio iwd[19160]:
> src/station.c:station_autoconnect_next() autoconnect:
> 'd8:07:b6:8e:97:7a' freq: 5785, rank: 13, strength: -8100
> Dec 29 07:45:26 runeaudio iwd[19160]:
> src/station.c:station_autoconnect_next() autoconnect:
> network_autoconnect: No such file or directory (-2)
> Dec 29 07:45:26 runeaudio iwd[19160]:
> src/wiphy.c:wiphy_radio_work_done() Work item 12 done
> Dec 29 07:45:30 runeaudio iwd[19160]:
> src/netdev.c:netdev_mlme_notify() MLME notification Del Station(20)
> Dec 29 07:45:30 runeaudio hostapd[1583]: ap0: STA f0:42:1c:d7:da:e8
> IEEE 802.11: disassociated
> Dec 29 07:45:30 runeaudio iwd[19160]:
> src/netdev.c:netdev_mlme_notify() MLME notification Del Station(20)
> Dec 29 07:45:30 runeaudio hostapd[1583]: ap0: STA f0:42:1c:d7:da:e8
> IEEE 802.11: disassociated
> Dec 29 07:45:49 runeaudio iwd[19160]:
> src/netdev.c:netdev_mlme_notify() MLME notification New Station(19)
> Dec 29 07:45:49 runeaudio hostapd[1583]: ap0: STA f0:42:1c:d7:da:e8
> IEEE 802.11: associated
> Dec 29 07:45:49 runeaudio hostapd[1583]: ap0: STA f0:42:1c:d7:da:e8
> RADIUS: starting accounting session 28F5839359A8BF79
> Dec 29 07:45:49 runeaudio hostapd[1583]: ap0: STA f0:42:1c:d7:da:e8
> WPA: pairwise key handshake completed (RSN)
>
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: disconnects when in AP mode
2023-12-29 18:53 ` KeithG
2023-12-29 22:16 ` James Prestwood
@ 2023-12-29 22:17 ` KeithG
2023-12-29 22:23 ` James Prestwood
1 sibling, 1 reply; 6+ messages in thread
From: KeithG @ 2023-12-29 22:17 UTC (permalink / raw)
To: iwd
On Fri, Dec 29, 2023 at 12:53 PM KeithG <ys3al35l@gmail.com> wrote:
>
> On Thu, Dec 28, 2023 at 12:42 PM KeithG <ys3al35l@gmail.com> wrote:
> >
> > I put iwd in debug mode and this is what happens at disconnect. Maybe
> > better for diagnostics.
> > If there is something else I can do to help diagnose it, please let me know
> >
> > Dec 28 12:32:37 runeaudio iwd[5127]: src/netdev.c:netdev_mlme_notify()
> > MLME notification Del Station(20)
> > Dec 28 12:32:37 runeaudio iwd[5127]: src/netdev.c:netdev_mlme_notify()
> > MLME notification Del Station(20)
> > Dec 28 12:35:13 runeaudio iwd[5127]: src/netdev.c:netdev_mlme_notify()
> > MLME notification New Station(19)
> > Dec 28 12:35:13 runeaudio iwd[5127]: KEY_SEQ not returned in GET_KEY reply
> > Dec 28 12:35:13 runeaudio iwd[5127]: src/eapol.c:eapol_start()
> > Dec 28 12:35:13 runeaudio iwd[5127]:
> > src/eapol.c:eapol_send_ptk_1_of_4() STA: f0:42:1c:d7:da:e8 retries=0
> > Dec 28 12:35:13 runeaudio iwd[5127]:
> > src/eapol.c:eapol_handle_ptk_2_of_4() ifindex=4
> > Dec 28 12:35:13 runeaudio iwd[5127]:
> > src/eapol.c:eapol_send_ptk_3_of_4() STA: f0:42:1c:d7:da:e8 retries=0
> > Dec 28 12:35:13 runeaudio iwd[5127]:
> > src/eapol.c:eapol_ptk_3_of_4_retry() attempt 1
> > Dec 28 12:35:13 runeaudio iwd[5127]:
> > src/eapol.c:eapol_handle_ptk_4_of_4() ifindex=4
> > Dec 28 12:35:13 runeaudio iwd[5127]: src/netdev.c:netdev_set_tk()
> > ifindex=4 key_idx=0
> > Dec 28 12:35:13 runeaudio iwd[5127]: src/netdev.c:netdev_set_station_cb()
> > Dec 28 12:35:13 runeaudio iwd[5127]:
> > src/netdev.c:try_handshake_complete() ptk_installed: 1, gtk_installed:
> > 1, igtk_installed: 1
> > Dec 28 12:35:13 runeaudio iwd[5127]:
> > src/netdev.c:try_handshake_complete() nhs->complete: 0
> > Dec 28 12:35:13 runeaudio iwd[5127]:
> > src/netdev.c:try_handshake_complete() Invoking handshake_event()
> > Dec 28 12:35:13 runeaudio iwd[5127]: src/ap.c:ap_new_rsna() STA
> > f0:42:1c:d7:da:e8 authenticated
> > Dec 28 12:35:55 runeaudio iwd[5127]: src/agent.c:agent_register()
> > agent register called
> > Dec 28 12:35:55 runeaudio iwd[5127]: src/agent.c:agent_register()
> > agent :1.566 path /agent/12001
> > Dec 28 12:35:55 runeaudio iwd[5127]: src/station.c:station_dbus_scan()
> > Scan called from DBus
> > Dec 28 12:35:55 runeaudio iwd[5127]:
> > src/wiphy.c:wiphy_radio_work_insert() Inserting work item 13
> > Dec 28 12:35:55 runeaudio iwd[5127]:
> > src/wiphy.c:wiphy_radio_work_next() Starting work item 13
> >
> > On Thu, Dec 28, 2023 at 12:19 PM KeithG <ys3al35l@gmail.com> wrote:
> > >
> > > Group,
> > >
> > > I finally gave up on getting connman to manage scanning when iwd is in
> > > AP mode. What I have done is listen to James who posted this a long
> > > time ago and I just finally figured out what he was saying.
> > >
> > > I am doing what is outlined here:
> > > https://lore.kernel.org/linux-wireless/87k0dhdg0d.fsf@bang-olufsen.dk/
> > >
> > > I am running this on RPis all with the brcmfmac adapters. I can get it
> > > all working, but when connected to the RPi on its advertised AP, I can
> > > get a connection for a bit then it disconnects, requiring a reconnect.
> > > I am running a freshly built iwd version 2.11 with ell 0.61 on RPiOS
> > > fully up to date on Bookworm
> > >
> > > I get tons of this in the log: "wiphy_estimate_data_rate() failed" and
> > > a few others but it does not seem like this is what triggers it to
> > > disconnect. I have not been able to pinpoint anything in the log where
> > > it disconnects.
> > >
> > > Any help appreciated.
> > >
> > > # uname -a
> > > Linux runeaudio 6.1.0-rpi7-rpi-v8 #1 SMP PREEMPT Debian
> > > 1:6.1.63-1+rpt1 (2023-11-24) aarch64 GNU/Linux
> > >
> > > this is what shows at bootup
> > > Dec 28 11:50:45 runeaudio kernel: brcmfmac: F1 signature read
> > > @0x18000000=0x15264345
> > > Dec 28 11:50:45 runeaudio kernel: brcmfmac: brcmf_fw_alloc_request:
> > > using brcm/brcmfmac43455-sdio for chip BCM4345/6
> > > Dec 28 11:50:45 runeaudio kernel: usbcore: registered new interface
> > > driver brcmfmac
> > > Dec 28 11:50:45 runeaudio kernel: Bluetooth: hci0: BCM4345C0
> > > 'brcm/BCM4345C0.raspberrypi,3-model-b-plus.hcd' Patch
> > > Dec 28 11:50:45 runeaudio kernel: brcmfmac: brcmf_c_preinit_dcmds:
> > > Firmware: BCM4345/6 wl0: Nov 1 2021 00:37:25 version 7.45.241
> > > (1a2f2fa CY) FWID 01-703fd60
> > > Dec 28 11:50:48 runeaudio kernel: brcmfmac:
> > > brcmf_cfg80211_set_power_mgmt: power save enabled
> > > Dec 28 11:50:55 runeaudio kernel: brcmfmac:
> > > brcmf_cfg80211_set_power_mgmt: power save disabled
> > > Dec 28 11:51:30 runeaudio kernel: brcmfmac:
> > > brcmf_cfg80211_set_power_mgmt: power save disabled
> > > Dec 28 11:51:31 runeaudio kernel: brcmfmac:
> > > brcmf_cfg80211_set_power_mgmt: power save disabled
> > > Dec 28 11:51:40 runeaudio kernel: ieee80211 phy0: brcmf_escan_timeout:
> > > timer expired
> > >
> > > I get this in the log:
> > > Dec 28 11:51:30 runeaudio iwd[1306]: No Diffie-Hellman support found,
> > > WPS will not be available
> > > Dec 28 11:51:30 runeaudio iwd[1306]: The following options are missing
> > > in the kernel:
> > > Dec 28 11:51:30 runeaudio iwd[1306]: CONFIG_KEY_DH_OPERATIONS
> > > Dec 28 11:51:30 runeaudio iwd[1306]: Wireless daemon version 2.11
> > > Dec 28 11:51:30 runeaudio iwd[1306]: Loaded configuration from
> > > /etc/iwd/main.conf
> > > Dec 28 11:51:30 runeaudio systemd[1]: Started iwd.service - Wireless service.
> > > Dec 28 11:51:30 runeaudio iwd[1306]: Wiphy: 0, Name: phy0
> > > Dec 28 11:51:30 runeaudio iwd[1306]: Permanent Address:
> > > b8:27:eb:52:cc:d0
> > > Dec 28 11:51:30 runeaudio iwd[1306]: 2.4GHz Band:
> > > Dec 28 11:51:30 runeaudio iwd[1306]: Bitrates (non-HT):
> > > Dec 28 11:51:30 runeaudio iwd[1306]: 1.0 Mbps
> > > Dec 28 11:51:30 runeaudio iwd[1306]: 2.0 Mbps
> > > Dec 28 11:51:30 runeaudio iwd[1306]: 5.5 Mbps
> > > Dec 28 11:51:30 runeaudio iwd[1306]: 11.0 Mbps
> > > Dec 28 11:51:30 runeaudio iwd[1306]: 6.0 Mbps
> > > Dec 28 11:51:30 runeaudio iwd[1306]: 9.0 Mbps
> > > Dec 28 11:51:30 runeaudio iwd[1306]: 12.0 Mbps
> > > Dec 28 11:51:30 runeaudio iwd[1306]: 18.0 Mbps
> > > Dec 28 11:51:30 runeaudio iwd[1306]: 24.0 Mbps
> > > Dec 28 11:51:30 runeaudio iwd[1306]: 36.0 Mbps
> > > Dec 28 11:51:30 runeaudio iwd[1306]: 48.0 Mbps
> > > Dec 28 11:51:30 runeaudio iwd[1306]: 54.0 Mbps
> > > Dec 28 11:51:30 runeaudio iwd[1306]: HT Capabilities:
> > > Dec 28 11:51:30 runeaudio iwd[1306]: HT40
> > > Dec 28 11:51:30 runeaudio iwd[1306]: Short GI for 20Mhz
> > > Dec 28 11:51:30 runeaudio iwd[1306]: HT RX MCS indexes:
> > > Dec 28 11:51:30 runeaudio iwd[1306]: 0-7
> > > Dec 28 11:51:30 runeaudio iwd[1306]: 5GHz Band:
> > > Dec 28 11:51:30 runeaudio iwd[1306]: Bitrates (non-HT):
> > > Dec 28 11:51:30 runeaudio iwd[1306]: 6.0 Mbps
> > > Dec 28 11:51:30 runeaudio iwd[1306]: 9.0 Mbps
> > > Dec 28 11:51:30 runeaudio iwd[1306]: 12.0 Mbps
> > > Dec 28 11:51:30 runeaudio iwd[1306]: 18.0 Mbps
> > > Dec 28 11:51:30 runeaudio iwd[1306]: 24.0 Mbps
> > > Dec 28 11:51:30 runeaudio iwd[1306]: 36.0 Mbps
> > > Dec 28 11:51:30 runeaudio iwd[1306]: 48.0 Mbps
> > > Dec 28 11:51:30 runeaudio iwd[1306]: 54.0 Mbps
> > > Dec 28 11:51:30 runeaudio iwd[1306]: HT Capabilities:
> > > Dec 28 11:51:30 runeaudio iwd[1306]: HT40
> > > Dec 28 11:51:30 runeaudio iwd[1306]: Short GI for 20Mhz
> > > Dec 28 11:51:30 runeaudio iwd[1306]: Short GI for 40Mhz
> > > Dec 28 11:51:30 runeaudio iwd[1306]: HT RX MCS indexes:
> > > Dec 28 11:51:30 runeaudio iwd[1306]: 0-7
> > > Dec 28 11:51:30 runeaudio iwd[1306]: VHT Capabilities:
> > > Dec 28 11:51:30 runeaudio iwd[1306]: Short GI for 80Mhz
> > > Dec 28 11:51:30 runeaudio iwd[1306]: Max RX
> > > MCS: 0-9 for NSS: 1
> > > Dec 28 11:51:30 runeaudio iwd[1306]: Max TX
> > > MCS: 0-9 for NSS: 1
> > > Dec 28 11:51:30 runeaudio iwd[1306]: Ciphers: BIP-CMAC-128 CCMP-128 TKIP
> > > Dec 28 11:51:30 runeaudio iwd[1306]: Supported iftypes: ad-hoc
> > > station ap p2p-client p2p-go p2p-device
> > > Dec 28 11:51:30 runeaudio iwd[1306]: Driver Flags: DefaultInterface
> > > Dec 28 11:51:30 runeaudio iwd[1306]: Wiphy phy0 will only use the
> > > default interface
> > > Dec 28 11:51:30 runeaudio iwd[1306]: Could not register frame watch
> > > type 00b0: -22
> > > Dec 28 11:51:46 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
> > > Dec 28 11:51:56 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
> > > Dec 28 11:52:22 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
> > > Dec 28 11:52:22 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
> > > Dec 28 11:52:29 runeaudio iwd[1306]: KEY_SEQ not returned in GET_KEY reply
> > > Dec 28 11:52:29 runeaudio iwd[1306]: 4-Way handshake failed for
> > > ifindex: 4, reason: 15
> > > Dec 28 11:52:39 runeaudio iwd[1306]: KEY_SEQ not returned in GET_KEY reply
> > > Dec 28 11:52:40 runeaudio iwd[1306]: 4-Way handshake failed for
> > > ifindex: 4, reason: 15
> > > Dec 28 11:52:49 runeaudio iwd[1306]: KEY_SEQ not returned in GET_KEY reply
> > > Dec 28 11:52:49 runeaudio iwd[1306]: 4-Way handshake failed for
> > > ifindex: 4, reason: 15
> > > Dec 28 11:53:07 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
> > > Dec 28 11:53:35 runeaudio iwd[1306]: KEY_SEQ not returned in GET_KEY reply
> > > Dec 28 11:54:33 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
> > > Dec 28 11:54:33 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
>
> I tried this similarly with hostapd and get similar results with
> disconnects. I have connman/iwd managing eth0 and wlano and created an
> ap0 virtual interface on wlan0 then start hostapd. It will come up but
> repeatedly disconnects in a similar fashion. I see these disconnects
> with my phone as well as with my laptop running an intel wireless
> card. My next investigation is to use wpa_supplicant on wlan0 and see
> if it is any more stable. After that, maybe looking for any more up to
> date firmware for the brcmfmac. Could iwd scanning in the wlan0 cause
> a disconnect on the virtual ap0? Any other ideas welcome.
>
> This is a snippet of the log showing iwd and hostapd:
>
> Dec 29 07:45:26 runeaudio iwd[19160]:
> src/station.c:station_autoconnect_next() autoconnect: Trying SSID:
> DemBoyz_5G
> Dec 29 07:45:26 runeaudio iwd[19160]:
> src/station.c:station_autoconnect_next() autoconnect:
> 'd8:07:b6:8e:97:7a' freq: 5785, rank: 13, strength: -8100
> Dec 29 07:45:26 runeaudio iwd[19160]:
> src/station.c:station_autoconnect_next() autoconnect:
> network_autoconnect: No such file or directory (-2)
> Dec 29 07:45:26 runeaudio iwd[19160]:
> src/wiphy.c:wiphy_radio_work_done() Work item 12 done
> Dec 29 07:45:30 runeaudio iwd[19160]:
> src/netdev.c:netdev_mlme_notify() MLME notification Del Station(20)
> Dec 29 07:45:30 runeaudio hostapd[1583]: ap0: STA f0:42:1c:d7:da:e8
> IEEE 802.11: disassociated
> Dec 29 07:45:30 runeaudio iwd[19160]:
> src/netdev.c:netdev_mlme_notify() MLME notification Del Station(20)
> Dec 29 07:45:30 runeaudio hostapd[1583]: ap0: STA f0:42:1c:d7:da:e8
> IEEE 802.11: disassociated
> Dec 29 07:45:49 runeaudio iwd[19160]:
> src/netdev.c:netdev_mlme_notify() MLME notification New Station(19)
> Dec 29 07:45:49 runeaudio hostapd[1583]: ap0: STA f0:42:1c:d7:da:e8
> IEEE 802.11: associated
> Dec 29 07:45:49 runeaudio hostapd[1583]: ap0: STA f0:42:1c:d7:da:e8
> RADIUS: starting accounting session 28F5839359A8BF79
> Dec 29 07:45:49 runeaudio hostapd[1583]: ap0: STA f0:42:1c:d7:da:e8
> WPA: pairwise key handshake completed (RSN)
I did the test of the latest firmware from cypress while still using
iwd and connman but using hostapd and get similar results. It still
disconnects right after iwd makes a scan.
Orig firmware on my Pi 7.45.241:
Dec 29 13:18:45 runeaudio kernel: brcmfmac: F1 signature read
@0x18000000=0x15264345
Dec 29 13:18:45 runeaudio kernel: brcmfmac: brcmf_fw_alloc_request:
using brcm/brcmfmac43455-sdio for chip BCM4345/6
Dec 29 13:18:45 runeaudio kernel: usbcore: registered new interface
driver brcmfmac
Dec 29 13:18:46 runeaudio kernel: brcmfmac: brcmf_c_preinit_dcmds:
Firmware: BCM4345/6 wl0: Nov 1 2021 00:37:25 version 7.45.241
(1a2f2fa CY) FWID 01-703fd60
This is the latest from cypress 7.45.265:
ec 29 14:17:26 runeaudio kernel: brcmfmac: F1 signature read
@0x18000000=0x15264345
Dec 29 14:17:26 runeaudio kernel: brcmfmac: brcmf_fw_alloc_request:
using brcm/brcmfmac43455-sdio for chip BCM4345/6
Dec 29 14:17:26 runeaudio kernel: usbcore: registered new interface
driver brcmfmac
Dec 29 14:17:27 runeaudio kernel: brcmfmac: brcmf_c_preinit_dcmds:
Firmware: BCM4345/6 wl0: Aug 29 2023 01:47:08 version 7.45.265
(28bca26 CY) FWID 01-b677b91b
This is is what happens with hostapd/dnsmasq on virtual ap0 and
connmanctl/iwd on wlan0. I get a disconnect as soon as iwd performs a
scan.
https://pastebin.com/FsepZ6PM
Could iwd -station be causing this to disconnect? When I use
connman/wpa_supplicant and hostapd, it is rock steady. No disconnects.
I waited over an hour and it stayed connected. There is not really a
way for me to use connman/wpa_supplicant and use iwctl to start the AP
on the virtual interface to test this hypothesis thst it is only iwd
station, but as it is, iwd ap mode does not really work for brcmfmac.
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: disconnects when in AP mode
2023-12-29 22:17 ` KeithG
@ 2023-12-29 22:23 ` James Prestwood
0 siblings, 0 replies; 6+ messages in thread
From: James Prestwood @ 2023-12-29 22:23 UTC (permalink / raw)
To: KeithG, iwd
Hi Keith,
On 12/29/23 2:17 PM, KeithG wrote:
> On Fri, Dec 29, 2023 at 12:53 PM KeithG <ys3al35l@gmail.com> wrote:
>> On Thu, Dec 28, 2023 at 12:42 PM KeithG <ys3al35l@gmail.com> wrote:
>>> I put iwd in debug mode and this is what happens at disconnect. Maybe
>>> better for diagnostics.
>>> If there is something else I can do to help diagnose it, please let me know
>>>
>>> Dec 28 12:32:37 runeaudio iwd[5127]: src/netdev.c:netdev_mlme_notify()
>>> MLME notification Del Station(20)
>>> Dec 28 12:32:37 runeaudio iwd[5127]: src/netdev.c:netdev_mlme_notify()
>>> MLME notification Del Station(20)
>>> Dec 28 12:35:13 runeaudio iwd[5127]: src/netdev.c:netdev_mlme_notify()
>>> MLME notification New Station(19)
>>> Dec 28 12:35:13 runeaudio iwd[5127]: KEY_SEQ not returned in GET_KEY reply
>>> Dec 28 12:35:13 runeaudio iwd[5127]: src/eapol.c:eapol_start()
>>> Dec 28 12:35:13 runeaudio iwd[5127]:
>>> src/eapol.c:eapol_send_ptk_1_of_4() STA: f0:42:1c:d7:da:e8 retries=0
>>> Dec 28 12:35:13 runeaudio iwd[5127]:
>>> src/eapol.c:eapol_handle_ptk_2_of_4() ifindex=4
>>> Dec 28 12:35:13 runeaudio iwd[5127]:
>>> src/eapol.c:eapol_send_ptk_3_of_4() STA: f0:42:1c:d7:da:e8 retries=0
>>> Dec 28 12:35:13 runeaudio iwd[5127]:
>>> src/eapol.c:eapol_ptk_3_of_4_retry() attempt 1
>>> Dec 28 12:35:13 runeaudio iwd[5127]:
>>> src/eapol.c:eapol_handle_ptk_4_of_4() ifindex=4
>>> Dec 28 12:35:13 runeaudio iwd[5127]: src/netdev.c:netdev_set_tk()
>>> ifindex=4 key_idx=0
>>> Dec 28 12:35:13 runeaudio iwd[5127]: src/netdev.c:netdev_set_station_cb()
>>> Dec 28 12:35:13 runeaudio iwd[5127]:
>>> src/netdev.c:try_handshake_complete() ptk_installed: 1, gtk_installed:
>>> 1, igtk_installed: 1
>>> Dec 28 12:35:13 runeaudio iwd[5127]:
>>> src/netdev.c:try_handshake_complete() nhs->complete: 0
>>> Dec 28 12:35:13 runeaudio iwd[5127]:
>>> src/netdev.c:try_handshake_complete() Invoking handshake_event()
>>> Dec 28 12:35:13 runeaudio iwd[5127]: src/ap.c:ap_new_rsna() STA
>>> f0:42:1c:d7:da:e8 authenticated
>>> Dec 28 12:35:55 runeaudio iwd[5127]: src/agent.c:agent_register()
>>> agent register called
>>> Dec 28 12:35:55 runeaudio iwd[5127]: src/agent.c:agent_register()
>>> agent :1.566 path /agent/12001
>>> Dec 28 12:35:55 runeaudio iwd[5127]: src/station.c:station_dbus_scan()
>>> Scan called from DBus
>>> Dec 28 12:35:55 runeaudio iwd[5127]:
>>> src/wiphy.c:wiphy_radio_work_insert() Inserting work item 13
>>> Dec 28 12:35:55 runeaudio iwd[5127]:
>>> src/wiphy.c:wiphy_radio_work_next() Starting work item 13
>>>
>>> On Thu, Dec 28, 2023 at 12:19 PM KeithG <ys3al35l@gmail.com> wrote:
>>>> Group,
>>>>
>>>> I finally gave up on getting connman to manage scanning when iwd is in
>>>> AP mode. What I have done is listen to James who posted this a long
>>>> time ago and I just finally figured out what he was saying.
>>>>
>>>> I am doing what is outlined here:
>>>> https://lore.kernel.org/linux-wireless/87k0dhdg0d.fsf@bang-olufsen.dk/
>>>>
>>>> I am running this on RPis all with the brcmfmac adapters. I can get it
>>>> all working, but when connected to the RPi on its advertised AP, I can
>>>> get a connection for a bit then it disconnects, requiring a reconnect.
>>>> I am running a freshly built iwd version 2.11 with ell 0.61 on RPiOS
>>>> fully up to date on Bookworm
>>>>
>>>> I get tons of this in the log: "wiphy_estimate_data_rate() failed" and
>>>> a few others but it does not seem like this is what triggers it to
>>>> disconnect. I have not been able to pinpoint anything in the log where
>>>> it disconnects.
>>>>
>>>> Any help appreciated.
>>>>
>>>> # uname -a
>>>> Linux runeaudio 6.1.0-rpi7-rpi-v8 #1 SMP PREEMPT Debian
>>>> 1:6.1.63-1+rpt1 (2023-11-24) aarch64 GNU/Linux
>>>>
>>>> this is what shows at bootup
>>>> Dec 28 11:50:45 runeaudio kernel: brcmfmac: F1 signature read
>>>> @0x18000000=0x15264345
>>>> Dec 28 11:50:45 runeaudio kernel: brcmfmac: brcmf_fw_alloc_request:
>>>> using brcm/brcmfmac43455-sdio for chip BCM4345/6
>>>> Dec 28 11:50:45 runeaudio kernel: usbcore: registered new interface
>>>> driver brcmfmac
>>>> Dec 28 11:50:45 runeaudio kernel: Bluetooth: hci0: BCM4345C0
>>>> 'brcm/BCM4345C0.raspberrypi,3-model-b-plus.hcd' Patch
>>>> Dec 28 11:50:45 runeaudio kernel: brcmfmac: brcmf_c_preinit_dcmds:
>>>> Firmware: BCM4345/6 wl0: Nov 1 2021 00:37:25 version 7.45.241
>>>> (1a2f2fa CY) FWID 01-703fd60
>>>> Dec 28 11:50:48 runeaudio kernel: brcmfmac:
>>>> brcmf_cfg80211_set_power_mgmt: power save enabled
>>>> Dec 28 11:50:55 runeaudio kernel: brcmfmac:
>>>> brcmf_cfg80211_set_power_mgmt: power save disabled
>>>> Dec 28 11:51:30 runeaudio kernel: brcmfmac:
>>>> brcmf_cfg80211_set_power_mgmt: power save disabled
>>>> Dec 28 11:51:31 runeaudio kernel: brcmfmac:
>>>> brcmf_cfg80211_set_power_mgmt: power save disabled
>>>> Dec 28 11:51:40 runeaudio kernel: ieee80211 phy0: brcmf_escan_timeout:
>>>> timer expired
>>>>
>>>> I get this in the log:
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: No Diffie-Hellman support found,
>>>> WPS will not be available
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: The following options are missing
>>>> in the kernel:
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: CONFIG_KEY_DH_OPERATIONS
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: Wireless daemon version 2.11
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: Loaded configuration from
>>>> /etc/iwd/main.conf
>>>> Dec 28 11:51:30 runeaudio systemd[1]: Started iwd.service - Wireless service.
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: Wiphy: 0, Name: phy0
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: Permanent Address:
>>>> b8:27:eb:52:cc:d0
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: 2.4GHz Band:
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: Bitrates (non-HT):
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: 1.0 Mbps
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: 2.0 Mbps
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: 5.5 Mbps
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: 11.0 Mbps
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: 6.0 Mbps
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: 9.0 Mbps
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: 12.0 Mbps
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: 18.0 Mbps
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: 24.0 Mbps
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: 36.0 Mbps
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: 48.0 Mbps
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: 54.0 Mbps
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: HT Capabilities:
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: HT40
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: Short GI for 20Mhz
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: HT RX MCS indexes:
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: 0-7
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: 5GHz Band:
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: Bitrates (non-HT):
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: 6.0 Mbps
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: 9.0 Mbps
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: 12.0 Mbps
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: 18.0 Mbps
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: 24.0 Mbps
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: 36.0 Mbps
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: 48.0 Mbps
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: 54.0 Mbps
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: HT Capabilities:
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: HT40
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: Short GI for 20Mhz
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: Short GI for 40Mhz
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: HT RX MCS indexes:
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: 0-7
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: VHT Capabilities:
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: Short GI for 80Mhz
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: Max RX
>>>> MCS: 0-9 for NSS: 1
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: Max TX
>>>> MCS: 0-9 for NSS: 1
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: Ciphers: BIP-CMAC-128 CCMP-128 TKIP
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: Supported iftypes: ad-hoc
>>>> station ap p2p-client p2p-go p2p-device
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: Driver Flags: DefaultInterface
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: Wiphy phy0 will only use the
>>>> default interface
>>>> Dec 28 11:51:30 runeaudio iwd[1306]: Could not register frame watch
>>>> type 00b0: -22
>>>> Dec 28 11:51:46 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
>>>> Dec 28 11:51:56 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
>>>> Dec 28 11:52:22 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
>>>> Dec 28 11:52:22 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
>>>> Dec 28 11:52:29 runeaudio iwd[1306]: KEY_SEQ not returned in GET_KEY reply
>>>> Dec 28 11:52:29 runeaudio iwd[1306]: 4-Way handshake failed for
>>>> ifindex: 4, reason: 15
>>>> Dec 28 11:52:39 runeaudio iwd[1306]: KEY_SEQ not returned in GET_KEY reply
>>>> Dec 28 11:52:40 runeaudio iwd[1306]: 4-Way handshake failed for
>>>> ifindex: 4, reason: 15
>>>> Dec 28 11:52:49 runeaudio iwd[1306]: KEY_SEQ not returned in GET_KEY reply
>>>> Dec 28 11:52:49 runeaudio iwd[1306]: 4-Way handshake failed for
>>>> ifindex: 4, reason: 15
>>>> Dec 28 11:53:07 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
>>>> Dec 28 11:53:35 runeaudio iwd[1306]: KEY_SEQ not returned in GET_KEY reply
>>>> Dec 28 11:54:33 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
>>>> Dec 28 11:54:33 runeaudio iwd[1306]: wiphy_estimate_data_rate() failed
>> I tried this similarly with hostapd and get similar results with
>> disconnects. I have connman/iwd managing eth0 and wlano and created an
>> ap0 virtual interface on wlan0 then start hostapd. It will come up but
>> repeatedly disconnects in a similar fashion. I see these disconnects
>> with my phone as well as with my laptop running an intel wireless
>> card. My next investigation is to use wpa_supplicant on wlan0 and see
>> if it is any more stable. After that, maybe looking for any more up to
>> date firmware for the brcmfmac. Could iwd scanning in the wlan0 cause
>> a disconnect on the virtual ap0? Any other ideas welcome.
>>
>> This is a snippet of the log showing iwd and hostapd:
>>
>> Dec 29 07:45:26 runeaudio iwd[19160]:
>> src/station.c:station_autoconnect_next() autoconnect: Trying SSID:
>> DemBoyz_5G
>> Dec 29 07:45:26 runeaudio iwd[19160]:
>> src/station.c:station_autoconnect_next() autoconnect:
>> 'd8:07:b6:8e:97:7a' freq: 5785, rank: 13, strength: -8100
>> Dec 29 07:45:26 runeaudio iwd[19160]:
>> src/station.c:station_autoconnect_next() autoconnect:
>> network_autoconnect: No such file or directory (-2)
>> Dec 29 07:45:26 runeaudio iwd[19160]:
>> src/wiphy.c:wiphy_radio_work_done() Work item 12 done
>> Dec 29 07:45:30 runeaudio iwd[19160]:
>> src/netdev.c:netdev_mlme_notify() MLME notification Del Station(20)
>> Dec 29 07:45:30 runeaudio hostapd[1583]: ap0: STA f0:42:1c:d7:da:e8
>> IEEE 802.11: disassociated
>> Dec 29 07:45:30 runeaudio iwd[19160]:
>> src/netdev.c:netdev_mlme_notify() MLME notification Del Station(20)
>> Dec 29 07:45:30 runeaudio hostapd[1583]: ap0: STA f0:42:1c:d7:da:e8
>> IEEE 802.11: disassociated
>> Dec 29 07:45:49 runeaudio iwd[19160]:
>> src/netdev.c:netdev_mlme_notify() MLME notification New Station(19)
>> Dec 29 07:45:49 runeaudio hostapd[1583]: ap0: STA f0:42:1c:d7:da:e8
>> IEEE 802.11: associated
>> Dec 29 07:45:49 runeaudio hostapd[1583]: ap0: STA f0:42:1c:d7:da:e8
>> RADIUS: starting accounting session 28F5839359A8BF79
>> Dec 29 07:45:49 runeaudio hostapd[1583]: ap0: STA f0:42:1c:d7:da:e8
>> WPA: pairwise key handshake completed (RSN)
> I did the test of the latest firmware from cypress while still using
> iwd and connman but using hostapd and get similar results. It still
> disconnects right after iwd makes a scan.
> Orig firmware on my Pi 7.45.241:
> Dec 29 13:18:45 runeaudio kernel: brcmfmac: F1 signature read
> @0x18000000=0x15264345
> Dec 29 13:18:45 runeaudio kernel: brcmfmac: brcmf_fw_alloc_request:
> using brcm/brcmfmac43455-sdio for chip BCM4345/6
> Dec 29 13:18:45 runeaudio kernel: usbcore: registered new interface
> driver brcmfmac
> Dec 29 13:18:46 runeaudio kernel: brcmfmac: brcmf_c_preinit_dcmds:
> Firmware: BCM4345/6 wl0: Nov 1 2021 00:37:25 version 7.45.241
> (1a2f2fa CY) FWID 01-703fd60
>
> This is the latest from cypress 7.45.265:
> ec 29 14:17:26 runeaudio kernel: brcmfmac: F1 signature read
> @0x18000000=0x15264345
> Dec 29 14:17:26 runeaudio kernel: brcmfmac: brcmf_fw_alloc_request:
> using brcm/brcmfmac43455-sdio for chip BCM4345/6
> Dec 29 14:17:26 runeaudio kernel: usbcore: registered new interface
> driver brcmfmac
> Dec 29 14:17:27 runeaudio kernel: brcmfmac: brcmf_c_preinit_dcmds:
> Firmware: BCM4345/6 wl0: Aug 29 2023 01:47:08 version 7.45.265
> (28bca26 CY) FWID 01-b677b91b
>
> This is is what happens with hostapd/dnsmasq on virtual ap0 and
> connmanctl/iwd on wlan0. I get a disconnect as soon as iwd performs a
> scan.
> https://pastebin.com/FsepZ6PM
>
> Could iwd -station be causing this to disconnect? When I use
> connman/wpa_supplicant and hostapd, it is rock steady. No disconnects.
> I waited over an hour and it stayed connected. There is not really a
> way for me to use connman/wpa_supplicant and use iwctl to start the AP
> on the virtual interface to test this hypothesis thst it is only iwd
> station, but as it is, iwd ap mode does not really work for brcmfmac.
Looks like we replied at the same time :)
If hostapd + wpa_supplicant doesn't cause disconnects then its likely
the type of scan IWD does that causes problems. You could get an iwmon
capture when wpa_supplicant is running, that would tell me what type of
scan its doing versus IWD. There are active/passive scans and tons of
knobs to toggle. You could also try and play around with iw and see what
works and what doesn't:
iw wlan0 scan active
iw wlan0 scan passive
etc.
Thanks,
James
^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2023-12-29 22:24 UTC | newest]
Thread overview: 6+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2023-12-28 18:19 disconnects when in AP mode KeithG
2023-12-28 18:42 ` KeithG
2023-12-29 18:53 ` KeithG
2023-12-29 22:16 ` James Prestwood
2023-12-29 22:17 ` KeithG
2023-12-29 22:23 ` James Prestwood
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox