All of lore.kernel.org
 help / color / mirror / Atom feed
* iwd needs restart after suspending
@ 2022-08-12 12:08 Joachim Breitner
  2022-08-12 14:09 ` Joachim Breitner
  0 siblings, 1 reply; 6+ messages in thread
From: Joachim Breitner @ 2022-08-12 12:08 UTC (permalink / raw)
  To: iwd

Hi,

On my Lenovo Thinkpad X1 Carbon Gen 9 I observe that after suspending,
WLAN connectivity is gone, and `iwctl station list` no longer shows any
devices. They come back with `systemctl restart iwd`.

I had this before upgrading to NixOS 22.05, but then it was fixed. But
it came up when I switched the kernel from 5.15 to 5.19. This is using
iwd-1.27.

Is this a known problem? If not, any information in particular I could
provide to fix it?

Cheers,
Joachim

(NB, also tracking this at https://github.com/NixOS/nixpkgs/issues/186274)



-- 
Joachim Breitner
  mail@joachim-breitner.de
  http://www.joachim-breitner.de/


^ permalink raw reply	[flat|nested] 6+ messages in thread
* Re: iwd needs restart after suspending
  2022-08-12 12:08 iwd needs restart after suspending Joachim Breitner
@ 2022-08-12 14:09 ` Joachim Breitner
  2022-08-12 15:01   ` Denis Kenzior
  0 siblings, 1 reply; 6+ messages in thread
From: Joachim Breitner @ 2022-08-12 14:09 UTC (permalink / raw)
  To: iwd

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

Hi,

Am Freitag, dem 12.08.2022 um 14:08 +0200 schrieb Joachim Breitner:
> Is this a known problem? If not, any information in particular I could
> provide to fix it?

I recorded the output of iwd -d on 5.15 and 5.19, see attachement. The
relevant bit seems to be

src/station.c:station_enter_state() Old State: connected, new state: disconnected        
src/station.c:station_enter_state() Old State: disconnected, new state: autoconnect_quick
src/wiphy.c:wiphy_radio_work_insert() Inserting work item 3                              
src/wiphy.c:wiphy_radio_work_next() Starting work item 3                                 
src/wiphy.c:wiphy_reg_notify() Notification of command Wiphy Reg Change(113)             
src/wiphy.c:wiphy_update_reg_domain() New reg domain country code for phy0 is XX         
src/scan.c:scan_notify() Scan notification Trigger Scan(33)                              
src/netconfig.c:netconfig_ifaddr_deleted() ifaddr 192.168.178.39/24                      
src/scan.c:scan_request_triggered() Active scan triggered for wdev 6                     
src/station.c:station_quick_scan_triggered() Quick scan triggered for wlan0              
src/scan.c:scan_notify() Scan notification New Scan Results(34)                          
src/netdev.c:netdev_link_notify() event 16 on ifindex 5                                  
src/scan.c:get_scan_callback() get_scan_callback                                         
src/scan.c:scan_parse_bss_information_elements() Load: 31/255                            
src/scan.c:get_scan_callback() get_scan_callback                                         
src/scan.c:get_scan_callback() get_scan_callback                                         

                           
with 5.15 and 

src/station.c:station_enter_state() Old State: connected, new state:
disconnected
src/station.c:station_enter_state() Old State: disconnected, new state:
autoconnect_quick
src/wiphy.c:wiphy_radio_work_insert() Inserting work item 3
src/wiphy.c:wiphy_radio_work_next() Starting work item 3
src/netdev.c:netdev_link_notify() event 16 on ifindex 3               
src/station.c:station_free()                                          
src/netconfig.c:netconfig_destroy()                                   
src/scan.c:scan_cancel() Trying to cancel scan id 3 for wdev 3        
src/scan.c:scan_cancel() Scan is already started                      
src/wiphy.c:wiphy_radio_work_done() Work item 3 done
src/station.c:station_roam_state_clear() 3          
src/rrm.c:rrm_station_watch_destroy()               

with 5.19, and no more output there.

Cheers,
Joachim


-- 
Joachim Breitner
  mail@joachim-breitner.de
  http://www.joachim-breitner.de/


[-- Attachment #2: iwd-linux-5.19.txt --]
[-- Type: text/plain, Size: 13739 bytes --]

Wireless daemon version 1.27
src/main.c:main() Using configuration directory /etc/iwd
Loaded configuration from /etc/iwd/main.conf
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() 
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)
src/manager.c:manager_wiphy_dump_done() 
src/manager.c:manager_filtered_wiphy_dump_done() 
Wiphy: 0, Name: phy0
	Permanent Address: 2c:8d:b1:25:46:21
	2.4Ghz Band:
		Bitrates (non-HT):
			 1.0 Mbps
			 2.0 Mbps
			 5.5 Mbps
			11.0 Mbps
			 6.0 Mbps
			 9.0 Mbps
			12.0 Mbps
			18.0 Mbps
			24.0 Mbps
			36.0 Mbps
			48.0 Mbps
			54.0 Mbps
		HT Capabilities:
			HT40
			Short GI for 20Mhz
			Short GI for 40Mhz
		HT RX MCS indexes:
			0-15
	5Ghz Band:
		Bitrates (non-HT):
			 6.0 Mbps
			 9.0 Mbps
			12.0 Mbps
			18.0 Mbps
			24.0 Mbps
			36.0 Mbps
			48.0 Mbps
			54.0 Mbps
		HT Capabilities:
			HT40
			Short GI for 20Mhz
			Short GI for 40Mhz
		HT RX MCS indexes:
			0-15
		VHT Capabilities:
			160 Mhz operation
			Short GI for 80Mhz
			Short GI for 160 and 80 + 80 Mhz
			Max RX MCS: 0-9 for NSS: 2
			Max TX MCS: 0-9 for NSS: 2
	Ciphers: CCMP TKIP BIP
	Supported iftypes: ad-hoc station ap p2p-client p2p-go p2p-device
src/manager.c:manager_interface_dump_done() 
src/manager.c:manager_create_interfaces() creating wlan0
src/manager.c:manager_create_interfaces() creating wlan0-p2p
src/wiphy.c:wiphy_update_reg_domain() New reg domain country code for phy0 is 00
src/manager.c:manager_config_notify() Notification of command New Interface(7)
src/netdev.c:netdev_link_notify() event 16 on ifindex 3
src/manager.c:manager_new_station_interface_cb() 
src/netdev.c:netdev_create_from_genl() Created interface wlan0[3 3]
src/manager.c:manager_config_notify() Notification of command New Interface(7)
src/manager.c:manager_new_p2p_interface_cb() 
src/p2p.c:p2p_device_update_from_genl() Created P2P device 4
src/netdev.c:netdev_link_notify() event 16 on ifindex 3
src/wiphy.c:wiphy_reg_notify() Notification of command Wiphy Reg Change(113)
src/wiphy.c:wiphy_update_reg_domain() New reg domain country code for phy0 is XX
src/netdev.c:netdev_set_4addr() netdev: 3 use_4addr: 0
src/netdev.c:netdev_initial_up_cb() Interface 3 initialized
src/netconfig.c:netconfig_new() Starting netconfig for interface: 3
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/rrm.c:rrm_add_frame_watches() 
src/netdev.c:netdev_link_notify() event 16 on ifindex 3
src/netdev.c:netdev_link_notify() event 16 on ifindex 3
src/manager.c:manager_config_notify() Notification of command Set Interface(6)
src/scan.c:scan_notify() Scan notification Trigger Scan(33)
src/scan.c:scan_request_triggered() Active scan triggered for wdev 3
src/station.c:station_quick_scan_triggered() Quick scan triggered for wlan0
src/scan.c:scan_notify() Scan notification New Scan Results(34)
src/netdev.c:netdev_link_notify() event 16 on ifindex 3
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:scan_parse_bss_information_elements() Load: 32/255
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:scan_parse_bss_information_elements() Load: 71/255
src/scan.c:scan_parse_advertisement_protocol() 
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: 97/255
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:scan_parse_advertisement_protocol() 
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: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: 87/255
src/scan.c:scan_parse_advertisement_protocol() 
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:get_scan_callback() get_scan_callback
src/scan.c:scan_parse_bss_information_elements() Load: 44/255
src/scan.c:scan_parse_advertisement_protocol() 
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:scan_parse_bss_information_elements() Load: 26/255
src/scan.c:get_scan_done() get_scan_done
src/station.c:station_add_seen_bss() Processing BSS 'dc:15:c8:12:e8:85' with SSID: Longbourn, freq: 5520, rank: 58253, strength: -4700, data_rate: 1733.3
src/station.c:station_add_seen_bss() Added new Network "Longbourn" security psk
src/station.c:station_add_seen_bss() Processing BSS 'dc:15:c8:12:e8:86' with SSID: Longbourn, freq: 2412, rank: 4854, strength: -4400, data_rate: 144.4
src/station.c:station_add_seen_bss() Processing BSS 'ec:a8:1f:36:d7:70' with SSID: Vodafone-D76C, freq: 2412, rank: 202, strength: -8000, data_rate: 7.2
src/station.c:station_add_seen_bss() Added new Network "Vodafone-D76C" security psk
src/station.c:station_add_seen_bss() Processing BSS 'd4:e2:cb:17:83:d8' with SSID: Vodafone-83D4, freq: 2462, rank: 184, strength: -8500, data_rate: 5.5
src/station.c:station_add_seen_bss() Added new Network "Vodafone-83D4" security psk
src/station.c:station_add_seen_bss() Processing BSS '70:54:25:64:51:50' with SSID: Zauberkiste-2.4GHz, freq: 2462, rank: 56, strength: -8600, data_rate: 2.0
src/station.c:station_add_seen_bss() Added new Network "Zauberkiste-2.4GHz" security psk
src/station.c:station_add_seen_bss() Processing BSS '72:54:25:64:51:30' with SSID: Vodafone Homespot, freq: 2462, rank: 56, strength: -8600, data_rate: 2.0
src/station.c:station_add_seen_bss() Added new Network "Vodafone Homespot" security open
src/station.c:station_add_seen_bss() Processing BSS '72:54:25:64:51:10' with SSID: Vodafone Hotspot, freq: 2462, rank: 56, strength: -8600, data_rate: 2.0
src/station.c:station_add_seen_bss() Added new Network "Vodafone Hotspot" security open
src/station.c:station_add_seen_bss() Processing BSS '34:2c:c4:73:74:c3' with SSID: UPC2466083, freq: 2412, rank: 56, strength: -8700, data_rate: 2.0
src/station.c:station_add_seen_bss() Added new Network "UPC2466083" security psk
src/station.c:station_add_seen_bss() Processing BSS '38:10:d5:81:b8:be' with SSID: FRITZ!Box 7412, freq: 2412, rank: 56, strength: -8700, data_rate: 2.0
src/station.c:station_add_seen_bss() Added new Network "FRITZ!Box 7412" security psk
src/station.c:station_add_seen_bss() Processing BSS 'd4:3f:cb:8d:10:74' with SSID: gorica, freq: 2462, rank: 56, strength: -8800, data_rate: 2.0
src/station.c:station_add_seen_bss() Added new Network "gorica" security psk
src/station.c:station_add_seen_bss() Processing BSS 'ee:a9:40:7d:4c:39' with SSID: Vodafone Homespot, freq: 2437, rank: 56, strength: -8900, data_rate: 2.0
src/station.c:station_add_seen_bss() Processing BSS 'ee:a9:40:7d:4c:19' with SSID: Vodafone Hotspot, freq: 2437, rank: 56, strength: -9000, data_rate: 2.0
src/station.c:station_add_seen_bss() Processing BSS 'ec:a9:40:75:77:8f' with SSID: Vodafone-A04B, freq: 2437, rank: 56, strength: -9000, data_rate: 2.0
src/station.c:station_add_seen_bss() Added new Network "Vodafone-A04B" security psk
src/station.c:station_add_seen_bss() Processing BSS 'ee:a9:40:75:77:bf' with SSID: Vodafone Homespot, freq: 2437, rank: 56, strength: -9000, data_rate: 2.0
src/station.c:station_add_seen_bss() Processing BSS '52:a5:dc:d3:c0:78' with SSID: Vodafone Hotspot, freq: 2412, rank: 56, strength: -9000, data_rate: 2.0
src/station.c:station_add_seen_bss() Processing BSS 'ee:a9:40:75:77:9f' with SSID: Vodafone Hotspot, freq: 2437, rank: 56, strength: -9100, data_rate: 2.0
src/station.c:station_add_seen_bss() Processing BSS 'd4:86:60:c9:44:4e' with SSID: MagentaWLAN-UKTR, freq: 2437, rank: 28, strength: -9000, data_rate: 1.0
src/station.c:station_add_seen_bss() Added new Network "MagentaWLAN-UKTR" security psk
src/station.c:station_add_seen_bss() Processing BSS '3c:37:12:95:b8:61' with SSID: FRITZ!Box 7530 BG, freq: 2412, rank: 28, strength: -9000, data_rate: 1.0
src/station.c:station_add_seen_bss() Added new Network "FRITZ!Box 7530 BG" security psk
src/station.c:station_autoconnect_start() 
src/station.c:station_autoconnect_next() autoconnect: Trying SSID: Longbourn
src/station.c:station_autoconnect_next() autoconnect: 'dc:15:c8:12:e8:85' freq: 5520, rank: 58253, strength: -4700
src/netdev.c:netdev_cqm_rssi_update() 
src/wiphy.c:wiphy_radio_work_insert() Inserting work item 2
src/station.c:__station_connect_network() connecting to BSS dc:15:c8:12:e8:85
src/station.c:station_enter_state() Old State: autoconnect_quick, new state: connecting (auto)
src/scan.c:scan_cancel() Trying to cancel scan id 1 for wdev 3
src/wiphy.c:wiphy_radio_work_done() Work item 1 done
src/wiphy.c:wiphy_radio_work_next() Starting work item 2
src/netdev.c:netdev_mlme_notify() MLME notification New Station(19)
src/station.c:station_netdev_event() Associating
src/wiphy.c:wiphy_reg_notify() Notification of command Wiphy Reg Change(113)
src/wiphy.c:wiphy_update_reg_domain() New reg domain country code for phy0 is EU
src/netdev.c:netdev_mlme_notify() MLME notification Authenticate(37)
src/netdev.c:netdev_authenticate_event() 
src/netdev.c:netdev_mlme_notify() MLME notification Associate(38)
src/netdev.c:netdev_associate_event() 
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_get_oci_cb() Obtained OCI: freq: 5520, width: 5, center1: 5570, center2: 0
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_unicast_notify() Unicast notification Control Port Frame(129)
src/netdev.c:netdev_control_port_frame_event() 
src/eapol.c:eapol_handle_ptk_1_of_4() ifindex=3
src/netdev.c:netdev_mlme_notify() MLME notification Control Port TX Status(139)
src/netdev.c:netdev_unicast_notify() Unicast notification Control Port Frame(129)
src/netdev.c:netdev_control_port_frame_event() 
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/netdev.c:netdev_mlme_notify() MLME notification Control Port TX Status(139)
src/netdev.c:netdev_mlme_notify() MLME notification Notify CQM(64)
src/station.c:station_connect_cb() 3, result: 0
src/station.c:station_connect_ok() 
src/netconfig.c:netconfig_ipv6_select_and_install() IPV6 configuration disabled
src/wiphy.c:wiphy_radio_work_done() Work item 2 done
src/netdev.c:netdev_unicast_notify() Unicast notification Frame(59)
src/netdev.c:netdev_link_notify() event 16 on ifindex 3
src/netdev.c:netdev_mlme_notify() MLME notification Frame TX Status(60)
src/netdev.c:netdev_unicast_notify() Unicast notification Frame(59)
src/station.c:station_early_neighbor_report_cb() ifindex: 3, error: 0()
src/netconfig.c:netconfig_ipv4_dhcp_event_handler() DHCPv4 event 0
src/netconfig.c:netconfig_ifaddr_added() wlan0: ifaddr 192.168.178.39/24 broadcast (null)
src/netconfig.c:netconfig_gateway_to_arp() Gateway MAC is known, setting into ARP cache
src/resolve.c:resolve_systemd_set_dns() ifindex: 3
src/resolve.c:systemd_builder_add_dns() installing DNS: 192.168.178.1
src/resolve.c:resolve_systemd_set_domains() ifindex: 3
src/station.c:station_enter_state() Old State: connecting (auto), new state: connected
src/netdev.c:netdev_unicast_notify() Unicast notification Frame(59)
src/netdev.c:netdev_mlme_notify() MLME notification Frame TX Status(60)
src/netdev.c:netdev_mlme_notify() MLME notification Del Station(20)
src/netdev.c:netdev_link_notify() event 16 on ifindex 3
src/netdev.c:netdev_mlme_notify() MLME notification Deauthenticate(39)
src/netdev.c:netdev_deauthenticate_event() 
src/netdev.c:netdev_link_notify() event 16 on ifindex 3
src/netdev.c:netdev_mlme_notify() MLME notification Disconnect(48)
src/netdev.c:netdev_disconnect_event() 
Received Deauthentication event, reason: 3, from_ap: false
src/station.c:station_disconnect_event() 3
src/station.c:station_disassociated() 3
src/resolve.c:resolve_systemd_revert() ifindex: 3
src/station.c:station_reset_connection_state() 3
src/station.c:station_roam_state_clear() 3
src/station.c:station_enter_state() Old State: connected, new state: disconnected
src/station.c:station_enter_state() Old State: disconnected, new state: autoconnect_quick
src/wiphy.c:wiphy_radio_work_insert() Inserting work item 3
src/wiphy.c:wiphy_radio_work_next() Starting work item 3
src/netdev.c:netdev_link_notify() event 16 on ifindex 3
src/station.c:station_free() 
src/netconfig.c:netconfig_destroy() 
src/scan.c:scan_cancel() Trying to cancel scan id 3 for wdev 3
src/scan.c:scan_cancel() Scan is already started
src/wiphy.c:wiphy_radio_work_done() Work item 3 done
src/station.c:station_roam_state_clear() 3
src/rrm.c:rrm_station_watch_destroy() 

[-- Attachment #3: iwd-linux-5.15.txt --]
[-- Type: text/plain, Size: 23718 bytes --]

Wireless daemon version 1.27
src/main.c:main() Using configuration directory /etc/iwd
Loaded configuration from /etc/iwd/main.conf
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() 
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)
src/manager.c:manager_wiphy_dump_done() 
src/manager.c:manager_filtered_wiphy_dump_done() 
Wiphy: 0, Name: phy0
	Permanent Address: 2c:8d:b1:25:46:21
	2.4Ghz Band:
		Bitrates (non-HT):
			 1.0 Mbps
			 2.0 Mbps
			 5.5 Mbps
			11.0 Mbps
			 6.0 Mbps
			 9.0 Mbps
			12.0 Mbps
			18.0 Mbps
			24.0 Mbps
			36.0 Mbps
			48.0 Mbps
			54.0 Mbps
		HT Capabilities:
			HT40
			Short GI for 20Mhz
			Short GI for 40Mhz
		HT RX MCS indexes:
			0-15
	5Ghz Band:
		Bitrates (non-HT):
			 6.0 Mbps
			 9.0 Mbps
			12.0 Mbps
			18.0 Mbps
			24.0 Mbps
			36.0 Mbps
			48.0 Mbps
			54.0 Mbps
		HT Capabilities:
			HT40
			Short GI for 20Mhz
			Short GI for 40Mhz
		HT RX MCS indexes:
			0-15
		VHT Capabilities:
			160 Mhz operation
			Short GI for 80Mhz
			Short GI for 160 and 80 + 80 Mhz
			Max RX MCS: 0-9 for NSS: 2
			Max TX MCS: 0-9 for NSS: 2
	Ciphers: CCMP TKIP BIP
	Supported iftypes: ad-hoc station ap p2p-client p2p-go p2p-device
src/manager.c:manager_interface_dump_done() 
src/manager.c:manager_create_interfaces() creating wlan0
src/manager.c:manager_create_interfaces() creating wlan0-p2p
src/wiphy.c:wiphy_update_reg_domain() New reg domain country code for phy0 is EU
src/manager.c:manager_config_notify() Notification of command New Interface(7)
src/netdev.c:netdev_link_notify() event 16 on ifindex 5
src/manager.c:manager_new_station_interface_cb() 
src/netdev.c:netdev_create_from_genl() Created interface wlan0[5 6]
src/manager.c:manager_config_notify() Notification of command New Interface(7)
src/manager.c:manager_new_p2p_interface_cb() 
src/p2p.c:p2p_device_update_from_genl() Created P2P device 7
src/netdev.c:netdev_link_notify() event 16 on ifindex 5
src/wiphy.c:wiphy_reg_notify() Notification of command Wiphy Reg Change(113)
src/wiphy.c:wiphy_update_reg_domain() New reg domain country code for phy0 is XX
src/netdev.c:netdev_set_4addr() netdev: 5 use_4addr: 0
src/netdev.c:netdev_initial_up_cb() Interface 5 initialized
src/netconfig.c:netconfig_new() Starting netconfig for interface: 5
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/rrm.c:rrm_add_frame_watches() 
src/netdev.c:netdev_link_notify() event 16 on ifindex 5
src/netdev.c:netdev_link_notify() event 16 on ifindex 5
src/manager.c:manager_config_notify() Notification of command Set Interface(6)
src/scan.c:scan_notify() Scan notification Trigger Scan(33)
src/scan.c:scan_request_triggered() Active scan triggered for wdev 6
src/station.c:station_quick_scan_triggered() Quick scan triggered for wlan0
src/scan.c:scan_notify() Scan notification New Scan Results(34)
src/netdev.c:netdev_link_notify() event 16 on ifindex 5
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:scan_parse_bss_information_elements() Load: 26/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: 108/255
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:scan_parse_bss_information_elements() Load: 48/255
src/scan.c:scan_parse_advertisement_protocol() 
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:scan_parse_bss_information_elements() Load: 91/255
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:scan_parse_bss_information_elements() Load: 86/255
src/scan.c:scan_parse_advertisement_protocol() 
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: 34/255
src/scan.c:scan_parse_advertisement_protocol() 
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: 44/255
src/scan.c:scan_parse_advertisement_protocol() 
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:get_scan_callback() get_scan_callback
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:scan_parse_bss_information_elements() Load: 1/255
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 'dc:15:c8:12:e8:85' with SSID: Longbourn, freq: 5520, rank: 52428, strength: -4900, data_rate: 1560.0
src/station.c:station_add_seen_bss() Added new Network "Longbourn" security psk
src/station.c:station_add_seen_bss() Processing BSS 'dc:15:c8:12:e8:86' with SSID: Longbourn, freq: 2412, rank: 4854, strength: -4400, data_rate: 144.4
src/station.c:station_add_seen_bss() Processing BSS 'ec:a8:1f:36:d7:70' with SSID: Vodafone-D76C, freq: 2412, rank: 485, strength: -7900, data_rate: 14.4
src/station.c:station_add_seen_bss() Added new Network "Vodafone-D76C" security psk
src/station.c:station_add_seen_bss() Processing BSS 'd4:86:60:c9:44:4e' with SSID: MagentaWLAN-UKTR, freq: 2437, rank: 154, strength: -8600, data_rate: 5.5
src/station.c:station_add_seen_bss() Added new Network "MagentaWLAN-UKTR" security psk
src/station.c:station_add_seen_bss() Processing BSS '70:54:25:64:51:50' with SSID: Zauberkiste-2.4GHz, freq: 2462, rank: 56, strength: -8600, data_rate: 2.0
src/station.c:station_add_seen_bss() Added new Network "Zauberkiste-2.4GHz" security psk
src/station.c:station_add_seen_bss() Processing BSS '72:54:25:64:51:30' with SSID: Vodafone Homespot, freq: 2462, rank: 56, strength: -8600, data_rate: 2.0
src/station.c:station_add_seen_bss() Added new Network "Vodafone Homespot" security open
src/station.c:station_add_seen_bss() Processing BSS '72:54:25:64:51:10' with SSID: Vodafone Hotspot, freq: 2462, rank: 56, strength: -8700, data_rate: 2.0
src/station.c:station_add_seen_bss() Added new Network "Vodafone Hotspot" security open
src/station.c:station_add_seen_bss() Processing BSS 'a2:04:60:e0:31:a0' with SSID: FH-Gast, freq: 2447, rank: 56, strength: -8800, data_rate: 2.0
src/station.c:station_add_seen_bss() Added new Network "FH-Gast" security psk
src/station.c:station_add_seen_bss() Processing BSS '34:2c:c4:73:74:c3' with SSID: UPC2466083, freq: 2412, rank: 56, strength: -8800, data_rate: 2.0
src/station.c:station_add_seen_bss() Added new Network "UPC2466083" security psk
src/station.c:station_add_seen_bss() Processing BSS '06:a2:22:7e:c1:67' with SSID: , freq: 5500, rank: 56, strength: -8900, data_rate: 2.0
src/station.c:station_add_seen_bss() BSS has hidden SSID
src/station.c:station_add_seen_bss() Processing BSS 'd4:3f:cb:8d:10:74' with SSID: gorica, freq: 2462, rank: 56, strength: -8900, data_rate: 2.0
src/station.c:station_add_seen_bss() Added new Network "gorica" security psk
src/station.c:station_add_seen_bss() Processing BSS 'ee:a9:40:7d:4c:19' with SSID: Vodafone Hotspot, freq: 2437, rank: 56, strength: -8900, data_rate: 2.0
src/station.c:station_add_seen_bss() Processing BSS 'ee:a9:40:7d:4c:39' with SSID: Vodafone Homespot, freq: 2437, rank: 56, strength: -8900, data_rate: 2.0
src/station.c:station_add_seen_bss() Processing BSS 'ee:a9:40:75:77:9f' with SSID: Vodafone Hotspot, freq: 2437, rank: 56, strength: -8900, data_rate: 2.0
src/station.c:station_add_seen_bss() Processing BSS 'd4:3f:cb:95:a1:1e' with SSID: Vodafone-F1EB, freq: 2462, rank: 56, strength: -9000, data_rate: 2.0
src/station.c:station_add_seen_bss() Added new Network "Vodafone-F1EB" security psk
src/station.c:station_add_seen_bss() Processing BSS '3c:37:12:95:b8:61' with SSID: FRITZ!Box 7530 BG, freq: 2412, rank: 56, strength: -9100, data_rate: 2.0
src/station.c:station_add_seen_bss() Added new Network "FRITZ!Box 7530 BG" security psk
src/station.c:station_add_seen_bss() Processing BSS 'd4:e2:cb:17:83:d8' with SSID: Vodafone-83D4, freq: 2462, rank: 33, strength: -8900, data_rate: 1.0
src/station.c:station_add_seen_bss() Added new Network "Vodafone-83D4" security psk
src/station.c:station_add_seen_bss() Processing BSS '1c:9d:72:59:61:38' with SSID: BudSpencer, freq: 2437, rank: 33, strength: -8900, data_rate: 1.0
src/station.c:station_add_seen_bss() Added new Network "BudSpencer" security psk
src/station.c:station_add_seen_bss() Processing BSS 'a0:04:60:e0:31:af' with SSID: chfeje, freq: 2447, rank: 28, strength: -8900, data_rate: 1.0
src/station.c:station_add_seen_bss() Added new Network "chfeje" security psk
src/station.c:station_add_seen_bss() Processing BSS '38:10:d5:81:b8:be' with SSID: FRITZ!Box 7412, freq: 2412, rank: 28, strength: -9000, data_rate: 1.0
src/station.c:station_add_seen_bss() Added new Network "FRITZ!Box 7412" security psk
src/station.c:station_autoconnect_start() 
src/station.c:station_autoconnect_next() autoconnect: Trying SSID: Longbourn
src/station.c:station_autoconnect_next() autoconnect: 'dc:15:c8:12:e8:85' freq: 5520, rank: 52428, strength: -4900
src/netdev.c:netdev_cqm_rssi_update() 
src/wiphy.c:wiphy_radio_work_insert() Inserting work item 2
src/station.c:__station_connect_network() connecting to BSS dc:15:c8:12:e8:85
src/station.c:station_enter_state() Old State: autoconnect_quick, new state: connecting (auto)
src/scan.c:scan_cancel() Trying to cancel scan id 1 for wdev 6
src/wiphy.c:wiphy_radio_work_done() Work item 1 done
src/wiphy.c:wiphy_radio_work_next() Starting work item 2
src/netdev.c:netdev_mlme_notify() MLME notification New Station(19)
src/station.c:station_netdev_event() Associating
src/wiphy.c:wiphy_reg_notify() Notification of command Wiphy Reg Change(113)
src/wiphy.c:wiphy_update_reg_domain() New reg domain country code for phy0 is EU
src/netdev.c:netdev_mlme_notify() MLME notification Authenticate(37)
src/netdev.c:netdev_authenticate_event() 
src/netdev.c:netdev_mlme_notify() MLME notification Associate(38)
src/netdev.c:netdev_associate_event() 
src/netdev.c:netdev_link_notify() event 16 on ifindex 5
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 5
src/netdev.c:netdev_link_notify() event 16 on ifindex 5
src/netdev.c:netdev_get_oci_cb() Obtained OCI: freq: 5520, width: 5, center1: 5570, center2: 0
src/netdev.c:netdev_link_notify() event 16 on ifindex 5
src/netdev.c:netdev_unicast_notify() Unicast notification Control Port Frame(129)
src/netdev.c:netdev_control_port_frame_event() 
src/eapol.c:eapol_handle_ptk_1_of_4() ifindex=5
src/netdev.c:netdev_mlme_notify() MLME notification Control Port TX Status(139)
src/netdev.c:netdev_unicast_notify() Unicast notification Control Port Frame(129)
src/netdev.c:netdev_control_port_frame_event() 
src/eapol.c:eapol_handle_ptk_3_of_4() ifindex=5
src/netdev.c:netdev_set_gtk() 5
src/station.c:station_handshake_event() Setting keys
src/netdev.c:netdev_set_tk() 5
src/netdev.c:netdev_set_rekey_offload() 5
src/netdev.c:netdev_mlme_notify() MLME notification Control Port TX Status(139)
src/station.c:station_connect_cb() 5, result: 0
src/station.c:station_connect_ok() 
src/netconfig.c:netconfig_ipv6_select_and_install() IPV6 configuration disabled
src/wiphy.c:wiphy_radio_work_done() Work item 2 done
src/netdev.c:netdev_link_notify() event 16 on ifindex 5
src/netdev.c:netdev_unicast_notify() Unicast notification Frame(59)
src/netdev.c:netdev_mlme_notify() MLME notification Frame TX Status(60)
src/netdev.c:netdev_unicast_notify() Unicast notification Frame(59)
src/station.c:station_early_neighbor_report_cb() ifindex: 5, error: 0()
src/netdev.c:netdev_mlme_notify() MLME notification Notify CQM(64)
src/netconfig.c:netconfig_ipv4_dhcp_event_handler() DHCPv4 event 0
src/netconfig.c:netconfig_ifaddr_added() wlan0: ifaddr 192.168.178.39/24 broadcast (null)
src/netconfig.c:netconfig_gateway_to_arp() Gateway MAC is known, setting into ARP cache
src/resolve.c:resolve_systemd_set_dns() ifindex: 5
src/resolve.c:systemd_builder_add_dns() installing DNS: 192.168.178.1
src/resolve.c:resolve_systemd_set_domains() ifindex: 5
src/station.c:station_enter_state() Old State: connecting (auto), new state: connected
src/netdev.c:netdev_unicast_notify() Unicast notification Frame(59)
src/netdev.c:netdev_mlme_notify() MLME notification Frame TX Status(60)
src/netdev.c:netdev_mlme_notify() MLME notification Notify CQM(64)
src/netdev.c:netdev_link_notify() event 16 on ifindex 5
src/netdev.c:netdev_mlme_notify() MLME notification Del Station(20)
src/netdev.c:netdev_link_notify() event 16 on ifindex 5
src/netdev.c:netdev_mlme_notify() MLME notification Deauthenticate(39)
src/netdev.c:netdev_deauthenticate_event() 
src/netdev.c:netdev_mlme_notify() MLME notification Disconnect(48)
src/netdev.c:netdev_disconnect_event() 
Received Deauthentication event, reason: 3, from_ap: false
src/station.c:station_disconnect_event() 5
src/station.c:station_disassociated() 5
src/resolve.c:resolve_systemd_revert() ifindex: 5
src/station.c:station_reset_connection_state() 5
src/station.c:station_roam_state_clear() 5
src/station.c:station_enter_state() Old State: connected, new state: disconnected
src/station.c:station_enter_state() Old State: disconnected, new state: autoconnect_quick
src/wiphy.c:wiphy_radio_work_insert() Inserting work item 3
src/wiphy.c:wiphy_radio_work_next() Starting work item 3
src/wiphy.c:wiphy_reg_notify() Notification of command Wiphy Reg Change(113)
src/wiphy.c:wiphy_update_reg_domain() New reg domain country code for phy0 is XX
src/scan.c:scan_notify() Scan notification Trigger Scan(33)
src/netconfig.c:netconfig_ifaddr_deleted() ifaddr 192.168.178.39/24
src/scan.c:scan_request_triggered() Active scan triggered for wdev 6
src/station.c:station_quick_scan_triggered() Quick scan triggered for wlan0
src/scan.c:scan_notify() Scan notification New Scan Results(34)
src/netdev.c:netdev_link_notify() event 16 on ifindex 5
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:scan_parse_bss_information_elements() Load: 31/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: 106/255
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:scan_parse_bss_information_elements() Load: 49/255
src/scan.c:scan_parse_advertisement_protocol() 
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:scan_parse_bss_information_elements() Load: 129/255
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:scan_parse_bss_information_elements() Load: 75/255
src/scan.c:scan_parse_advertisement_protocol() 
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: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: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:get_scan_callback() get_scan_callback
src/scan.c:scan_parse_bss_information_elements() Load: 44/255
src/scan.c:scan_parse_advertisement_protocol() 
src/scan.c:get_scan_callback() get_scan_callback
src/scan.c:scan_parse_bss_information_elements() Load: 1/255
src/scan.c:get_scan_done() get_scan_done
src/station.c:station_add_seen_bss() Processing BSS 'dc:15:c8:12:e8:85' with SSID: Longbourn, freq: 5520, rank: 52428, strength: -4900, data_rate: 1560.0
src/station.c:station_add_seen_bss() Processing BSS 'dc:15:c8:12:e8:86' with SSID: Longbourn, freq: 2412, rank: 4854, strength: -4800, data_rate: 144.4
src/station.c:station_add_seen_bss() Processing BSS 'ec:a8:1f:36:d7:70' with SSID: Vodafone-D76C, freq: 2412, rank: 485, strength: -7800, data_rate: 14.4
src/station.c:station_add_seen_bss() Processing BSS 'd4:e2:cb:17:83:d8' with SSID: Vodafone-83D4, freq: 2462, rank: 67, strength: -8700, data_rate: 2.0
src/station.c:station_add_seen_bss() Processing BSS '70:54:25:64:51:50' with SSID: Zauberkiste-2.4GHz, freq: 2462, rank: 56, strength: -8600, data_rate: 2.0
src/station.c:station_add_seen_bss() Processing BSS '72:54:25:64:51:30' with SSID: Vodafone Homespot, freq: 2462, rank: 56, strength: -8600, data_rate: 2.0
src/station.c:station_add_seen_bss() Processing BSS 'd4:3f:cb:8d:10:74' with SSID: gorica, freq: 2462, rank: 56, strength: -8700, data_rate: 2.0
src/station.c:station_add_seen_bss() Processing BSS '72:54:25:64:51:10' with SSID: Vodafone Hotspot, freq: 2462, rank: 56, strength: -8800, data_rate: 2.0
src/station.c:station_add_seen_bss() Processing BSS 'a0:04:60:e0:31:af' with SSID: chfeje, freq: 2447, rank: 56, strength: -8800, data_rate: 2.0
src/station.c:station_add_seen_bss() Processing BSS 'ee:a9:40:75:77:9f' with SSID: Vodafone Hotspot, freq: 2437, rank: 56, strength: -8800, data_rate: 2.0
src/station.c:station_add_seen_bss() Processing BSS '34:2c:c4:73:74:c3' with SSID: UPC2466083, freq: 2412, rank: 56, strength: -8800, data_rate: 2.0
src/station.c:station_add_seen_bss() Processing BSS 'ee:a9:40:75:77:bf' with SSID: Vodafone Homespot, freq: 2437, rank: 56, strength: -8900, data_rate: 2.0
src/station.c:station_add_seen_bss() Processing BSS 'd6:3f:cb:95:ba:b0' with SSID: Vodafone Homespot, freq: 2462, rank: 56, strength: -9000, data_rate: 2.0
src/station.c:station_add_seen_bss() Processing BSS 'ec:a9:40:75:77:8f' with SSID: Vodafone-A04B, freq: 2437, rank: 56, strength: -9000, data_rate: 2.0
src/station.c:station_add_seen_bss() Added new Network "Vodafone-A04B" security psk
src/station.c:station_add_seen_bss() Processing BSS 'd4:86:60:c9:44:4e' with SSID: MagentaWLAN-UKTR, freq: 2437, rank: 56, strength: -9100, data_rate: 2.0
src/station.c:station_add_seen_bss() Processing BSS '3c:37:12:95:b8:61' with SSID: FRITZ!Box 7530 BG, freq: 2412, rank: 56, strength: -9100, data_rate: 2.0
src/station.c:station_add_seen_bss() Processing BSS '4a:4e:fc:92:fe:98' with SSID: Vodafone Hotspot, freq: 2437, rank: 56, strength: -9200, data_rate: 2.0
src/station.c:station_add_seen_bss() Processing BSS 'ee:a9:40:7d:4c:19' with SSID: Vodafone Hotspot, freq: 2437, rank: 56, strength: -9200, data_rate: 2.0
src/station.c:station_add_seen_bss() Processing BSS 'a2:04:60:e0:31:a0' with SSID: FH-Gast, freq: 2447, rank: 28, strength: -8900, data_rate: 1.0
src/station.c:station_add_seen_bss() Processing BSS '38:10:d5:81:b8:be' with SSID: FRITZ!Box 7412, freq: 2412, rank: 28, strength: -8900, data_rate: 1.0
src/station.c:station_add_seen_bss() Processing BSS '06:a2:22:7e:c1:67' with SSID: , freq: 5500, rank: 56, strength: -8900, data_rate: 2.0
src/station.c:station_add_seen_bss() BSS has hidden SSID
src/station.c:station_add_seen_bss() Processing BSS 'ee:a9:40:7d:4c:39' with SSID: Vodafone Homespot, freq: 2437, rank: 56, strength: -8900, data_rate: 2.0
src/station.c:station_add_seen_bss() Processing BSS 'd4:3f:cb:95:a1:1e' with SSID: Vodafone-F1EB, freq: 2462, rank: 56, strength: -9000, data_rate: 2.0
src/station.c:station_add_seen_bss() Processing BSS '1c:9d:72:59:61:38' with SSID: BudSpencer, freq: 2437, rank: 33, strength: -8900, data_rate: 1.0
src/station.c:station_autoconnect_start() 
src/station.c:station_autoconnect_next() autoconnect: Trying SSID: Longbourn
src/station.c:station_autoconnect_next() autoconnect: 'dc:15:c8:12:e8:85' freq: 5520, rank: 52428, strength: -4900
src/netdev.c:netdev_cqm_rssi_update() 
src/wiphy.c:wiphy_radio_work_insert() Inserting work item 4
src/station.c:__station_connect_network() connecting to BSS dc:15:c8:12:e8:85
src/station.c:station_enter_state() Old State: autoconnect_quick, new state: connecting (auto)
src/scan.c:scan_cancel() Trying to cancel scan id 3 for wdev 6
src/wiphy.c:wiphy_radio_work_done() Work item 3 done
src/wiphy.c:wiphy_radio_work_next() Starting work item 4
src/netdev.c:netdev_mlme_notify() MLME notification New Station(19)
src/station.c:station_netdev_event() Associating
src/wiphy.c:wiphy_reg_notify() Notification of command Wiphy Reg Change(113)
src/wiphy.c:wiphy_update_reg_domain() New reg domain country code for phy0 is EU
src/netdev.c:netdev_mlme_notify() MLME notification Authenticate(37)
src/netdev.c:netdev_authenticate_event() 
src/netdev.c:netdev_mlme_notify() MLME notification Associate(38)
src/netdev.c:netdev_associate_event() 
src/netdev.c:netdev_link_notify() event 16 on ifindex 5
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 5
src/netdev.c:netdev_link_notify() event 16 on ifindex 5
src/netdev.c:netdev_get_oci_cb() Obtained OCI: freq: 5520, width: 5, center1: 5570, center2: 0
src/netdev.c:netdev_link_notify() event 16 on ifindex 5
src/netdev.c:netdev_unicast_notify() Unicast notification Control Port Frame(129)
src/netdev.c:netdev_control_port_frame_event() 
src/eapol.c:eapol_handle_ptk_1_of_4() ifindex=5
src/netdev.c:netdev_mlme_notify() MLME notification Control Port TX Status(139)
src/netdev.c:netdev_unicast_notify() Unicast notification Control Port Frame(129)
src/netdev.c:netdev_control_port_frame_event() 
src/eapol.c:eapol_handle_ptk_3_of_4() ifindex=5
src/netdev.c:netdev_set_gtk() 5
src/station.c:station_handshake_event() Setting keys
src/netdev.c:netdev_set_tk() 5
src/netdev.c:netdev_set_rekey_offload() 5
src/netdev.c:netdev_mlme_notify() MLME notification Control Port TX Status(139)
src/station.c:station_connect_cb() 5, result: 0
src/station.c:station_connect_ok() 
src/netconfig.c:netconfig_ipv6_select_and_install() IPV6 configuration disabled
src/wiphy.c:wiphy_radio_work_done() Work item 4 done
src/netdev.c:netdev_link_notify() event 16 on ifindex 5
src/netdev.c:netdev_mlme_notify() MLME notification Frame TX Status(60)
src/netdev.c:netdev_unicast_notify() Unicast notification Frame(59)
src/station.c:station_early_neighbor_report_cb() ifindex: 5, error: 0()
src/netconfig.c:netconfig_ipv4_dhcp_event_handler() DHCPv4 event 0
src/netconfig.c:netconfig_ifaddr_added() wlan0: ifaddr 192.168.178.39/24 broadcast (null)
src/netconfig.c:netconfig_gateway_to_arp() Gateway MAC is known, setting into ARP cache
src/resolve.c:resolve_systemd_set_dns() ifindex: 5
src/resolve.c:systemd_builder_add_dns() installing DNS: 192.168.178.1
src/resolve.c:resolve_systemd_set_domains() ifindex: 5
src/station.c:station_enter_state() Old State: connecting (auto), new state: connected
src/netdev.c:netdev_mlme_notify() MLME notification Notify CQM(64)
src/netdev.c:netdev_unicast_notify() Unicast notification Frame(59)
src/netdev.c:netdev_mlme_notify() MLME notification Frame TX Status(60)
src/netdev.c:netdev_unicast_notify() Unicast notification Frame(59)
src/rrm.c:rrm_frame_watch_cb() Max requests per second reached, ignoring request

^ permalink raw reply	[flat|nested] 6+ messages in thread
* Re: iwd needs restart after suspending
  2022-08-12 14:09 ` Joachim Breitner
