Re: DEL_INTERFACE and CMD_SET_CQM failed; Could not register frame watch type 00d0: -95

[Philip Stewart <philip.stewart.public@gmail.com>]

[-- Attachment #1: Type: text/plain, Size: 10915 bytes --]

Hi James,

Interestingly, I do see them:

src/eapol.c:eapol_handle_ptk_1_of_4() ifindex=3
src/eapol.c:eapol_handle_ptk_3_of_4() ifindex=3

Full debug log attached.

I'm using iwd version 1.12 and iw version 5.9, in Debian bullseye.

Cheers,
Phil

On Mon, 19 Apr, 2021 at 13:10, James Prestwood <prestwoj@gmail.com> 
wrote:
> Hi Philip,
> 
> <snip>
>>  	Supported commands:
>>  		 * set_interface
>>  		 * new_key
>>  		 * join_ibss
>>  		 * set_pmksa
>>  		 * del_pmksa
>>  		 * flush_pmksa
>>  		 * connect
>>  		 * disconnect
> 
> Yes, this appears to be a fullmac card based on the commands it
> supports.
> 
>>  	software interface modes (can always be added):
>>  	interface combinations are not supported
>>  	Device supports scan flush.
>>  	max # scan plans: 1
>>  	max scan plan interval: -1
>>  	max scan plan iterations: 0
>>  	Supported extended features:
> 
> No extended features could be due to an outdated iw version, though my
> thought was that is would support handshake offloading which is
> somewhat old at this point.
> 
> Since its working well for you I wouldn't worry about it, though I am
> somewhat curious how exactly the 4-way handshake is working with a 
> zero
> MAC. Do you by chance see any eapol messages in your IWD logs (running
> in debug mode):
> 
> src/eapol.c:eapol_handle_ptk_1_of_4() ifindex=50
> src/netdev.c:netdev_mlme_notify() MLME notification Unknown(139)
> src/netdev.c:netdev_unicast_notify() Unicast notification 129
> src/netdev.c:netdev_control_port_frame_event()
> src/eapol.c:eapol_handle_ptk_3_of_4() ifindex=50
> 
> Those "handle_ptk_" calls mean the 4-way is happening in userspace. If
> you don't see them then the 4-way is being offloaded to the firmware
> which would make the most sense based on your zero MAC.
> 
>> 
>>  Given it appears to be performing well, I can live with it :)
>> 
>>  All the best,
>>  Phil
>> 
>>  On Mon, 19 Apr, 2021 at 12:06, James Prestwood <prestwoj@gmail.com>
>>  wrote:
>>  > Hi Philip,
>>  >
>>  > On Mon, 2021-04-19 at 19:16 +0100, Philip Stewart wrote:
>>  > >  Hi James,
>>  > >
>>  > >  Thanks for the clarification around DEL_INTERFACE/CQM, that's
>>  > >  reassuring and makes sense!
>>  > >
>>  > >  On the MAC address, yes - /sys/class/ieee80211/phy0/macaddress
>>  > >  reports
>>  > >  all zeros. Would you expect the wl driver to set this?
>>  >
>>  > I would expect that yeah. My only guess is that broadcom-wl is a
>>  > fullmac driver that doesn't set this and handles everything in the
>>  > firmware. You could see what extended features and commands it
>>  > advertises with 'iw list' to verify.
>>  >
>>  > >  n.b. I note that '[iwd]# station wlan0 show' and '# iw wlan0
>>  > > link'
>>  > >  both
>>  > >  successfully report the MAC address for the access point.
>>  > >
>>  > >  Cheers,
>>  > >  Phil
>>  > >
>>  > >  On Mon, 19 Apr, 2021 at 09:07, James Prestwood <
>>  > > prestwoj(a)gmail.com>
>>  > >  wrote:
>>  > >  > Hi Philip,
>>  > >  >
>>  > >  > On Sun, 2021-04-18 at 18:21 +0100, Philip Stewart wrote:
>>  > >  > >  Hello,
>>  > >  > >
>>  > >  > >  I've recently switched from NetworkManager and
>>  > > wpasupplicant to
>>  > >  > >  systemd-networkd and iwd. Whilst everything appears to be
>>  > >  > > working
>>  > >  > >  fine,
>>  > >  > >  I'm curious about some failures reported by iwd:
>>  > >  > >
>>  > >  > >  Apr 18 15:10:32 systemd[1]: Starting Wireless service...
>>  > >  > >  Apr 18 15:10:33 iwd[661]: Wireless daemon version 1.12
>>  > >  > >  Apr 18 15:10:33 systemd[1]: Started Wireless service.
>>  > >  > >  Apr 18 15:10:33 iwd[661]: station: Network configuration 
>> is
>>  > >  > > disabled.
>>  > >  > >  Apr 18 15:10:33 iwd[661]: Wiphy: 0, Name: phy0
>>  > >  > >  Apr 18 15:10:33 iwd[661]:         Permanent Address:
>>  > >  > >  00:00:00:00:00:00
>>  > >  > >  Apr 18 15:10:33 iwd[661]:         Bands: 2.4 GHz 5 GHz
>>  > >  > >  Apr 18 15:10:33 iwd[661]:         Ciphers: CCMP TKIP BIP
>>  > >  > >  Apr 18 15:10:33 iwd[661]:         Supported iftypes: 
>> ad-hoc
>>  > >  > > station
>>  > >  > >  Apr 18 15:10:33 iwd[661]: DEL_INTERFACE failed: Operation
>>  > > not
>>  > >  > >  supported
>>  > >  > >  Apr 18 15:10:33 iwd[661]: Could not register frame watch
>>  > > type
>>  > >  > > 00d0:
>>  > >  > >  -95
>>  > >  > >  Apr 18 15:10:33 iwd[661]: Could not register frame watch
>>  > > type
>>  > >  > > 00d0:
>>  > >  > >  -95
>>  > >  > >  Apr 18 15:10:33 iwd[661]: Could not register frame watch
>>  > > type
>>  > >  > > 00d0:
>>  > >  > >  -95
>>  > >  > >  Apr 18 15:10:33 iwd[661]: Could not register frame watch
>>  > > type
>>  > >  > > 00d0:
>>  > >  > >  -95
>>  > >  > >  Apr 18 15:10:33 iwd[661]: CMD_SET_CQM failed: Operation 
>> not
>>  > >  > > supported
>>  > >  > >  Apr 18 15:10:33 iwd[661]: Could not register frame watch
>>  > > type
>>  > >  > > 00d0:
>>  > >  > >  -95
>>  > >  > >  Apr 18 15:10:33 iwd[661]: Could not register frame watch
>>  > > type
>>  > >  > > 00d0:
>>  > >  > >  -95
>>  > >  > >
>>  > >  > >  Further, I note that in the output of 'networkctl status
>>  > > wlan0',
>>  > >  > > the
>>  > >  > >  WiFi access point MAC address is reported as
>>  > > 00:00:00:00:00:00
>>  > >  > > and
>>  > >  > >  I'm
>>  > >  > >  wondering if this is a consequence of these failures and 
>> if
>>  > >  > > there is
>>  > >  > >  anything I can do about it?
>>  > >  >
>>  > >  > I'm not familiar with the wl driver specifically but I'm
>>  > > guessing
>>  > >  > it
>>  > >  > does not support DEL_INTERFACE/CQM.
>>  > >  >
>>  > >  > This is fine though. In the DEL_INTERFACE case IWD will just
>>  > > use
>>  > >  > the
>>  > >  > interface that already exists on the system. Effectively
>>  > >  > [General].UseDefaultInterface=true.
>>  > >  >
>>  > >  > CQM is also ok as the driver (presumably) manages low RSSI
>>  > > itself
>>  > >  > and
>>  > >  > will roam on its own. At least this is what I would expect.
>>  > >  >
>>  > >  > We pull the permanent address from
>>  > >  > /sys/class/ieee80211/<phy>/macaddress. Is that reporting
>>  > > zero's?
>>  > >  >
>>  > >  > Thanks,
>>  > >  > James
>>  > >  >
>>  > >  > >  Kind regards,
>>  > >  > >  Phil
>>  > >  > >
>>  > >  > >  # lspci -vv -d 14e4:
>>  > >  > >  03:00.0 Network controller: Broadcom Inc. and subsidiaries
>>  > >  > > BCM4322
>>  > >  > >  802.11a/b/g/n Wireless LAN Controller (rev 01)
>>  > >  > >  	Subsystem: Apple Inc. AirPort Extreme
>>  > >  > >  	Control: I/O- Mem+ BusMaster+ SpecCycle- MemWINV-
>>  > > VGASnoop-
>>  > >  > >  ParErr-
>>  > >  > >  Stepping- SERR- FastB2B- DisINTx-
>>  > >  > >  	Status: Cap+ 66MHz- UDF- FastB2B- ParErr- DEVSEL=fast
>>  > > >TAbort-
>>  > >  > >  <TAbort- <MAbort- >SERR- <PERR- INTx-
>>  > >  > >  	Latency: 0, Cache Line Size: 256 bytes
>>  > >  > >  	Interrupt: pin A routed to IRQ 20
>>  > >  > >  	Region 0: Memory at d3200000 (64-bit, non-prefetchable)
>>  > >  > >  [size=16K]
>>  > >  > >  	Capabilities: [40] Power Management version 3
>>  > >  > >  		Flags: PMEClk- DSI- D1+ D2+ AuxCurrent=0mA
>>  > >  > >  PME(D0+,D1-,D2-,D3hot+,D3cold+)
>>  > >  > >  		Status: D0 NoSoftRst+ PME-Enable- DSel=0
>>  > > DScale=2 PME-
>>  > >  > >  	Capabilities: [58] Vendor Specific Information: Len=78
>>  > > <?>
>>  > >  > >  	Capabilities: [e8] MSI: Enable- Count=1/1 Maskable-
>>  > > 64bit+
>>  > >  > >  		Address: 0000000000000000  Data: 0000
>>  > >  > >  	Capabilities: [d0] Express (v1) Endpoint, MSI 00
>>  > >  > >  		DevCap:	MaxPayload 128 bytes, PhantFunc
>>  > > 0,
>>  > >  > > Latency
>>  > >  > >  L0s <4us, L1
>>  > >  > >  unlimited
>>  > >  > >  			ExtTag+ AttnBtn- AttnInd- PwrInd- RBE+
>>  > > FLReset-
>>  > >  > >  SlotPowerLimit 0.000W
>>  > >  > >  		DevCtl:	CorrErr- NonFatalErr- FatalErr-
>>  > > UnsupReq-
>>  > >  > >  			RlxdOrd- ExtTag+ PhantFunc- AuxPwr-
>>  > > NoSnoop-
>>  > >  > >  			MaxPayload 128 bytes, MaxReadReq 128
>>  > > bytes
>>  > >  > >  		DevSta:	CorrErr- NonFatalErr- FatalErr-
>>  > > UnsupReq-
>>  > >  > >  AuxPwr- TransPend-
>>  > >  > >  		LnkCap:	Port #0, Speed 2.5GT/s, Width x1,
>>  > > ASPM
>>  > >  > > L0s
>>  > >  > >  L1, Exit Latency
>>  > >  > >  L0s <4us, L1 <64us
>>  > >  > >  			ClockPM+ Surprise- LLActRep- BwNot-
>>  > >  > >  ASPMOptComp-
>>  > >  > >  		LnkCtl:	ASPM L0s L1 Enabled; RCB 64
>>  > > bytes,
>>  > >  > > Disabled-
>>  > >  > >  CommClk+
>>  > >  > >  			ExtSynch- ClockPM+ AutWidDis- BWInt-
>>  > > AutBWInt-
>>  > >  > >  		LnkSta:	Speed 2.5GT/s (ok), Width x1 (ok)
>>  > >  > >  			TrErr- Train- SlotClk+ DLActive-
>>  > > BWMgmt-
>>  > >  > >  ABWMgmt-
>>  > >  > >  	Capabilities: [100 v1] Advanced Error Reporting
>>  > >  > >  		UESta:	DLP- SDES- TLP- FCP- CmpltTO-
>>  > > CmpltAbrt-
>>  > >  > >  UnxCmplt- RxOF-
>>  > >  > >  MalfTLP- ECRC- UnsupReq- ACSViol-
>>  > >  > >  		UEMsk:	DLP- SDES- TLP- FCP- CmpltTO-
>>  > > CmpltAbrt-
>>  > >  > >  UnxCmplt- RxOF-
>>  > >  > >  MalfTLP- ECRC- UnsupReq- ACSViol-
>>  > >  > >  		UESvrt:	DLP+ SDES- TLP- FCP+ CmpltTO-
>>  > > CmpltAbrt-
>>  > >  > >  UnxCmplt- RxOF+
>>  > >  > >  MalfTLP+ ECRC- UnsupReq- ACSViol-
>>  > >  > >  		CESta:	RxErr- BadTLP- BadDLLP- Rollover-
>>  > >  > > Timeout-
>>  > >  > >  AdvNonFatalErr-
>>  > >  > >  		CEMsk:	RxErr- BadTLP- BadDLLP- Rollover-
>>  > >  > > Timeout-
>>  > >  > >  AdvNonFatalErr+
>>  > >  > >  		AERCap:	First Error Pointer: 00,
>>  > > ECRCGenCap+
>>  > >  > >  ECRCGenEn- ECRCChkCap+
>>  > >  > >  ECRCChkEn-
>>  > >  > >  			MultHdrRecCap- MultHdrRecEn-
>>  > > TLPPfxPres-
>>  > >  > >  HdrLogCap-
>>  > >  > >  		HeaderLog: 00000000 00000000 00000000 00000000
>>  > >  > >  	Capabilities: [13c v1] Virtual Channel
>>  > >  > >  		Caps:	LPEVC=0 RefClk=100ns PATEntryBits=1
>>  > >  > >  		Arb:	Fixed- WRR32- WRR64- WRR128-
>>  > >  > >  		Ctrl:	ArbSelect=Fixed
>>  > >  > >  		Status:	InProgress-
>>  > >  > >  		VC0:	Caps:	PATOffset=00 MaxTimeSlots=1
>>  > >  > >  RejSnoopTrans-
>>  > >  > >  			Arb:	Fixed- WRR32- WRR64- WRR128-
>>  > > TWRR128-
>>  > >  > >  WRR256-
>>  > >  > >  			Ctrl:	Enable+ ID=0 ArbSelect=Fixed
>>  > > TC/VC=ff
>>  > >  > >  			Status:	NegoPending- InProgress-
>>  > >  > >  	Capabilities: [160 v1] Device Serial Number xx-xx-xx-
>>  > > xx-xx-xx-
>>  > >  > >  xx-xx
>>  > >  > >  	Capabilities: [16c v1] Power Budgeting <?>
>>  > >  > >  	Kernel driver in use: wl
>>  > >  > >  	Kernel modules: ssb, wl
>>  > >  > >
>>  > >  > >
>>  > >  > >  _______________________________________________
>>  > >  > >  iwd mailing list -- iwd(a)lists.01.org
>>  > >  > >  To unsubscribe send an email to iwd-leave(a)lists.01.org
>>  > >
>>  > >
>> 
>> 
> 


