Debian testing wpa_supplicant 1.03 cannot roam between wifi APs without me killing wpa_supplicant (intel 6300 AGN)

[Marc MERLIN]

[resent with correct Email]

Howdy

First, the basics:

kernel: 3.7.4-amd64-preempt-20121226-fixwd
debian-testing
wpasupplicant-1.0-3+b2

iwlwifi 0000:03:00.0: loaded firmware version 9.221.4.1 build 25532
iwldvm: Intel(R) Wireless WiFi Link AGN driver for Linux, in-tree:d
iwldvm: Copyright(c) 2003-2012 Intel Corporation
iwlwifi 0000:03:00.0: CONFIG_IWLWIFI_DEBUG enabled
iwlwifi 0000:03:00.0: CONFIG_IWLWIFI_DEBUGFS disabled
iwlwifi 0000:03:00.0: CONFIG_IWLWIFI_DEVICE_TRACING disabled
iwlwifi 0000:03:00.0: CONFIG_IWLWIFI_DEVICE_TESTMODE enabled
iwlwifi 0000:03:00.0: CONFIG_IWLWIFI_P2P enabled
iwlwifi 0000:03:00.0: Detected Intel(R) Centrino(R) Ultimate-N 6300 AGN, REV=0x74
iwlwifi 0000:03:00.0: L1 Enabled; Disabling L0S
iwlwifi 0000:03:00.0: RF_KILL bit toggled to enable radio.
iwlwifi 0000:03:00.0: device EEPROM VER=0x43a, CALIB=0x6
iwlwifi 0000:03:00.0: Device SKU: 0x1F0
iwlwifi 0000:03:00.0: Valid Tx ant: 0x7, Valid Rx ant: 0x7

I started with being connected ok to 2C:B0:5D:3C:7D:F1, and walked mostly out of range and close to 2c:b0:5d:a0:c8:a6

wpa_supplicant actually did connect to 2c:b0:5d:a0:c8:a6, then I had a few pings that went through the
new AP, and then the pings stopped.
Networking never recovered until after I ran kilall wpa_supplicant.
This basically happens every time I roam :(

Debian runs it like so:
root     14862  0.0  0.0  31024  2828 ?        S    20:59   0:00 /sbin/wpa_supplicant -u -s -O /var/run/wpa_supplicant

Should I be overriding what debian does and run it like so instead?
/sbin/wpa_supplicant -u -onl80211 -O/var/run/wpa_supplicant -f /var/log/wpa_supplicant.log               

Here are the full logs if that helps, with annotations:

> Feb 14 20:29:43 gandalfthegreat wpa_supplicant[2501]: wlan0: SME: Trying to authenticate with 2c:b0:5d:a0:c8:a6 (SSID='magicnet-a' freq=5785 MHz)
> Feb 14 20:29:45 gandalfthegreat kernel: iwlwifi 0000:03:00.0: fail to flush all tx fifo queues
> Feb 14 20:29:45 gandalfthegreat kernel: wlan0: authenticate with 2c:b0:5d:a0:c8:a6
> Feb 14 20:29:45 gandalfthegreat NetworkManager[1926]: <info> (wlan0): supplicant interface state: completed -> authenticating
> Feb 14 20:29:45 gandalfthegreat kernel: wlan0: send auth to 2c:b0:5d:a0:c8:a6 (try 1/3)
> Feb 14 20:29:45 gandalfthegreat wpa_supplicant[2501]: wlan0: Trying to associate with 2c:b0:5d:a0:c8:a6 (SSID='magicnet-a' freq=5785 MHz)
> Feb 14 20:29:45 gandalfthegreat kernel: wlan0: send auth to 2c:b0:5d:a0:c8:a6 (try 2/3)
> Feb 14 20:29:45 gandalfthegreat kernel: wlan0: authenticated
> Feb 14 20:29:45 gandalfthegreat NetworkManager[1926]: <info> (wlan0): supplicant interface state: authenticating -> associating
> Feb 14 20:29:45 gandalfthegreat kernel: wlan0: associate with 2c:b0:5d:a0:c8:a6 (try 1/3)
> Feb 14 20:29:45 gandalfthegreat kernel: wlan0: RX AssocResp from 2c:b0:5d:a0:c8:a6 (capab=0x11 status=0 aid=3)
> Feb 14 20:29:45 gandalfthegreat wpa_supplicant[2501]: wlan0: Associated with 2c:b0:5d:a0:c8:a6
> Feb 14 20:29:45 gandalfthegreat kernel: wlan0: associated
> Feb 14 20:29:45 gandalfthegreat kernel: cfg80211: Calling CRDA for country: US
> Feb 14 20:29:45 gandalfthegreat NetworkManager[1926]: <info> (wlan0): supplicant interface state: associating -> associated
> Feb 14 20:29:45 gandalfthegreat kernel: cfg80211: Updating information on frequency 2412 MHz for a 20 MHz width channel with regulatory rule:
> Feb 14 20:29:45 gandalfthegreat kernel: cfg80211: 2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2700 mBm)
(...)
> Feb 14 20:29:45 gandalfthegreat kernel: cfg80211:   (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 3000 mBm)
> Feb 14 20:29:45 gandalfthegreat kernel: cfg80211: Found new beacon on frequency: 5785 MHz (Ch 157) on phy0
> Feb 14 20:29:45 gandalfthegreat wpa_supplicant[2501]: wlan0: WPA: Key negotiation completed with 2c:b0:5d:a0:c8:a6 [PTK=CCMP GTK=CCMP]
> Feb 14 20:29:45 gandalfthegreat wpa_supplicant[2501]: wlan0: CTRL-EVENT-CONNECTED - Connection to 2c:b0:5d:a0:c8:a6 completed (reauth) [id=0 id_str=]
> Feb 14 20:29:45 gandalfthegreat NetworkManager[1926]: <info> (wlan0): supplicant interface state: associated -> completed
> Feb 14 20:29:50 gandalfthegreat NetworkManager[1926]: <info> (wlan0): roamed from BSSID 2C:B0:5D:3C:7D:F1 (magicnet-a) to 2C:B0:5D:A0:C8:A6 (magicnet-a)
 
