Immediate disconnection of wpa_supplicant and dhcpcd after successful connection

[Ivan Ux]

When starting a new wireless connection to my home network, wicd starts wpa_supplicant correctly, then starts DHCPCD correctly and almost immediately sends a disconnection order to both program.

The result is the following:

MACHINE ~ # ps ax | grep wpa && ps ax | grep dhcp <-------------- NOTHING BEFORE
 6309 pts/0 S+ 0:00 grep --colour=auto wpa
 6311 pts/0 S+ 0:00 grep --colour=auto dhcp
MACHINE ~ # ps ax | grep wpa && ps ax | grep dhcp
 6314 ? Ss 0:00 wpa_supplicant -B -i ath0 -c /var/lib/wicd/configurations/001970391074 -D wext
 6321 pts/0 S+ 0:00 grep --colour=auto wpa
 6323 pts/0 S+ 0:00 grep --colour=auto dhcp
MACHINE ~ # ps ax | grep wpa && ps ax | grep dhcp <-------------- WPA_SUPPLICANT STARTS
 6314 ? Ss 0:00 wpa_supplicant -B -i ath0 -c /var/lib/wicd/configurations/001970391074 -D wext
 6326 pts/0 S+ 0:00 grep --colour=auto wpa
 6328 pts/0 S+ 0:00 grep --colour=auto dhcp
[...]
MACHINE ~ # ps ax | grep wpa && ps ax | grep dhcp <-------------- DHCPCD STARTS
 6314 ? Ss 0:00 wpa_supplicant -B -i ath0 -c /var/lib/wicd/configurations/001970391074 -D wext
 6381 pts/0 S+ 0:00 grep --colour=auto wpa
 6371 ? Ss 0:00 /sbin/dhcpcd ath0 -h MACHINE
 6385 pts/0 S+ 0:00 grep --colour=auto dhcp
[...]
MACHINE ~ # ps ax | grep wpa && ps ax | grep dhcp <-------------- DHCPCD IS KILLED ALMOST IMMEDIATELY!
 6314 ? Ss 0:00 wpa_supplicant -B -i ath0 -c /var/lib/wicd/configurations/001970391074 -D wext
 6403 pts/0 S+ 0:00 grep --colour=auto wpa
 6392 ? S 0:00 /sbin/dhcpcd -k ath0
 6405 pts/0 S+ 0:00 grep --colour=auto dhcp
MACHINE ~ # ps ax | grep wpa && ps ax | grep dhcp <-------------- NOTHING LEFT!
 6417 pts/0 S+ 0:00 grep --colour=auto wpa
 6419 pts/0 S+ 0:00 grep --colour=auto dhcp

Which results in an autoreconnect procedure which gives the same results.

Here are the results of a "wicd -afoe" command:

---------------------------
wicd initializing...
---------------------------
wicd is version 1.7.1b2 565
setting backend to external
trying to load backend external
successfully loaded backend external
trying to load backend external
successfully loaded backend external
Automatically detected wireless interface ath0
setting wireless interface ath0
automatically detected wired interface eth0
setting wired interface eth0
setting wpa driver wext
setting use global dns to False
setting global dns
global dns servers are None None None
domain is None
search domain is None
setting automatically reconnect when connection drops True
Setting dhcp client to 0
Wireless configuration file found...
Wired configuration file found...
chmoding configuration files 0600...
chowning configuration files root:root...
Using wireless interface...ath0
Using wired interface...eth0
--no-autoconnect detected, not autoconnecting...
Connecting to wireless network Univers2
dhcpcd[19079]: dhcpcd not running
dev: Host name lookup failure
Failed to connect to wpa_supplicant - wpa_ctrl_open: No such file or directory
dhcpcd[19085]: dhcpcd not running
dev: Host name lookup failure
Putting interface down
Releasing DHCP leases...
dhcpcd[19092]: dhcpcd not running
Setting false IP...
Stopping wpa_supplicant
Failed to connect to wpa_supplicant - wpa_ctrl_open: No such file or directory
Flushing the routing table...
dev: Host name lookup failure
Putting interface up...
Generating psk...
Attempting to authenticate...
Running DHCP with hostname MACHINE
dhcpcd[19196]: version 5.2.12 starting

dhcpcd[19196]: forked to background, child pid 19197