[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: iwd_debug.log --]
[-- Type: text/x-log, Size: 10286 bytes --]

# /usr/libexec/iwd --debug
Wireless daemon version 1.12
src/main.c:main() Using configuration directory /etc/iwd
src/storage.c:storage_create_dirs() Using state directory /var/lib/iwd
src/main.c:nl80211_appeared() Found nl80211 interface
src/module.c:iwd_modules_init() 
station: Network configuration is disabled.
src/wsc.c:wsc_init() 
src/eap.c:__eap_method_enable() 
src/eap-wsc.c:eap_wsc_init() 
src/eap-md5.c:eap_md5_init() 
src/eap-tls.c:eap_tls_init() 
src/eap-ttls.c:eap_ttls_init() 
src/eap-mschapv2.c:eap_mschapv2_init() 
src/eap-sim.c:eap_sim_init() 
src/eap-aka.c:eap_aka_prime_init() 
src/eap-aka.c:eap_aka_init() 
src/eap-peap.c:eap_peap_init() 
src/eap-gtc.c:eap_gtc_init() 
src/eap-pwd.c:eap_pwd_init() 
src/manager.c:manager_wiphy_dump_callback() New wiphy phy0 added (0)
Wiphy: 0, Name: phy0
	Permanent Address: 00:00:00:00:00:00
	Bands: 2.4 GHz 5 GHz
	Ciphers: CCMP TKIP BIP
	Supported iftypes: ad-hoc station
