You are not logged in.
So here's a brief description: my power is out for a few days due to hurricane Irene and today I was trying to do some work at Panera Bread (free wifi), but my wireless connection would never stay connected for more than about 1 minute before it would disconnect.
At home I looked over the logs and found (what I believe) are relevant entries.
In the first section, I can see that NetworkManager gets though all 5 stages of connecting to the wireless network with no problem.
Aug 30 16:18:22 localhost NetworkManager[872]: <info> Activation (wlan0) starting connection 'PANERA'
Aug 30 16:18:22 localhost NetworkManager[872]: <info> (wlan0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Aug 30 16:18:22 localhost NetworkManager[872]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
Aug 30 16:18:22 localhost NetworkManager[872]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
Aug 30 16:18:22 localhost NetworkManager[872]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
Aug 30 16:18:22 localhost NetworkManager[872]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
Aug 30 16:18:22 localhost NetworkManager[872]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
Aug 30 16:18:22 localhost NetworkManager[872]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0]
Aug 30 16:18:22 localhost NetworkManager[872]: <info> Activation (wlan0/wireless): connection 'PANERA' requires no security. No secrets needed.
Aug 30 16:18:22 localhost NetworkManager[872]: <info> Config: added 'ssid' value 'PANERA'
Aug 30 16:18:22 localhost NetworkManager[872]: <info> Config: added 'scan_ssid' value '1'
Aug 30 16:18:22 localhost NetworkManager[872]: <info> Config: added 'key_mgmt' value 'NONE'
Aug 30 16:18:22 localhost NetworkManager[872]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
Aug 30 16:18:22 localhost NetworkManager[872]: <info> Config: set interface ap_scan to 1
Aug 30 16:18:22 localhost NetworkManager[872]: <info> (wlan0): supplicant interface state: inactive -> scanning
Aug 30 16:18:25 localhost kernel: [ 1943.340549] wlan0: authenticate with 00:50:e8:02:2d:31 (try 1)
Aug 30 16:18:25 localhost NetworkManager[872]: <info> (wlan0): supplicant interface state: scanning -> authenticating
Aug 30 16:18:25 localhost kernel: [ 1943.342822] wlan0: authenticated
Aug 30 16:18:25 localhost NetworkManager[872]: <info> (wlan0): supplicant interface state: authenticating -> associating
Aug 30 16:18:25 localhost kernel: [ 1943.351174] wlan0: associate with 00:50:e8:02:2d:31 (try 1)
Aug 30 16:18:25 localhost kernel: [ 1943.353163] wlan0: RX AssocResp from 00:50:e8:02:2d:31 (capab=0x401 status=0 aid=38)
Aug 30 16:18:25 localhost kernel: [ 1943.353167] wlan0: associated
Aug 30 16:18:25 localhost kernel: [ 1943.357537] ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Aug 30 16:18:25 localhost NetworkManager[872]: <info> (wlan0): supplicant interface state: associating -> completed
Aug 30 16:18:25 localhost NetworkManager[872]: <info> Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful. Connected to wireless network 'PANERA'.
Aug 30 16:18:25 localhost NetworkManager[872]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled.
Aug 30 16:18:25 localhost NetworkManager[872]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) started...
Aug 30 16:18:25 localhost NetworkManager[872]: <info> (wlan0): device state change: config -> ip-config (reason 'none') [50 70 0]
Aug 30 16:18:25 localhost NetworkManager[872]: <info> Activation (wlan0) Beginning DHCPv4 transaction (timeout in 45 seconds)
Aug 30 16:18:25 localhost NetworkManager[872]: <info> dhcpcd started with pid 17513
Aug 30 16:18:25 localhost NetworkManager[872]: <info> Activation (wlan0) Beginning IP6 addrconf.
Aug 30 16:18:25 localhost NetworkManager[872]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete.
Aug 30 16:18:25 localhost dhcpcd[17513]: version 5.2.12 starting
Aug 30 16:18:25 localhost dhcpcd[17513]: wlan0: rebinding lease of 10.0.0.141
Aug 30 16:18:25 localhost NetworkManager[872]: <info> (wlan0): DHCPv4 state changed nbi -> preinit
Aug 30 16:18:26 localhost dhcpcd[17513]: wlan0: acknowledged 10.0.0.141 from 10.0.0.4 `<FF>'
Aug 30 16:18:26 localhost dhcpcd[17513]: wlan0: checking for 10.0.0.141
Aug 30 16:18:27 localhost avahi-daemon[1072]: Registering new address record for fe80::224:d7ff:fe27:db38 on wlan0.*.
Aug 30 16:18:31 localhost dhcpcd[17513]: wlan0: leased 10.0.0.141 for 86400 seconds
Aug 30 16:18:31 localhost avahi-daemon[1072]: Joining mDNS multicast group on interface wlan0.IPv4 with address 10.0.0.141.
Aug 30 16:18:31 localhost avahi-daemon[1072]: New relevant interface wlan0.IPv4 for mDNS.
Aug 30 16:18:31 localhost avahi-daemon[1072]: Registering new address record for 10.0.0.141 on wlan0.IPv4.
Aug 30 16:18:31 localhost NetworkManager[872]: <info> (wlan0): DHCPv4 state changed preinit -> bound
Aug 30 16:18:31 localhost NetworkManager[872]: <info> Activation (wlan0) Stage 4 of 5 (IP4 Configure Get) scheduled...
Aug 30 16:18:31 localhost NetworkManager[872]: <info> Activation (wlan0) Stage 4 of 5 (IP4 Configure Get) started...
Aug 30 16:18:31 localhost NetworkManager[872]: <info> address 10.0.0.141
Aug 30 16:18:31 localhost NetworkManager[872]: <info> prefix 24 (255.255.255.0)
Aug 30 16:18:31 localhost NetworkManager[872]: <info> gateway 10.0.0.4
Aug 30 16:18:31 localhost NetworkManager[872]: <info> nameserver '205.139.50.143'
Aug 30 16:18:31 localhost NetworkManager[872]: <info> nameserver '63.209.206.118'
Aug 30 16:18:31 localhost NetworkManager[872]: <info> nameserver '4.2.2.1'
Aug 30 16:18:31 localhost NetworkManager[872]: <info> domain name 'DNSContentFiltering'
Aug 30 16:18:31 localhost NetworkManager[872]: <info> Activation (wlan0) Stage 4 of 5 (IP4 Configure Get) complete.
Aug 30 16:18:36 localhost kernel: [ 1954.135461] wlan0: no IPv6 routers present
Aug 30 16:18:46 localhost NetworkManager[872]: <info> (wlan0): IP6 addrconf timed out or failed.
Aug 30 16:18:46 localhost NetworkManager[872]: <info> Activation (wlan0) Stage 4 of 5 (IP6 Configure Timeout) scheduled...
Aug 30 16:18:46 localhost NetworkManager[872]: <info> Activation (wlan0) Stage 4 of 5 (IP6 Configure Timeout) started...
Aug 30 16:18:46 localhost NetworkManager[872]: <info> Activation (wlan0) Stage 5 of 5 (IP Configure Commit) scheduled...
Aug 30 16:18:46 localhost NetworkManager[872]: <info> Activation (wlan0) Stage 4 of 5 (IP6 Configure Timeout) complete.
Aug 30 16:18:46 localhost NetworkManager[872]: <info> Activation (wlan0) Stage 5 of 5 (IP Configure Commit) started...
Aug 30 16:18:47 localhost NetworkManager[872]: <info> (wlan0): device state change: ip-config -> activated (reason 'none') [70 100 0]
However in this next section, I keep getting errors about
wlan0): device state change: disconnected -> unavailable (reason 'supplicant-failed')
the change to "unavailable" status is what kills my connection to the network. This occurs several times, until it looks like NetworkManager decides to kill wpa_supplicant and start the connection from the beginning (last 2 lines).
ug 30 16:18:47 localhost NetworkManager[872]: <info> Policy set 'PANERA' (wlan0) as default for IPv4 routing and DNS.
Aug 30 16:18:47 localhost NetworkManager[872]: <info> Activation (wlan0) successful, device activated.
Aug 30 16:18:47 localhost NetworkManager[872]: <info> Activation (wlan0) Stage 5 of 5 (IP Configure Commit) complete.
Aug 30 16:18:47 localhost dbus[847]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Aug 30 16:18:47 localhost dbus[847]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Aug 30 16:19:17 localhost NetworkManager[872]: <info> wpa_supplicant stopped
Aug 30 16:19:17 localhost NetworkManager[872]: <info> (wlan0): supplicant interface state: completed -> down
Aug 30 16:19:17 localhost NetworkManager[872]: <info> (wlan0): device state change: activated -> unavailable (reason 'supplicant-failed') [100 20 10]
Aug 30 16:19:17 localhost NetworkManager[872]: <info> (wlan0): deactivating device (reason: 10).
Aug 30 16:19:17 localhost dbus[847]: [system] Activating service name='fi.w1.wpa_supplicant1' (using servicehelper)
Aug 30 16:19:17 localhost dhcpcd[17513]: received SIGTERM, stopping
Aug 30 16:19:17 localhost dhcpcd[17513]: wlan0: removing interface
Aug 30 16:19:17 localhost avahi-daemon[1072]: Withdrawing address record for 10.0.0.141 on wlan0.
Aug 30 16:19:17 localhost avahi-daemon[1072]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 10.0.0.141.
Aug 30 16:19:17 localhost avahi-daemon[1072]: Interface wlan0.IPv4 no longer relevant for mDNS.
Aug 30 16:19:17 localhost dbus[847]: [system] Successfully activated service 'fi.w1.wpa_supplicant1'
Aug 30 16:19:18 localhost NetworkManager[872]: <info> (wlan0): canceled DHCP transaction, DHCP client pid 17513
Aug 30 16:19:18 localhost dbus[847]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Aug 30 16:19:18 localhost NetworkManager[872]: <warn> (pid 17513) unhandled DHCP event for interface wlan0
Aug 30 16:19:18 localhost NetworkManager[872]: <info> wpa_supplicant started
Aug 30 16:19:18 localhost dbus[847]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Aug 30 16:19:18 localhost NetworkManager[872]: <info> (wlan0): supplicant interface state: starting -> ready
Aug 30 16:19:18 localhost NetworkManager[872]: <info> (wlan0): device state change: unavailable -> disconnected (reason 'supplicant-available') [20 30 42]
Aug 30 16:19:18 localhost NetworkManager[872]: <info> (wlan0): supplicant interface state: ready -> inactive
Aug 30 16:19:25 localhost kernel: [ 2003.063361] wlan0: deauthenticating from 00:50:e8:02:2d:31 by local choice (reason=2)
Aug 30 16:19:25 localhost kernel: [ 2003.087846] cfg80211: Calling CRDA to update world regulatory domain
Aug 30 16:19:25 localhost NetworkManager[872]: <info> wpa_supplicant stopped
Aug 30 16:19:25 localhost NetworkManager[872]: <info> (wlan0): supplicant interface state: inactive -> down
Aug 30 16:19:25 localhost NetworkManager[872]: <info> (wlan0): device state change: disconnected -> unavailable (reason 'supplicant-failed') [30 20 10]
Aug 30 16:19:25 localhost NetworkManager[872]: <info> (wlan0): deactivating device (reason: 10).
Aug 30 16:19:25 localhost dbus[847]: [system] Activating service name='fi.w1.wpa_supplicant1' (using servicehelper)
Aug 30 16:19:25 localhost dbus[847]: [system] Successfully activated service 'fi.w1.wpa_supplicant1'
Aug 30 16:19:25 localhost NetworkManager[872]: <info> wpa_supplicant started
Aug 30 16:19:25 localhost NetworkManager[872]: <info> (wlan0): supplicant interface state: starting -> ready
Aug 30 16:19:25 localhost NetworkManager[872]: <info> (wlan0): device state change: unavailable -> disconnected (reason 'supplicant-available') [20 30 42]
Aug 30 16:19:25 localhost NetworkManager[872]: <info> (wlan0): supplicant interface state: ready -> inactive
Aug 30 16:19:30 localhost NetworkManager[872]: <info> wpa_supplicant stopped
Aug 30 16:19:30 localhost NetworkManager[872]: <info> (wlan0): supplicant interface state: inactive -> down
Aug 30 16:19:30 localhost NetworkManager[872]: <info> (wlan0): device state change: disconnected -> unavailable (reason 'supplicant-failed') [30 20 10]
Aug 30 16:19:30 localhost NetworkManager[872]: <info> (wlan0): deactivating device (reason: 10).
Aug 30 16:19:30 localhost dbus[847]: [system] Activating service name='fi.w1.wpa_supplicant1' (using servicehelper)
Aug 30 16:19:30 localhost NetworkManager[872]: <info> wpa_supplicant die count 3; ignoring for 10 seconds
Aug 30 16:19:30 localhost dbus[847]: [system] Successfully activated service 'fi.w1.wpa_supplicant1'
Aug 30 16:19:30 localhost NetworkManager[872]: <info> wpa_supplicant started
Aug 30 16:19:40 localhost NetworkManager[872]: <info> (wlan0): supplicant interface state: init -> starting
Aug 30 16:19:40 localhost NetworkManager[872]: <info> wpa_supplicant die count reset
Aug 30 16:19:40 localhost NetworkManager[872]: <info> (wlan0): supplicant interface state: starting -> ready
Aug 30 16:19:40 localhost NetworkManager[872]: <info> (wlan0): device state change: unavailable -> disconnected (reason 'supplicant-available') [20 30 42]
Aug 30 16:19:40 localhost NetworkManager[872]: <info> (wlan0): supplicant interface state: ready -> inactive
Aug 30 16:19:44 localhost NetworkManager[872]: <info> wpa_supplicant stopped
Aug 30 16:19:44 localhost NetworkManager[872]: <info> (wlan0): supplicant interface state: inactive -> down
Aug 30 16:19:44 localhost NetworkManager[872]: <info> (wlan0): device state change: disconnected -> unavailable (reason 'supplicant-failed') [30 20 10]
Aug 30 16:19:44 localhost NetworkManager[872]: <info> (wlan0): deactivating device (reason: 10).
Aug 30 16:19:44 localhost dbus[847]: [system] Activating service name='fi.w1.wpa_supplicant1' (using servicehelper)
Aug 30 16:19:44 localhost dbus[847]: [system] Successfully activated service 'fi.w1.wpa_supplicant1'
Aug 30 16:19:44 localhost NetworkManager[872]: <info> wpa_supplicant started
Aug 30 16:19:45 localhost NetworkManager[872]: <info> (wlan0): supplicant interface state: starting -> ready
Aug 30 16:19:45 localhost NetworkManager[872]: <info> (wlan0): device state change: unavailable -> disconnected (reason 'supplicant-available') [20 30 42]
Aug 30 16:19:45 localhost NetworkManager[872]: <info> (wlan0): supplicant interface state: ready -> inactive
Aug 30 16:19:49 localhost NetworkManager[872]: <info> wpa_supplicant stopped
Aug 30 16:19:49 localhost NetworkManager[872]: <info> (wlan0): supplicant interface state: inactive -> down
Aug 30 16:19:49 localhost NetworkManager[872]: <info> (wlan0): device state change: disconnected -> unavailable (reason 'supplicant-failed') [30 20 10]
Aug 30 16:19:49 localhost NetworkManager[872]: <info> (wlan0): deactivating device (reason: 10).
Aug 30 16:19:49 localhost dbus[847]: [system] Activating service name='fi.w1.wpa_supplicant1' (using servicehelper)
Aug 30 16:19:49 localhost dbus[847]: [system] Successfully activated service 'fi.w1.wpa_supplicant1'
Aug 30 16:19:49 localhost NetworkManager[872]: <info> wpa_supplicant started
Aug 30 16:19:49 localhost NetworkManager[872]: <info> (wlan0): supplicant interface state: starting -> ready
Aug 30 16:19:49 localhost NetworkManager[872]: <info> (wlan0): device state change: unavailable -> disconnected (reason 'supplicant-available') [20 30 42]
Aug 30 16:19:49 localhost NetworkManager[872]: <info> (wlan0): supplicant interface state: ready -> inactive
Aug 30 16:19:53 localhost NetworkManager[872]: <info> wpa_supplicant stopped
Aug 30 16:19:53 localhost NetworkManager[872]: <info> (wlan0): supplicant interface state: inactive -> down
Aug 30 16:19:53 localhost NetworkManager[872]: <info> (wlan0): device state change: disconnected -> unavailable (reason 'supplicant-failed') [30 20 10]
Aug 30 16:19:53 localhost NetworkManager[872]: <info> (wlan0): deactivating device (reason: 10).
Aug 30 16:19:53 localhost dbus[847]: [system] Activating service name='fi.w1.wpa_supplicant1' (using servicehelper)
Aug 30 16:19:53 localhost NetworkManager[872]: <info> wpa_supplicant die count 3; ignoring for 10 seconds
Aug 30 16:19:53 localhost dbus[847]: [system] Successfully activated service 'fi.w1.wpa_supplicant1'
Aug 30 16:19:53 localhost NetworkManager[872]: <info> wpa_supplicant started
Aug 30 16:20:04 localhost NetworkManager[872]: <info> (wlan0): supplicant interface state: init -> starting
Aug 30 16:20:04 localhost NetworkManager[872]: <info> wpa_supplicant die count reset
Aug 30 16:20:04 localhost NetworkManager[872]: <info> (wlan0): supplicant interface state: starting -> ready
Aug 30 16:20:04 localhost NetworkManager[872]: <info> (wlan0): device state change: unavailable -> disconnected (reason 'supplicant-available') [20 30 42]
Aug 30 16:20:04 localhost NetworkManager[872]: <info> (wlan0): supplicant interface state: ready -> inactive
Aug 30 16:20:08 localhost NetworkManager[872]: <info> Auto-activating connection 'PANERA'.
Aug 30 16:20:08 localhost NetworkManager[872]: <info> Activation (wlan0) starting connection 'PANERA'
The PANERA network is not WEP/WPA/WPA2, but my network card can see other networks that are WPA. At home I usually run a open wifi network and have not experienced any problems staying connected. I have a Thinkpad T410s with an Intel board and use the iwlagn driver.
PS: I tried to do some searching to see if anyone else had the problem (I didn't find anything that matched my issue), but I don't have a whole lot of connectivity to search right now (even this post was composed offline). So sorry if if the answer is floating on the forums.
Offline
Well today I did manage to get a solid connection to Panera's wifi using iwconfig and dhclient. I also tired with wicd, but that hung on obtaining an IP address with dhcpcd, but worked when I used dhclient.
While I had a good connection I tried to build a new copy of NetworkManager that only used dhclient, but trying to connect with that gave me the same wpa_supplicant errors. Frankly, I don't know why NetworkManager is even calling wpa_supplicant for an open network.
While NetworkManager is freaking out about wpa_supplicant, it actually sets the hardware to "unavailable", and loses the connection. Trying to use nm-tool to see available networks returns nothing, and there are no networks listed under the nm-applet menu, just "Device Unavailable".
Despite nm-tool not seeing any networks, if I run "sudo iwlist scan", all the networks & APs that my laptop can see are listed. The higher number I saw listed was 35 "cells" (I'm assuming cells = APs), I think maybe the high number of APs are throwing NetworkManager into a fit.
Power is back on now and I've confirmed at home I can connect to both open and WPA networks using NetworkManager, no problem.
Any thoughts on what the problem might be?
Offline
I'm getting the same problem. Latest kernel, network manager. I'm working around by command line wpa_supplicant and dhcpd.
Last edited by wilson (2011-10-03 21:25:09)
Offline
Exactly the same thing is happening to me now with wicd after the latest update.
1) wicd trys to connect
2) it connects
3) within 1-5 seconds of a connection, it disconnects
Did I mention it disconnected immediately when the upgrade affecting it occurred?
Glad I have netcfg on here... otherwise I'd be unable to connect, I think.
Last edited by 1LordAnubis (2011-10-04 03:31:19)
Any society that would give up a little liberty to gain a little security will deserve neither and lose both.
-Benjamin Franklin
The reasonable man adapts himself to the world; the unreasonable one persists in trying to adapt the world to himself. Therefore all progress depends on the unreasonable man.
-George Bernard Shaw
Offline
Exactly the same thing is happening to me now with wicd after the latest update.
1) wicd trys to connect
2) it connects
3) within 1-5 seconds of a connection, it disconnectsDid I mention it disconnected immediately when the upgrade affecting it occurred?
Glad I have netcfg on here... otherwise I'd be unable to connect, I think.
I have the same problem as well since the last update. wicd tries to reconnect forever.
At the moment I survice using netcfg / wifi-select but there's clearly something messed up with wicd. Will do some debugging later today.
Last edited by redcomet (2011-10-04 04:55:35)
Offline
WICD temporary fix for me: Preferences - Advanced Settings - Backend -change to ioctl
Offline
WICD temporary fix for me: Preferences - Advanced Settings - Backend -change to ioctl
after upgrade net-tools i ve encountered this problem with wicd. This fix works for me too. tx
Offline
WICD temporary fix for me: Preferences - Advanced Settings - Backend -change to ioctl
Thank you very very very much. This worked for me as well. Been banging my head against the wall for the past 3 hours. I installed gnome 3 on top of a working kde setup and suddenly wicd got disconnected. I did notice net-tools was either installed/upgraded. Anyway issue solved for now.
Offline
Thanks a lot, rich.atc, i was so annoyed about the update breaking my wlan that I was about to install Ubuntu
"Freedom is the freedom to say that two plus two make four. If that is granted, all else follows." - George Orwell
Offline
Changing the backend to ioctl does indeed work. Thanks for the suggestion !
Now lets find out why it fails to work with the backend on 'external'.
edit: There is a wicd update now that fixes this issue, time to do pacman -Syu ( don't forget to completely stop and start all the wicd processes after this) . I can confirm that the update fixed the problem on my system.
Last edited by redcomet (2011-10-04 17:06:34)
Offline
I think you folks have just saved my sanity - thank you all :-) (And I thought my wireless networks didn't want to know me any more...)
BTW: do we need to switch the backend back to "external" once wicd is upgraded, or should it stay with ioctl?
--
Asus Eee 701SD (8Gb SSD) - Arch Linux
The continuing adventures: http://eee701planetoid.wordpress.com/
--
Offline
To answer my own question: after the wicd upgrade, it appears you can switch back to "external" as the backend, and wicd works fine. YMMV.
--
Asus Eee 701SD (8Gb SSD) - Arch Linux
The continuing adventures: http://eee701planetoid.wordpress.com/
--
Offline