strange behavior with synthetic ap0

KeithG <[email protected]> Sun, 6 Apr 2025 22:48:38 -0500
Newsgroups dev.linux.lists.iwd
Message-ID <CAG17S_Mgb9fHFcwW1KoNZ2QxZVH2rKZuwG5i78c8us0HjwO7Eg@mail.gmail.com>
I have been messing around with a synthetic ap0 to set up AP mode up
on my brcmfmac equipped Pis. This attempt is on a Pi4 with the 43455
chip, but I've recently seen this with other Pis.
What I do to set up the ap0 is this:

iw dev wlan0 interface add ap0 type __ap
ip link set dev ap0 address d8:3a:dd:60:a3:cg
systemctl reload-or-restart iwd
iwctl device ap0 set-property Mode ap
iwctl ap ap0 start-profile test

Then from connmanctl, I attempt to connect to a known SSID. If ap0 is
up, I cannot connect to the SSID with the correct password. If I take
ap0 down 'iw ap0 del' and try again, it connects. This is with either
iwd controlling the AP or hostapd. It doesn't matter which is
controlling the ap0, if it is up, I always get a failed password if
ap0 is up. This used to work and seems to have regressed.

When I enable debug for iwd, this is what it looks like when I attempt
to connect to a known SSID when the ap0 is up.
Apr 06 16:36:09 pi4 connmand[138138]: Interface wlan0 [ wifi ] state
is association
Apr 06 16:36:09 pi4 iwd[158609]: src/network.c:network_connect()
Apr 06 16:36:09 pi4 iwd[158609]: src/network.c:network_connect_psk()
ask_passphrase: true
Apr 06 16:36:09 pi4 iwd[158609]:
src/agent.c:agent_request_passphrase() agent 0x5582c692f0 owner
:1.5673 path /net/connman/iwd_agent
Apr 06 16:36:09 pi4 iwd[158609]: src/agent.c:agent_send_next_request()
send request to :1.5673 /net/connman/iwd_agent
Apr 06 16:36:09 pi4 iwd[158609]: src/agent.c:agent_receive_reply()
agent 0x5582c692f0 request id 117
Apr 06 16:36:09 pi4 iwd[158609]: src/network.c:passphrase_callback() result 0
Apr 06 16:36:09 pi4 iwd[158609]:
src/network.c:network_generate_sae_pt() Generating PT for Group 19
Apr 06 16:36:09 pi4 iwd[158609]:
src/network.c:network_generate_sae_pt() Generating PT for Group 20
Apr 06 16:36:09 pi4 iwd[158609]: src/wiphy.c:wiphy_radio_work_insert()
Inserting work item 6
Apr 06 16:36:09 pi4 iwd[158609]: src/wiphy.c:wiphy_radio_work_next()
Starting work item 6
Apr 06 16:36:09 pi4 iwd[158609]: event: connect-info, ssid: keithS23,
bss: 56:ba:50:be:c8:62, signal: -69, load: 0/255
Apr 06 16:36:09 pi4 iwd[158609]: event: state, old: autoconnect_full,
new: connecting
Apr 06 16:36:09 pi4 iwd[158609]: src/scan.c:scan_periodic_stop()
Stopping periodic scan for wdev 1
Apr 06 16:36:09 pi4 connmand[138138]: Interface wlan0 [ wifi ] state
is configuration
Apr 06 16:36:09 pi4 iwd[158609]: src/netdev.c:netdev_mlme_notify()
MLME notification Connect(46)
Apr 06 16:36:09 pi4 iwd[158609]: src/netdev.c:netdev_connect_event()
Apr 06 16:36:09 pi4 iwd[158609]: src/netdev.c:netdev_connect_event()
aborting and ignore_connect_event not set, proceed
Apr 06 16:36:09 pi4 iwd[158609]: src/netdev.c:netdev_connect_event()
expect_connect_failure not set, proceed
Apr 06 16:36:09 pi4 iwd[158609]: src/netdev.c:parse_request_ies()
Apr 06 16:36:09 pi4 iwd[158609]: src/netdev.c:netdev_connect_event()
Request / Response IEs parsed
Apr 06 16:36:09 pi4 iwd[158609]: src/netdev.c:netdev_get_oci()
Apr 06 16:36:09 pi4 connmand[138138]: wlan0 {RX} 335 packets 72684 bytes
Apr 06 16:36:09 pi4 connmand[138138]: wlan0 {TX} 1615 packets 216925 bytes
Apr 06 16:36:09 pi4 connmand[138138]: wlan0 {update} flags 102403 <UP,LOWER_UP>
Apr 06 16:36:09 pi4 connmand[138138]: wlan0 {newlink} index 3 address
DC:A6:32:B4:50:CF mtu 1500
Apr 06 16:36:09 pi4 connmand[138138]: wlan0 {newlink} index 3
operstate 5 <DORMANT>
Apr 06 16:36:09 pi4 iwd[158609]: src/netdev.c:netdev_link_notify()
event 16 on ifindex 3
Apr 06 16:36:09 pi4 iwd[158609]: src/netdev.c:netdev_get_oci_cb()
Obtained OCI: freq: 5785, width: 3, center1: 5775, center2: 0
Apr 06 16:36:09 pi4 iwd[158609]: src/eapol.c:eapol_start()
Apr 06 16:36:09 pi4 iwd[158609]:
src/station.c:station_handshake_event() Handshaking
Apr 06 16:36:09 pi4 iwd[158609]: src/eapol.c:eapol_handle_ptk_1_of_4() ifindex=3
Apr 06 16:36:09 pi4 iwd[158609]: src/netdev.c:netdev_link_notify()
event 16 on ifindex 3
Apr 06 16:36:09 pi4 iwd[158609]: src/netdev.c:netdev_link_notify()
event 16 on ifindex 3
Apr 06 16:36:09 pi4 iwd[158609]: src/netdev.c:netdev_link_notify()
event 16 on ifindex 3
Apr 06 16:36:09 pi4 iwd[158609]: src/eapol.c:eapol_handle_ptk_3_of_4() ifindex=3
Apr 06 16:36:09 pi4 iwd[158609]: src/netdev.c:netdev_set_gtk()
ifindex=3 key_idx=1
Apr 06 16:36:09 pi4 iwd[158609]:
src/station.c:station_handshake_event() Setting keys
Apr 06 16:36:09 pi4 iwd[158609]: src/network.c:network_sync_settings()
Apr 06 16:36:09 pi4 iwd[158609]: src/netdev.c:netdev_set_tk()
ifindex=3 key_idx=0
Apr 06 16:36:09 pi4 iwd[158609]: src/netdev.c:netdev_set_rekey_offload() 3
Apr 06 16:36:09 pi4 iwd[158609]:
src/netdev.c:netdev_new_group_key_cb() ifindex: 3, err: 0
Apr 06 16:36:09 pi4 iwd[158609]: src/netdev.c:try_handshake_complete()
ptk_installed: 0, gtk_installed: 1, igtk_installed: 1
Apr 06 16:36:09 pi4 iwd[158609]: hardware_rekey not supported
Apr 06 16:36:09 pi4 iwd[158609]: src/netdev.c:netdev_set_station_cb()
Apr 06 16:36:09 pi4 iwd[158609]: src/netdev.c:try_handshake_complete()
ptk_installed: 1, gtk_installed: 1, igtk_installed: 1
Apr 06 16:36:09 pi4 iwd[158609]: src/netdev.c:try_handshake_complete()
nhs->complete: 0
Apr 06 16:36:09 pi4 iwd[158609]: src/netdev.c:try_handshake_complete()
Invoking handshake_event()
Apr 06 16:36:09 pi4 iwd[158609]:
src/handshake.c:handshake_state_cache_pmksa() No PMKSA for
56:ba:50:be:c8:62
Apr 06 16:36:09 pi4 iwd[158609]: src/netdev.c:netdev_connect_ok()
Apr 06 16:36:09 pi4 iwd[158609]: src/station.c:station_connect_cb() 3, result: 0
Apr 06 16:36:09 pi4 iwd[158609]: src/station.c:station_connect_ok()
Apr 06 16:36:09 pi4 iwd[158609]: event: state, old: connecting, new:
connecting (netconfig)
Apr 06 16:36:09 pi4 iwd[158609]: src/wiphy.c:wiphy_radio_work_done()
Work item 6 done
Apr 06 16:36:09 pi4 connmand[138138]: wlan0 {RX} 336 packets 72839 bytes
Apr 06 16:36:09 pi4 connmand[138138]: wlan0 {TX} 1619 packets 217577 bytes
Apr 06 16:36:09 pi4 connmand[138138]: wlan0 {update} flags 102467
<UP,RUNNING,LOWER_UP>
Apr 06 16:36:09 pi4 connmand[138138]: wlan0 {newlink} index 3 address
DC:A6:32:B4:50:CF mtu 1500
Apr 06 16:36:09 pi4 connmand[138138]: wlan0 {newlink} index 3 operstate 6 <UP>
Apr 06 16:36:09 pi4 iwd[158609]: src/netdev.c:netdev_link_notify()
event 16 on ifindex 3
Apr 06 16:36:19 pi4 iwd[158609]: src/netdev.c:netdev_mlme_notify()
MLME notification Disconnect(48)
Apr 06 16:36:19 pi4 iwd[158609]: src/netdev.c:netdev_disconnect_event()
Apr 06 16:36:19 pi4 iwd[158609]: Received Deauthentication event,
reason: 0, from_ap: false
Apr 06 16:36:19 pi4 iwd[158609]: src/station.c:station_disconnect_event() 3
Apr 06 16:36:19 pi4 iwd[158609]: event: disconnect-info, reason: 0
Apr 06 16:36:19 pi4 iwd[158609]: src/station.c:station_disassociated() 3
Apr 06 16:36:19 pi4 iwd[158609]:
src/station.c:station_reset_connection_state() 3
Apr 06 16:36:19 pi4 iwd[158609]: src/station.c:station_roam_state_clear() 3
Apr 06 16:36:19 pi4 connmand[138138]: wlan0 {RX} 336 packets 72839 bytes
Apr 06 16:36:19 pi4 connmand[138138]: wlan0 {TX} 1635 packets 220020 bytes
Apr 06 16:36:19 pi4 connmand[138138]: wlan0 {update} flags 36867 <UP>
Apr 06 16:36:19 pi4 connmand[138138]: wlan0 {newlink} index 3 address
DC:A6:32:B4:50:CF mtu 1500
Apr 06 16:36:19 pi4 connmand[138138]: wlan0 {newlink} index 3 operstate 2 <DOWN>
Apr 06 16:36:19 pi4 iwd[158609]: event: state, old: connecting
(netconfig), new: disconnected
Apr 06 16:36:19 pi4 iwd[158609]: event: state, old: disconnected, new:
autoconnect_quick
Apr 06 16:36:19 pi4 iwd[158609]: src/wiphy.c:wiphy_radio_work_insert()
Inserting work item 7
Apr 06 16:36:19 pi4 iwd[158609]: src/wiphy.c:wiphy_radio_work_next()
Starting work item 7
Apr 06 16:36:19 pi4 iwd[158609]: src/netdev.c:netdev_link_notify()
event 16 on ifindex 3
Apr 06 16:36:19 pi4 iwd[158609]: src/scan.c:scan_notify() Scan
notification Trigger Scan(33)
Apr 06 16:36:19 pi4 iwd[158609]: src/netdev.c:netdev_link_notify()
event 16 on ifindex 3
Apr 06 16:36:19 pi4 iwd[158609]: src/scan.c:scan_request_triggered()
Passive scan triggered for wdev 1
Apr 06 16:36:19 pi4 iwd[158609]:
src/station.c:station_quick_scan_triggered() Quick scan triggered for
wlan0
Apr 06 16:36:19 pi4 connmand[138138]: Interface wlan0 [ wifi ] error
"connect-failed"
Apr 06 16:36:19 pi4 connmand[138138]: Interface wlan0 [ wifi ] state is failure
Apr 06 16:36:19 pi4 iwd[158609]: src/station.c:station_dbus_disconnect()
Apr 06 16:36:19 pi4 iwd[158609]: event: state, old: autoconnect_quick,
new: disconnected

It is strange that it reports a bad password. Is this a brcmfmac
driver issue or a firmware issue?

Keith