NetworkManager asks for password after unrelated connection errors
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_
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.
Oct 23 12:12:20 arioch dnsmasq[4683]: query[A] talk.google.
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.
Oct 23 12:13:50 arioch dnsmasq[4683]: query[A] talk.google.
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_
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.
what is the unexpected connection error in the log snippet you provided?