Bug#746962: netcfg: wifi autoconfiguration after 3 second link detect timeout
Package: netcfg
In bug #739668 (wheezy install report, see section 13) I had problems
connecting from a laptop to a particular AP from a commercial wifi
provider using the Debian installer. At the same time a phone next to
the laptop had no such problems, and the same laptop running a
non-Linux OS had no problems. The failure to connect was repeatable
until at some point where it did connect, and it then worked from that
point on (it seems some details were cached on the AP and it began to
behave differently, rdnssd began to return the hostname that had been
used on the first working connection).
The log of the failed connection shows netcfg reporting:
Reached timeout for link detection on wlan0
Commencing network autoconfiguration on wlan0
It looks like netcfg ignores that link is not up yet and tries to
configure it anyway? Is this appropriate for wifi, should it not wait
for the association to complete before trying to configure the
interface?
Bug #610752 mentions the 3 second timeout was introduced based on "a
bit of testing" - was this testing done on Wifi connections, which may
perhaps have higher delays than wired ones?
With the closing of #414117, we've introduced a more robust method of
detecting which network interfaces we want to configure have link. This is
required because link autonegotiation (and other associated
shenanigans like
802.1X authentication) can take some time.
The problem is, the Ethernet spec is fairly quiet on the subject of
precisely how long we need to wait. Based on a bit of testing,
the value of
"3 seconds" for the wait time has been set as the default
Bug #537271 comment says:
btw, (unrelated to #537271), it seems to me that 3 seconds is a fairly
short value for NETCFG_LINK_WAIT_TIME. i'm pretty sure i've seen
link-up take longer than that on occasion before, depending on NIC
chipset, switch, autonegotiation latency, etc. 5 - 10 seconds would be
a more conservative default, given that there's no penalty if link-up
occurs before the timeout.
Logs follow.
The logs of the failed connection show:
Feb 20 06:21:32 netcfg[6576]: DEBUG: State is now 0
Feb 20 06:21:32 netcfg[6576]: DEBUG: Want link on wlan0
Feb 20 06:21:32 netcfg[6576]: INFO: Waiting time set to 3
Feb 20 06:21:32 netcfg[6576]: INFO: ethtool-lite: wlan0 is disconnected.
Feb 20 06:21:35 netcfg[6576]: INFO: Reached timeout for link detection on wlan0
Feb 20 06:21:35 netcfg[6576]: DEBUG: Commencing network
autoconfiguration on wlan0
Feb 20 06:21:35 netcfg[6576]: DEBUG: rdnssd started; PID: 7110
..
Feb 20 06:21:38 netcfg[6576]: DEBUG: ip line: 6: wlan0:
<NO-CARRIER,BROADCAST,MULTICAST,UP> mtu 1500 qdisc mq qlen 1000
Feb 20 06:21:38 netcfg[6576]: DEBUG: ip line: link/ether
20:c9:d0:82:f9:31 brd ff:ff:ff:ff:ff:ff
Feb 20 06:21:38 netcfg[6576]: INFO: No IPv6 support found... how does
that happen?
Feb 20 06:21:38 netcfg[6576]: DEBUG: Stopping rdnssd, PID 7110
Feb 20 06:21:38 netcfg[6576]: DEBUG: No RA received; attempting IPv4 autoconfig
Feb 20 06:21:38 netcfg[6576]: WARNING **: Started DHCP client; PID is 7136
Feb 20 06:21:57 main-menu[298]: (process:6575): udhcpc (v1.20.2) started
Feb 20 06:21:57 main-menu[298]: 6575): Sending discover...
Feb 20 06:22:03 netcfg[6576]: DEBUG: Reading nameservers from /etc/resolv.conf
Feb 20 06:22:03 netcfg[6576]: DEBUG: Read nameserver 192.168.0.1
Feb 20 06:22:03 netcfg[6576]: DEBUG: Read nameserver 192.168.1.1
[ 1012.239700] b43-phy0: Loading firmware version 666.2 (2011-02-23 01:15:07)
[ 1012.300546] ADDRCONF(NETDEV_UP): wlan0: link is not ready
[ 1043.990586] b43-phy0: Loading firmware version 666.2 (2011-02-23 01:15:07)
[ 1044.051438] ADDRCONF(NETDEV_UP): wlan0: link is not ready
[ 1224.676597] b43-phy0: Loading firmware version 666.2 (2011-02-23 01:15:07)
[ 1224.737438] ADDRCONF(NETDEV_UP): wlan0: link is not ready
The logs of a successful connection look like:
Feb 20 06:52:06 netcfg[6604]: INFO: Activating interface wlan0
Feb 20 06:52:06 kernel: [ 296.020570] b43-phy0: Loading firmware
version 666.2 (2011-02-23 01:15:07)
Feb 20 06:52:06 netcfg[6604]: DEBUG: State is now 0
Feb 20 06:52:06 netcfg[6604]: DEBUG: Want link on wlan0
Feb 20 06:52:06 netcfg[6604]: INFO: Waiting time set to 3
Feb 20 06:52:06 kernel: [ 296.081405] ADDRCONF(NETDEV_UP): wlan0:
link is not ready
Feb 20 06:52:07 kernel: [ 296.264447] wlan0: authenticate with
d4:ca:6d:25:d5:d7 (try 1)
Feb 20 06:52:07 kernel: [ 296.272201] wlan0: authenticated
Feb 20 06:52:07 kernel: [ 296.272406] wlan0: associate with
d4:ca:6d:25:d5:d7 (try 1)
Feb 20 06:52:07 kernel: [ 296.281454] wlan0: RX AssocResp from
d4:ca:6d:25:d5:d7 (capab=0x421 status=0 ai
d=2)
Feb 20 06:52:07 kernel: [ 296.281458] wlan0: associated
Feb 20 06:52:07 kernel: [ 296.282419] ADDRCONF(NETDEV_CHANGE): wlan0:
link becomes ready
Feb 20 06:52:07 netcfg[6604]: INFO: ethtool-lite: wlan0 is connected.
Feb 20 06:52:07 netcfg[6604]: INFO: Found link on wlan0
Feb 20 06:52:07 netcfg[6604]: DEBUG: Commencing network
autoconfiguration on wlan0
Reply to: