Arch Linux

Sarek23

Member

Registered: 2009-04-18

Posts: 5

Failed connection to WPA WiFi network with NetworkManager

For a few days I have had severe trouble connecting to my WiFi network at home. It is a WPA-PSK/WPA2-PSK secured network. I have no trouble connecting to an open network or a WPA2 network secured by certificates. I also have no trouble connecting to my home network "manually" using wpa_supplicant and dhcpcd.

I am currently using kernel 3.2.8-1-ARCH along with NetworkManager 0.9.2.0. I am relatively sure the error first ocurred after the kernel update to 3.2.7. Unfortunately, I can't remember which packages were upgraded along with it.

I think I have narrowed down the problem to something related to IP configuration, it appears that setting the default route fails because of a missing argument.

This is an excerpt from /var/log/messages.log and shows a single try of NetworkManager to connect to my network:

Feb 28 16:45:41 localhost NetworkManager[3019]: <info> Auto-activating connection 'Auto uliweb'.
Feb 28 16:45:41 localhost NetworkManager[3019]: <info> Activation (wlan0) starting connection 'Auto uliweb'
Feb 28 16:45:41 localhost NetworkManager[3019]: <info> (wlan0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Feb 28 16:45:41 localhost NetworkManager[3019]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
Feb 28 16:45:41 localhost NetworkManager[3019]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
Feb 28 16:45:41 localhost NetworkManager[3019]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
Feb 28 16:45:41 localhost NetworkManager[3019]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
Feb 28 16:45:41 localhost NetworkManager[3019]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
Feb 28 16:45:41 localhost NetworkManager[3019]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0]
Feb 28 16:45:41 localhost NetworkManager[3019]: <info> Activation (wlan0/wireless): access point 'Auto uliweb' has security, but secrets are required.
Feb 28 16:45:41 localhost NetworkManager[3019]: <info> (wlan0): device state change: config -> need-auth (reason 'none') [50 60 0]
Feb 28 16:45:41 localhost NetworkManager[3019]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
Feb 28 16:45:41 localhost NetworkManager[3019]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
Feb 28 16:45:41 localhost NetworkManager[3019]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
Feb 28 16:45:41 localhost NetworkManager[3019]: <info> (wlan0): device state change: need-auth -> prepare (reason 'none') [60 40 0]
Feb 28 16:45:41 localhost NetworkManager[3019]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
Feb 28 16:45:41 localhost NetworkManager[3019]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
Feb 28 16:45:41 localhost NetworkManager[3019]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
Feb 28 16:45:41 localhost NetworkManager[3019]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0]
Feb 28 16:45:41 localhost NetworkManager[3019]: <info> Activation (wlan0/wireless): connection 'Auto uliweb' has security, and secrets exist.  No new secrets needed.
Feb 28 16:45:41 localhost NetworkManager[3019]: <info> Config: added 'ssid' value 'uliweb'
Feb 28 16:45:41 localhost NetworkManager[3019]: <info> Config: added 'scan_ssid' value '1'
Feb 28 16:45:41 localhost NetworkManager[3019]: <info> Config: added 'key_mgmt' value 'WPA-PSK'
Feb 28 16:45:41 localhost NetworkManager[3019]: <info> Config: added 'psk' value '<omitted>'
Feb 28 16:45:41 localhost NetworkManager[3019]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
Feb 28 16:45:41 localhost NetworkManager[3019]: <info> Config: set interface ap_scan to 1
Feb 28 16:45:41 localhost NetworkManager[3019]: <info> (wlan0): supplicant interface state: disconnected -> scanning
Feb 28 16:45:43 localhost NetworkManager[3019]: <info> (wlan0): supplicant interface state: scanning -> authenticating
Feb 28 16:45:43 localhost NetworkManager[3019]: <info> (wlan0): supplicant interface state: authenticating -> associating
Feb 28 16:45:43 localhost NetworkManager[3019]: <info> (wlan0): supplicant interface state: associating -> associated
Feb 28 16:45:44 localhost NetworkManager[3019]: <info> (wlan0): supplicant interface state: associated -> 4-way handshake
Feb 28 16:45:44 localhost NetworkManager[3019]: <info> (wlan0): supplicant interface state: 4-way handshake -> completed
Feb 28 16:45:44 localhost NetworkManager[3019]: <info> Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful.  Connected to wireless network 'uliweb'.
Feb 28 16:45:44 localhost NetworkManager[3019]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled.
Feb 28 16:45:44 localhost NetworkManager[3019]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) started...
Feb 28 16:45:44 localhost NetworkManager[3019]: <info> (wlan0): device state change: config -> ip-config (reason 'none') [50 70 0]
Feb 28 16:45:44 localhost NetworkManager[3019]: <info> Activation (wlan0) Beginning DHCPv4 transaction (timeout in 45 seconds)
Feb 28 16:45:44 localhost NetworkManager[3019]: <info> dhcpcd started with pid 3990
Feb 28 16:45:44 localhost NetworkManager[3019]: <info> Activation (wlan0) Beginning IP6 addrconf.
Feb 28 16:45:44 localhost NetworkManager[3019]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete.
Feb 28 16:45:44 localhost dhcpcd[3990]: version 5.5.4 starting
Feb 28 16:45:44 localhost NetworkManager[3019]: <info> (wlan0): DHCPv4 state changed nbi -> preinit
Feb 28 16:45:44 localhost dhcpcd[3990]: wlan0: sending IPv6 Router Solicitation
Feb 28 16:45:44 localhost dhcpcd[3990]: wlan0: rebinding lease of 192.168.178.22
Feb 28 16:45:45 localhost dhcpcd[3990]: wlan0: acknowledged 192.168.178.22 from 192.168.178.1
Feb 28 16:45:45 localhost dhcpcd[3990]: wlan0: checking for 192.168.178.22
Feb 28 16:45:46 localhost dhcpcd[3200]: eth0: Router Advertisement from fe80::be05:43ff:fea5:984
Feb 28 16:45:46 localhost dhcpcd[3990]: wlan0: Router Advertisement from fe80::be05:43ff:fea5:984
Feb 28 16:45:46 localhost NetworkManager[3019]: <info> (wlan0): DHCPv4 state changed preinit -> (null)
Feb 28 16:45:47 localhost NetworkManager[3019]: <info> Activation (wlan0) Stage 4 of 5 (IP6 Configure Get) scheduled...
Feb 28 16:45:47 localhost NetworkManager[3019]: <info> Activation (wlan0) Stage 4 of 5 (IP6 Configure Get) started...
Feb 28 16:45:47 localhost NetworkManager[3019]: <info> Activation (wlan0) Stage 4 of 5 (IP6 Configure Get) complete.
Feb 28 16:45:49 localhost dhcpcd[3990]: wlan0: leased 192.168.178.22 for 864000 seconds
Feb 28 16:45:49 localhost NetworkManager[3019]: <info> (wlan0): DHCPv4 state changed (null) -> bound
Feb 28 16:45:49 localhost NetworkManager[3019]: <info> Activation (wlan0) Stage 4 of 5 (IP4 Configure Get) scheduled...
Feb 28 16:45:49 localhost NetworkManager[3019]: <info> Activation (wlan0) Stage 4 of 5 (IP4 Configure Get) started...
Feb 28 16:45:49 localhost NetworkManager[3019]: <info>   address 192.168.178.22
Feb 28 16:45:49 localhost NetworkManager[3019]: <info>   prefix 24 (255.255.255.0)
Feb 28 16:45:49 localhost NetworkManager[3019]: <info>   gateway 192.168.178.1
Feb 28 16:45:49 localhost NetworkManager[3019]: <info>   nameserver '192.168.178.1'
Feb 28 16:45:49 localhost NetworkManager[3019]: <info>   domain name 'fritz.box'
Feb 28 16:45:49 localhost NetworkManager[3019]: <info> Activation (wlan0) Stage 5 of 5 (IP Configure Commit) scheduled...
Feb 28 16:45:49 localhost NetworkManager[3019]: <info> Activation (wlan0) Stage 4 of 5 (IP4 Configure Get) complete.
Feb 28 16:45:49 localhost NetworkManager[3019]: <info> Activation (wlan0) Stage 5 of 5 (IP Configure Commit) started...
Feb 28 16:45:50 localhost NetworkManager[3019]: <info> Policy set 'Wired connection 1' (eth0) as default for IPv4 routing and DNS.
Feb 28 16:45:51 localhost NetworkManager[3019]: <info> Policy set 'Wired connection 1' (eth0) as default for IPv4 routing and DNS.
Feb 28 16:45:51 localhost NetworkManager[3019]: <info> (wlan0): device state change: ip-config -> activated (reason 'none') [70 100 0]
Feb 28 16:45:51 localhost NetworkManager[3019]: <warn> Failed to add route Missing attribute
Feb 28 16:45:51 localhost NetworkManager[3019]: <info> Policy set 'Auto uliweb' (wlan0) as default for IPv6 routing and DNS.
Feb 28 16:45:51 localhost NetworkManager[3019]: <info> Activation (wlan0) successful, device activated.
Feb 28 16:45:51 localhost NetworkManager[3019]: <info> Activation (wlan0) Stage 5 of 5 (IP Configure Commit) complete.
Feb 28 16:45:51 localhost dbus[792]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Feb 28 16:45:51 localhost NetworkManager[3019]: <info> (wlan0): device state change: activated -> failed (reason 'ip-config-unavailable') [100 120 5]
Feb 28 16:45:51 localhost NetworkManager[3019]: <warn> Activation (wlan0) failed for access point (uliweb)
Feb 28 16:45:51 localhost NetworkManager[3019]: <warn> Activation (wlan0) failed.
Feb 28 16:45:51 localhost NetworkManager[3019]: <info> (wlan0): device state change: failed -> disconnected (reason 'none') [120 30 0]
Feb 28 16:45:51 localhost NetworkManager[3019]: <info> (wlan0): deactivating device (reason 'none') [0]
Feb 28 16:45:51 localhost dhcpcd[3990]: received SIGTERM, stopping
Feb 28 16:45:51 localhost dhcpcd[3990]: wlan0: removing interface
Feb 28 16:45:51 localhost dbus[792]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Feb 28 16:45:51 localhost NetworkManager[3019]: <info> (wlan0): canceled DHCP transaction, DHCP client pid 3990
Feb 28 16:45:51 localhost NetworkManager[3019]: <info> Policy set 'Wired connection 1' (eth0) as default for IPv4 routing and DNS.
Feb 28 16:45:51 localhost NetworkManager[3019]: <info> Policy set 'Wired connection 1' (eth0) as default for IPv4 routing and DNS.
Feb 28 16:45:51 localhost NetworkManager[3019]: <warn> (pid 3990) unhandled DHCP event for interface wlan0
Feb 28 16:45:51 localhost kernel: [ 1673.487787] cfg80211: Calling CRDA to update world regulatory domain
Feb 28 16:45:51 localhost NetworkManager[3019]: <warn> (pid 3990) unhandled DHCP event for interface wlan0
Feb 28 16:45:51 localhost NetworkManager[3019]: <info> (wlan0): supplicant interface state: completed -> disconnected

