Re: strange behavior with synthetic ap0

Hi Keith,

On 4/6/25 10:48 PM, KeithG wrote:
> 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)

So the connection succeeds...

> 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

But the kernel / firmware disconnects us.  There may be a limitation with this 
hardware where the AP/STA must operate on the same channel.  Have you tried 
setting the AP interface to operate on the same frequency as the AP you're 
trying to connect to?

> Apr 06 16:36:19 pi4 iwd[158609]: event: disconnect-info, reason: 0

Reason given is 'unspecified'...

> 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?

That is an assumption iwd makes since there's no sensible error information 
about the disconnect.

> 
> Keith
> 

Regards,
-Denis