DHCP connection successful
not verifying
Connecting thread exiting.
Sending connection attempt result Success
dhcpcd[19317]: sending signal 1 to pid 19197
dhcpcd[19317]: waiting for pid 19197 to exit
dev: Host name lookup failure
dhcpcd[19349]: dhcpcd not running
dev: Host name lookup failure
Connecting to wireless network Univers2
dhcpcd[19405]: dhcpcd not running
dev: Host name lookup failure
Failed to connect to wpa_supplicant - wpa_ctrl_open: No such file or directory
dhcpcd[19411]: dhcpcd not running
dev: Host name lookup failure
Putting interface down
Releasing DHCP leases...
dhcpcd[19418]: dhcpcd not running
Setting false IP...
Stopping wpa_supplicant
Failed to connect to wpa_supplicant - wpa_ctrl_open: No such file or directory
Flushing the routing table...
dev: Host name lookup failure
Putting interface up...
Generating psk...
Attempting to authenticate...
Running DHCP with hostname MACHINE
dhcpcd[19502]: version 5.2.12 starting

dhcpcd[19502]: forked to background, child pid 19503

DHCP connection successful
not verifying
Connecting thread exiting.
Sending connection attempt result Success
Starting automatic reconnect process
Autoconnecting...
No wired connection present, attempting to autoconnect to wireless network
hidden
trying to automatically connect to...Univers2
Connecting to wireless network Univers2
dhcpcd[19541]: sending signal 1 to pid 19503
dhcpcd[19541]: waiting for pid 19503 to exit
dev: Host name lookup failure
dhcpcd[19556]: dhcpcd not running
dev: Host name lookup failure
Putting interface down
Releasing DHCP leases...
dhcpcd[19564]: dhcpcd not running
Setting false IP...
Stopping wpa_supplicant
Failed to connect to wpa_supplicant - wpa_ctrl_open: No such file or directory
Flushing the routing table...
dev: Host name lookup failure
Putting interface up...
dhcpcd[19572]: dhcpcd not running
dev: Host name lookup failure
Failed to connect to wpa_supplicant - wpa_ctrl_open: No such file or directory
dhcpcd[19578]: dhcpcd not running
dev: Host name lookup failure
Generating psk...
Attempting to authenticate...
Running DHCP with hostname MACHINE
dhcpcd[19614]: version 5.2.12 starting

dhcpcd[19614]: forked to background, child pid 19615

DHCP connection successful
not verifying
Connecting thread exiting.
Sending connection attempt result Success
Starting automatic reconnect process
Autoconnecting...
No wired connection present, attempting to autoconnect to wireless network
hidden
trying to automatically connect to...Univers2
Connecting to wireless network Univers2
dhcpcd[19641]: sending signal 1 to pid 19615
dhcpcd[19641]: waiting for pid 19615 to exit
dev: Host name lookup failure
dhcpcd[19656]: dhcpcd not running
dev: Host name lookup failure
Putting interface down
Releasing DHCP leases...
dhcpcd[19665]: dhcpcd not running
Setting false IP...
Stopping wpa_supplicant
Failed to connect to wpa_supplicant - wpa_ctrl_open: No such file or directory
Flushing the routing table...
dev: Host name lookup failure
Putting interface up...
dhcpcd[19671]: dhcpcd not running
dev: Host name lookup failure
Failed to connect to wpa_supplicant - wpa_ctrl_open: No such file or directory
dhcpcd[19677]: dhcpcd not running
dev: Host name lookup failure
Generating psk...
Attempting to authenticate...
[MANUALLY CTRL+Ced]

As you can see, the result is always "success", but the monitor invokes the reconnect/retry procedure before DHCPCD actually ends its task.

I have tracked down the problem and build a primary diagnostic. The workaround that I use (and it is an HORRIBLE ONE but due to my poor knowledge of python I have to live with it) is to add a "time.sleep(15)" call in the "update_connection_status" function of ConnectionStatus class (monitor.py) which prevents too rapid reconnect trials caused by the "self.auto_reconnect(from_wireless)" call at the end of the function and to comment out both "daemon.Disconnect()" and "daemon.SetForcedDisconnect(False)" calls of the "update_state" function to prevent immediate reconnect trials after first connection temptative.

It's obviously a problem of synchro because dhcpcd seems to take to long to fully acquire a DHCP address.

I am postively sure that my wpa_supplicant settings are correct, because if I use manually both command shown in the process list (ps ax) above, I get a stable wifi connection.

A few version information to help:

- wpa_supplicant: 0.7.3-r2
- dhcpcd: 5.2.12
- wicd: 1.7.1_beta2-r4

Thank you in advance!

Ivanux

[AopicieR (aopicier)]

I'm also testing the interplay of wicd 1.7.1~b3 and dhcpcd 5.2.12 right now (on Debian sid). I can reproduce your problems if either
- the global dhcpcd is running after for example "$ /etc/init.d/dhcpcd start" (which does not seem to be the case in your setup)
or
- I explicitly set "background" in my dhcpcd.conf (or dhcpcd somehow gets invoked with the "-b" option).
In both cases the problem is that when wicd invokes dhcpcd, the dhcpcd process immediately goes to the background while apparently wicd expects it to only go in the background after the lease has been successfully obtained.

