wpa_supplicant with madwifi-ng Scan timeout (30 seconds to associate)

Ricardo T. Muggli ricardo.muggli at mnsu.edu
Mon Feb 20 01:26:39 EST 2006


It takes 30 seconds to associate with the access point using 
wpa_supplicant with madwifi-ng. Most of this time appears to be waiting
for the scan to timeout. Scanning seems to be fast using normal
utilities such as iwlist. (I have including timing from iwlist below.
The wireless connection does work after waiting the 30 seconds for the
association.

Summary of versions:
  - Linux: 2.6.15.4
  - wpa_supplicant: latest CVS
  - madwifi-ng: svnversion 1452

Here is a snippet of the full wpa_supplicant output that shows the 30
second delay (I added the blank line to show where the delay is):
1140414357.823834: State: DISCONNECTED -> SCANNING
1140414357.823858: Starting AP scan (broadcast SSID)
1140414357.823908: Wireless event: cmd=0x8b1a len=8

1140414387.825829: Scan timeout - try to get results
1140414387.825963: Received 333 bytes of scan results (1 BSSes)
1140414387.825978: Scan results: 1


I have included in this e-mail the following information:
  - wpa_supplicant version
  - cat /etc/wpa_supplicant.conf
  - Access Point Information
  - madwifi-ng information from dmesg
  - /sbin/iwconfig ath0
  - time iwlist ath0 scan
  - /usr/local/sbin/wpa_supplicant -d -K -t -i ath0 -D madwifi -c /etc/wpa_supplicant.conf

Does anyone have any suggestions for me as to how to speed up the association?

Thanks for your help,
Ricardo Muggli

------------------------------------------------------------------------
wpa_supplicant version
------------------------------------------------------------------------
In version.h it says "0.5.1"
I downloaded this version from cvs at about Sun Feb 19 23:07:00 CST 2006.


------------------------------------------------------------------------
cat /etc/wpa_supplicant.conf
------------------------------------------------------------------------
network={
         ssid="YOURSSID"
         #psk="yourpassphrase"
         psk=edda86468aa67c3f71c0bbaf7828aedccd320f9011d63e699f5381a5b77e0c2a
}


------------------------------------------------------------------------
Access Point Information
------------------------------------------------------------------------
Linksys WRT54G v1.1
Firmware Version: v4.20.7, Aug. 18, 2005

Wireless Network Mode: Mixed
Wireless Network Name (SSID): YOURSSID
Wireless Channel: 6 - 2.437GHz
Wireless SSID Broadcast: Enabled
Security Mode: WPA2 Personal
WPA Algorithms: TKIP+AES
WPA Shared Key: yourpassphrase
Group Key Renewal: 3600 seconds


------------------------------------------------------------------------
madwifi-ng information from dmesg
------------------------------------------------------------------------
ath_hal: module license 'Proprietary' taints kernel.
ath_hal: 0.9.16.16 (AR5210, AR5211, AR5212, RF5111, RF5112, RF2413, RF5413)
wlan: 0.8.4.2 (svn 1452)
ath_rate_sample: 1.2 (svn 1452)
ath_pci: 0.9.4.5 (svn 1452)
wifi0: 11a rates: 6Mbps 9Mbps 12Mbps 18Mbps 24Mbps 36Mbps 48Mbps 54Mbps
wifi0: 11b rates: 1Mbps 2Mbps 5.5Mbps 11Mbps
wifi0: 11g rates: 1Mbps 2Mbps 5.5Mbps 11Mbps 6Mbps 9Mbps 12Mbps 18Mbps 24Mbps 36Mbps 48Mbps 54Mbps
wifi0: H/W encryption support: WEP AES AES_CCM TKIP
wifi0: mac 5.9 phy 4.3 radio 3.6
wifi0: Use hw queue 1 for WME_AC_BE traffic
wifi0: Use hw queue 0 for WME_AC_BK traffic
wifi0: Use hw queue 2 for WME_AC_VI traffic
wifi0: Use hw queue 3 for WME_AC_VO traffic
wifi0: Use hw queue 8 for CAB traffic
wifi0: Use hw queue 9 for beacons
wifi0: Atheros 5212: mem=0xc0210000, irq=11


------------------------------------------------------
/sbin/iwconfig ath0
------------------------------------------------------
ath0      IEEE 802.11g  ESSID:"YOURSSID"
           Mode:Managed  Frequency:2.437 GHz  Access Point: 00:0C:41:C2:5E:55
           Bit Rate:54 Mb/s   Tx-Power:13 dBm   Sensitivity=0/3
           Retry:off   RTS thr:off   Fragment thr:off
           Encryption key:1CDF-0B46-DED3-872E-D4C8-9FED-5950-1821   Security mode:restricted
           Power Management:off
           Link Quality=55/94  Signal level=-40 dBm  Noise level=-95 dBm
           Rx invalid nwid:1789  Rx invalid crypt:0  Rx invalid frag:0
           Tx excessive retries:0  Invalid misc:0   Missed beacon:0


------------------------------------------------------
time iwlist ath0 scan
------------------------------------------------------
ath0      Scan completed :
           Cell 01 - Address: 00:0C:41:C2:5E:55
                     ESSID:"YOURSSID"
                     Mode:Master
                     Frequency:2.437 GHz (Channel 6)
                     Quality=52/94  Signal level=-43 dBm  Noise level=-95 dBm
                     Encryption key:on
                     Bit Rates:1 Mb/s; 2 Mb/s; 5.5 Mb/s; 11 Mb/s; 18 Mb/s
                               24 Mb/s; 36 Mb/s; 54 Mb/s; 6 Mb/s; 9 Mb/s
                               12 Mb/s; 48 Mb/s
                     Extra:bcn_int=100
                     Extra:rsn_ie=30180100000fac020200000fac04000fac020100000fac020000
                     Extra:wpa_ie=dd1c0050f20101000050f20202000050f2040050f20201000050f2020000


real    0m0.254s
user    0m0.000s
sys     0m0.004s

------------------------------------------------------
/usr/local/sbin/wpa_supplicant -d -K -t -i ath0 -D madwifi -c /etc/wpa_supplicant.conf
------------------------------------------------------
1140414357.698610: Initializing interface 'ath0' conf '/etc/wpa_supplicant.conf' driver 'madwifi' ctrl_interface 'N/A'
1140414357.698705: Configuration file '/etc/wpa_supplicant.conf' -> '/etc/wpa_supplicant.conf'
1140414357.698722: Reading configuration file '/etc/wpa_supplicant.conf'
1140414357.698830: Priority group 0
1140414357.698848:    id=0 ssid='YOURSSID'
1140414357.698863: Initializing interface (2) 'ath0'
1140414357.709104: SIOCGIWRANGE: WE(compiled)=19 WE(source)=13 enc_capa=0x0
1140414357.709629:   capabilities: key_mgmt 0x0 enc 0x3
1140414357.719828: Own MAC address: 00:0e:9b:6e:4f:f4
1140414357.720288: wpa_driver_madwifi_del_key: keyidx=0
1140414357.720748: wpa_driver_madwifi_del_key: keyidx=1
1140414357.721175: wpa_driver_madwifi_del_key: keyidx=2
1140414357.721602: wpa_driver_madwifi_del_key: keyidx=3
1140414357.722029: wpa_driver_madwifi_set_countermeasures: enabled=0
1140414357.722464: wpa_driver_madwifi_set_drop_unencrypted: enabled=1
1140414357.722917: Setting scan request: 0 sec 100000 usec
1140414357.723350: Added interface ath0
1140414357.724157: Wireless event: cmd=0x8b06 len=8
1140414357.724612: Ignore event for foreign ifindex 3
1140414357.725090: RTM_NEWLINK, IFLA_IFNAME: Interface 'ath0' added
1140414357.725541: RTM_NEWLINK, IFLA_IFNAME: Interface 'ath0' added
1140414357.823834: State: DISCONNECTED -> SCANNING
1140414357.823858: Starting AP scan (broadcast SSID)
1140414357.823908: Wireless event: cmd=0x8b1a len=8

1140414387.825829: Scan timeout - try to get results
1140414387.825963: Received 333 bytes of scan results (1 BSSes)
1140414387.825978: Scan results: 1
1140414387.825992: Selecting BSS from priority group 0
1140414387.826003: 0: 00:0c:41:c2:5e:55 ssid='YOURSSID' wpa_ie_len=30 rsn_ie_len=26 caps=0x11
1140414387.826026:    selected based on RSN IE
1140414387.826047: Trying to associate with 00:0c:41:c2:5e:55 (SSID='YOURSSID' freq=2437 MHz)
1140414387.826061: Cancelling scan request
1140414387.826076: WPA: clearing own WPA/RSN IE
1140414387.826086: Automatic auth_alg selection: 0x1
1140414387.826111: RSN: using IEEE 802.11i/D9.0
1140414387.826121: WPA: Selected cipher suites: group 8 pairwise 24 key_mgmt 2
1140414387.826134: WPA: set AP WPA IE - hexdump(len=30): dd 1c 00 50 f2 01 01 00 00 50 f2 02 02 00 00 50 f2 04 00 50 f2 02 01 00 00 50 f2 02 00 00
1140414387.826173: WPA: set AP RSN IE - hexdump(len=26): 30 18 01 00 00 0f ac 02 02 00 00 0f ac 04 00 0f ac 02 01 00 00 0f ac 02 00 00
1140414387.826209: WPA: using GTK TKIP
1140414387.826257: WPA: using PTK CCMP
1140414387.826269: WPA: using KEY_MGMT WPA-PSK
1140414387.826280: WPA: Set own WPA IE default - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1140414387.826312: No keys have been configured - skip key clearing
1140414387.826323: wpa_driver_madwifi_set_drop_unencrypted: enabled=1
1140414387.826339: State: SCANNING -> ASSOCIATING
1140414387.826350: wpa_driver_madwifi_associate
ioctl[unknown???]: Invalid argument
1140414387.837582: Association request to the driver failed
1140414387.841054: Setting authentication timeout: 5 sec 0 usec
1140414387.841542: Wireless event: cmd=0x8b1a len=17
1140414387.842046: RX EAPOL from 00:0c:41:c2:5e:55
1140414387.842491: Setting authentication timeout: 10 sec 0 usec
1140414387.842932: IEEE 802.1X RX: version=2 type=3 length=117
1140414387.843369:   EAPOL-Key type=2
1140414387.843800: State: ASSOCIATING -> 4WAY_HANDSHAKE
1140414387.844231: WPA: RX message 1 of 4-Way Handshake from 00:0c:41:c2:5e:55 (ver=2)
1140414387.844680: RSN: msg 1/4 key data - hexdump(len=22): dd 14 00 0f ac 04 dd 69 cd 47 6c 6a b7 5f ac a1 df b6 ce 4c 6c 28
1140414387.845166: RSN: PMKID from Authenticator - hexdump(len=16): dd 69 cd 47 6c 6a b7 5f ac a1 df b6 ce 4c 6c 28
1140414387.845641: RSN: no matching PMKID found
1140414387.846150: WPA: WPA IE for msg 2/4 - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1140414387.850656: WPA: Renewed SNonce - hexdump(len=32): 03 89 97 c6 3b 67 46 a4 b2 65 c1 55 52 51 40 0b bf f9 62 4d 39 f0 b2 05 b0 32 7b 10 9a ca 87 38
1140414387.851290: WPA: PMK - hexdump(len=32): ed da 86 46 8a a6 7c 3f 71 c0 bb af 78 28 ae dc cd 32 0f 90 11 d6 3e 69 9f 53 81 a5 b7 7e 0c 2a
1140414387.851796: WPA: PTK - hexdump(len=64): 52 fe 6b 5a 4a d7 d2 ca 75 4a 20 ac 88 52 31 81 ce 46 b3 3b 07 40 5f 7b c3 1d ba 79 8b 5e 6b 2e 40 31 3b eb c1 55 4f 65 05 63 60 62 37 06 b4 21 84 52 53 dc ec 73 af fc 67 f6 27 43 b0 05 3a 32
1140414387.852453: WPA: Sending EAPOL-Key 2/4
1140414387.852975: Wireless event: cmd=0x8b15 len=20
1140414387.853409: Wireless event: new AP: 00:0c:41:c2:5e:55
1140414387.853860: State: 4WAY_HANDSHAKE -> ASSOCIATED
1140414387.854300: Associated to a new BSS: BSSID=00:0c:41:c2:5e:55
1140414387.854734: No keys have been configured - skip key clearing
1140414387.855173: Associated with 00:0c:41:c2:5e:55
1140414387.855596: WPA: Association event - clear replay counter
1140414387.856031: Setting authentication timeout: 10 sec 0 usec
1140414387.856520: RTM_NEWLINK, IFLA_IFNAME: Interface 'ath0' added
1140414387.857203: RX EAPOL from 00:0c:41:c2:5e:55
1140414387.858849: Setting authentication timeout: 10 sec 0 usec
1140414387.860489: IEEE 802.1X RX: version=2 type=3 length=175
1140414387.862482:   EAPOL-Key type=2
1140414387.863836: RSN: encrypted key data - hexdump(len=80): cc 2f 88 2a 3e cb 41 25 02 78 d7 4e 83 6d dd a3 ae fd a1 19 de 4f da 07 0a e4 f0 7d 49 25 01 ce c7 a9 b4 ac 0c e6 b6 b5 59 b8 22 ed d1 2d ec 1d 88 68 2a 83 90 03 54 6f fc 9d a6 e5 0b f7 fd 43 76 64 54 20 a3 b3 e1 4a 36 21 ec 6d ff fd 58 46
1140414387.865558: WPA: decrypted EAPOL-Key key data - hexdump(len=72): 30 18 01 00 00 0f ac 02 02 00 00 0f ac 04 00 0f ac 02 01 00 00 0f ac 02 00 00 dd 26 00 0f ac 01 01 00 28 c4 07 8c 90 cb b1 b6 68 12 fb 2c 65 08 8f d6 c8 83 34 1c f4 7d d9 0e 00 64 24 26 7e ba b8 83 dd 00 00 00 00 00
1140414387.867181: State: ASSOCIATED -> 4WAY_HANDSHAKE
1140414387.868792: WPA: RX message 3 of 4-Way Handshake from 00:0c:41:c2:5e:55 (ver=2)
1140414387.870375: WPA: IE KeyData - hexdump(len=72): 30 18 01 00 00 0f ac 02 02 00 00 0f ac 04 00 0f ac 02 01 00 00 0f ac 02 00 00 dd 26 00 0f ac 01 01 00 28 c4 07 8c 90 cb b1 b6 68 12 fb 2c 65 08 8f d6 c8 83 34 1c f4 7d d9 0e 00 64 24 26 7e ba b8 83 dd 00 00 00 00 00
1140414387.872056: WPA: Sending EAPOL-Key 4/4
1140414387.873714: WPA: Installing PTK to the driver.
1140414387.875318: wpa_driver_madwifi_set_key: alg=CCMP key_idx=0 set_tx=1 seq_len=6 key_len=16
1140414387.876990: State: 4WAY_HANDSHAKE -> GROUP_HANDSHAKE
1140414387.878744: RSN: received GTK in pairwise handshake - hexdump(len=34): 01 00 28 c4 07 8c 90 cb b1 b6 68 12 fb 2c 65 08 8f d6 c8 83 34 1c f4 7d d9 0e 00 64 24 26 7e ba b8 83
1140414387.880259: WPA: Group Key - hexdump(len=32): 28 c4 07 8c 90 cb b1 b6 68 12 fb 2c 65 08 8f d6 c8 83 34 1c f4 7d d9 0e 00 64 24 26 7e ba b8 83
1140414387.881920: WPA: Installing GTK to the driver (keyidx=1 tx=0).
1140414387.883552: WPA: RSC - hexdump(len=6): 59 0a 00 00 00 00
1140414387.885220: wpa_driver_madwifi_set_key: alg=TKIP key_idx=1 set_tx=0 seq_len=6 key_len=32
1140414387.886881: WPA: Key negotiation completed with 00:0c:41:c2:5e:55 [PTK=CCMP GTK=TKIP]
1140414387.894954: Cancelling authentication timeout
1140414387.895450: State: GROUP_HANDSHAKE -> COMPLETED
1140414387.895892: CTRL-EVENT-CONNECTED - Connection to 00:0c:41:c2:5e:55 completed (auth)



More information about the HostAP mailing list