mac80211: 3.9.0+: Invalid WDS/flush state and non-connecting station.

[Ben Greear <greearb@candelatech.com>]

Kernel is hacked 3.9.0+

I've been seeing this problem for a while (and posted about it previously).  The problem
is that a station appears to associate fine, but never actually 'connects'.  This problem
is not easy to reproduce...

I added printouts in the connect logic to help debug this..for instance, here is an
interface that worked:


May  2 12:03:37 localhost kernel: [88122.116646] wiphy0: start_sw_scan: running-other-vifs: 1  running-station-vifs: 21, associated-stations: 20 scanning 
current channel: 2437 MHz
May  2 12:03:37 localhost kernel: [88122.149736] wiphy0: start_sw_scan: running-other-vifs: 2  running-station-vifs: 42, associated-stations: 40 scanning 
current channel: 2437 MHz
May  2 12:03:38 localhost kernel: [88122.218702] sta17: authenticate with 80:01:02:03:04:05
May  2 12:03:38 localhost kernel: [88122.246420] sta17: send auth to 80:01:02:03:04:05 (try 1/3)
May  2 12:03:38 localhost kernel: [88122.315220] sta17: authenticated
May  2 12:03:38 localhost kernel: [88122.329509] sta17: associate with 80:01:02:03:04:05 (try 1/3)
May  2 12:03:38 localhost kernel: [88122.350295] sta17: RX AssocResp from 80:01:02:03:04:05 (capab=0x401 status=0 aid=21)
May  2 12:03:38 localhost kernel: [88122.364322] IPv6: ADDRCONF(NETDEV_CHANGE): sta17: link becomes ready
May  2 12:03:38 localhost kernel: [88122.376190] sta17: associated
May  2 12:03:38 localhost kernel: [88122.388795] nl80211_send_connect_result, dev: sta17  status: 0
May  2 12:03:38 localhost kernel: [88122.400701] nl80211_send_connect_result, dev: sta17  sending msg...

Here is the stuck one (sta4).  What may be of interest is that the Invalid WDS/flush state shows up in
these logs.  Any idea if this could somehow cause the 'connect' logic to not be
called?

May  2 12:36:37 localhost kernel: [90101.873677] sta4: authenticated
May  2 12:36:37 localhost kernel: [90101.891233] sta4: associate with 80:01:02:03:04:05 (try 1/3)
May  2 12:36:37 localhost kernel: [90101.908620] sta4: RX AssocResp from 80:01:02:03:04:05 (capab=0x401 status=0 aid=19)
May  2 12:36:37 localhost kernel: [90101.922494] IPv6: ADDRCONF(NETDEV_CHANGE): sta4: link becomes ready
May  2 12:36:37 localhost kernel: [90101.935228] sta4: associated
May  2 12:36:42 localhost ntpd[1243]: Listen normally on 935 sta4 fe80::2ab:cdff:feef:105 UDP 123
May  2 12:37:50 localhost kernel: [90174.724370] sta4: Invalid WDS/flush state, type: 2  WDS: 5  flushed: 1
May  2 12:37:51 localhost ntpd[1243]: Deleting interface #935 sta4, fe80::2ab:cdff:feef:105#123, interface stats: received=0, sent=0, dropped=0, active_time=69 secs
May  2 12:37:55 localhost kernel: [90179.828649] IPv6: ADDRCONF(NETDEV_UP): sta4: link is not ready
May  2 12:37:55 localhost kernel: [90179.844669] wiphy0: start_sw_scan: running-other-vifs: 1  running-station-vifs: 21, associated-stations: 20 scanning 
current channel: 2437 MHz
May  2 12:37:55 localhost kernel: [90179.870926] wiphy0: start_sw_scan: running-other-vifs: 2  running-station-vifs: 42, associated-stations: 40 scanning 
current channel: 2437 MHz
May  2 12:37:55 localhost kernel: [90180.012706] IPv6: ADDRCONF(NETDEV_UP): sta4: link is not ready
May  2 12:37:55 localhost kernel: [90180.098460] sta4: authenticate with 80:01:02:03:04:05
May  2 12:37:55 localhost kernel: [90180.116506] sta4: send auth to 80:01:02:03:04:05 (try 1/3)
May  2 12:37:55 localhost kernel: [90180.144183] sta4: authenticated
May  2 12:37:55 localhost kernel: [90180.155081] sta4: associate with 80:01:02:03:04:05 (try 1/3)
May  2 12:37:55 localhost kernel: [90180.171836] sta4: RX AssocResp from 80:01:02:03:04:05 (capab=0x401 status=0 aid=19)
May  2 12:37:56 localhost kernel: [90180.192507] IPv6: ADDRCONF(NETDEV_CHANGE): sta4: link becomes ready
May  2 12:37:56 localhost kernel: [90180.196250] sta4: associated
May  2 12:38:00 localhost ntpd[1243]: Listen normally on 936 sta4 fe80::2ab:cdff:feef:105 UDP 123
May  2 12:38:38 localhost kernel: [90222.695314] sta4: Invalid WDS/flush state, type: 2  WDS: 5  flushed: 1
May  2 12:38:38 localhost kernel: [90222.728069] IPv6: ADDRCONF(NETDEV_UP): sta4: link is not ready
May  2 12:38:38 localhost kernel: [90222.746386] wiphy0: start_sw_scan: running-other-vifs: 1  running-station-vifs: 21, associated-stations: 20 scanning 
current channel: 2437 MHz
May  2 12:38:38 localhost kernel: [90222.772198] wiphy0: start_sw_scan: running-other-vifs: 2  running-station-vifs: 42, associated-stations: 40 scanning 
current channel: 2437 MHz
May  2 12:38:38 localhost kernel: [90222.862226] sta4: authenticate with 80:01:02:03:04:05
May  2 12:38:38 localhost kernel: [90222.880675] sta4: send auth to 80:01:02:03:04:05 (try 1/3)
May  2 12:38:38 localhost kernel: [90222.898643] sta4: deauthenticating from 80:01:02:03:04:05 by local choice (reason=3)
May  2 12:38:38 localhost kernel: [90222.943259] sta4: authenticate with 80:01:02:03:04:05
May  2 12:38:38 localhost kernel: [90222.956498] sta4: send auth to 80:01:02:03:04:05 (try 1/3)
May  2 12:38:38 localhost kernel: [90222.994180] sta4: authenticated
May  2 12:38:38 localhost kernel: [90223.004165] sta4: associate with 80:01:02:03:04:05 (try 1/3)
May  2 12:38:38 localhost kernel: [90223.022441] sta4: RX AssocResp from 80:01:02:03:04:05 (capab=0x401 status=0 aid=19)
May  2 12:38:38 localhost kernel: [90223.041723] IPv6: ADDRCONF(NETDEV_CHANGE): sta4: link becomes ready
May  2 12:38:38 localhost kernel: [90223.060054] sta4: associated
May  2 12:38:39 localhost ntpd[1243]: Deleting interface #936 sta4, fe80::2ab:cdff:feef:105#123, interface stats: received=0, sent=0, dropped=0, active_time=39 secs
May  2 12:38:43 localhost ntpd[1243]: Listen normally on 937 sta4 fe80::2ab:cdff:feef:105 UDP 123


Thanks,
Ben

-- 
Ben Greear <greearb@candelatech.com>
Candela Technologies Inc  http://www.candelatech.com