@ 2022-08-12 15:01   ` Denis Kenzior
  2022-08-12 15:53     ` Joachim Breitner
  0 siblings, 1 reply; 6+ messages in thread
From: Denis Kenzior @ 2022-08-12 15:01 UTC (permalink / raw)
  To: Joachim Breitner, iwd

Hi Joachim,

> I recorded the output of iwd -d on 5.15 and 5.19, see attachement. The
> relevant bit seems to be
> 

We should add this to our debug output, but what driver / hardware are you using?

> src/station.c:station_enter_state() Old State: connected, new state: disconnected
> src/station.c:station_enter_state() Old State: disconnected, new state: autoconnect_quick
> src/wiphy.c:wiphy_radio_work_insert() Inserting work item 3
> src/wiphy.c:wiphy_radio_work_next() Starting work item 3
> src/wiphy.c:wiphy_reg_notify() Notification of command Wiphy Reg Change(113)
> src/wiphy.c:wiphy_update_reg_domain() New reg domain country code for phy0 is XX
> src/scan.c:scan_notify() Scan notification Trigger Scan(33)
> src/netconfig.c:netconfig_ifaddr_deleted() ifaddr 192.168.178.39/24
> src/scan.c:scan_request_triggered() Active scan triggered for wdev 6
> src/station.c:station_quick_scan_triggered() Quick scan triggered for wlan0
> src/scan.c:scan_notify() Scan notification New Scan Results(34)
> src/netdev.c:netdev_link_notify() event 16 on ifindex 5
> src/scan.c:get_scan_callback() get_scan_callback
> src/scan.c:scan_parse_bss_information_elements() Load: 31/255
> src/scan.c:get_scan_callback() get_scan_callback
> src/scan.c:get_scan_callback() get_scan_callback
> 
>                             

So with 5.15, the underlying netdev is disconnected.  We get notified of that 
and start scanning.

> with 5.15 and
> 
> src/station.c:station_enter_state() Old State: connected, new state:
> disconnected
> src/station.c:station_enter_state() Old State: disconnected, new state:
> autoconnect_quick
> src/wiphy.c:wiphy_radio_work_insert() Inserting work item 3
> src/wiphy.c:wiphy_radio_work_next() Starting work item 3
> src/netdev.c:netdev_link_notify() event 16 on ifindex 3

Here, we receive what looks to be an IFDOWN event.

> src/station.c:station_free()
> src/netconfig.c:netconfig_destroy()
> src/scan.c:scan_cancel() Trying to cancel scan id 3 for wdev 3
> src/scan.c:scan_cancel() Scan is already started
> src/wiphy.c:wiphy_radio_work_done() Work item 3 done
> src/station.c:station_roam_state_clear() 3
> src/rrm.c:rrm_station_watch_destroy()
> 

So the question is why is the kernel changing this behavior?  iwd is not aware 
of resume/suspend, so I'm not sure we can tell whether the ifdown event came 
from the user manually bringing down the device or due to suspend / resume.

What does rfkill look like on 5.15 & 5.19 after resume?

Regards,
-Denis

^ permalink raw reply	[flat|nested] 6+ messages in thread
* Re: iwd needs restart after suspending
  2022-08-12 15:53     ` Joachim Breitner
@ 2022-08-12 15:45       ` Denis Kenzior
  2022-08-12 16:16         ` Joachim Breitner
  0 siblings, 1 reply; 6+ messages in thread
From: Denis Kenzior @ 2022-08-12 15:45 UTC (permalink / raw)
  To: Joachim Breitner, iwd

Hi Joachim,

>    Model: "Intel Wi-Fi 6 AX201"

Ok, we should have one of these to test on our side.  But so far I see nothing 
to indicate that this is an iwd bug.  Seems like a kernel regression?  I would 
file a bug against the kernel or check if something like this already exists. 
See bugzilla.kernel.org.

>>
>> So the question is why is the kernel changing this behavior?
> 
> I could narrow it down to 5.15 vs. 5.17, if that helps. But
> linux/drivers/net/wireless/intel/iwlwifi seems to be a rather busy
> directory:
> https://github.com/torvalds/linux/commits/v5.17/drivers/net/wireless/intel/iwlwifi

That would help, but ideally we need a bisected commit or something else 
concrete to work with.  Do you see anything suspicious in dmesg?

Regards,
-Denis

^ permalink raw reply	[flat|nested] 6+ messages in thread
* Re: iwd needs restart after suspending
  2022-08-12 15:01   ` Denis Kenzior
