bug 456 [REGRESSION 0.7.3-6 => 1.0-2] WPA-PSK + openmoko: unable to get DHCPACK

Thu Jun 28 14:51:34 PDT 2012

Jouni Malinen <j at w1.fi> writes:
> This looks like some kind of issue with the driver taking way too long
> to scan or maybe more likely, inconvenient timing with operations and
> missing indicate of scan completions..

Do the log files that I linked from the bug report help here at all? It
does show "Scan timeout" in both cases:

http://w1.fi/bugz/show_bug.cgi?id=456

> I would assume that this driver should really be used with ap_scan=2
> mode (i.e., driver-based BSS selection) rather than ap_scan=1 to avoid
> this type of issues.

I tried

sudo wpa_cli -p /var/run/wpa_supplicant -i wlan ap_scan 2

but dhclient still can't get an IP:

1340920078.721452: wpa_supplicant v1.0
1340920078.722241: random: Trying to read entropy from /dev/random
1340920078.722524: Initializing interface 'wlan' conf 'N/A' driver 'wext' ctrl_interface '/var/run/wpa_supplicant' bridge 'N/A'
1340920078.723968: rfkill: Cannot open RFKILL control device
1340920078.724131: WEXT: RFKILL status not available
1340920078.735391: SIOCGIWRANGE: WE(compiled)=22 WE(source)=13 enc_capa=0x0
1340920078.735572:   capabilities: key_mgmt 0x0 enc 0x3 flags 0x0
1340920078.736655: WEXT: Failed to set bogus SSID to disconnect
1340920078.765387: netlink: Operstate: linkmode=1, operstate=5
1340920078.766675: wlan: Own MAC address: 00:12:cf:8f:19:1e
1340920078.766825: wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
1340920078.767480: Driver did not support SIOCSIWENCODEEXT, trying SIOCSIWENCODE
1340920078.767735: wpa_driver_wext_set_key: alg=0 key_idx=1 set_tx=0 seq_len=0 key_len=0
1340920078.768431: Driver did not support SIOCSIWENCODEEXT, trying SIOCSIWENCODE
1340920078.768651: wpa_driver_wext_set_key: alg=0 key_idx=2 set_tx=0 seq_len=0 key_len=0
1340920078.769339: Driver did not support SIOCSIWENCODEEXT, trying SIOCSIWENCODE
1340920078.769560: wpa_driver_wext_set_key: alg=0 key_idx=3 set_tx=0 seq_len=0 key_len=0
1340920078.770238: Driver did not support SIOCSIWENCODEEXT, trying SIOCSIWENCODE
1340920078.770485: wpa_driver_wext_set_countermeasures
1340920078.771038: wlan: RSN: flushing PMKID list in the driver
1340920078.771268: wlan: State: DISCONNECTED -> INACTIVE
1340920078.820351: EAPOL: SUPP_PAE entering state DISCONNECTED
1340920078.820592: EAPOL: Supplicant port status: Unauthorized
1340920078.820713: EAPOL: KEY_RX entering state NO_KEY_RECEIVE
1340920078.820737: EAPOL: SUPP_BE entering state INITIALIZE
1340920078.820818: EAP: EAP entering state DISABLED
1340920078.820950: EAPOL: Supplicant port status: Unauthorized
1340920078.820983: EAPOL: Supplicant port status: Unauthorized
1340920078.821808: wlan: Added interface wlan
1340920078.821958: Daemonize..
1340920078.827995: random: Got 20/20 bytes from /dev/random
1340920078.828811: RTM_NEWLINK: operstate=0 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
1340920078.829132: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan' added
1340920078.829550: WEXT: if_removed already cleared - ignore event
1340920078.829729: RTM_NEWLINK: operstate=0 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
1340920078.829874: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan' added
1340920078.830036: WEXT: if_removed already cleared - ignore event
1340920078.830218: Wireless event: cmd=0x8b06 len=8
1340920078.830404: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1340920078.830539: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan' added
1340920078.830705: WEXT: if_removed already cleared - ignore event
1340920078.830869: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1340920078.831005: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan' added
1340920078.831165: WEXT: if_removed already cleared - ignore event
1340920078.831284: Wireless event: cmd=0x8b2a len=8
1340920078.831353: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1340920078.831485: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan' added
1340920078.831645: WEXT: if_removed already cleared - ignore event
1340920078.831765: Wireless event: cmd=0x8b2a len=8
1340920078.831838: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1340920078.831972: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan' added
1340920078.832137: WEXT: if_removed already cleared - ignore event
1340920078.832259: Wireless event: cmd=0x8b2a len=8
1340920078.832331: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1340920078.832466: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan' added
1340920078.832636: WEXT: if_removed already cleared - ignore event
1340920078.832757: Wireless event: cmd=0x8b2a len=8
1340920079.834957: EAPOL: disable timer tick
1340920079.835195: EAPOL: Supplicant port status: Unauthorized
1340920082.987014: RX ctrl_iface - hexdump_ascii(len=9):
     41 50 5f 53 43 41 4e 20 32                        AP_SCAN 2       