I had nothing in the logs for a while, and 1mn later, wpa_supplicant disconnected from the close ap and reconnected to the far away one: 
 
> Feb 14 20:30:55 gandalfthegreat wpa_supplicant[2501]: wlan0: WPA: Group rekeying completed with 2c:b0:5d:a0:c8:a6 [GTK=CCMP]
> Feb 14 20:30:55 gandalfthegreat wpa_supplicant[2501]: wlan0: WPA: Group rekeying completed with 2c:b0:5d:a0:c8:a6 [GTK=CCMP]
> Feb 14 20:30:56 gandalfthegreat wpa_supplicant[2501]: wlan0: WPA: Group rekeying completed with 2c:b0:5d:a0:c8:a6 [GTK=CCMP]
> Feb 14 20:30:57 gandalfthegreat wpa_supplicant[2501]: wlan0: WPA: Group rekeying completed with 2c:b0:5d:a0:c8:a6 [GTK=CCMP]
> Feb 14 20:31:01 gandalfthegreat kernel: cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on phy0
> Feb 14 20:31:04 gandalfthegreat kernel: iwlwifi 0000:03:00.0: fail to flush all tx fifo queues
> Feb 14 20:31:04 gandalfthegreat kernel: wlan0: deauthenticated from 2c:b0:5d:a0:c8:a6 (Reason: 2)

disconnection was here:

