Fails to connect in first attempt

[Hernan]

wicd 1.7.0 dhclient3 V3.1.3
Debian testing. driver ath5k
Kernel 2.6.33
Hardware Acer aspire 4697 (AMD 64bits)

For one particular open AP provided by Linksys hardware, wicd fails to make the connection in the first attempt and goes
into waiting mode. When the operation is repeated it connects inmediately. If discinnected and reconnected it connects effortless.
If the connection is first attempted by hand with
ifconfig wlan0 up
iwconfig wlan0 essid X
dhclient3 wlan0
it connects in the first request. wicd-client then recognizes the connection but if disconnected we fall in the previous case.
There is no info in wicd debugging files. Info regarding the network, and dmesg out attached.
The same operation used to trigger a bug in ath5k (kernel 2.6.32-rc8) but no longer does

[Hernan (hgsolari)]

The same happens using dhcpcd..... here is
/var/log/wicd/wicd.log
2010/03/08 09:04:38 :: Shutting down...
2010/03/08 13:01:07 :: ---------------------------
2010/03/08 13:01:07 :: wicd initializing...
2010/03/08 13:01:07 :: ---------------------------
2010/03/08 13:01:07 :: wicd is version 1.7.0 552
2010/03/08 13:01:07 :: setting backend to external
2010/03/08 13:01:07 :: trying to load backend external
2010/03/08 13:01:07 :: successfully loaded backend external
2010/03/08 13:01:07 :: trying to load backend external
2010/03/08 13:01:07 :: successfully loaded backend external
2010/03/08 13:01:07 :: Couldn't detect a wireless interface.
2010/03/08 13:01:07 :: setting wireless interface wlan0
2010/03/08 13:01:07 :: automatically detected wired interface eth0
2010/03/08 13:01:07 :: setting wired interface eth0
2010/03/08 13:01:07 :: setting wpa driver wext
2010/03/08 13:01:07 :: setting use global dns to True
2010/03/08 13:01:07 :: setting global dns
2010/03/08 13:01:07 :: global dns servers are 208.67.220.220 208.67.220.222 None
2010/03/08 13:01:07 :: domain is None
2010/03/08 13:01:07 :: search domain is None
2010/03/08 13:01:07 :: setting automatically reconnect when connection drops True
2010/03/08 13:01:08 :: Setting dhcp client to 0
2010/03/08 13:01:08 :: Wireless configuration file found...
2010/03/08 13:01:08 :: Wired configuration file found...
2010/03/08 13:01:08 :: chmoding configuration files 0600...
2010/03/08 13:01:08 :: chowning configuration files root:root...
2010/03/08 13:01:08 :: Using wireless interface...wlan0
2010/03/08 13:01:08 :: Using wired interface...eth0
2010/03/08 13:01:14 :: Autoconnecting...
2010/03/08 13:01:14 :: No wired connection present, attempting to autoconnect to wireless network
2010/03/08 13:01:15 :: Unable to autoconnect, you'll have to manually connect
2010/03/08 13:01:19 :: Autoconnecting...
2010/03/08 13:01:19 :: No wired connection present, attempting to autoconnect to wireless network
2010/03/08 13:01:20 :: Unable to autoconnect, you'll have to manually connect
2010/03/08 13:01:24 :: Autoconnecting...
2010/03/08 13:01:24 :: No wired connection present, attempting to autoconnect to wireless network
2010/03/08 13:01:25 :: Unable to autoconnect, you'll have to manually connect
2010/03/08 13:01:29 :: Autoconnecting...
2010/03/08 13:01:29 :: No wired connection present, attempting to autoconnect to wireless network
2010/03/08 13:01:30 :: Unable to autoconnect, you'll have to manually connect
2010/03/08 13:01:55 :: Connecting to wireless network df
2010/03/08 13:01:55 :: Putting interface down
2010/03/08 13:01:55 :: Releasing DHCP leases...
2010/03/08 13:01:55 :: Setting false IP...
2010/03/08 13:01:55 :: Stopping wpa_supplicant
2010/03/08 13:01:55 :: Flushing the routing table...
2010/03/08 13:01:55 :: Putting interface up...
2010/03/08 13:01:57 :: Running DHCP with hostname dinnu
2010/03/08 13:02:17 :: err, wlan0: timed out
2010/03/08 13:02:17 ::
2010/03/08 13:02:17 :: DHCP connection failed
2010/03/08 13:02:17 :: exiting connection thread
2010/03/08 13:02:17 :: Sending connection attempt result dhcp_failed

and second attemp
2010/03/08 13:03:55 :: Connecting to wireless network df
2010/03/08 13:03:55 :...

[Lithopsian (x-uzuntu-c)]

I came up against this problem in 1.7.2.4. Symptoms are that wicd does not connect to a plugged in wired interface at startup. Hacking around, I see that it makes no attempt to do so. First the daemon scans for wireless networks, then it sleeps until an auto-connect, then it looks for a wired connection, thinks none are plugged in (wrong!), sleeps again, then finds there is a wired connection after all.

A complete bodge fix is to force a wired_autoconnect() at startup and it instantly connects. I'm sure a real fix should be more careful ...

[Lithopsian (x-uzuntu-c)]