1340920083.120842: RX ctrl_iface - hexdump_ascii(len=11):
     41 44 44 5f 4e 45 54 57 4f 52 4b                  ADD_NETWORK     
1340920083.121178: CTRL_IFACE: ADD_NETWORK
1340920087.276792: RX ctrl_iface - hexdump_ascii(len=51): [REMOVED]
1340920087.277012: CTRL_IFACE: SET_NETWORK id=0 name='ssid'
1340920087.277138: CTRL_IFACE: value - hexdump_ascii(len=32): [REMOVED]
1340920087.277390: ssid - hexdump_ascii(len=30):
     53 6f 6e 65 72 61 47 61 74 65 77 61 79 30 30 2d   SoneraGateway00-
     32 36 2d 34 34 2d 41 31 2d 34 35 2d 41 39         26-44-A1-45-A9  
1340920091.436249: RX ctrl_iface - hexdump_ascii(len=30): [REMOVED]
1340920091.436472: CTRL_IFACE: SET_NETWORK id=0 name='psk'
1340920091.436596: CTRL_IFACE: value - hexdump_ascii(len=12): [REMOVED]
1340920091.436635: PSK (ASCII passphrase) - hexdump_ascii(len=10): [REMOVED]
1340920091.777050: PSK (from passphrase) - hexdump(len=32): [REMOVED]
1340920095.935542: RX ctrl_iface - hexdump_ascii(len=16):
     45 4e 41 42 4c 45 5f 4e 45 54 57 4f 52 4b 20 30   ENABLE_NETWORK 0