@ 2022-08-12 15:53     ` Joachim Breitner
  2022-08-12 15:45       ` Denis Kenzior
  0 siblings, 1 reply; 6+ messages in thread
From: Joachim Breitner @ 2022-08-12 15:53 UTC (permalink / raw)
  To: Denis Kenzior, iwd

Dear Denis,


Am Freitag, dem 12.08.2022 um 10:01 -0500 schrieb Denis Kenzior:
> > I recorded the output of iwd -d on 5.15 and 5.19, see attachement. The
> > relevant bit seems to be
> > 
> 
> We should add this to our debug output, but what driver / hardware are you using?


~ $ hwinfo --wlan
06: PCI 14.3: 0282 WLAN controller                              
  [Created at pci.386]
  Unique ID: y9sn.qVqUKmQ3GD6
  SysFS ID: /devices/pci0000:00/0000:00:14.3
  SysFS BusID: 0000:00:14.3
  Hardware Class: network
  Model: "Intel Wi-Fi 6 AX201"
  Vendor: pci 0x8086 "Intel Corporation"
  Device: pci 0xa0f0 "Wi-Fi 6 AX201"
  SubVendor: pci 0x8086 "Intel Corporation"
  SubDevice: pci 0x0070 
  Revision: 0x20
  Driver: "iwlwifi"
  Driver Modules: "iwlwifi"
  Device File: wlan0
  Features: WLAN
  Memory Range: 0x603d1cc000-0x603d1cffff (rw,non-prefetchable)
  IRQ: 16 (no events)
  HW Address: 2c:8d:b1:25:46:21
  Permanent HW Address: 2c:8d:b1:25:46:21
  Link detected: yes
  WLAN channels: 1 2 3 4 5 6 7 8 9 10 11 12 13 36 40 44 48 52 56 60 64 100 104 108 112 116 120 124 128 132 136 140
  WLAN frequencies: 2.412 2.417 2.422 2.427 2.432 2.437 2.442 2.447 2.452 2.457 2.462 2.467 2.472 5.18 5.2 5.22 5.24 5.26 5.28 5.3 5.32 5.5 5.52 5.54 5.56 5.58 5.6 5.62 5.64 5.66 5.68 5.7
  WLAN encryption modes: WEP40 WEP104 TKIP CCMP
  WLAN authentication modes: open sharedkey wpa-psk wpa-eap
  Module Alias: "pci:v00008086d0000A0F0sv00008086sd00000070bc02sc80i00"
  Config Status: cfg=new, avail=yes, need=no, active=unknown