src/manager.c:manager_interface_dump_callback() 
src/manager.c:manager_get_interface_cb() 
src/manager.c:manager_get_interface_cb() 
src/wiphy.c:wiphy_update_reg_domain() New reg domain country code for (global) is 00
src/manager.c:manager_del_interface_cb() 
DEL_INTERFACE failed: Operation not supported
src/manager.c:manager_use_default() 
src/netdev.c:netdev_create_from_genl() Created interface wlan0[3 1]
src/netdev.c:netdev_cqm_rssi_update() 
Could not register frame watch type 00d0: -95
Could not register frame watch type 00d0: -95
src/netdev.c:netdev_link_notify() event 16 on ifindex 3
src/netdev.c:netdev_set_4addr() netdev: 3 use_4addr: 0
src/netdev.c:netdev_initial_up_cb() Interface 3 initialized
src/station.c:station_enter_state() Old State: disconnected, new state: autoconnect_quick
src/wiphy.c:wiphy_radio_work_insert() Inserting work item 1
src/wiphy.c:wiphy_radio_work_next() Starting work item 1
src/wsc.c:wsc_add_station() Simple Configuration isn't supported by ifindex 3
Could not register frame watch type 00d0: -95
Could not register frame watch type 00d0: -95
CMD_SET_CQM failed: Operation not supported
src/manager.c:manager_config_notify() Notification of command Set Interface(6)
Could not register frame watch type 00d0: -95
src/scan.c:scan_notify() Scan notification Trigger Scan(33)
src/scan.c:scan_request_triggered() Passive scan triggered for wdev 1
src/station.c:station_quick_scan_triggered() Quick scan triggered for wlan0
Could not register frame watch type 00d0: -95
src/wiphy.c:wiphy_reg_notify() Notification of command Reg Beacon Hint(42)
src/wiphy.c:wiphy_reg_notify() Notification of command Reg Beacon Hint(42)
src/netdev.c:netdev_link_notify() event 16 on ifindex 3
src/wiphy.c:wiphy_reg_notify() Notification of command Reg Beacon Hint(42)
src/scan.c:scan_notify() Scan notification New Scan Results(34)
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:scan_parse_bss_information_elements() Load: 193/255
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:scan_parse_bss_information_elements() Load: 140/255
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:scan_parse_bss_information_elements() Load: 56/255
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:scan_parse_bss_information_elements() Load: 56/255
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:scan_parse_bss_information_elements() Load: 84/255
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:scan_parse_bss_information_elements() Load: 75/255
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:scan_parse_bss_information_elements() Load: 20/255
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:scan_parse_bss_information_elements() Load: 16/255
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:scan_parse_bss_information_elements() Load: 2/255
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:scan_parse_bss_information_elements() Load: 2/255
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:scan_parse_bss_information_elements() Load: 136/255
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:get_scan_done() get_scan_done
src/station.c:station_add_seen_bss() Processing BSS '54:83:3a:07:40:ce' with SSID: bubble, freq: 5500, rank: 10689, strength: -4900
src/station.c:station_add_seen_bss() Added new Network "bubble" security psk
src/station.c:station_add_seen_bss() Processing BSS '72:83:3a:07:40:cb' with SSID: , freq: 5500, rank: 10689, strength: -4900
src/station.c:station_add_seen_bss() BSS has hidden SSID
src/station.c:station_add_seen_bss() Processing BSS '70:50:af:b5:15:85' with SSID: SKY8734E, freq: 5180, rank: 8332, strength: -5800
src/station.c:station_add_seen_bss() Added new Network "SKY8734E" security psk
src/station.c:station_add_seen_bss() Processing BSS '5c:03:39:8b:e0:23' with SSID: VodafoneConnect58472940, freq: 5260, rank: 7109, strength: -5700
src/station.c:station_add_seen_bss() Added new Network "VodafoneConnect58472940" security psk
src/station.c:station_add_seen_bss() Processing BSS '6a:83:3a:07:40:cc' with SSID: erebos, freq: 2437, rank: 4976, strength: -4800
src/station.c:station_add_seen_bss() Added new Network "erebos" security psk
src/station.c:station_add_seen_bss() Processing BSS '54:83:3a:07:40:cd' with SSID: bubble, freq: 2437, rank: 4976, strength: -4800
src/station.c:station_add_seen_bss() Processing BSS '78:65:59:84:95:5a' with SSID: PLUSNET-2JWN, freq: 2412, rank: 4167, strength: -4600
src/station.c:station_add_seen_bss() Added new Network "PLUSNET-2JWN" security psk
src/station.c:station_add_seen_bss() Processing BSS '70:50:af:b5:15:82' with SSID: SKY8734E, freq: 2437, rank: 3935, strength: -4900
src/station.c:station_add_seen_bss() Processing BSS '5c:03:39:8b:e0:21' with SSID: VodafoneConnect58472940, freq: 2472, rank: 3241, strength: -5800
src/station.c:station_add_seen_bss() Processing BSS '9c:31:c3:46:f3:ad' with SSID: SKY1E8VY, freq: 5180, rank: 2937, strength: -7300
src/station.c:station_add_seen_bss() Added new Network "SKY1E8VY" security psk
src/station.c:station_add_seen_bss() Processing BSS '78:65:59:84:95:5b' with SSID: PLUSNET-2JWN, freq: 5180, rank: 2538, strength: -7200
src/station.c:station_add_seen_bss() Processing BSS '9c:31:c3:46:f3:aa' with SSID: SKY1E8VY, freq: 2462, rank: 2495, strength: -6700
src/station.c:station_add_seen_bss() Processing BSS '24:7f:20:54:c2:cd' with SSID: Sagemcom-83K9PH, freq: 2462, rank: 2268, strength: -7000
src/station.c:station_add_seen_bss() Added new Network "Sagemcom-83K9PH" security psk
src/station.c:station_add_seen_bss() Processing BSS 'a0:04:60:3a:81:08' with SSID: SKY8734E_2GEXT, freq: 2437, rank: 2147, strength: -7100
src/station.c:station_add_seen_bss() Added new Network "SKY8734E_2GEXT" security psk
src/station.c:station_add_seen_bss() Processing BSS 'b0:5a:da:f6:7c:ad' with SSID: DIRECT-AC-HP OfficeJet 4650, freq: 2412, rank: 2117, strength: -7100
src/station.c:station_add_seen_bss() Added new Network "DIRECT-AC-HP OfficeJet 4650" security psk
src/station.c:station_add_seen_bss() Processing BSS '08:d5:9d:9f:2f:c4' with SSID: PLUSNET-TCF5, freq: 2437, rank: 2073, strength: -7200
src/station.c:station_add_seen_bss() Added new Network "PLUSNET-TCF5" security psk
src/station.c:station_add_seen_bss() Processing BSS 'd8:0d:17:9a:e0:4e' with SSID: TP-Link_E04E, freq: 2412, rank: 1935, strength: -6800
src/station.c:station_add_seen_bss() Added new Network "TP-Link_E04E" security psk
src/station.c:station_add_seen_bss() Processing BSS 'cc:40:d0:50:e3:15' with SSID: Familyhome_EXT, freq: 2412, rank: 1533, strength: -7900
src/station.c:station_add_seen_bss() Added new Network "Familyhome_EXT" security psk
src/station.c:station_add_seen_bss() Processing BSS '80:72:15:bc:83:f2' with SSID: SKYCE6EM, freq: 2462, rank: 1460, strength: -8000
src/station.c:station_add_seen_bss() Added new Network "SKYCE6EM" security psk
src/station.c:station_add_seen_bss() Processing BSS 'a0:04:60:3a:81:07' with SSID: SKY8734E_5GEXT, freq: 5180, rank: 1387, strength: -8100
src/station.c:station_add_seen_bss() Added new Network "SKY8734E_5GEXT" security psk
src/station.c:station_add_seen_bss() Processing BSS 'cc:32:e5:39:11:fe' with SSID: bubble, freq: 5180, rank: 1080, strength: -8500
src/station.c:station_add_seen_bss() Processing BSS '08:d5:9d:9f:2f:c5' with SSID: PLUSNET-TCF5, freq: 5240, rank: 1008, strength: -8600
src/station.c:station_autoconnect_next() Considering autoconnecting to BSS '54:83:3a:07:40:ce' with SSID: bubble, freq: 5500, rank: 10689, strength: -4900
src/wiphy.c:wiphy_radio_work_insert() Inserting work item 2
src/station.c:__station_connect_network() connecting to BSS 54:83:3a:07:40:ce
src/station.c:station_enter_state() Old State: autoconnect_quick, new state: connecting
src/scan.c:scan_cancel() Trying to cancel scan id 1 for wdev 1
src/wiphy.c:wiphy_radio_work_done() Work item 1 done
src/wiphy.c:wiphy_radio_work_next() Starting work item 2
src/station.c:station_netdev_event() Associating
src/netdev.c:netdev_mlme_notify() MLME notification Connect(46)
src/netdev.c:netdev_connect_event() 
src/netdev.c:netdev_link_notify() event 16 on ifindex 3
src/netdev.c:netdev_link_notify() event 16 on ifindex 3
src/netdev.c:netdev_link_notify() event 16 on ifindex 3
src/wiphy.c:wiphy_reg_notify() Notification of command Reg Change(36)
src/wiphy.c:wiphy_update_reg_domain() New reg domain country code for (global) is DE
src/eapol.c:eapol_handle_ptk_1_of_4() ifindex=3
src/eapol.c:eapol_handle_ptk_3_of_4() ifindex=3
src/netdev.c:netdev_set_gtk() 3
src/station.c:station_handshake_event() Setting keys
src/netdev.c:netdev_set_tk() 3
src/netdev.c:netdev_set_rekey_offload() 3
src/station.c:station_connect_cb() 3, result: 0
src/station.c:station_enter_state() Old State: connecting, new state: connected
src/wiphy.c:wiphy_radio_work_done() Work item 2 done