1340920095.935834: CTRL_IFACE: ENABLE_NETWORK id=0
1340920095.936098: wlan: Setting scan request: 0 sec 0 usec
1340920095.936569: wlan: State: INACTIVE -> SCANNING
1340920095.936821: wlan: Trying to associate with SSID 'SoneraGateway00-26-44-A1-45-A9'
1340920095.937002: wlan: Cancelling scan request
1340920095.937217: wlan: WPA: clearing own WPA/RSN IE
1340920095.937390: wlan: Automatic auth_alg selection: 0x1
1340920095.937554: wlan: WPA: No WPA/RSN IE available from association info
1340920095.937723: wlan: WPA: Set cipher suites based on configuration
1340920095.937899: wlan: WPA: Selected cipher suites: group 30 pairwise 24 key_mgmt 3 proto 2
1340920095.938061: wlan: WPA: clearing AP WPA IE
1340920095.938224: wlan: WPA: clearing AP RSN IE
1340920095.938381: wlan: WPA: using GTK CCMP
1340920095.938525: wlan: WPA: using PTK CCMP
1340920095.938669: wlan: WPA: using KEY_MGMT 802.1X
1340920095.938843: WPA: Set own WPA IE default - hexdump(len=22): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 01 00 00
1340920095.939203: wlan: No keys have been configured - skip key clearing
1340920095.939366: wlan: State: SCANNING -> ASSOCIATING
1340920095.939476: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
1340920095.939516: netlink: Operstate: linkmode=-1, operstate=5
1340920095.939826: wpa_driver_wext_associate
1340920095.939966: wpa_driver_wext_set_drop_unencrypted
1340920095.940173: wpa_driver_wext_set_psk
1340920095.940844: wlan: Setting authentication timeout: 60 sec 0 usec
1340920095.941021: EAPOL: External notification - EAP success=0
1340920095.941211: EAPOL: Supplicant port status: Unauthorized
1340920095.941285: EAPOL: External notification - EAP fail=0
1340920095.941339: EAPOL: Supplicant port status: Unauthorized
1340920095.941384: EAPOL: External notification - portControl=Auto
1340920095.941436: EAPOL: Supplicant port status: Unauthorized
1340920095.941863: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1340920095.942042: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan' added
1340920095.942280: WEXT: if_removed already cleared - ignore event
1340920095.942417: Wireless event: cmd=0x8b06 len=8
1340920095.942497: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1340920095.942627: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan' added
1340920095.942796: WEXT: if_removed already cleared - ignore event
1340920095.942916: Wireless event: cmd=0x8b1a len=38
1340920155.981364: wlan: Authentication with 00:00:00:00:00:00 timed out.
1340920155.981532: Added BSSID 00:00:00:00:00:00 into blacklist
1340920155.981675: wlan: No keys have been configured - skip key clearing
1340920155.981820: wlan: State: ASSOCIATING -> DISCONNECTED
1340920155.981909: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
1340920155.981954: netlink: Operstate: linkmode=-1, operstate=5
1340920155.982180: EAPOL: External notification - portEnabled=0
1340920155.982303: EAPOL: Supplicant port status: Unauthorized
1340920155.982342: EAPOL: External notification - portValid=0
1340920155.982395: EAPOL: Supplicant port status: Unauthorized
1340920155.982576: wlan: Setting scan request: 1 sec 0 usec
1340920156.991578: wlan: State: DISCONNECTED -> SCANNING
1340920156.991808: wlan: Trying to associate with SSID 'SoneraGateway00-26-44-A1-45-A9'
1340920156.991975: wlan: Cancelling scan request
1340920156.992150: wlan: WPA: clearing own WPA/RSN IE
1340920156.992319: wlan: Automatic auth_alg selection: 0x1
1340920156.992482: wlan: WPA: No WPA/RSN IE available from association info
1340920156.992647: wlan: WPA: Set cipher suites based on configuration
1340920156.992821: wlan: WPA: Selected cipher suites: group 30 pairwise 24 key_mgmt 3 proto 2
1340920156.992981: wlan: WPA: clearing AP WPA IE
1340920156.993142: wlan: WPA: clearing AP RSN IE
1340920156.993300: wlan: WPA: using GTK CCMP
1340920156.993442: wlan: WPA: using PTK CCMP
1340920156.993589: wlan: WPA: using KEY_MGMT 802.1X
1340920156.993708: WPA: Set own WPA IE default - hexdump(len=22): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 01 00 00
1340920156.993869: wlan: No keys have been configured - skip key clearing
1340920156.994025: wlan: State: SCANNING -> ASSOCIATING
1340920156.994135: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
1340920156.994173: netlink: Operstate: linkmode=-1, operstate=5
1340920156.994338: wpa_driver_wext_associate
1340920156.994456: wpa_driver_wext_set_drop_unencrypted
1340920156.994658: wpa_driver_wext_set_psk
1340920156.995333: wlan: Setting authentication timeout: 60 sec 0 usec
1340920156.995513: EAPOL: External notification - EAP success=0
1340920156.995610: EAPOL: Supplicant port status: Unauthorized
1340920156.995681: EAPOL: External notification - EAP fail=0
1340920156.995746: EAPOL: Supplicant port status: Unauthorized
1340920156.995773: EAPOL: External notification - portControl=Auto
1340920156.995842: EAPOL: Supplicant port status: Unauthorized
1340920156.996228: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1340920156.996387: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan' added
1340920156.996645: WEXT: if_removed already cleared - ignore event
1340920156.996790: Wireless event: cmd=0x8b06 len=8
1340920156.996871: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1340920156.997001: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan' added
1340920156.997162: WEXT: if_removed already cleared - ignore event
1340920156.997282: Wireless event: cmd=0x8b1a len=38
1340920217.038438: wlan: Authentication with 00:00:00:00:00:00 timed out.
1340920217.038644: BSSID 00:00:00:00:00:00 blacklist count incremented to 2
1340920217.038812: wlan: No keys have been configured - skip key clearing
1340920217.038977: wlan: State: ASSOCIATING -> DISCONNECTED
1340920217.039084: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
1340920217.039120: netlink: Operstate: linkmode=-1, operstate=5
1340920217.039290: EAPOL: External notification - portEnabled=0
1340920217.039414: EAPOL: Supplicant port status: Unauthorized
1340920217.039461: EAPOL: External notification - portValid=0
1340920217.039535: EAPOL: Supplicant port status: Unauthorized
1340920217.039637: wlan: Setting scan request: 1 sec 0 usec
1340920218.048368: wlan: State: DISCONNECTED -> SCANNING
1340920218.048594: wlan: Trying to associate with SSID 'SoneraGateway00-26-44-A1-45-A9'
1340920218.048763: wlan: Cancelling scan request
1340920218.048940: wlan: WPA: clearing own WPA/RSN IE
1340920218.049111: wlan: Automatic auth_alg selection: 0x1
1340920218.049277: wlan: WPA: No WPA/RSN IE available from association info
1340920218.049442: wlan: WPA: Set cipher suites based on configuration
1340920218.049616: wlan: WPA: Selected cipher suites: group 30 pairwise 24 key_mgmt 3 proto 2
1340920218.049778: wlan: WPA: clearing AP WPA IE
1340920218.049942: wlan: WPA: clearing AP RSN IE
1340920218.050103: wlan: WPA: using GTK CCMP
1340920218.050255: wlan: WPA: using PTK CCMP
1340920218.050405: wlan: WPA: using KEY_MGMT 802.1X
1340920218.050530: WPA: Set own WPA IE default - hexdump(len=22): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 01 00 00
1340920218.050703: wlan: No keys have been configured - skip key clearing
1340920218.050934: wlan: State: SCANNING -> ASSOCIATING
1340920218.051055: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
1340920218.051094: netlink: Operstate: linkmode=-1, operstate=5
1340920218.051270: wpa_driver_wext_associate
1340920218.051395: wpa_driver_wext_set_drop_unencrypted
1340920218.051627: wpa_driver_wext_set_psk
1340920218.052316: wlan: Setting authentication timeout: 60 sec 0 usec
1340920218.052484: EAPOL: External notification - EAP success=0
1340920218.052590: EAPOL: Supplicant port status: Unauthorized
1340920218.052674: EAPOL: External notification - EAP fail=0
1340920218.052744: EAPOL: Supplicant port status: Unauthorized
1340920218.052791: EAPOL: External notification - portControl=Auto
1340920218.052848: EAPOL: Supplicant port status: Unauthorized
1340920218.053224: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1340920218.053389: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan' added
1340920218.053645: WEXT: if_removed already cleared - ignore event
1340920218.053798: Wireless event: cmd=0x8b06 len=8
1340920218.053877: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1340920218.054010: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan' added
1340920218.054187: WEXT: if_removed already cleared - ignore event
1340920218.054309: Wireless event: cmd=0x8b1a len=38