NM loose WIFI connection - device cannot be readied for configuration

[Steven Valsesia]

Hi there !

Since I upgraded from Ubuntu 14.10 to 15.04, I have some WIFI disconnections. Seems to appears for no reasons... maybe after a period of non utilization but i'm not sure.

Here some informations :

Package : network-manager-gnome 0.9.10.1-0ubuntu4

root@steven-desktop:/home/steven# /etc/init.d/network-manager status

● NetworkManager.service - Network Manager
   Loaded: loaded (/lib/systemd/system/NetworkManager.service; enabled; vendor preset: enabled)
   Active: active (running) since sam. 2015-06-20 11:15:43 CEST; 16min ago
 Main PID: 8594 (NetworkManager)
   CGroup: /system.slice/NetworkManager.service
           ├─ 812 /usr/sbin/dnsmasq --no-resolv --keep-in-foreground --no-hosts --bind-interfaces --pid-file=/run/sendsigs.omit.d/network-mana...
           ├─8594 /usr/sbin/NetworkManager --no-daemon
           └─8604 /sbin/dhclient -d -q -sf /usr/lib/NetworkManager/nm-dhcp-helper -pf /run/sendsigs.omit.d/network-manager.dhclient-wlan0.pid ...

juin 20 11:15:44 steven-desktop dhclient[8604]: bound to 192.168.1.35 -- renewal in 37987 seconds.
juin 20 11:15:44 steven-desktop NetworkManager[8594]: <info> NetworkManager state is now CONNECTED_GLOBAL
juin 20 11:15:44 steven-desktop NetworkManager[8594]: <info> Policy set '**************' (wlan0) as default for IPv4 routing and DNS.
juin 20 11:15:44 steven-desktop NetworkManager[8594]: <info> Writing DNS information to /sbin/resolvconf
juin 20 11:15:44 steven-desktop dnsmasq[812]: configuration des serveurs amonts à partir de DBus
juin 20 11:15:44 steven-desktop dnsmasq[812]: utilise le serveur de nom 192.168.1.1#53
juin 20 11:15:44 steven-desktop NetworkManager[8594]: <info> Activation (wlan0) successful, device activated.
juin 20 11:15:49 steven-desktop NetworkManager[8594]: <info> startup complete
juin 20 11:15:54 steven-desktop NetworkManager[8594]: <info> WiFi hardware radio set enabled
juin 20 11:15:54 steven-desktop NetworkManager[8594]: <info> WWAN hardware radio set enabled

Here logs when I have this problem, reported error is first with reason : NM_DEVICE_STATE_REASON_CONFIG_FAILED

root@steven-desktop:/home/steven# cat /var/log/syslog | grep wpa_supplicant

 Jun 20 10:49:04 steven-desktop wpa_supplicant[777]: wlan0: WPA: Group rekeying completed with 18:62:2c:93:fa:72 [GTK=TKIP]
Jun 20 11:00:55 steven-desktop wpa_supplicant[777]: wlan0: CTRL-EVENT-DISCONNECTED bssid=18:62:2c:93:fa:72 reason=4 locally_generated=1
Jun 20 11:00:56 steven-desktop wpa_supplicant[777]: wlan0: CTRL-EVENT-SCAN-STARTED
Jun 20 11:00:57 steven-desktop wpa_supplicant[777]: wlan0: SME: Trying to authenticate with 18:62:2c:93:fa:72 (SSID='******************' freq=2437 MHz)
Jun 20 11:01:00 steven-desktop wpa_supplicant[777]: wlan0: CTRL-EVENT-SCAN-STARTED
Jun 20 11:01:01 steven-desktop wpa_supplicant[777]: wlan0: SME: Trying to authenticate with 18:62:2c:93:fa:72 (SSID='******************' freq=2437 MHz)
Jun 20 11:01:03 steven-desktop wpa_supplicant[777]: wlan0: CTRL-EVENT-SCAN-STARTED
Jun 20 11:01:04 steven-desktop wpa_supplicant[777]: wlan0: SME: Trying to authenticate with 18:62:2c:93:fa:72 (SSID='******************' freq=2437 MHz)
Jun 20 11:01:04 steven-desktop wpa_supplicant[777]: wlan0: Trying to associate with 18:62:2c:93:fa:72 (SSID='******************' freq=2437 MHz)
Jun 20 11:01:05 steven-desktop wpa_supplicant[777]: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="******************" auth_failures=1 duration=10
Jun 20 11:01:10 steven-desktop wpa_supplicant[777]: wlan0: CTRL-EVENT-SCAN-STARTED
Jun 20 11:01:11 steven-desktop wpa_supplicant[777]: wlan0: Reject scan trigger since one is already pending
Jun 20 11:01:11 steven-desktop wpa_supplicant[777]: wlan0: SME: Trying to authenticate with 18:62:2c:93:fa:72 (SSID='******************' freq=2437 MHz)
Jun 20 11:01:12 steven-desktop wpa_supplicant[777]: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="******************" auth_failures=1 duration=10
[...]

root@steven-desktop:/home/steven# cat /var/log/syslog | grep NetworkManager

