Still some nl80211 connection problem

Tue Sep 15 04:45:01 PDT 2009

1253010370.195968: Trying to authenticate with 00:13:19:80:da:30 (SSID='TEST' freq=2437 MHz)
1253010370.200780: Trying to associate with 00:13:19:80:da:30 (SSID='TEST' freq=2437 MHz)
1253010370.203212: Associated with 00:13:19:80:da:30
1253010370.205572: ROAM: roam_rssi -65, RSSI -1
1253010372.206809: ROAM: roam_rssi -65, RSSI -41
1253010374.208011: ROAM: roam_rssi -65, RSSI -37
1253010376.210145: ROAM: roam_rssi -65, RSSI -45
1253010378.212339: ROAM: roam_rssi -65, RSSI -49
1253010380.214487: ROAM: roam_rssi -65, RSSI -51
1253010382.216618: ROAM: roam_rssi -65, RSSI -56
1253010384.218750: ROAM: roam_rssi -65, RSSI -51
1253010386.220880: ROAM: roam_rssi -65, RSSI -65
1253010388.223008: ROAM: roam_rssi -65, RSSI -62
1253010390.225137: ROAM: roam_rssi -65, RSSI -63
1253010392.227267: ROAM: roam_rssi -65, RSSI -62
1253010394.229397: ROAM: roam_rssi -65, RSSI -65
1253010396.231525: ROAM: roam_rssi -65, RSSI -76
1253010397.319566: Trying to authenticate with 00:1b:53:11:dc:40 (SSID='TEST' freq=2412 MHz)
1253010397.429380: Trying to associate with 00:1b:53:11:dc:40 (SSID='TEST' freq=2412 MHz)
1253010397.430049: Association request to the driver failed

However, with WEXT i can move my laptop freely between the two APs
with no problems whatsoever, wpa_supplicant can always connect.

Also note that this hasn't anything to do with my roaming code.
When I use the unpatched wpa_supplicant, move the laptop, and
issue a manual "iw eth1 scan" command, the effect is the same:
with -Dwext, it connects to the best AP, with -Dnl80211 it
tries, fails, and stays stuck.

MAYBE it should send a NL80211_CMD_DISCONNECT command before
connecting?

I did the same test again, now with more debugging:

