NetworkManager asks for password after unrelated connection errors

Bug #289108 reported by Bogdan Butnaru
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
network-manager (Ubuntu)
Expired
Undecided
Unassigned

Bug Description

Binary package hint: network-manager

Hello!

I've been to a conference this week where they had a very flaky WiFi access point. I think it crashed or at least overloaded because of the many people trying to connect at the same time.

Anyway, I noticed a bug: whenever the network manager failed to connect it would ask me for the network key, even though the failure was not related to authentication. I've noticed this a couple times before, but during the conference it happened all the time.

I've saved a snippet of /var/log/daemon.log (below) which shows this happening. As you can see, around the bottom it asks for new secrets, despite the only error being a timeout.

There's also a "<WARN> nm_device_wifi_set_enabled(): not in expected unavailable state!" line that kept appearing often, should I file a bug for that, too?

Oct 23 12:11:35 arioch NetworkManager: <info> (wlan1): bringing up device.
Oct 23 12:11:35 arioch acpid: client connected from 5073[0:0]
Oct 23 12:11:35 arioch NetworkManager: <info> (wlan1): preparing device.
Oct 23 12:11:35 arioch NetworkManager: <info> (wlan1): deactivating device (reason: 2).
Oct 23 12:11:35 arioch NetworkManager: <info> (wlan1): device state change: 2 -> 3
Oct 23 12:11:35 arioch NetworkManager: <info> (wlan1): supplicant interface state change: 1 -> 2.
Oct 23 12:11:35 arioch NetworkManager: <info> Activation (wlan1) starting connection 'agora/bda2008'
Oct 23 12:11:35 arioch NetworkManager: <info> (wlan1): device state change: 3 -> 4
Oct 23 12:11:35 arioch NetworkManager: <info> Activation (wlan1) Stage 1 of 5 (Device Prepare) scheduled...
Oct 23 12:11:35 arioch NetworkManager: <info> Activation (wlan1) Stage 1 of 5 (Device Prepare) started...
Oct 23 12:11:35 arioch NetworkManager: <info> Activation (wlan1) Stage 2 of 5 (Device Configure) scheduled...
Oct 23 12:11:35 arioch NetworkManager: <info> Activation (wlan1) Stage 1 of 5 (Device Prepare) complete.
Oct 23 12:11:35 arioch NetworkManager: <info> Activation (wlan1) Stage 2 of 5 (Device Configure) starting...
Oct 23 12:11:35 arioch NetworkManager: <info> (wlan1): device state change: 4 -> 5
Oct 23 12:11:35 arioch NetworkManager: <info> Activation (wlan1/wireless): connection 'agora/bda2008' has security, and secrets exist. No new secrets needed.
Oct 23 12:11:35 arioch NetworkManager: <info> Config: added 'ssid' value 'agora'
Oct 23 12:11:35 arioch NetworkManager: <info> Config: added 'scan_ssid' value '1'
Oct 23 12:11:35 arioch NetworkManager: <info> Config: added 'key_mgmt' value 'WPA-PSK'
Oct 23 12:11:35 arioch NetworkManager: <info> Config: added 'psk' value '<omitted>'
Oct 23 12:11:35 arioch NetworkManager: <info> Config: added 'proto' value 'WPA RSN'
Oct 23 12:11:35 arioch NetworkManager: <info> Config: added 'pairwise' value 'TKIP CCMP'
Oct 23 12:11:35 arioch NetworkManager: <info> Config: added 'group' value 'WEP40 WEP104 TKIP CCMP'
Oct 23 12:11:35 arioch NetworkManager: <info> Activation (wlan1) Stage 2 of 5 (Device Configure) complete.
Oct 23 12:11:35 arioch NetworkManager: <info> Config: set interface ap_scan to 1
Oct 23 12:11:35 arioch NetworkManager: <info> (wlan1): supplicant connection state change: 1 -> 2
Oct 23 12:12:00 arioch NetworkManager: <info> Activation (wlan1/wireless): association took too long.
Oct 23 12:12:00 arioch NetworkManager: <info> (wlan1): device state change: 5 -> 6
Oct 23 12:12:00 arioch NetworkManager: <info> Activation (wlan1/wireless): asking for new secrets
Oct 23 12:12:00 arioch NetworkManager: <info> (wlan1): supplicant connection state change: 2 -> 0
Oct 23 12:12:07 arioch NetworkManager: <info> Activation (wlan1) Stage 1 of 5 (Device Prepare) scheduled...
Oct 23 12:12:07 arioch NetworkManager: <info> Activation (wlan1) Stage 1 of 5 (Device Prepare) started...
Oct 23 12:12:07 arioch NetworkManager: <info> (wlan1): device state change: 6 -> 4
Oct 23 12:12:07 arioch NetworkManager: <info> Activation (wlan1) Stage 2 of 5 (Device Configure) scheduled...
Oct 23 12:12:07 arioch NetworkManager: <info> Activation (wlan1) Stage 1 of 5 (Device Prepare) complete.
Oct 23 12:12:07 arioch NetworkManager: <info> Activation (wlan1) Stage 2 of 5 (Device Configure) starting...
Oct 23 12:12:07 arioch NetworkManager: <info> (wlan1): device state change: 4 -> 5
Oct 23 12:12:07 arioch NetworkManager: <info> Activation (wlan1/wireless): connection 'agora/bda2008' has security, and secrets exist. No new secrets needed.
Oct 23 12:12:07 arioch NetworkManager: <info> Config: added 'ssid' value 'agora'
Oct 23 12:12:07 arioch NetworkManager: <info> Config: added 'scan_ssid' value '1'
Oct 23 12:12:07 arioch NetworkManager: <info> Config: added 'key_mgmt' value 'WPA-PSK'
Oct 23 12:12:07 arioch NetworkManager: <info> Config: added 'psk' value '<omitted>'
Oct 23 12:12:07 arioch NetworkManager: <info> Config: added 'proto' value 'WPA RSN'
Oct 23 12:12:07 arioch NetworkManager: <info> Config: added 'pairwise' value 'TKIP CCMP'
Oct 23 12:12:07 arioch NetworkManager: <info> Config: added 'group' value 'WEP40 WEP104 TKIP CCMP'
Oct 23 12:12:07 arioch NetworkManager: <info> Activation (wlan1) Stage 2 of 5 (Device Configure) complete.
Oct 23 12:12:07 arioch NetworkManager: <info> Config: set interface ap_scan to 1
Oct 23 12:12:07 arioch NetworkManager: <info> (wlan1): supplicant connection state change: 0 -> 2
Oct 23 12:12:20 arioch dnsmasq[4683]: query[A] talk.google.com from 127.0.0.1
Oct 23 12:12:20 arioch dnsmasq[4683]: query[A] talk.google.com from 127.0.0.1
Oct 23 12:12:20 arioch dnsmasq[4683]: query[A] talk.google.com.WAG54GS from 127.0.0.1
Oct 23 12:12:20 arioch dnsmasq[4683]: query[A] talk.google.com.WAG54GS from 127.0.0.1
Oct 23 12:12:32 arioch NetworkManager: <info> Activation (wlan1/wireless): association took too long.
Oct 23 12:12:32 arioch NetworkManager: <info> (wlan1): device state change: 5 -> 6
Oct 23 12:12:32 arioch NetworkManager: <info> Activation (wlan1/wireless): asking for new secrets
Oct 23 12:12:32 arioch NetworkManager: <info> (wlan1): supplicant connection state change: 2 -> 0
Oct 23 12:12:47 arioch NetworkManager: <info> wlan1: link timed out.
Oct 23 12:13:15 arioch NetworkManager: <info> (wlan1): supplicant connection state change: 0 -> 2
Oct 23 12:13:50 arioch ntpd[23599]: Deleting interface #2 wlan1, 192.168.1.107#123, interface stats: received=0, sent=0, dropped=0, active_time=601 secs
Oct 23 12:13:50 arioch dnsmasq[4683]: query[A] talk.google.com from 127.0.0.1
Oct 23 12:13:50 arioch dnsmasq[4683]: query[A] talk.google.com from 127.0.0.1
Oct 23 12:13:50 arioch dnsmasq[4683]: query[A] talk.google.com.WAG54GS from 127.0.0.1
Oct 23 12:13:50 arioch dnsmasq[4683]: query[A] talk.google.com.WAG54GS from 127.0.0.1
Oct 23 12:13:53 arioch NetworkManager: <info> Activation (wlan1) Stage 1 of 5 (Device Prepare) scheduled...
Oct 23 12:13:53 arioch NetworkManager: <info> Activation (wlan1) Stage 1 of 5 (Device Prepare) started...
Oct 23 12:13:53 arioch NetworkManager: <info> (wlan1): device state change: 6 -> 4
Oct 23 12:13:53 arioch NetworkManager: <info> Activation (wlan1) Stage 2 of 5 (Device Configure) scheduled...
Oct 23 12:13:53 arioch NetworkManager: <info> Activation (wlan1) Stage 1 of 5 (Device Prepare) complete.
Oct 23 12:13:53 arioch NetworkManager: <info> Activation (wlan1) Stage 2 of 5 (Device Configure) starting...
Oct 23 12:13:53 arioch NetworkManager: <info> (wlan1): device state change: 4 -> 5
Oct 23 12:13:53 arioch NetworkManager: <info> Activation (wlan1/wireless): connection 'agora/bda2008' has security, and secrets exist. No new secrets needed.
Oct 23 12:13:53 arioch NetworkManager: <info> Config: added 'ssid' value 'agora'
Oct 23 12:13:53 arioch NetworkManager: <info> Config: added 'scan_ssid' value '1'
Oct 23 12:13:53 arioch NetworkManager: <info> Config: added 'key_mgmt' value 'WPA-PSK'
Oct 23 12:13:53 arioch NetworkManager: <info> Config: added 'psk' value '<omitted>'
Oct 23 12:13:53 arioch NetworkManager: <info> Config: added 'proto' value 'WPA RSN'
Oct 23 12:13:53 arioch NetworkManager: <info> Config: added 'pairwise' value 'TKIP CCMP'
Oct 23 12:13:53 arioch NetworkManager: <info> Config: added 'group' value 'WEP40 WEP104 TKIP CCMP'
Oct 23 12:13:53 arioch NetworkManager: <info> Activation (wlan1) Stage 2 of 5 (Device Configure) complete.
Oct 23 12:13:53 arioch NetworkManager: <info> (wlan1): supplicant connection state change: 2 -> 0
Oct 23 12:13:53 arioch NetworkManager: <info> Config: set interface ap_scan to 1
Oct 23 12:13:53 arioch NetworkManager: <info> (wlan1): supplicant connection state change: 0 -> 2
Oct 23 12:14:08 arioch NetworkManager: <info> wlan1: link timed out.
Oct 23 12:14:18 arioch NetworkManager: <info> Activation (wlan1/wireless): association took too long.
Oct 23 12:14:18 arioch NetworkManager: <info> (wlan1): device state change: 5 -> 6
Oct 23 12:14:18 arioch NetworkManager: <info> Activation (wlan1/wireless): asking for new secrets
Oct 23 12:14:18 arioch NetworkManager: <info> (wlan1): supplicant connection state change: 2 -> 0
Oct 23 12:14:25 arioch NetworkManager: <info> (wlan1): supplicant connection state change: 0 -> 2
Oct 23 12:14:33 arioch NetworkManager: <info> wlan1: link timed out.
Oct 23 12:15:53 arioch NetworkManager: <info> (wlan1): device state change: 6 -> 2
Oct 23 12:15:53 arioch NetworkManager: <info> (wlan1): deactivating device (reason: 0).
Oct 23 12:15:53 arioch NetworkManager: <info> (wlan1): taking down device.
Oct 23 12:16:18 arioch NetworkManager: <WARN> nm_device_wifi_set_enabled(): not in expected unavailable state!
Oct 23 12:16:18 arioch NetworkManager: <info> (wlan1): bringing up device.
Oct 23 12:16:18 arioch NetworkManager: <info> (wlan1): device state change: 2 -> 3
Oct 23 12:16:18 arioch NetworkManager: <info> (wlan1): supplicant interface state change: 1 -> 2.