Jun 20 11:00:55 steven-desktop NetworkManager[645]: <warn> Connection disconnected (reason -4)
Jun 20 11:00:55 steven-desktop NetworkManager[645]: <info> (wlan0): supplicant interface state: completed -> disconnected
Jun 20 11:00:56 steven-desktop NetworkManager[645]: <info> (wlan0): supplicant interface state: disconnected -> scanning
Jun 20 11:00:57 steven-desktop NetworkManager[645]: <info> (wlan0): supplicant interface state: scanning -> authenticating
Jun 20 11:00:58 steven-desktop NetworkManager[645]: <info> (wlan0): supplicant interface state: authenticating -> disconnected
Jun 20 11:01:00 steven-desktop NetworkManager[645]: <info> (wlan0): supplicant interface state: disconnected -> scanning
Jun 20 11:01:01 steven-desktop NetworkManager[645]: <info> (wlan0): supplicant interface state: scanning -> authenticating
Jun 20 11:01:02 steven-desktop NetworkManager[645]: <info> (wlan0): supplicant interface state: authenticating -> disconnected
Jun 20 11:01:03 steven-desktop NetworkManager[645]: <info> (wlan0): supplicant interface state: disconnected -> scanning
Jun 20 11:01:04 steven-desktop NetworkManager[645]: <info> (wlan0): supplicant interface state: scanning -> authenticating
Jun 20 11:01:04 steven-desktop NetworkManager[645]: <info> (wlan0): supplicant interface state: authenticating -> associating
Jun 20 11:01:05 steven-desktop NetworkManager[645]: <info> (wlan0): supplicant interface state: associating -> disconnected
Jun 20 11:01:10 steven-desktop NetworkManager[645]: <info> (wlan0): supplicant interface state: disconnected -> scanning
Jun 20 11:01:11 steven-desktop NetworkManager[645]: <warn> (wlan0): link timed out.
Jun 20 11:01:11 steven-desktop NetworkManager[645]: <info> (wlan0): device state change: activated -> failed (reason 'supplicant-timeout') [100 120 11]
Jun 20 11:01:11 steven-desktop NetworkManager[645]: <info> NetworkManager state is now CONNECTED_LOCAL
Jun 20 11:01:11 steven-desktop NetworkManager[645]: <info> NetworkManager state is now DISCONNECTED
Jun 20 11:01:11 steven-desktop NetworkManager[645]: <warn> Activation (wlan0) failed for connection '******************'
Jun 20 11:01:11 steven-desktop NetworkManager[645]: <info> (wlan0): device state change: failed -> disconnected (reason 'none') [120 30 0]
Jun 20 11:01:11 steven-desktop NetworkManager[645]: <info> (wlan0): deactivating device (reason 'none') [0]
Jun 20 11:01:11 steven-desktop NetworkManager[645]: <info> (wlan0): canceled DHCP transaction, DHCP client pid 809
Jun 20 11:01:11 steven-desktop NetworkManager[645]: _nl_get_vtable: assertion 'vtable.handle' failed
Jun 20 11:01:11 steven-desktop NetworkManager[645]: <info> Writing DNS information to /sbin/resolvconf
Jun 20 11:01:11 steven-desktop NetworkManager[645]: <warn> Couldn't disconnect supplicant interface: This interface is not connected.
Jun 20 11:01:11 steven-desktop NetworkManager[645]: <info> Auto-activating connection '******************'.
Jun 20 11:01:11 steven-desktop NetworkManager[645]: <info> Activation (wlan0) starting connection '******************'
Jun 20 11:01:11 steven-desktop NetworkManager[645]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
Jun 20 11:01:11 steven-desktop NetworkManager[645]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
Jun 20 11:01:11 steven-desktop NetworkManager[645]: <info> (wlan0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Jun 20 11:01:11 steven-desktop NetworkManager[645]: <info> NetworkManager state is now CONNECTING
Jun 20 11:01:11 steven-desktop NetworkManager[645]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
Jun 20 11:01:11 steven-desktop NetworkManager[645]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
Jun 20 11:01:11 steven-desktop NetworkManager[645]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
Jun 20 11:01:11 steven-desktop NetworkManager[645]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0]
Jun 20 11:01:11 steven-desktop NetworkManager[645]: <info> Activation (wlan0/wireless): access point '******************' has security, but secrets are required.
[...]

My solution is to restart network-manager like this "service network-manager restart", but maybe network-manager is not the faulty package.

Thanks for your help !

[Steven Valsesia (steven-valsesia)]

Hi ! No one can help ?

I saw in dmesg some messages telling that the queue 0 can't be flush.
Then after many warning, there is a message saying that there's non-free space on queue 0.
Do I have to report a bug to the rt2x00 driver team ?

[Steven Valsesia (steven-valsesia)]

Here's what I get in syslog when I restart network-manager :