> Feb 14 20:31:06 gandalfthegreat wpa_supplicant[2501]: wlan0: CTRL-EVENT-DISCONNECTED bssid=2c:b0:5d:a0:c8:a6 reason=2
> Feb 14 20:31:06 gandalfthegreat kernel: iwlwifi 0000:03:00.0: fail to flush all tx fifo queues
> Feb 14 20:31:06 gandalfthegreat kernel: cfg80211: All devices are disconnected, going to restore regulatory settings
> Feb 14 20:31:06 gandalfthegreat kernel: cfg80211: Restoring regulatory settings
> Feb 14 20:31:06 gandalfthegreat kernel: cfg80211: Calling CRDA to update world regulatory domain
> Feb 14 20:31:06 gandalfthegreat NetworkManager[1926]: <info> (wlan0): supplicant interface state: completed -> disconnected
> Feb 14 20:31:06 gandalfthegreat kernel: cfg80211: Ignoring regulatory request Set by core since the driver uses its own custom regulatory domain
> Feb 14 20:31:06 gandalfthegreat kernel: cfg80211: World regulatory domain updated:
> Feb 14 20:31:06 gandalfthegreat kernel: cfg80211:   (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
> Feb 14 20:31:06 gandalfthegreat kernel: cfg80211:   (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
> Feb 14 20:31:06 gandalfthegreat kernel: cfg80211:   (2457000 KHz - 2482000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
> Feb 14 20:31:06 gandalfthegreat kernel: cfg80211:   (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
> Feb 14 20:31:06 gandalfthegreat kernel: cfg80211:   (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
> Feb 14 20:31:06 gandalfthegreat kernel: cfg80211:   (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
> Feb 14 20:31:06 gandalfthegreat NetworkManager[1926]: <info> (wlan0): supplicant interface state: disconnected -> scanning
> Feb 14 20:31:06 gandalfthegreat kernel: cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on phy0
> Feb 14 20:31:06 gandalfthegreat wpa_supplicant[2501]: wlan0: SME: Trying to authenticate with 2c:b0:5d:3c:7d:f1 (SSID='magicnet-a' freq=5745 MHz)
> Feb 14 20:31:06 gandalfthegreat kernel: wlan0: authenticate with 2c:b0:5d:3c:7d:f1
> Feb 14 20:31:06 gandalfthegreat NetworkManager[1926]: <info> (wlan0): supplicant interface state: scanning -> authenticating
> Feb 14 20:31:06 gandalfthegreat kernel: wlan0: send auth to 2c:b0:5d:3c:7d:f1 (try 1/3)
> Feb 14 20:31:06 gandalfthegreat kernel: wlan0: send auth to 2c:b0:5d:3c:7d:f1 (try 2/3)
> Feb 14 20:31:07 gandalfthegreat wpa_supplicant[2501]: wlan0: Trying to associate with 2c:b0:5d:3c:7d:f1 (SSID='magicnet-a' freq=5745 MHz)
> Feb 14 20:31:07 gandalfthegreat kernel: wlan0: send auth to 2c:b0:5d:3c:7d:f1 (try 3/3)
> Feb 14 20:31:07 gandalfthegreat kernel: wlan0: authenticated
> Feb 14 20:31:07 gandalfthegreat NetworkManager[1926]: <info> (wlan0): supplicant interface state: authenticating -> associating
> Feb 14 20:31:07 gandalfthegreat kernel: wlan0: associate with 2c:b0:5d:3c:7d:f1 (try 1/3)
> Feb 14 20:31:07 gandalfthegreat kernel: wlan0: associate with 2c:b0:5d:3c:7d:f1 (try 2/3)
> Feb 14 20:31:07 gandalfthegreat kernel: wlan0: associate with 2c:b0:5d:3c:7d:f1 (try 3/3)
> Feb 14 20:31:07 gandalfthegreat kernel: wlan0: RX AssocResp from 2c:b0:5d:3c:7d:f1 (capab=0x11 status=0 aid=1)
> Feb 14 20:31:07 gandalfthegreat wpa_supplicant[2501]: wlan0: Associated with 2c:b0:5d:3c:7d:f1
> Feb 14 20:31:07 gandalfthegreat kernel: wlan0: associated
> Feb 14 20:31:07 gandalfthegreat NetworkManager[1926]: <info> (wlan0): supplicant interface state: associating -> associated
> Feb 14 20:31:08 gandalfthegreat NetworkManager[1926]: <info> (wlan0): roamed from BSSID 2C:B0:5D:A0:C8:A6 (magicnet-a) to 2C:B0:5D:3C:7D:F1 (magicnet-a)
> Feb 14 20:31:08 gandalfthegreat NetworkManager[1926]: <info> (wlan0): supplicant interface state: associated -> 4-way handshake
> Feb 14 20:31:08 gandalfthegreat wpa_supplicant[2501]: wlan0: WPA: Key negotiation completed with 2c:b0:5d:3c:7d:f1 [PTK=CCMP GTK=CCMP]
> Feb 14 20:31:08 gandalfthegreat wpa_supplicant[2501]: wlan0: CTRL-EVENT-CONNECTED - Connection to 2c:b0:5d:3c:7d:f1 completed (reauth) [id=0 id_str=]
> Feb 14 20:31:08 gandalfthegreat NetworkManager[1926]: <info> (wlan0): supplicant interface state: 4-way handshake -> completed
> Feb 14 20:32:43 gandalfthegreat kernel: cfg80211: Found new beacon on frequency: 5785 MHz (Ch 157) on phy0
> Feb 14 20:32:45 gandalfthegreat kernel: iwlwifi 0000:03:00.0: fail to flush all tx fifo queues

Ok, so now I got impatient and ran killall wpa_supplicant. After that NetworkManager restarted it, and it reconnected ok to the close AP.