I also tried running NetworkManager in debug mode, but that did not shed any light on the issue, there weren't more or more detailed error messages. Setting a static IPv4 configuration and disabling IPv6 also led to the same error.

Any ideas on what causes this behaviour would be greatly appreciated! :-)

Blind

Member

From: Desert mountain

Registered: 2005-02-06

Posts: 386

Re: Failed connection to WPA WiFi network with NetworkManager

I do have a very similar issue with an AP at work.
Logs look pretty much the same...
Any help?

sasek

Member

From: Poland

Registered: 2009-12-26

Posts: 10

Re: Failed connection to WPA WiFi network with NetworkManager

Same issue at my laptop. WPA2 and RTL8187SE.

gun26

Member

Registered: 2007-07-05

Posts: 55

Re: Failed connection to WPA WiFi network with NetworkManager

https://bbs.archlinux.org/viewtopic.php?id=136482

I think something broke in the networking drivers during the point releases of kernel 3.2, including the current Arch kernel. I suggest trying the current LTS kernel as a fix.

RockrKnight

Member

Registered: 2011-06-03

Posts: 10

Re: Failed connection to WPA WiFi network with NetworkManager

Like sasek, I'm using the RTL8187SE card and I can't use networkmanager because it just doesn't detect the networks. What I've seen in the log files is that wpa_supplicant is stuck in a loop. I used Fedora for a few days and it connects fine, using the gnome-shell applet, but Fedora is so damn slow on my laptop.

Right now I'm using wicd-curses. That's my solution for now.