Jun 26 08:29:52 steven-desktop NetworkManager[625]: <warn> Activation (wlan0/wireless): association took too long, failing activation.
Jun 26 08:29:52 steven-desktop NetworkManager[625]: <warn> Activation (wlan0) failed for connection '******************'
Jun 26 08:29:52 steven-desktop NetworkManager[625]: <warn> Couldn't disconnect supplicant interface: This interface is not connected.
Jun 26 08:29:59 steven-desktop NetworkManager[2469]: <warn> error in connection /etc/NetworkManager/system-connections/USRP: File did not exist or was not a regular file
Jun 26 08:29:59 steven-desktop NetworkManager[2469]: <warn> could not get interface properties: No readable properties in this interface.
Jun 26 08:29:59 steven-desktop NetworkManager[2469]: <warn> could not get interface properties: No readable properties in this interface.
Jun 26 08:31:13 steven-desktop kernel: [ 1377.940024] ieee80211 phy0: rt2x00queue_flush_queue: Warning - Queue 0 failed to flush
Jun 26 08:31:19 steven-desktop kernel: [ 1383.404053] ieee80211 phy0: rt2x00queue_flush_queue: Warning - Queue 0 failed to flush
Jun 26 08:31:25 steven-desktop kernel: [ 1389.368057] ieee80211 phy0: rt2x00queue_flush_queue: Warning - Queue 0 failed to flush
Jun 26 08:32:19 steven-desktop kernel: [ 1444.112044] ieee80211 phy0: rt2x00queue_flush_queue: Warning - Queue 0 failed to flush

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[jth (jth)]

Hi

I get the same disconnecting problem in 15.04, I had no problem in 14.10. But with different computers and wireless cards.

Lenovo T61p
Kernel Linux tpjohthe 3.19.0-21-generic #21-Ubuntu SMP Sun Jun 14 18:31:11 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux
LANG=C lshw -C network
       description: Wireless interface
       product: PRO/Wireless 4965 AG or AGN [Kedron] Network Connection
       vendor: Intel Corporation
       physical id: 0
       bus info: pci@0000:03:00.0
       logical name: wlan0
       version: 61
       serial: 00:21:XX:XX:XX:XX
       width: 64 bits
       clock: 33MHz
       capabilities: pm msi pciexpress bus_master cap_list ethernet physical wireless
       configuration: broadcast=yes driver=iwl4965 driverversion=3.19.0-21-generic firmware=228.61.2.24 ip=192.168.0.X latency=0 link=yes multicast=yes wireless=IEEE 802.11abgn
       resources: irq:33 memory:df2fe000-df2fffff

Lenovo T61
LANG=C lshw -C network
  *-network
       description: Wireless interface
       product: PRO/Wireless 3945ABG [Golan] Network Connection
       vendor: Intel Corporation
       physical id: 0
       bus info: pci@0000:03:00.0
       logical name: wlan0
       version: 02
       serial: 00:1c:XX:XX:XX:XX
       width: 32 bits
       clock: 33MHz
       capabilities: pm msi pciexpress bus_master cap_list ethernet physical wireless
       configuration: broadcast=yes driver=iwl3945 driverversion=3.19.0-21-generic firmware=15.32.2.9 ip=192.168.0.Xlatency=0 link=yes multicast=yes wireless=IEEE 802.11abg
       resources: irq:33 memory:df3ff000-df3fffff

syslog
Jul 2 09:56:25 tpjohthe wpa_supplicant[1010]: wlan0: WPA: Group rekeying completed with 00:26:XX:XX:XX:XX [GTK=CCMP]
Jul 2 10:47:53 tpjohthe wpa_supplicant[1010]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:26:XX:XX:XX:XX reason=4 locally_generated=1
Jul 2 10:47:53 tpjohthe NetworkManager[789]: <warn> Connection disconnected (reason -4)
Jul 2 10:47:53 tpjohthe kernel: [ 9066.873467] cfg80211: Calling CRDA to update world regulatory domain
Jul 2 10:47:53 tpjohthe NetworkManager[789]: <info> (wlan0): supplicant interface state: completed -> disconnected
Jul 2 10:47:53 tpjohthe kernel: [ 9066.880573] cfg80211: World regulatory domain updated:
Jul 2 10:47:53 tpjohthe kernel: [ 9066.880577] cfg80211: DFS Master region: unset
Jul 2 10:47:53 tpjohthe kernel: [ 9066.880580] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp), (dfs_cac_time)
Jul 2 10:47:53 tpjohthe kernel: [ 9066.880584] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm), (N/A)
Jul 2 10:47:53 tpjohthe kernel: [ 9066.880588] cfg80211: (2457000 KHz - 2482000 KHz @ 40000 KHz), (300 mBi, 2000 mBm), (N/A)
Jul 2 10:47:53 tpjohthe kernel: [ 9066.880591] cfg80211: (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm), (N/A)
Jul 2 10:47:53 tpjohthe kernel: [ 9066.880594] cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm), (N/A)
Jul 2 10:47:53 tpjohthe kernel: [ 9066.880597] cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm), (N/A)
Jul 2 10:47:53 tpjohthe kernel: [ 9066.880615] cfg80211: Calling CRDA for country: SE
Jul 2 ...

[Steven Valsesia (steven-valsesia)]

Can someone tell us more about the cause of this bug please ?

[Steven Valsesia (steven-valsesia)]

This bug is really annoying, can someone help us ?