> 
> So the question is why is the kernel changing this behavior?

I could narrow it down to 5.15 vs. 5.17, if that helps. But 
linux/drivers/net/wireless/intel/iwlwifi seems to be a rather busy
directory:
https://github.com/torvalds/linux/commits/v5.17/drivers/net/wireless/intel/iwlwifi

>   iwd is not aware 
> of resume/suspend, so I'm not sure we can tell whether the ifdown event came 
> from the user manually bringing down the device or due to suspend / resume.
> 
> What does rfkill look like on 5.15 & 5.19 after resume?


On 5.19, before suspend, after suspend and after restarting iwd it is
always simply

~ $ LANG=C rfkill
ID TYPE      DEVICE                   SOFT      HARD
 0 bluetooth tpacpi_bluetooth_sw unblocked unblocked
 1 bluetooth hci0                unblocked unblocked
 2 wlan      phy0                unblocked unblocked

Cheers,
Joachim

-- 
Joachim Breitner
  mail@joachim-breitner.de
  http://www.joachim-breitner.de/


^ permalink raw reply	[flat|nested] 6+ messages in thread
* Re: iwd needs restart after suspending
  2022-08-12 15:45       ` Denis Kenzior
@ 2022-08-12 16:16         ` Joachim Breitner
  0 siblings, 0 replies; 6+ messages in thread