Revision history for this message
Alexander Sack (asac) wrote :

what is the unexpected connection error in the log snippet you provided?

Changed in network-manager:
status: New → Incomplete
Revision history for this message
Bogdan Butnaru (bogdanb) wrote :

I'm not sure what you mean. Are you talking about a specific line in the log or is there something unclear in the description?

Revision history for this message
Duane Hinnen (duanedesign) wrote :

You reported this bug a while ago and there hasn't been any activity in it recently. We were wondering if this is still an issue for you. Can you try with the latest Ubuntu release? You can get a Live CD at:
http://www.ubuntu.com/testing/karmic/alpha6
Thanks in advance.

Revision history for this message
Bogdan Butnaru (bogdanb) wrote :

Hello,

I'm already running Karmic on most of my computers, but I use the wireless much less often these days so I'm not 100% sure of my answer.

However, I do remember distinctly several situations where NM asked me for the password after unrelated failures. In fact, as far as I can tell, it will (almost) always ask again for the password, for any kind of connection errors. (I.e., I'm sure that's the correct password, but the signal is weak or similar cases; I'm not sure exactly how WiFi authentication works, but certainly (in cases where I can check) the router isn't saying “bad password”, since I can connect to it via wire and check that it knows it.)

Revision history for this message
Brian (rephorm) wrote :
Download full text (8.3 KiB)

