[pkg-wpa-devel] Bug#489948: wpasupplicant: Sets WEP key 30 seconds after starting

Vedran Furač vedranf at riteh.hr
Tue Jul 8 21:46:19 UTC 2008 

Package: wpasupplicant
Version: 0.6.3-2
Severity: normal

Configuration:

fast_reauth=1
ap_scan=2
network={
        ssid="..."
        mode=1
        frequency=2412
        key_mgmt=NONE
        wep_key0=...
        wep_tx_keyidx=0
        id_str="wlan-home"
        auth_alg=SHARED
}

Wpasupplicant sets WEP encryption key after 30 second delay. Ifup scripts
activate interface and run dhclient but it fails because key is not set yet.
Then I have to manualy run:

# ifconfig wlan1 down
# ifconfig wlan1 up
# dhclient3 wlan1

...to enable wireless. 

Here is the debug output of wpasupplicant (you can clearly see the 30s delay):

1215542262.671441: Initializing interface 'wlan1' conf '/etc/wpa_supplicant/wpa_supplicant.conf' driver 'wext' ctrl_interface 'N/A' bridge 'N/A'
1215542262.671574: Configuration file '/etc/wpa_supplicant/wpa_supplicant.conf' -> '/etc/wpa_supplicant/wpa_supplicant.conf'
1215542262.671595: Reading configuration file '/etc/wpa_supplicant/wpa_supplicant.conf'
1215542262.686937: ctrl_interface='DIR=/var/run/wpa_supplicant GROUP=netdev'
1215542262.686980: fast_reauth=1
1215542262.686994: ap_scan=2
1215542262.687114: Priority group 0
1215542262.687130:    id=0 ssid='...'
1215542262.687142: Initializing interface (2) 'wlan1'
1215542264.474207: Interface wlan1 set UP - waiting a second for the driver to complete initialization
1215542265.474400: SIOCGIWRANGE: WE(compiled)=22 WE(source)=21 enc_capa=0xf
1215542265.474446:   capabilities: key_mgmt 0xf enc 0xf
1215542265.509655: WEXT: Operstate: linkmode=1, operstate=5
1215542265.536380: Own MAC address: 00:1a:73:f8:a2:6e
1215542265.536395: wpa_driver_wext_set_wpa
1215542265.536405: wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
1215542265.536419: wpa_driver_wext_set_key: alg=0 key_idx=1 set_tx=0 seq_len=0 key_len=0
1215542265.536428: wpa_driver_wext_set_key: alg=0 key_idx=2 set_tx=0 seq_len=0 key_len=0
1215542265.536436: wpa_driver_wext_set_key: alg=0 key_idx=3 set_tx=0 seq_len=0 key_len=0
1215542265.536444: wpa_driver_wext_set_countermeasures
1215542265.536452: wpa_driver_wext_set_drop_unencrypted
1215542265.536458: RSN: flushing PMKID list in the driver
1215542265.536472: Setting scan request: 0 sec 100000 usec
1215542265.574288: EAPOL: SUPP_PAE entering state DISCONNECTED
1215542265.574328: EAPOL: KEY_RX entering state NO_KEY_RECEIVE
1215542265.574339: EAPOL: SUPP_BE entering state INITIALIZE
1215542265.574354: EAP: EAP entering state DISABLED
1215542265.575442: ctrl_interface_group=105 (from group name 'netdev')
1215542265.575569: Added interface wlan1
1215542265.575626: Ignore event for foreign ifindex 3
1215542265.575643: RTM_NEWLINK: operstate=0 ifi_flags=0x1043 ([UP][RUNNING])
1215542265.575657: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan1' added
1215542265.575682: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1215542265.575695: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan1' added
1215542265.575709: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1215542265.575721: Wireless event: cmd=0x8b06 len=12
1215542265.640378: State: DISCONNECTED -> SCANNING
1215542265.640413: Trying to associate with SSID '...'
1215542265.640428: Cancelling scan request
1215542265.640439: WPA: clearing own WPA/RSN IE
1215542265.640449: Automatic auth_alg selection: 0x1
1215542265.640458: Overriding auth_alg selection: 0x2
1215542265.640477: WPA: clearing AP WPA IE
1215542265.640488: WPA: clearing AP RSN IE
1215542265.640498: WPA: clearing own WPA/RSN IE
1215542265.640508: No keys have been configured - skip key clearing
1215542265.640519: wpa_driver_wext_set_key: alg=1 key_idx=0 set_tx=1 seq_len=0 key_len=5
1215542265.640560: wpa_driver_wext_set_drop_unencrypted
1215542265.640575: State: SCANNING -> ASSOCIATING
1215542265.640585: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
1215542265.640597: WEXT: Operstate: linkmode=-1, operstate=5
1215542265.640627: wpa_driver_wext_associate
1215542267.477979: WEXT: SIOCSIWAUTH(param 10 value 0x1) failed: Invalid argument)
1215542267.478156: Association request to the driver failed
1215542267.478176: Setting authentication timeout: 10 sec 0 usec
1215542267.478192: EAPOL: External notification - portControl=ForceAuthorized
1215542267.478226: EAPOL: disable timer tick
1215542267.478248: Ignore event for foreign ifindex 3
1215542267.478262: RTM_NEWLINK: operstate=0 ifi_flags=0x1002 ()
1215542267.478275: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan1' added
1215542267.478291: RTM_NEWLINK: operstate=0 ifi_flags=0x1002 ()
1215542267.478303: Wireless event: cmd=0x8b06 len=12
1215542267.478316: Ignore event for foreign ifindex 3
1215542267.478328: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1215542267.478341: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan1' added
1215542267.478397: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1215542267.478411: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan1' added
1215542267.478425: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1215542267.478437: Wireless event: cmd=0x8b04 len=16
1215542267.478449: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1215542267.478461: Wireless event: cmd=0x8b1a len=28
1215542268.240424: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1215542268.240472: Wireless event: cmd=0x8b19 len=16
1215542268.240520: Received 465 bytes of scan results (2 BSSes)
1215542268.240561: CTRL-EVENT-SCAN-RESULTS 
1215542268.252949: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1215542268.252972: Wireless event: cmd=0x8b15 len=24
1215542268.252983: Wireless event: new AP: c2:73:6b:e4:c9:8f
1215542268.253002: State: ASSOCIATING -> ASSOCIATED
1215542268.253015: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
1215542268.253028: WEXT: Operstate: linkmode=-1, operstate=5
1215542268.253059: Associated to a new BSS: BSSID=c2:73:6b:e4:c9:8f
1215542268.253074: Select network based on association information
1215542268.253090: Network configuration found for the current AP
1215542268.253102: WPA: clearing AP WPA IE
1215542268.253111: WPA: clearing AP RSN IE
1215542268.253121: WPA: clearing own WPA/RSN IE
1215542268.253133: EAPOL: External notification - portControl=ForceAuthorized
1215542268.253150: Associated with c2:73:6b:e4:c9:8f
1215542268.253161: WPA: Association event - clear replay counter
1215542268.253172: EAPOL: External notification - portEnabled=0
1215542268.253183: EAPOL: External notification - portValid=0
1215542268.253193: EAPOL: External notification - portEnabled=1
1215542268.253204: EAPOL: SUPP_PAE entering state S_FORCE_AUTH
1215542268.253214: EAPOL: SUPP_BE entering state IDLE
1215542268.253225: Cancelling authentication timeout
1215542268.253237: State: ASSOCIATED -> COMPLETED
1215542268.253253: CTRL-EVENT-CONNECTED - Connection to c2:73:6b:e4:c9:8f completed (auth) [id=0 id_str=wlan-home]
1215542268.253264: wpa_driver_wext_set_operstate: operstate 0->1 (UP)
1215542268.253275: WEXT: Operstate: linkmode=-1, operstate=6
1215542268.253668: Cancelling scan request
1215542268.253690: RTM_NEWLINK: operstate=1 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
1215542268.253705: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan1' added
1215542298.252521: RTM_NEWLINK: operstate=1 ifi_flags=0x1043 ([UP][RUNNING])
1215542298.252579: Wireless event: cmd=0x8b15 len=24
1215542298.252592: Wireless event: new AP: 00:00:00:00:00:00
1215542298.252614: Setting scan request: 0 sec 100000 usec
1215542298.252631: Added BSSID c2:73:6b:e4:c9:8f into blacklist
1215542298.252646: CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys
1215542298.252658: State: COMPLETED -> DISCONNECTED
1215542298.252670: wpa_driver_wext_set_operstate: operstate 1->0 (DORMANT)
1215542298.252682: WEXT: Operstate: linkmode=-1, operstate=5
1215542298.253063: EAPOL: External notification - portEnabled=0
1215542298.253080: EAPOL: SUPP_PAE entering state DISCONNECTED
1215542298.253089: EAPOL: SUPP_BE entering state INITIALIZE
1215542298.253102: EAPOL: External notification - portValid=0
1215542298.253116: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1215542298.253130: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan1' added
1215542298.265769: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1215542298.265798: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan1' added
1215542298.357369: State: DISCONNECTED -> SCANNING
1215542298.357394: Trying to associate with SSID '...'
1215542298.357408: Cancelling scan request
1215542298.357420: WPA: clearing own WPA/RSN IE
1215542298.357430: Automatic auth_alg selection: 0x1
1215542298.357439: Overriding auth_alg selection: 0x2
1215542298.357457: WPA: clearing AP WPA IE
1215542298.357468: WPA: clearing AP RSN IE
1215542298.357478: WPA: clearing own WPA/RSN IE
1215542298.357488: wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
1215542298.357557: wpa_driver_wext_set_key: alg=0 key_idx=1 set_tx=0 seq_len=0 key_len=0
1215542298.357576: wpa_driver_wext_set_key: alg=0 key_idx=2 set_tx=0 seq_len=0 key_len=0
1215542298.357593: wpa_driver_wext_set_key: alg=0 key_idx=3 set_tx=0 seq_len=0 key_len=0
1215542298.357609: wpa_driver_wext_set_key: alg=1 key_idx=0 set_tx=1 seq_len=0 key_len=5
1215542298.357644: wpa_driver_wext_set_drop_unencrypted
1215542298.357658: State: SCANNING -> ASSOCIATING
1215542298.357669: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
1215542298.357681: WEXT: Operstate: linkmode=-1, operstate=5
1215542298.357702: wpa_driver_wext_associate
1215542298.357764: WEXT: SIOCSIWAUTH(param 10 value 0x1) failed: Invalid argument)
1215542298.357960: Association request to the driver failed
1215542298.357979: Setting authentication timeout: 10 sec 0 usec
1215542298.357993: EAPOL: External notification - portControl=ForceAuthorized
1215542298.358025: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1215542298.358041: Wireless event: cmd=0x8b06 len=12
1215542298.358055: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1215542298.358067: Wireless event: cmd=0x8b04 len=16
1215542298.358080: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1215542298.358091: Wireless event: cmd=0x8b15 len=24
1215542298.358102: Wireless event: new AP: c2:73:6b:e4:c9:8f
1215542298.358114: State: ASSOCIATING -> ASSOCIATED
1215542298.358126: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
1215542298.358137: WEXT: Operstate: linkmode=-1, operstate=5
1215542298.358162: Associated to a new BSS: BSSID=c2:73:6b:e4:c9:8f
1215542298.358175: Select network based on association information
1215542298.358191: Network configuration found for the current AP
1215542298.358201: WPA: clearing AP WPA IE
1215542298.358211: WPA: clearing AP RSN IE
1215542298.358220: WPA: clearing own WPA/RSN IE
1215542298.358230: EAPOL: External notification - portControl=ForceAuthorized
1215542298.358246: Associated with c2:73:6b:e4:c9:8f
1215542298.358257: WPA: Association event - clear replay counter
1215542298.358267: EAPOL: External notification - portEnabled=0
1215542298.358278: EAPOL: External notification - portValid=0
1215542298.358289: EAPOL: External notification - portEnabled=1
1215542298.358299: EAPOL: SUPP_PAE entering state S_FORCE_AUTH
1215542298.358308: EAPOL: SUPP_BE entering state IDLE
1215542298.358320: Cancelling authentication timeout
1215542298.358331: Removed BSSID c2:73:6b:e4:c9:8f from blacklist
1215542298.358344: State: ASSOCIATED -> COMPLETED
1215542298.358360: CTRL-EVENT-CONNECTED - Connection to c2:73:6b:e4:c9:8f completed (reauth) [id=0 id_str=wlan-home]
1215542298.358371: wpa_driver_wext_set_operstate: operstate 0->1 (UP)
1215542298.358382: WEXT: Operstate: linkmode=-1, operstate=6
1215542298.358399: Cancelling scan request
1215542298.358414: RTM_NEWLINK: operstate=1 ifi_flags=0x1003 ([UP])
1215542298.358427: Wireless event: cmd=0x8b1a len=28
1215542345.580415: Ignore event for foreign ifindex 3
1215542345.668493: RTM_NEWLINK: operstate=1 ifi_flags=0x1002 ()
1215542345.668544: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan1' added
1215542349.590258: Ignore event for foreign ifindex 3
1215542349.640528: RTM_NEWLINK: operstate=1 ifi_flags=0x11003 ([UP][LOWER_UP])
1215542349.640557: WEXT: Operstate: linkmode=-1, operstate=6
1215542349.641507: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan1' added
1215542349.641543: RTM_NEWLINK: operstate=1 ifi_flags=0x11003 ([UP][LOWER_UP])
1215542349.641554: WEXT: Operstate: linkmode=-1, operstate=6
1215542349.641569: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan1' added
1215542349.641582: RTM_NEWLINK: operstate=1 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
1215542349.641592: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan1' added




-- System Information:
Debian Release: lenny/sid
  APT prefers unstable
  APT policy: (900, 'unstable'), (800, 'experimental'), (500, 'testing')
Architecture: i386 (i686)

Kernel: Linux 2.6.25 (PREEMPT)
Locale: LANG=hr_HR.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/bash

More information about the Pkg-wpa-devel mailing list