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

login
register
mail settings
Submitter Timo Juhani Lindfors
Date June 28, 2012, 4:42 p.m.
Message ID <84fw9f5qxw.fsf@sauna.l.org>
Download mbox | patch
Permalink /patch/167925/
State Not Applicable
Headers show

Comments

Timo Juhani Lindfors - June 28, 2012, 4:42 p.m.
Hi,

I bisected this down to


commit 180cdf45a415969b851aab530e9b23606032941a
Author: Jouni Malinen <jouni@qca.qualcomm.com>
Date:   Tue Oct 18 23:04:36 2011 +0300

    wext: Increase scan timeout from 5 to 10 seconds
    
    Some dualband cards can use more than five seconds to run through
    a full scan, so increase the timeout to avoid hitting the missing
    scan completed event workaround.



Here's the log for completeness:



git bisect start
# good: [0b86f67a2970403d1b1b6d34ce49f5485ef5dbb3] Add wpa_gui-qt4 translation files into build
git bisect good 0b86f67a2970403d1b1b6d34ce49f5485ef5dbb3
# bad: [106233504ab2f55dd5f5b6454e2443aed7914383] Update version number for 1.0 release.
git bisect bad 106233504ab2f55dd5f5b6454e2443aed7914383
# good: [2a0cd0670b08ae84796352e17279b792e26fa8ba] OpenSSL: Add access to Android certificates
git bisect good 2a0cd0670b08ae84796352e17279b792e26fa8ba
# good: [a4cba8f1e208c95218f89daec01cbcb59d97dc6c] Use sched_scan in driver init
git bisect good a4cba8f1e208c95218f89daec01cbcb59d97dc6c
# bad: [1dc77cda118410904886776194f56f3623f830b4] Make crypto_hash_init() easier for static analyzers
git bisect bad 1dc77cda118410904886776194f56f3623f830b4
# bad: [3803bd331de647bb99a80db00cf19361b0b04be2] TLS: Validate RSA ClientKeyExchange length field
git bisect bad 3803bd331de647bb99a80db00cf19361b0b04be2
# good: [ea08bfe3847c7075c7fab802441a519dd02c7654] netlink: Do not use void pointer for pointer arithmetic
git bisect good ea08bfe3847c7075c7fab802441a519dd02c7654
# bad: [9fb0407055112d9f24cd451ce880326197988a61] nl80211: Use a wrapper for genlmsg_put
git bisect bad 9fb0407055112d9f24cd451ce880326197988a61
# bad: [9b90955ec706905d1c5b864885d252ebf7ddba4e] AP: Pass only bssid/addr/wds to EVENT_RX_FROM_UNKNOWN
git bisect bad 9b90955ec706905d1c5b864885d252ebf7ddba4e
# bad: [7a25f29d890f56c4df81143f8b5eb42fb5eeeb07] Interworking: Use unsigned integer for bitfield
git bisect bad 7a25f29d890f56c4df81143f8b5eb42fb5eeeb07
# good: [54e9c5fc6976c4cd1fd4cccf2b7dadaad2c4e437] EAP: Clear ClientTimeout back to default value in INITIALIZE
git bisect good 54e9c5fc6976c4cd1fd4cccf2b7dadaad2c4e437
# bad: [180cdf45a415969b851aab530e9b23606032941a] wext: Increase scan timeout from 5 to 10 seconds
git bisect bad 180cdf45a415969b851aab530e9b23606032941a
# good: [0597a5b59d731142d53bd854b18f802fb2e01046] Add log_level command
git bisect good 0597a5b59d731142d53bd854b18f802fb2e01046


Any idea what the _real_ issue here could be? Surely increasing timeout
should not cause regressions?
Timo Juhani Lindfors - June 28, 2012, 9:15 p.m.
Hi,