From: Joachim Breitner @ 2022-08-12 16:16 UTC (permalink / raw)
  To: Denis Kenzior, iwd

Hi,

Am Freitag, dem 12.08.2022 um 10:45 -0500 schrieb Denis Kenzior:

> > > 
> > > So the question is why is the kernel changing this behavior?
> > 
> > I could narrow it down to 5.15 vs. 5.17, if that helps. But
> > linux/drivers/net/wireless/intel/iwlwifi seems to be a rather busy
> > directory:
> > https://github.com/torvalds/linux/commits/v5.17/drivers/net/wireless/intel/iwlwifi
> 
> That would help, but ideally we need a bisected commit or something else 
> concrete to work with.

Yeah, but bisecting this with all the manual rebuilding, rebooting,
suspending sounds daunting…

>   Do you see anything suspicious in dmesg?

Hmm, maybe this is suspicious?

[ 6215.382573] PM: suspend entry (s2idle)
[ 6215.391000] Filesystems sync: 0.008 seconds
[ 6215.514851] Freezing user space processes ... (elapsed 0.001 seconds) done.
[ 6215.516769] OOM killer disabled.
[ 6215.516781] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[ 6215.517980] printk: Suspending console(s) (use no_console_suspend to debug)
[ 6215.518444] wlan0: deauthenticating from dc:15:c8:12:e8:85 by local choice (Reason: 3=DEAUTH_LEAVING)
[ 6215.638139] iwlmei 0000:00:16.0-13280904-7792-4fcb-a1aa-5e70cbb1e865: Couldn't get ACK from CSME on HOST_GOES_DOWN message
[ 6215.638250] iwlmei 0000:00:16.0-13280904-7792-4fcb-a1aa-5e70cbb1e865: failed to send the SAP_ME_MSG_CHECK_SHARED_AREA message -19
[ 6216.985516] ACPI: EC: interrupt blocked
[ 6220.116906] ACPI: EC: interrupt unblocked
[ 6220.412349] i2c_hid_acpi i2c-ELAN0672:00: i2c_hid_get_input: incomplete report (14/65280)
[ 6220.437632] nvme nvme0: Shutdown timeout set to 10 seconds
[ 6220.439318] nvme nvme0: 8/0/0 default/read/poll queues
[ 6220.694608] OOM killer enabled.
[ 6220.694611] Restarting tasks ... 
[ 6220.694710] usb 3-3: USB disconnect, device number 7
[ 6220.695734] done.
[ 6220.700829] mei_hdcp 0000:00:16.0-b638ab7e-94e2-4ea2-a552-d1c54b627f04: bound 0000:00:02.0 (ops i915_hdcp_component_ops [i915])
[ 6220.706607] thermal thermal_zone7: failed to read out thermal zone (-61)
[ 6220.810825] PM: suspend exit
[ 6220.811417] usb 3-3: new full-speed USB device number 8 using xhci_hcd
[ 6220.940161] usb 3-3: New USB device found, idVendor=06cb, idProduct=00fc, bcdDevice= 0.00
[ 6220.940169] usb 3-3: New USB device strings: Mfr=0, Product=0, SerialNumber=1
[ 6220.940172] usb 3-3: SerialNumber: ce8cf4b20507

ah, googling for that message leads to this thread, which seems highly
relevant, and it seems upstream knows about it:
https://www.spinics.net/lists/linux-wireless/msg223249.html

Unfortunately, no resolution in that thread. I’ll try to follow up
there.

Cheers,
Joachim


-- 
Joachim Breitner
  mail@joachim-breitner.de
  http://www.joachim-breitner.de/


^ permalink raw reply	[flat|nested] 6+ messages in thread
end of thread, other threads:[~2022-08-12 16:16 UTC | newest]

Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2022-08-12 12:08 iwd needs restart after suspending Joachim Breitner
2022-08-12 14:09 ` Joachim Breitner
2022-08-12 15:01   ` Denis Kenzior
2022-08-12 15:53     ` Joachim Breitner
2022-08-12 15:45       ` Denis Kenzior
2022-08-12 16:16         ` Joachim Breitner

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.