Re: strange behavior with synthetic ap0

On Mon, Apr 7, 2025 at 9:57 AM Denis Kenzior <[email protected]> wrote:
>
> 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

Denis,

It succeeds, but never gets an IP before it disconnects, I noticed.

How do I ensure it is on the same frequency? I would think that I
would have to change the freq to whatever the freq of the SSID I am
connecting to. The process would then have to be: query the SSID for a
freq then stop and restart the AP... Wouldn't this disconnect the AP0
from whatever is connected to it?

A bit oif background, I am trying to write a python script to do a bit
of magic. We use connman as the front end and iwd as the wifi
controller and there is no real good way to have this headless,
embedded device always allow a connection, so I am trying to get a
python script to monitor dbus and when it looses its wlan0 connection
to start ap0 and allow a connection that way unless it 'sees' an SSID
it already recognizes. In that case, I am having is down the ap0 then
connect to the SSID on wlan0. That works, but it must be serial: shut
down ap0 before connecting to SSID on wlan0 or it complains that the
password is bad.

I may be mistaken, but I think that a year or so ago (kernel 5.x or
6.1) it used to actually allow both simultaneously.

I built a kernel last night so that I nave nlmon available to query
what is being passed if that is needed.

Keith