1253010685.771864: Setting scan request: 0 sec 1 usec
1253010685.772013: Scan requested (ret=0) - scan timeout 10 seconds
1253010685.772048: nl80211: Event message available
1253010685.772073: nl80211: Ignored unknown event (cmd=33)
1253010686.823414: nl80211: Event message available
1253010686.823450: nl80211: New scan results available
1253010686.823537: Received scan results (3 BSSes)
1253010686.823559: CTRL-EVENT-SCAN-RESULTS
1253010686.823571: Selecting BSS from priority group 0
1253010686.823585: 1: 00:1b:53:11:dc:40 ssid=TEST rssi -310 e-1
1253010686.823604: 2: 00:13:19:80:da:30 ssid=TEST rssi -325 e-1
1253010686.823633:    selected non-WPA AP 00:1b:53:11:dc:40 ssid='TEST'
1253010686.823650: Automatic auth_alg selection: 0x1
1253010686.823664: WPA: clearing AP WPA IE
1253010686.823675: WPA: clearing AP RSN IE
1253010686.823685: WPA: clearing own WPA/RSN IE
1253010686.823700: Cancelling scan request
1253010686.823718: Trying to authenticate with 00:1b:53:11:dc:40 (SSID='TEST' freq=2412 MHz)
1253010686.823732: nl_set_encr: ifindex=5 alg=0 addr=0x80929ce key_idx=0 set_tx=0 seq_len=0 key_len=0
1253010686.823784: nl_set_encr: ifindex=5 alg=0 addr=0x80929ce key_idx=1 set_tx=0 seq_len=0 key_len=0
1253010686.823828: nl_set_encr: ifindex=5 alg=0 addr=0x80929ce key_idx=2 set_tx=0 seq_len=0 key_len=0
1253010686.823869: nl_set_encr: ifindex=5 alg=0 addr=0x80929ce key_idx=3 set_tx=0 seq_len=0 key_len=0
1253010686.823910: nl_set_encr: ifindex=5 alg=0 addr=0x839f89c key_idx=0 set_tx=0 seq_len=0 key_len=0
1253010686.823933:    addr=00:1b:53:11:dc:40
1253010686.823968: State: COMPLETED -> AUTHENTICATING
1253010686.823985: EAPOL: External notification - EAP success=0
1253010686.824001: EAPOL: External notification - EAP fail=0
1253010686.824013: EAPOL: External notification - portControl=ForceAuthorized
1253010686.824030: nl80211: Authenticate (ifindex=5)
1253010686.824042: nl_set_encr: ifindex=5 alg=1 addr=(nil) key_idx=0 set_tx=1 seq_len=0 key_len=5
1253010686.824111:   * bssid=00:1b:53:11:dc:40
1253010686.824129:   * freq=2412
1253010686.824140:   * SSID - hexdump_ascii(len=4):
1253010686.824173:   * IEs - hexdump(len=0): [NULL]
1253010686.824186:   * Auth Type 0
1253010686.824225: nl80211: Authentication request send successfully
1253010686.824248: RTM_NEWLINK: operstate=1 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
1253010686.824267: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth1' added
1253010686.910972: nl80211: Event message available
1253010686.911008: nl80211: MLME event 37
1253010686.911023: SME: Authentication response: peer=00:1b:53:11:dc:40 auth_type=0 status_code=0
1253010686.911050: Trying to associate with 00:1b:53:11:dc:40 (SSID='TEST' freq=2412 MHz)
1253010686.911064: State: AUTHENTICATING -> ASSOCIATING
1253010686.911077: wpa_driver_nl80211_set_operstate: operstate 1->0 (DORMANT)
1253010686.911092: nl80211: Operstate: linkmode=-1, operstate=5
1253010686.912590: nl80211: Associate (ifindex=5)
1253010686.912612:   * bssid=00:1b:53:11:dc:40
1253010686.912628:   * freq=2412
1253010686.912639:   * SSID - hexdump_ascii(len=4):
1253010686.912672:   * IEs - hexdump(len=0): [NULL]
1253010686.912733: nl80211: MLME command failed: ret=-16 (Device or resource busy)
                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
1253010686.912754: Association request to the driver failed
1253010686.912781: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1253010686.912799: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth1' added
1253010689.396078: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1253010689.396103: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth1' added
1253010689.396157: nl80211: Event message available
1253010689.396185: nl80211: MLME event 39
1253010689.396200: Added BSSID 00:1b:53:11:dc:40 into blacklist
1253010689.396220: CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys
1253010689.396234: State: ASSOCIATING -> DISCONNECTED
1253010689.396247: wpa_driver_nl80211_set_operstate: operstate 0->0 (DORMANT)
1253010689.396261: nl80211: Operstate: linkmode=-1, operstate=5
1253010689.396282: EAPOL: External notification - portEnabled=0
1253010689.396295: EAPOL: SUPP_PAE entering state DISCONNECTED
1253010689.396307: EAPOL: Supplicant port status: Unauthorized
1253010689.396371: EAPOL: SUPP_BE entering state INITIALIZE
1253010689.396388: EAPOL: Supplicant port status: Unauthorized
1253010689.396443: EAPOL: External notification - portValid=0
1253010689.396459: EAPOL: Supplicant port status: Unauthorized
1253010689.396550: nl80211: Event message available
1253010689.396578: nl80211: MLME event 39
1253010689.396592: Added BSSID 00:00:00:00:00:00 into blacklist
                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ Huh ?
1253010689.396610: CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys

-- 
http://www.holgerschurig.de