Timo Juhani Lindfors <timo.lindfors@iki.fi> writes:
>          * read results after a timeout. */
> -       timeout = 5;
> +       timeout = 10;
>         if (drv->scan_complete_events) {

I recompiled the debian package and reverted this change, now the
package works for me so I am confident that this change indeed has
something to do with the regression.
Jouni Malinen - June 28, 2012, 9:26 p.m.
On Fri, Jun 29, 2012 at 12:15:23AM +0300, Timo Juhani Lindfors wrote:
> >          * read results after a timeout. */
> > -       timeout = 5;
> > +       timeout = 10;
> >         if (drv->scan_complete_events) {
> 
> I recompiled the debian package and reverted this change, now the
> package works for me so I am confident that this change indeed has
> something to do with the regression.

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.. 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.
Timo Juhani Lindfors - June 28, 2012, 9:51 p.m.
Jouni Malinen <j@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
Jouni Malinen - June 30, 2012, 10:01 a.m.
On Fri, Jun 29, 2012 at 12:51:34AM +0300, Timo Juhani Lindfors wrote:
> Do the log files that I linked from the bug report help here at all? It
> does show "Scan timeout" in both cases:

Well, they just confirmed that the driver does not seem to indicate when
scan results are available. As such, the timeout within wpa_supplicant
is in full control of the interval between the scan request and
connection request going to the driver.

> 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

That's not enough for ap_scan 2 mode. You will need to specify the
security policy in full, i.e., set key_mgmt, pairwise, group, and proto
parameters to match with the network you are using. These seemed to be
key_mgmt=WPA-PSK, pairwise=CCMP, group=TKIP, proto=RSN based on the
debug logs with ap_scan 1. This does not match with the wpa_supplicant
defaults:

> 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

At least the GTK (group) parameter is different, so the driver may
refuse to connect because of this. Setting the group parameter to TKIP
should address that.
Timo Juhani Lindfors - June 30, 2012, 1:13 p.m.
Jouni Malinen <j@w1.fi> writes:
> Well, they just confirmed that the driver does not seem to indicate when
> scan results are available.

Ok. How should it indicate this? The source code at

http://gitorious.org/pkg-fso/linux-2-6-gta02/blobs/gta02/debian/patches/features/gta02/0032-Add-ar6000-wireless-driver.patch

shows ar6000_ioctl_siwscan() with

    ar->scan_complete = 0;
    wait_event_interruptible_timeout(ar6000_scan_queue, ar->scan_complete,
                                     5 * HZ);

and ar6000_scanComplete_event() with

    ar->scan_complete = 1;
    wake_up_interruptible(&ar6000_scan_queue);

Using

sudo killall dhclient
sudo killall wpa_supplicant
om wifi power 0
om wifi power 1
while ! ip link show wlan; do sleep 1; done
om wifi maxperf wlan 1
sudo rm -f /tmp/wpasupplicant.log
sudo wpa_supplicant -B -f /tmp/wpasupplicant.log -P /var/run/wpa_supplicant.wlan.pid -i wlan -D wext -t -ddd -C /var/run/wpa_supplicant
while [ ! -e /var/run/wpa_supplicant ]; do sleep 0.5; done
sudo wpa_cli -p /var/run/wpa_supplicant -i wlan add_network
sudo wpa_cli -p /var/run/wpa_supplicant -i wlan set_network 0 ssid "\"SoneraGateway00-26-44-A1-45-A9\""
sudo wpa_cli -p /var/run/wpa_supplicant -i wlan set_network 0 psk "\"Thaeret0\""
sudo wpa_cli -p /var/run/wpa_supplicant -i wlan enable_network 0
sudo dhclient -d wlan

and

sudo stap -e 'probe module("ar6000").function("ar6000_ioctl_siwscan"), module("ar6000").function("ar6000_scanComplete_event") { printf("%d %s\n", gettimeofday_us(), probefunc()); } probe module("ar6000").function("ar6000_ioctl_siwscan").return { printf("%d %s returned\n", gettimeofday_us(), probefunc()); }'

I see

1341061682435032 ar6000_ioctl_siwscan
1341061685389787 ar6000_scanComplete_event
1341061685389787 ar6000_ioctl_siwscan returned

The matching wpa_supplicant.log.gz is attached.
> That's not enough for ap_scan 2 mode. You will need to specify the
> security policy in full, i.e., set key_mgmt, pairwise, group, and proto
> parameters to match with the network you are using. These seemed to be
> key_mgmt=WPA-PSK, pairwise=CCMP, group=TKIP, proto=RSN based on the
> debug logs with ap_scan 1. This does not match with the wpa_supplicant
> defaults:

I can confirm that the following works:

sudo killall dhclient
sudo killall wpa_supplicant
om wifi power 0
om wifi power 1
while ! ip link show wlan; do sleep 1; done
om wifi maxperf wlan 1
sudo rm -f /tmp/wpasupplicant.log
sudo wpa_supplicant -B -f /tmp/wpasupplicant.log -P /var/run/wpa_supplicant.wlan.pid -i wlan -D wext -t -ddd -C /var/run/wpa_supplicant
while [ ! -e /var/run/wpa_supplicant ]; do sleep 0.5; done
sudo wpa_cli -p /var/run/wpa_supplicant -i wlan ap_scan 2
sudo wpa_cli -p /var/run/wpa_supplicant -i wlan add_network
sudo wpa_cli -p /var/run/wpa_supplicant -i wlan set_network 0 key_mgmt WPA-PSK
sudo wpa_cli -p /var/run/wpa_supplicant -i wlan set_network 0 pairwise CCMP
sudo wpa_cli -p /var/run/wpa_supplicant -i wlan set_network 0 group TKIP
sudo wpa_cli -p /var/run/wpa_supplicant -i wlan set_network 0 proto RSN
sudo wpa_cli -p /var/run/wpa_supplicant -i wlan set_network 0 ssid "\"SoneraGateway00-26-44-A1-45-A9\""
sudo wpa_cli -p /var/run/wpa_supplicant -i wlan set_network 0 psk "\"Thaeret0\""
sudo wpa_cli -p /var/run/wpa_supplicant -i wlan enable_network 0
sudo dhclient -d wlan

(However this is not very practical since I don't want to manually
specify such parameters for the networks that I visit...)
Timo Juhani Lindfors - June 30, 2012, 3:13 p.m.
[ Resending a copy without the attachment since
 http://lists.shmoo.com/pipermail/hostap/2012-June/026251.html does not
 seem to show the original message since it contains an attachment and I
 really want to make sure that the discussion is indexed by search
 engines so that others can benefit from our results. ]

Jouni Malinen <j@w1.fi> writes:
> Well, they just confirmed that the driver does not seem to indicate when
> scan results are available.

Ok. How should it indicate this? The source code at

http://gitorious.org/pkg-fso/linux-2-6-gta02/blobs/gta02/debian/patches/features/gta02/0032-Add-ar6000-wireless-driver.patch

shows ar6000_ioctl_siwscan() with

    ar->scan_complete = 0;
    wait_event_interruptible_timeout(ar6000_scan_queue, ar->scan_complete,
                                     5 * HZ);

and ar6000_scanComplete_event() with

    ar->scan_complete = 1;
    wake_up_interruptible(&ar6000_scan_queue);

Using

sudo killall dhclient
sudo killall wpa_supplicant
om wifi power 0
om wifi power 1
while ! ip link show wlan; do sleep 1; done
om wifi maxperf wlan 1
sudo rm -f /tmp/wpasupplicant.log
sudo wpa_supplicant -B -f /tmp/wpasupplicant.log -P /var/run/wpa_supplicant.wlan.pid -i wlan -D wext -t -ddd -C /var/run/wpa_supplicant
while [ ! -e /var/run/wpa_supplicant ]; do sleep 0.5; done
sudo wpa_cli -p /var/run/wpa_supplicant -i wlan add_network
sudo wpa_cli -p /var/run/wpa_supplicant -i wlan set_network 0 ssid "\"SoneraGateway00-26-44-A1-45-A9\""
sudo wpa_cli -p /var/run/wpa_supplicant -i wlan set_network 0 psk "\"Thaeret0\""
sudo wpa_cli -p /var/run/wpa_supplicant -i wlan enable_network 0
sudo dhclient -d wlan

and

sudo stap -e 'probe module("ar6000").function("ar6000_ioctl_siwscan"), module("ar6000").function("ar6000_scanComplete_event") { printf("%d %s\n", gettimeofday_us(), probefunc()); } probe module("ar6000").function("ar6000_ioctl_siwscan").return { printf("%d %s returned\n", gettimeofday_us(), probefunc()); }'

I see

1341061682435032 ar6000_ioctl_siwscan
1341061685389787 ar6000_scanComplete_event
1341061685389787 ar6000_ioctl_siwscan returned

The matching wpa_supplicant.log.gz is attached but here are the most
relevant lines:

...
1341061682.437789: CTRL_IFACE: ENABLE_NETWORK id=0
1341061682.438047: wlan: Setting scan request: 0 sec 0 usec
1341061682.438510: wlan: State: INACTIVE -> SCANNING
1341061682.438715: wlan: Starting AP scan for wildcard SSID
1341061685.391121: Scan requested (ret=0) - scan timeout 10 seconds
1341061695.399522: Scan timeout - try to get results
1341061695.399843: wlan: Event SCAN_RESULTS (3) received
1341061695.401823: Received 3223 bytes of scan results (13 BSSes)
1341061695.402211: Sorted scan results
1341061695.402347: 00:1e:69:36:5f:11 freq=2462 qual=19 noise=-95 level=-76 flags=0x0
1341061695.402506: 68:7f:74:1b:ce:f8 freq=2412 qual=17 noise=-95 level=-78 flags=0x0
1341061695.402599: 00:26:44:a1:45:a9 freq=2437 qual=15 noise=-95 level=-80 flags=0x0
...

> That's not enough for ap_scan 2 mode. You will need to specify the
> security policy in full, i.e., set key_mgmt, pairwise, group, and proto
> parameters to match with the network you are using. These seemed to be
> key_mgmt=WPA-PSK, pairwise=CCMP, group=TKIP, proto=RSN based on the
> debug logs with ap_scan 1. This does not match with the wpa_supplicant
> defaults:

I can confirm that the following works:

sudo killall dhclient
sudo killall wpa_supplicant
om wifi power 0
om wifi power 1
while ! ip link show wlan; do sleep 1; done
om wifi maxperf wlan 1
sudo rm -f /tmp/wpasupplicant.log
sudo wpa_supplicant -B -f /tmp/wpasupplicant.log -P /var/run/wpa_supplicant.wlan.pid -i wlan -D wext -t -ddd -C /var/run/wpa_supplicant
while [ ! -e /var/run/wpa_supplicant ]; do sleep 0.5; done
sudo wpa_cli -p /var/run/wpa_supplicant -i wlan ap_scan 2
sudo wpa_cli -p /var/run/wpa_supplicant -i wlan add_network
sudo wpa_cli -p /var/run/wpa_supplicant -i wlan set_network 0 key_mgmt WPA-PSK
sudo wpa_cli -p /var/run/wpa_supplicant -i wlan set_network 0 pairwise CCMP
sudo wpa_cli -p /var/run/wpa_supplicant -i wlan set_network 0 group TKIP
sudo wpa_cli -p /var/run/wpa_supplicant -i wlan set_network 0 proto RSN
sudo wpa_cli -p /var/run/wpa_supplicant -i wlan set_network 0 ssid "\"SoneraGateway00-26-44-A1-45-A9\""
sudo wpa_cli -p /var/run/wpa_supplicant -i wlan set_network 0 psk "\"Thaeret0\""
sudo wpa_cli -p /var/run/wpa_supplicant -i wlan enable_network 0
sudo dhclient -d wlan

(However this is not very practical since I don't want to manually
specify such parameters for the networks that I visit...)

Patch

diff --git a/src/drivers/driver_wext.c b/src/drivers/driver_wext.c
index 9fa356b..e44aeac 100644
--- a/src/drivers/driver_wext.c
+++ b/src/drivers/driver_wext.c
@@ -1007,7 +1007,7 @@  int wpa_driver_wext_scan(void *priv, struct wpa_driver_scan_params *params)
 
        /* Not all drivers generate "scan completed" wireless event, so try to
         * read results after a timeout. */
-       timeout = 5;
+       timeout = 10;
        if (drv->scan_complete_events) {
                /*
                 * The driver seems to deliver SIOCGIWSCAN events to notify