Have you set "background" in your dhcpcd.conf? Maybe you could also try to explicitly set "waitip" in your dhcpcd.conf. If you run wicd in debug mode (which can be enabled through wicd-curses and the like) you will also see the command that wicd uses to invoke dhcpcd. Maybe through some black magic a "-b" has found its way into the options of dhcpcd?

[Wim Lewis (wiml)]

I am also having this problem. I am unable to use wicd because it almost always disconnects immediately after connecting. I'm using the ArchLinux package wicd 1.7.2.4-3, Linux version 3.5.3-1-ARCH (ArchLinux 2012.08.04), on an x86_64 MacBookPro. All the other packages are the defaults that ship with that version of Arch.

Here's what the system log file looks like during a connection attempt. Note that it authenticates, associates, and successfully gets an IPv4 address, and then is immediately disconnected "by local choice"(?).

There is an IPv6 router on this network so it's possible that this is more similar to bug 933378, but from the log it looks like the IPv4 address is acquired and the interface shut down before any IPv6 address is assigned, so I think this is not a case of bug 933378.

Aug 31 21:31:24 archecko kernel: [ 100.227645] wlan0: authenticate with 00:16:b6:da:e4:8c
Aug 31 21:31:24 archecko kernel: [ 100.227854] wlan0: send auth to 00:16:b6:da:e4:8c (try 1/3)
Aug 31 21:31:24 archecko kernel: [ 100.229565] wlan0: authenticated
Aug 31 21:31:24 archecko kernel: [ 100.230200] wlan0: associate with 00:16:b6:da:e4:8c (try 1/3)
Aug 31 21:31:24 archecko kernel: [ 100.233739] wlan0: RX AssocResp from 00:16:b6:da:e4:8c (capab=0x411 status=0 aid=3)
Aug 31 21:31:24 archecko kernel: [ 100.234334] wlan0: associated
Aug 31 21:31:24 archecko kernel: [ 100.235486] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Aug 31 21:31:24 archecko dhcpcd[434]: wlan0: carrier acquired
Aug 31 21:31:24 archecko dhcpcd[434]: wlan0: sending IPv6 Router Solicitation
Aug 31 21:31:24 archecko dhcpcd[434]: wlan0: sendmsg: Cannot assign requested address
Aug 31 21:31:24 archecko dhcpcd[434]: wlan0: broadcasting for a lease
Aug 31 21:31:24 archecko dhcpcd[434]: wlan0: offered 10.1.0.49 from 10.1.0.22
Aug 31 21:31:24 archecko dhcpcd[434]: wlan0: acknowledged 10.1.0.49 from 10.1.0.22
Aug 31 21:31:24 archecko dhcpcd[434]: wlan0: checking for 10.1.0.49
Aug 31 21:31:25 archecko dhcpcd[1610]: sending commands to master dhcpcd process
Aug 31 21:31:25 archecko dhcpcd[434]: control command: /usr/sbin/dhcpcd -h archecko.hhhh.org --noipv4ll wlan0
Aug 31 21:31:25 archecko dhcpcd[1614]: sending commands to master dhcpcd process
Aug 31 21:31:25 archecko dhcpcd[434]: control command: /usr/sbin/dhcpcd -k wlan0
Aug 31 21:31:25 archecko dhcpcd[434]: wlan0: removing interface
Aug 31 21:31:25 archecko kernel: [ 101.295875] wlan0: deauthenticating from 00:16:b6:da:e4:8c by local choice (reason=3)
Aug 31 21:31:25 archecko kernel: [ 101.300603] cfg80211: Calling CRDA to update world regulatory domain
Aug 31 21:31:25 archecko kernel: [ 101.530250] b43-phy0: Loading firmware version 666.2 (2011-02-23 01:15:07)
Aug 31 21:31:25 archecko kernel: [ 101.761985] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Aug 31 21:31:25 archecko dhcpcd[1630]: sending commands to master dhcpcd process
Aug 31 21:31:25 archecko dhcpcd[434]: wlan0: waiting for carrier
Aug 31 21:31:25 archecko dhcpcd[434]: control command: /usr/sbin/dhcpcd -k eth0
Aug 31 21:31:25 archecko dhcpcd[434]: eth0: removing interface
Aug 31 21:31:25 archecko kernel: [ 101.788802] forcedeth 0000:00:0a.0: irq 44 for...