Is it intended that a wired connection has already been brought up before wicd starts? wicd accepts a pre-existing live connection, but it isn't really a viable configuration because the basic networking scripts are not good at deciding whether a wired connection is present or not, they just blindly blunder in and can get hung up for ages.

I tracked down why the first wired check fails: although the driver is up (flags set), the carrier file has not yet been created and so it is assumed that there is no wire plugged in. It takes a fraction of a second (about 0.1s on my machine) for the carrier file to be created, so the plugged check succeeds on the next connection attempt.

[Lithopsian (x-uzuntu-c)]

Here's the full sequence at the first connection attempt:
1. flags file is present and indicates down, carrier file is not present
2. Run ifconfig %iface% up
3. Immediately, flags file indicates up, carrier file is present and indicates no carrier
4. About 2 seconds later, the carrier file changes to indicate a carrier (ie. plugged in)

In the current code, there is a 2 second sleep after ifconfig up, looping for more sleeps if the flags file still doesn't indicate up. As soon as the flags file indicates up, then it attempts to read the carrier file, which is present but may not yet indicate a carrier is present.

On my machine, it never loops, just one 2 second sleep, and I think this is standard behaviour with current drivers. The carrier file is not changed until slightly over 2 seconds, so I get no connection at the first attempt. Probably for some people, maybe most people, it is just less than 2 seconds and everything seems fine. So the loop on the flags file may not be necessary, but a short loop waiting on the carrier file would be helpful. Obviously not too long since there might not be a carrier even if a wired ethernet connection is configured.

[Tito (tito-webtito)]

I had the same issue : wicd always abandons the first attempt. This can be seen in dmesg with logs similar to what I copy below. Please note the ~16 seconds pause between tries that corresponds to wicd waiting before an autoreconnect task.

I tracked the issue to wicd trying to set the channel and getting an error from iwconfig :

iwconfig wlan1 channel 11
Error for wireless request "Set Frequency" (8B04) :
    SET failed on device wlan1 ; Device or resource busy.

Following that error, it seems wicd abandons and it triggers the DEAUTH_LEAVING. This error is most likely due to iwconfig command orders : after setting the essid you can't set the channel.

I currently have a workaround for this issue, as I commented two calls to iwconfig channel in wnettools.py. I am thus relying on auto channel selection. The real solution is probably to reorder the loop so that the channel is set before the ESSID and AP.

I will look into that and maybe propose a patch.

dmesg log :

[ 34.617763] IPv6: ADDRCONF(NETDEV_UP): wlan1: link is not ready
[ 34.838828] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
[ 34.939282] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
[ 34.939578] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[ 35.977949] IPv6: ADDRCONF(NETDEV_UP): wlan1: link is not ready
[ 38.076103] wlan1: authenticate with AA:AA:AA:AA:AA:AA
[ 39.762668] wlan1: send auth to AA:AA:AA:AA:AA:AA (try 1/3)
[ 39.768432] wlan1: authenticated
[ 39.777150] wlan1: associate with AA:AA:AA:AA:AA:AA (try 1/3)
[ 39.778346] wlan1: aborting association with AA:AA:AA:AA:AA:AA by local choice (Reason: 3=DEAUTH_LEAVING)
[ 40.118720] wlan1: authenticate with BB:BB:BB:BB:BB:BB
[ 40.799658] wlan1: send auth to BB:BB:BB:BB:BB:BB (try 1/3)
[ 40.802322] wlan1: authenticated
[ 40.807102] wlan1: associate with BB:BB:BB:BB:BB:BB (try 1/3)
[ 40.811588] wlan1: RX AssocResp from BB:BB:BB:BB:BB:BB (capab=0x421 status=0 aid=1)
[ 40.837626] wlan1: associated
[ 40.837741] wlan1: deauthenticating from BB:BB:BB:BB:BB:BB by local choice (Reason: 3=DEAUTH_LEAVING)

[ 56.580747] IPv6: ADDRCONF(NETDEV_UP): wlan1: link is not ready
[ 56.760483] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
[ 56.869408] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
[ 56.869673] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[ 57.908720] IPv6: ADDRCONF(NETDEV_UP): wlan1: link is not ready
[ 58.972952] IPv6: ADDRCONF(NETDEV_UP): wlan1: link is not ready
[ 59.215578] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
[ 59.330667] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
[ 59.331116] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[ 60.007090] wlan1: authenticate with BB:BB:BB:BB:BB:BB
[ 60.671651] wlan1: send auth to BB:BB:BB:BB:BB:BB (try 1/3)
[ 60.674288] wlan1: authenticated
[ 60.677140] wlan1: associate with BB:BB:BB:BB:BB:BB (try 1/3)
[ 60.682451] wlan1: RX AssocResp from BB:BB:BB:BB:BB:BB (capab=0x421 status=0 aid=1)
[ 60.706604] wlan1: associated
[ 60.708122] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready

[Tito (tito-webtito)]

Here is a proposed patch. It simply sets channel and BSSID before setting ESSID in the Associate method.

On a sidenote, I think that method could use a bit of rewrite. It should use the existing SetChannel method, and we should create and use a SetBSSID method.

[Tito (tito-webtito)]

Sorry for the spam, third response in a row.

My patch seems to break networks with authentification... Running wpa_supplicant before iwconfig channel has the same effect as discussed before. In wicd/networking.py the authentification is indeed done before the association (only for non-Ralink drivers, I don't understand why that is).