kernel-packages team mailing list archive
-
kernel-packages team
-
Mailing list archive
-
Message #176123
[Bug 1578796] [NEW] 1.127.22 causes wifi instability on Intel N7260 chipset
Public bug reported:
OS: Linux Mint 17 Qiana (based on Ubuntu 14.04 Trusty)
Package Version: linux-firmware 1.127.22.0
After upgrading to 1.127.22, my wifi on my lenovo x240 became unstable.
It would connect, then after less than ten minutes it would somehow
disassociate from the AP, and only cycling the hardware wifi switch
would bring it back. A typical portion of /var/log/syslog during the
course of the problem would look like:
May 2 19:43:54 MACHINENAME NetworkManager[1063]: <info> (wlan0): bringing up device.
May 2 19:43:54 MACHINENAME kernel: [57059.429299] iwlwifi 0000:03:00.0: L1 Enabled; Disabling L0S
May 2 19:43:54 MACHINENAME kernel: [57059.430096] iwlwifi 0000:03:00.0: L1 Enabled; Disabling L0S
May 2 19:43:54 MACHINENAME NetworkManager[1063]: <info> WiFi hardware radio set enabled
May 2 19:43:54 MACHINENAME NetworkManager[1063]: <info> WiFi now enabled by radio killswitch
May 2 19:43:54 MACHINENAME kernel: [57059.447505] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
May 2 19:43:54 MACHINENAME NetworkManager[1063]: <info> (wlan0) supports 5 scan SSIDs
May 2 19:43:54 MACHINENAME NetworkManager[1063]: <info> (wlan0): supplicant interface state: starting -> ready
May 2 19:43:54 MACHINENAME NetworkManager[1063]: <info> (wlan0): device state change: unavailable -> disconnected (reason 'supplicant-available') [20 30 42]
May 2 19:43:54 MACHINENAME NetworkManager[1063]: <warn> Trying to remove a non-existant call id.
May 2 19:43:54 MACHINENAME NetworkManager[1063]: <info> (wlan0): supplicant interface state: ready -> disconnected
May 2 19:43:54 MACHINENAME NetworkManager[1063]: <info> (wlan0) supports 5 scan SSIDs
May 2 19:43:54 MACHINENAME wpa_supplicant[1726]: wlan0: Reject scan trigger since one is already pending
May 2 19:43:54 MACHINENAME wpa_supplicant[1726]: wlan0: CTRL-EVENT-SCAN-STARTED
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): supplicant interface state: disconnected -> inactive
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Auto-activating connection 'Auto XXXXX'.
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) starting connection 'Auto XXXXX'
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> NetworkManager state is now CONNECTING
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0]
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0/wireless): access point 'Auto XXXXX' has security, but secrets are required.
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): device state change: config -> need-auth (reason 'none') [50 60 0]
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): device state change: need-auth -> prepare (reason 'none') [60 40 0]
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0]
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0/wireless): connection 'Auto XXXXX' has security, and secrets exist. No new secrets needed.
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Config: added 'ssid' value 'XXXXX'
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Config: added 'scan_ssid' value '1'
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Config: added 'key_mgmt' value 'WPA-PSK'
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Config: added 'auth_alg' value 'OPEN'
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Config: added 'psk' value '<omitted>'
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Config: set interface ap_scan to 1
May 2 19:43:55 MACHINENAME wpa_supplicant[1726]: wlan0: SME: Trying to authenticate with XX:XX:XX:XX:XX:XX (SSID='XXXXX' freq=2447 MHz)
May 2 19:43:55 MACHINENAME kernel: [57059.971562] wlan0: authenticate with XX:XX:XX:XX:XX:XX
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): supplicant interface state: inactive -> authenticating
May 2 19:43:55 MACHINENAME kernel: [57059.975238] wlan0: send auth to XX:XX:XX:XX:XX:XX (try 1/3)
May 2 19:43:55 MACHINENAME wpa_supplicant[1726]: wlan0: Trying to associate with XX:XX:XX:XX:XX:XX (SSID='XXXXX' freq=2447 MHz)
May 2 19:43:55 MACHINENAME kernel: [57059.977372] wlan0: authenticated
May 2 19:43:55 MACHINENAME kernel: [57059.981323] wlan0: associate with XX:XX:XX:XX:XX:XX (try 1/3)
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): supplicant interface state: authenticating -> associating
May 2 19:43:55 MACHINENAME kernel: [57059.985407] wlan0: RX AssocResp from XX:XX:XX:XX:XX:XX (capab=0x1411 status=0 aid=3)
May 2 19:43:55 MACHINENAME wpa_supplicant[1726]: wlan0: Associated with XX:XX:XX:XX:XX:XX
May 2 19:43:55 MACHINENAME kernel: [57059.989688] wlan0: associated
May 2 19:43:55 MACHINENAME kernel: [57059.989720] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): supplicant interface state: associating -> 4-way handshake
May 2 19:43:55 MACHINENAME wpa_supplicant[1726]: wlan0: WPA: Key negotiation completed with XX:XX:XX:XX:XX:XX [PTK=CCMP GTK=CCMP]
May 2 19:43:55 MACHINENAME wpa_supplicant[1726]: wlan0: CTRL-EVENT-CONNECTED - Connection to XX:XX:XX:XX:XX:XX completed [id=0 id_str=]
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): supplicant interface state: 4-way handshake -> completed
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful. Connected to wireless network 'XXXXX'.
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled.
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) started...
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): device state change: config -> ip-config (reason 'none') [50 70 0]
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Beginning DHCPv4 transaction (timeout in 45 seconds)
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> dhclient started with pid 25167
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Beginning IP6 addrconf.
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete.
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): DHCPv4 state changed nbi -> preinit
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): DHCPv4 state changed preinit -> reboot
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> address 192.168.0.5
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> prefix 24 (255.255.255.0)
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> gateway 192.168.0.1
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> nameserver '192.168.0.1'
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 5 of 5 (IPv4 Configure Commit) scheduled...
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 5 of 5 (IPv4 Commit) started...
May 2 19:43:56 MACHINENAME NetworkManager[1063]: <info> (wlan0): device state change: ip-config -> secondaries (reason 'none') [70 90 0]
May 2 19:43:56 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 5 of 5 (IPv4 Commit) complete.
May 2 19:43:56 MACHINENAME NetworkManager[1063]: <info> (wlan0): device state change: secondaries -> activated (reason 'none') [90 100 0]
May 2 19:43:56 MACHINENAME NetworkManager[1063]: <info> NetworkManager state is now CONNECTED_GLOBAL
May 2 19:43:56 MACHINENAME NetworkManager[1063]: <info> Policy set 'Auto XXXXX' (wlan0) as default for IPv4 routing and DNS.
May 2 19:43:56 MACHINENAME NetworkManager[1063]: <info> Writing DNS information to /sbin/resolvconf
May 2 19:43:56 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) successful, device activated.
May 2 19:43:56 MACHINENAME dbus[575]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
May 2 19:43:56 MACHINENAME dbus[575]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
May 2 19:44:15 MACHINENAME NetworkManager[1063]: <info> (wlan0): IP6 addrconf timed out or failed.
May 2 19:44:15 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 4 of 5 (IPv6 Configure Timeout) scheduled...
May 2 19:44:15 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 4 of 5 (IPv6 Configure Timeout) started...
May 2 19:44:15 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 4 of 5 (IPv6 Configure Timeout) complete.
May 2 19:44:17 MACHINENAME wpa_supplicant[1726]: wlan0: CTRL-EVENT-SCAN-STARTED
May 2 19:44:51 MACHINENAME kernel: [57116.406291] e1000e 0000:00:19.0: irq 61 for MSI/MSI-X
May 2 19:47:45 MACHINENAME kernel: [57290.016074] thinkpad_ec: thinkpad_ec_request_row: arg0 rejected: (0x01:0x00)->0x00
May 2 19:47:45 MACHINENAME kernel: [57290.016080] thinkpad_ec: thinkpad_ec_read_row: failed requesting row: (0x01:0x00)->0xfffffffb
May 2 19:47:45 MACHINENAME kernel: [57290.016082] thinkpad_ec: initial ec test failed
May 2 19:47:45 MACHINENAME kernel: [57290.105637] thinkpad_acpi: EC reports that Thermal Table has changed
May 2 19:47:45 MACHINENAME anacron[25964]: Anacron 2.3 started on 2016-05-02
May 2 19:47:45 MACHINENAME anacron[25964]: Normal exit (0 jobs run)
May 2 19:48:55 MACHINENAME kernel: [57360.202372] wlan0: disassociated from XX:XX:XX:XX:XX:XX (Reason: 7)
May 2 19:48:55 MACHINENAME hostapd: wlan0: STA XX:XX:XX:XX:XX:XX IEEE 802.11: disassociated
May 2 19:47:26 MACHINENAME wpa_supplicant[1726]: message repeated 3 times: [ wlan0: CTRL-EVENT-SCAN-STARTED ]
May 2 19:48:55 MACHINENAME wpa_supplicant[1726]: wlan0: CTRL-EVENT-DISCONNECTED bssid=XX:XX:XX:XX:XX:XX reason=7
May 2 19:48:55 MACHINENAME wpa_supplicant[1726]: wlan0: SME: Trying to authenticate with XX:XX:XX:XX:XX:XX (SSID='XXXXX' freq=2447 MHz)
May 2 19:48:55 MACHINENAME NetworkManager[1063]: <warn> Connection disconnected (reason 7)
May 2 19:48:55 MACHINENAME kernel: [57360.248867] wlan0: deauthenticating from XX:XX:XX:XX:XX:XX by local choice (reason=3)
May 2 19:48:55 MACHINENAME kernel: [57360.248950] cfg80211: Calling CRDA to update world regulatory domain
May 2 19:48:55 MACHINENAME wpa_supplicant[1726]: wlan0: CTRL-EVENT-SCAN-STARTED
May 2 19:48:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): supplicant interface state: completed -> authenticating
May 2 19:48:55 MACHINENAME kernel: [57360.256323] cfg80211: World regulatory domain updated:
May 2 19:48:55 MACHINENAME kernel: [57360.256331] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
May 2 19:48:55 MACHINENAME kernel: [57360.256337] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
May 2 19:48:55 MACHINENAME kernel: [57360.256341] cfg80211: (2457000 KHz - 2482000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
May 2 19:48:55 MACHINENAME kernel: [57360.256345] cfg80211: (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
May 2 19:48:55 MACHINENAME kernel: [57360.256348] cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
May 2 19:48:55 MACHINENAME kernel: [57360.256352] cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
May 2 19:48:55 MACHINENAME kernel: [57360.256392] cfg80211: Calling CRDA for country: US
May 2 19:48:55 MACHINENAME kernel: [57360.258939] cfg80211: Regulatory domain changed to country: US
May 2 19:48:55 MACHINENAME kernel: [57360.258942] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
May 2 19:48:55 MACHINENAME kernel: [57360.258944] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2700 mBm)
May 2 19:48:55 MACHINENAME kernel: [57360.258945] cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 1700 mBm)
May 2 19:48:55 MACHINENAME kernel: [57360.258946] cfg80211: (5250000 KHz - 5330000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
May 2 19:48:55 MACHINENAME kernel: [57360.258947] cfg80211: (5490000 KHz - 5600000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
May 2 19:48:55 MACHINENAME kernel: [57360.258948] cfg80211: (5650000 KHz - 5710000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
May 2 19:48:55 MACHINENAME kernel: [57360.258949] cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 3000 mBm)
May 2 19:48:55 MACHINENAME kernel: [57360.258951] cfg80211: (57240000 KHz - 63720000 KHz @ 2160000 KHz), (N/A, 4000 mBm)
May 2 19:48:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): supplicant interface state: authenticating -> disconnected
May 2 19:48:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): supplicant interface state: disconnected -> scanning
May 2 19:49:10 MACHINENAME NetworkManager[1063]: <warn> (wlan0): link timed out.
May 2 19:49:10 MACHINENAME NetworkManager[1063]: <info> (wlan0): device state change: activated -> failed (reason 'SSID not found') [100 120 53]
May 2 19:49:10 MACHINENAME NetworkManager[1063]: <info> NetworkManager state is now DISCONNECTED
May 2 19:49:10 MACHINENAME NetworkManager[1063]: <warn> Activation (wlan0) failed for connection 'Auto XXXXX'
May 2 19:49:10 MACHINENAME dbus[575]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
May 2 19:49:10 MACHINENAME NetworkManager[1063]: <info> (wlan0): device state change: failed -> disconnected (reason 'none') [120 30 0]
May 2 19:49:10 MACHINENAME NetworkManager[1063]: <info> (wlan0): deactivating device (reason 'none') [0]
May 2 19:49:10 MACHINENAME dbus[575]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
May 2 19:49:10 MACHINENAME NetworkManager[1063]: <info> (wlan0): canceled DHCP transaction, DHCP client pid 25167
May 2 19:49:10 MACHINENAME kernel: [57375.721732] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
May 2 19:49:10 MACHINENAME NetworkManager[1063]: <warn> DNS: plugin dnsmasq update failed
May 2 19:49:10 MACHINENAME NetworkManager[1063]: <info> Removing DNS information from /sbin/resolvconf
May 2 19:49:10 MACHINENAME NetworkManager[1063]: <warn> Couldn't disconnect supplicant interface: This interface is not connected.
May 2 19:56:30 MACHINENAME NetworkManager[1063]: <info> (wlan0): device state change: disconnected -> unavailable (reason 'none') [30 20 0]
May 2 19:56:30 MACHINENAME NetworkManager[1063]: <info> (wlan0): deactivating device (reason 'none') [0]
May 2 19:56:30 MACHINENAME NetworkManager[1063]: <info> (wlan0): taking down device.
May 2 19:56:30 MACHINENAME NetworkManager[1063]: <info> WiFi hardware radio set disabled
May 2 19:56:30 MACHINENAME NetworkManager[1063]: <info> WiFi now disabled by radio killswitch
To walk you through it, I hardware-enabled wifi at the beginning of the log. By 19:44:17, wifi is up and working fine. At 19:48:55, the interface disassociates from the AP (reason=7). It tries to reconnect, but fails, and I don't notice until the end of the log, at which point I hardware disable wifi and the whole process starts all over.
Downgrading linux-firmware back to 1.127.20 solved this problem for me.
I'm happy to test patches or temporarily upgrade back to 1.127.22 to
provide more detailed log info.
** Affects: linux-firmware (Ubuntu)
Importance: Undecided
Status: New
--
You received this bug notification because you are a member of Kernel
Packages, which is subscribed to linux-firmware in Ubuntu.
https://bugs.launchpad.net/bugs/1578796
Title:
1.127.22 causes wifi instability on Intel N7260 chipset
Status in linux-firmware package in Ubuntu:
New
Bug description:
OS: Linux Mint 17 Qiana (based on Ubuntu 14.04 Trusty)
Package Version: linux-firmware 1.127.22.0
After upgrading to 1.127.22, my wifi on my lenovo x240 became
unstable. It would connect, then after less than ten minutes it would
somehow disassociate from the AP, and only cycling the hardware wifi
switch would bring it back. A typical portion of /var/log/syslog
during the course of the problem would look like:
May 2 19:43:54 MACHINENAME NetworkManager[1063]: <info> (wlan0): bringing up device.
May 2 19:43:54 MACHINENAME kernel: [57059.429299] iwlwifi 0000:03:00.0: L1 Enabled; Disabling L0S
May 2 19:43:54 MACHINENAME kernel: [57059.430096] iwlwifi 0000:03:00.0: L1 Enabled; Disabling L0S
May 2 19:43:54 MACHINENAME NetworkManager[1063]: <info> WiFi hardware radio set enabled
May 2 19:43:54 MACHINENAME NetworkManager[1063]: <info> WiFi now enabled by radio killswitch
May 2 19:43:54 MACHINENAME kernel: [57059.447505] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
May 2 19:43:54 MACHINENAME NetworkManager[1063]: <info> (wlan0) supports 5 scan SSIDs
May 2 19:43:54 MACHINENAME NetworkManager[1063]: <info> (wlan0): supplicant interface state: starting -> ready
May 2 19:43:54 MACHINENAME NetworkManager[1063]: <info> (wlan0): device state change: unavailable -> disconnected (reason 'supplicant-available') [20 30 42]
May 2 19:43:54 MACHINENAME NetworkManager[1063]: <warn> Trying to remove a non-existant call id.
May 2 19:43:54 MACHINENAME NetworkManager[1063]: <info> (wlan0): supplicant interface state: ready -> disconnected
May 2 19:43:54 MACHINENAME NetworkManager[1063]: <info> (wlan0) supports 5 scan SSIDs
May 2 19:43:54 MACHINENAME wpa_supplicant[1726]: wlan0: Reject scan trigger since one is already pending
May 2 19:43:54 MACHINENAME wpa_supplicant[1726]: wlan0: CTRL-EVENT-SCAN-STARTED
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): supplicant interface state: disconnected -> inactive
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Auto-activating connection 'Auto XXXXX'.
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) starting connection 'Auto XXXXX'
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> NetworkManager state is now CONNECTING
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0]
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0/wireless): access point 'Auto XXXXX' has security, but secrets are required.
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): device state change: config -> need-auth (reason 'none') [50 60 0]
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): device state change: need-auth -> prepare (reason 'none') [60 40 0]
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0]
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0/wireless): connection 'Auto XXXXX' has security, and secrets exist. No new secrets needed.
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Config: added 'ssid' value 'XXXXX'
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Config: added 'scan_ssid' value '1'
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Config: added 'key_mgmt' value 'WPA-PSK'
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Config: added 'auth_alg' value 'OPEN'
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Config: added 'psk' value '<omitted>'
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Config: set interface ap_scan to 1
May 2 19:43:55 MACHINENAME wpa_supplicant[1726]: wlan0: SME: Trying to authenticate with XX:XX:XX:XX:XX:XX (SSID='XXXXX' freq=2447 MHz)
May 2 19:43:55 MACHINENAME kernel: [57059.971562] wlan0: authenticate with XX:XX:XX:XX:XX:XX
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): supplicant interface state: inactive -> authenticating
May 2 19:43:55 MACHINENAME kernel: [57059.975238] wlan0: send auth to XX:XX:XX:XX:XX:XX (try 1/3)
May 2 19:43:55 MACHINENAME wpa_supplicant[1726]: wlan0: Trying to associate with XX:XX:XX:XX:XX:XX (SSID='XXXXX' freq=2447 MHz)
May 2 19:43:55 MACHINENAME kernel: [57059.977372] wlan0: authenticated
May 2 19:43:55 MACHINENAME kernel: [57059.981323] wlan0: associate with XX:XX:XX:XX:XX:XX (try 1/3)
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): supplicant interface state: authenticating -> associating
May 2 19:43:55 MACHINENAME kernel: [57059.985407] wlan0: RX AssocResp from XX:XX:XX:XX:XX:XX (capab=0x1411 status=0 aid=3)
May 2 19:43:55 MACHINENAME wpa_supplicant[1726]: wlan0: Associated with XX:XX:XX:XX:XX:XX
May 2 19:43:55 MACHINENAME kernel: [57059.989688] wlan0: associated
May 2 19:43:55 MACHINENAME kernel: [57059.989720] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): supplicant interface state: associating -> 4-way handshake
May 2 19:43:55 MACHINENAME wpa_supplicant[1726]: wlan0: WPA: Key negotiation completed with XX:XX:XX:XX:XX:XX [PTK=CCMP GTK=CCMP]
May 2 19:43:55 MACHINENAME wpa_supplicant[1726]: wlan0: CTRL-EVENT-CONNECTED - Connection to XX:XX:XX:XX:XX:XX completed [id=0 id_str=]
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): supplicant interface state: 4-way handshake -> completed
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful. Connected to wireless network 'XXXXX'.
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled.
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) started...
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): device state change: config -> ip-config (reason 'none') [50 70 0]
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Beginning DHCPv4 transaction (timeout in 45 seconds)
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> dhclient started with pid 25167
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Beginning IP6 addrconf.
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete.
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): DHCPv4 state changed nbi -> preinit
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): DHCPv4 state changed preinit -> reboot
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> address 192.168.0.5
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> prefix 24 (255.255.255.0)
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> gateway 192.168.0.1
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> nameserver '192.168.0.1'
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 5 of 5 (IPv4 Configure Commit) scheduled...
May 2 19:43:55 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 5 of 5 (IPv4 Commit) started...
May 2 19:43:56 MACHINENAME NetworkManager[1063]: <info> (wlan0): device state change: ip-config -> secondaries (reason 'none') [70 90 0]
May 2 19:43:56 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 5 of 5 (IPv4 Commit) complete.
May 2 19:43:56 MACHINENAME NetworkManager[1063]: <info> (wlan0): device state change: secondaries -> activated (reason 'none') [90 100 0]
May 2 19:43:56 MACHINENAME NetworkManager[1063]: <info> NetworkManager state is now CONNECTED_GLOBAL
May 2 19:43:56 MACHINENAME NetworkManager[1063]: <info> Policy set 'Auto XXXXX' (wlan0) as default for IPv4 routing and DNS.
May 2 19:43:56 MACHINENAME NetworkManager[1063]: <info> Writing DNS information to /sbin/resolvconf
May 2 19:43:56 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) successful, device activated.
May 2 19:43:56 MACHINENAME dbus[575]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
May 2 19:43:56 MACHINENAME dbus[575]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
May 2 19:44:15 MACHINENAME NetworkManager[1063]: <info> (wlan0): IP6 addrconf timed out or failed.
May 2 19:44:15 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 4 of 5 (IPv6 Configure Timeout) scheduled...
May 2 19:44:15 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 4 of 5 (IPv6 Configure Timeout) started...
May 2 19:44:15 MACHINENAME NetworkManager[1063]: <info> Activation (wlan0) Stage 4 of 5 (IPv6 Configure Timeout) complete.
May 2 19:44:17 MACHINENAME wpa_supplicant[1726]: wlan0: CTRL-EVENT-SCAN-STARTED
May 2 19:44:51 MACHINENAME kernel: [57116.406291] e1000e 0000:00:19.0: irq 61 for MSI/MSI-X
May 2 19:47:45 MACHINENAME kernel: [57290.016074] thinkpad_ec: thinkpad_ec_request_row: arg0 rejected: (0x01:0x00)->0x00
May 2 19:47:45 MACHINENAME kernel: [57290.016080] thinkpad_ec: thinkpad_ec_read_row: failed requesting row: (0x01:0x00)->0xfffffffb
May 2 19:47:45 MACHINENAME kernel: [57290.016082] thinkpad_ec: initial ec test failed
May 2 19:47:45 MACHINENAME kernel: [57290.105637] thinkpad_acpi: EC reports that Thermal Table has changed
May 2 19:47:45 MACHINENAME anacron[25964]: Anacron 2.3 started on 2016-05-02
May 2 19:47:45 MACHINENAME anacron[25964]: Normal exit (0 jobs run)
May 2 19:48:55 MACHINENAME kernel: [57360.202372] wlan0: disassociated from XX:XX:XX:XX:XX:XX (Reason: 7)
May 2 19:48:55 MACHINENAME hostapd: wlan0: STA XX:XX:XX:XX:XX:XX IEEE 802.11: disassociated
May 2 19:47:26 MACHINENAME wpa_supplicant[1726]: message repeated 3 times: [ wlan0: CTRL-EVENT-SCAN-STARTED ]
May 2 19:48:55 MACHINENAME wpa_supplicant[1726]: wlan0: CTRL-EVENT-DISCONNECTED bssid=XX:XX:XX:XX:XX:XX reason=7
May 2 19:48:55 MACHINENAME wpa_supplicant[1726]: wlan0: SME: Trying to authenticate with XX:XX:XX:XX:XX:XX (SSID='XXXXX' freq=2447 MHz)
May 2 19:48:55 MACHINENAME NetworkManager[1063]: <warn> Connection disconnected (reason 7)
May 2 19:48:55 MACHINENAME kernel: [57360.248867] wlan0: deauthenticating from XX:XX:XX:XX:XX:XX by local choice (reason=3)
May 2 19:48:55 MACHINENAME kernel: [57360.248950] cfg80211: Calling CRDA to update world regulatory domain
May 2 19:48:55 MACHINENAME wpa_supplicant[1726]: wlan0: CTRL-EVENT-SCAN-STARTED
May 2 19:48:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): supplicant interface state: completed -> authenticating
May 2 19:48:55 MACHINENAME kernel: [57360.256323] cfg80211: World regulatory domain updated:
May 2 19:48:55 MACHINENAME kernel: [57360.256331] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
May 2 19:48:55 MACHINENAME kernel: [57360.256337] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
May 2 19:48:55 MACHINENAME kernel: [57360.256341] cfg80211: (2457000 KHz - 2482000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
May 2 19:48:55 MACHINENAME kernel: [57360.256345] cfg80211: (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
May 2 19:48:55 MACHINENAME kernel: [57360.256348] cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
May 2 19:48:55 MACHINENAME kernel: [57360.256352] cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
May 2 19:48:55 MACHINENAME kernel: [57360.256392] cfg80211: Calling CRDA for country: US
May 2 19:48:55 MACHINENAME kernel: [57360.258939] cfg80211: Regulatory domain changed to country: US
May 2 19:48:55 MACHINENAME kernel: [57360.258942] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
May 2 19:48:55 MACHINENAME kernel: [57360.258944] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2700 mBm)
May 2 19:48:55 MACHINENAME kernel: [57360.258945] cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 1700 mBm)
May 2 19:48:55 MACHINENAME kernel: [57360.258946] cfg80211: (5250000 KHz - 5330000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
May 2 19:48:55 MACHINENAME kernel: [57360.258947] cfg80211: (5490000 KHz - 5600000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
May 2 19:48:55 MACHINENAME kernel: [57360.258948] cfg80211: (5650000 KHz - 5710000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
May 2 19:48:55 MACHINENAME kernel: [57360.258949] cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 3000 mBm)
May 2 19:48:55 MACHINENAME kernel: [57360.258951] cfg80211: (57240000 KHz - 63720000 KHz @ 2160000 KHz), (N/A, 4000 mBm)
May 2 19:48:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): supplicant interface state: authenticating -> disconnected
May 2 19:48:55 MACHINENAME NetworkManager[1063]: <info> (wlan0): supplicant interface state: disconnected -> scanning
May 2 19:49:10 MACHINENAME NetworkManager[1063]: <warn> (wlan0): link timed out.
May 2 19:49:10 MACHINENAME NetworkManager[1063]: <info> (wlan0): device state change: activated -> failed (reason 'SSID not found') [100 120 53]
May 2 19:49:10 MACHINENAME NetworkManager[1063]: <info> NetworkManager state is now DISCONNECTED
May 2 19:49:10 MACHINENAME NetworkManager[1063]: <warn> Activation (wlan0) failed for connection 'Auto XXXXX'
May 2 19:49:10 MACHINENAME dbus[575]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
May 2 19:49:10 MACHINENAME NetworkManager[1063]: <info> (wlan0): device state change: failed -> disconnected (reason 'none') [120 30 0]
May 2 19:49:10 MACHINENAME NetworkManager[1063]: <info> (wlan0): deactivating device (reason 'none') [0]
May 2 19:49:10 MACHINENAME dbus[575]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
May 2 19:49:10 MACHINENAME NetworkManager[1063]: <info> (wlan0): canceled DHCP transaction, DHCP client pid 25167
May 2 19:49:10 MACHINENAME kernel: [57375.721732] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
May 2 19:49:10 MACHINENAME NetworkManager[1063]: <warn> DNS: plugin dnsmasq update failed
May 2 19:49:10 MACHINENAME NetworkManager[1063]: <info> Removing DNS information from /sbin/resolvconf
May 2 19:49:10 MACHINENAME NetworkManager[1063]: <warn> Couldn't disconnect supplicant interface: This interface is not connected.
May 2 19:56:30 MACHINENAME NetworkManager[1063]: <info> (wlan0): device state change: disconnected -> unavailable (reason 'none') [30 20 0]
May 2 19:56:30 MACHINENAME NetworkManager[1063]: <info> (wlan0): deactivating device (reason 'none') [0]
May 2 19:56:30 MACHINENAME NetworkManager[1063]: <info> (wlan0): taking down device.
May 2 19:56:30 MACHINENAME NetworkManager[1063]: <info> WiFi hardware radio set disabled
May 2 19:56:30 MACHINENAME NetworkManager[1063]: <info> WiFi now disabled by radio killswitch
To walk you through it, I hardware-enabled wifi at the beginning of the log. By 19:44:17, wifi is up and working fine. At 19:48:55, the interface disassociates from the AP (reason=7). It tries to reconnect, but fails, and I don't notice until the end of the log, at which point I hardware disable wifi and the whole process starts all over.
Downgrading linux-firmware back to 1.127.20 solved this problem for
me.
I'm happy to test patches or temporarily upgrade back to 1.127.22 to
provide more detailed log info.
To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/linux-firmware/+bug/1578796/+subscriptions
Follow ups