I have several walls between my wireless router and my desktop which has an RT61 wireless card in it. The antenna is on the floor and so the signal is pretty weak. The strength fluctuates dramatically depending on various factors (whether the door is open or closed, whether a cat is sitting in the window, the humidity, who knows what else). Anyway, often after the signal is dropped, NM asks again for the WPA key when it comes back up. If I cancel, and then select my AP from the NM applet, then it connects without asking.

Now, I'm not familiar enough with the authentication process to know if its legitimate that NM thinks the key is invalid. (E.g. is the router receiving a garbled key and responding that it is invalid? Or is NM just assuming that the authentication is failing because of an invalid key when in fact it is due to the signal being too weak).

In either case, in the key dialog, it would be nice to have some way of saying "just use the key you have stored". Or even better, "really, just keep trying with this key until the signal is strong enough to connect".

A relevant snippet from daemon.log of an attempted reconnect is:

(after a few messages from other daemons saying they can't resolve domain names since the connection has dropped)
Jan 24 13:29:52 weyl wpa_supplicant[1632]: CTRL-EVENT-SCAN-RESULTS
Jan 24 13:30:38 weyl NetworkManager: <info> (wlan0): device state change: 6 -> 9 (reason 7)
Jan 24 13:30:38 weyl NetworkManager: <info> Activation (wlan0) failed for access point (boru)
Jan 24 13:30:38 weyl NetworkManager: <info> Marking connection 'Auto boru' invalid.
Jan 24 13:30:38 weyl NetworkManager: <info> Activation (wlan0) failed.
Jan 24 13:30:38 weyl NetworkManager: <info> (wlan0): device state change: 9 -> 3 (reason 0)
Jan 24 13:30:38 weyl NetworkManager: <info> (wlan0): deactivating device (reason: 0).
Jan 24 13:30:38 weyl wpa_supplicant[1632]: CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys

(a minute passed before I did an "iwlist scan" from a terminal to verify my AP was in the list, and then chose it from the applet)

Jan 24 13:31:21 weyl wpa_supplicant[1632]: CTRL-EVENT-SCAN-RESULTS
Jan 24 13:31:28 weyl NetworkManager: <info> Activation (wlan0) starting connection 'Auto boru'
Jan 24 13:31:28 weyl NetworkManager: <info> (wlan0): device state change: 3 -> 4 (reason 0)
Jan 24 13:31:28 weyl NetworkManager: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
Jan 24 13:31:28 weyl NetworkManager: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
Jan 24 13:31:28 weyl NetworkManager: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
Jan 24 13:31:28 weyl NetworkManager: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
Jan 24 13:31:28 weyl NetworkManager: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
Jan 24 13:31:28 weyl NetworkManager: <info> (wlan0): device state change: 4 -> 5 (reason 0)
Jan 24 13:31:28 weyl NetworkManager: <info> Activation (wlan0/wireless): access point 'Auto boru' has security, but secrets are required.
Jan 24 13:31:28 weyl NetworkManager: <info> (wlan0): device state change: 5 -> 6 (r...

Read more...

Revision history for this message
Teunis Peters (teunis) wrote :

I can reproduce the bug quickly and easily. Move out of network range and back into - it fails and asks for a key. Basically all disconnect conditions where reconnecting takes any period of time, the key is re-requested. Annoying as all anything and applies to all versions of network-manager with any hardware I've tested (about a dozen different wireless chipsets over the last 3 years).

Revision history for this message
Launchpad Janitor (janitor) wrote :

[Expired for network-manager (Ubuntu) because there has been no activity for 60 days.]

Changed in network-manager (Ubuntu):
status: Incomplete → Expired
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.