Question on debugging loop of assoc/disassoc with 400 stations.

Fri Jan 13 11:00:42 PST 2012

I've been running some tests with 400 or so stations associated against a single
AP (ath9k client & AP).  I'm using top-of-tree hostap/supplicant plus some local patches,
and kernel 3.0.15 plus some patches.  The virtual client machine has two NICs, 200 STAs each.

I'm also driving supplicant with another process.  So, it's a big thing to
try to debug...

I saw the system get into a state where many of the stations on one of the
NICs (but not the other, as far as I can tell), got into a big loop of associating
and dis-associating.  A snippet of the hostapd logs is here.  It shows
station :a8 doing some things and then dis-associating with reason 2, it seems.
The supplicant side was complaining about step 4 failing, maybe because of
bad password (I managed to lose those logs...will save them next time if I can reproduce
the problem.)

At this point, I'm just curious what sorts of things might be causing
disassoc with reason 2.

1326479921.614048: vap0: Event EAPOL_RX (27) received
1326479921.614158: IEEE 802.1X: 121 bytes from 00:99:00:00:00:a8
1326479921.614197:    IEEE 802.1X: version=1 type=3 length=117
1326479921.614229: WPA: Received EAPOL-Key from 00:99:00:00:00:a8 key_info=0x10a type=2 key_data_length=22
1326479921.614264: WPA: Received Key Nonce - hexdump(len=32): 97 02 a2 d4 70 64 e3 7e dd b4 4a 40 86 5b 5b 20 7b 33 0b 2b b3 63 62 7f 3e 76 dd d9 c3 14 ab b0
1326479921.614330: WPA: Received Replay Counter - hexdump(len=8): 00 00 00 00 00 00 00 01
1326479921.614399: 1326479921.614413: WPA: 00:99:00:00:00:a8 WPA_PTK entering state PTKCALCNEGOTIATING
1326479921.614547: WPA: PTK derivation - A1=00:88:99:88:99:01 A2=00:99:00:00:00:a8
1326479921.614594: WPA: Nonce1 - hexdump(len=32): c1 c1 50 fb 56 e5 ff 10 3c 4b 63 fd 25 19 93 53 42 13 ba 20 3e 6b 16 97 ab 59 ab 38 b7 cb 5e 04
1326479921.614654: WPA: Nonce2 - hexdump(len=32): 97 02 a2 d4 70 64 e3 7e dd b4 4a 40 86 5b 5b 20 7b 33 0b 2b b3 63 62 7f 3e 76 dd d9 c3 14 ab b0
1326479921.614729: WPA: PMK - hexdump(len=32): [REMOVED]
1326479921.614812: WPA: PTK - hexdump(len=48): [REMOVED]
1326479921.614892: 1326479921.620353: vap0: Event EAPOL_RX (27) received
1326479921.620434: IEEE 802.1X: 121 bytes from 00:99:00:00:00:c6
1326479921.620520:    IEEE 802.1X: version=1 type=3 length=117
1326479921.620558: WPA: Received EAPOL-Key from 00:99:00:00:00:c6 key_info=0x10a type=2 key_data_length=22
1326479921.620593: WPA: Received Key Nonce - hexdump(len=32): 88 0f 11 b8 28 ba 35 89 16 42 ef e7 7a 41 e1 7c e0 8a 7b ac 7d e9 1d 85 f4 2f 43 3c ba 3c 31 5a
1326479921.620665: WPA: Received Replay Counter - hexdump(len=8): 00 00 00 00 00 00 00 02
1326479921.620729: 1326479921.620739: received replay counter - hexdump(len=8): 00 00 00 00 00 00 00 02
1326479921.702338: 1326479921.702355: WPA: 00:99:00:00:00:c6 WPA_PTK entering state PTKSTART
1326479921.702460: 1326479921.702516: WPA: 00:99:00:00:00:c6 WPA_PTK entering state DISCONNECT
1326479921.702557: wpa_sta_disconnect STA 00:99:00:00:00:c6
1326479921.702589: hostapd_wpa_auth_disconnect: WPA authenticator requests disconnect: STA 00:99:00:00:00:c6 reason 2
1326479921.702785: WPA: 00:99:00:00:00:c6 WPA_PTK entering state DISCONNECTED
1326479921.702904: WPA: 00:99:00:00:00:c6 WPA_PTK entering state INITIALIZE
1326479921.702999: wpa_driver_nl80211_set_key: ifindex=10 alg=0 addr=0x856b9a0 key_idx=0 set_tx=1 seq_len=0 key_len=0
1326479921.703057:    addr=00:99:00:00:00:c6
1326479921.703322: 1326479921.703377: 1326479921.703386: WPA: 00:99:00:00:00:ab WPA_PTK entering state PTKSTART
1326479921.703455: 1326479921.703531: WPA: Send EAPOL(version=2 secure=0 mic=0 ack=1 install=0 pairwise=8 kde_len=0 keyidx=0 encr=0)
1326479921.703638: WPA: Use EAPOL-Key timeout of 2000 ms (retry counter 2)
1326479921.703710: vap0: Event TX_STATUS (18) received
1326479921.703744: mgmt::deauth cb
1326479921.703777: STA 00:99:00:00:00:c6 acknowledged deauth
1326479921.703860: Removing STA 00:99:00:00:00:c6 from kernel driver
1326479921.709868: 1326479921.709892: 1326479921.709956: wpa_driver_nl80211_set_key: ifindex=10 alg=0 addr=0x856b9a0 key_idx=0 set_tx=1 seq_len=0 key_len=0
1326479921.710051:    addr=00:99:00:00:00:c6
1326479921.710271: nl80211: Event message available
1326479921.710338: nl80211: Delete station 00:99:00:00:00:c6
1326479921.710878: vap0: Event TX_STATUS (18) received
1326479921.733037: vap0: Station 00:99:00:00:00:b6 has been active 0s ago
1326479921.767892: 1326479921.767907: WPA: 00:99:00:00:00:c3 WPA_PTK entering state PTKSTART
1326479921.768013: 1326479921.768023: WPA: 00:99:00:00:00:c3 WPA_PTK entering state DISCONNECT
1326479921.768057: wpa_sta_disconnect STA 00:99:00:00:00:c3
1326479921.768090: hostapd_wpa_auth_disconnect: WPA authenticator requests disconnect: STA 00:99:00:00:00:c3 reason 2
1326479921.768271: WPA: 00:99:00:00:00:c3 WPA_PTK entering state DISCONNECTED
1326479921.768313: WPA: 00:99:00:00:00:c3 WPA_PTK entering state INITIALIZE
1326479921.768400: wpa_driver_nl80211_set_key: ifindex=10 alg=0 addr=0x8563890 key_idx=0 set_tx=1 seq_len=0 key_len=0
1326479921.768446:    addr=00:99:00:00:00:c3
1326479921.768796: 1326479921.768871: vap0: Event TX_STATUS (18) received
1326479921.768943: mgmt::deauth cb
1326479921.768975: STA 00:99:00:00:00:c3 acknowledged deauth
1326479921.769065: Removing STA 00:99:00:00:00:c3 from kernel driver
1326479921.786956: 1326479921.786982: 1326479921.787034: wpa_driver_nl80211_set_key: ifindex=10 alg=0 addr=0x8563890 key_idx=0 set_tx=1 seq_len=0 key_len=0
1326479921.787240:    addr=00:99:00:00:00:c3
1326479921.788081: nl80211: Event message available
1326479921.788351: nl80211: Delete station 00:99:00:00:00:c3
1326479921.802613: vap0: Station 00:99:00:00:00:b5 has been active 0s ago
1326479921.843570: 1326479921.843588: WPA: 00:99:00:00:00:a5 WPA_PTK entering state PTKSTART
1326479921.843690: 1326479921.843699: WPA: Send EAPOL(version=2 secure=0 mic=0 ack=1 install=0 pairwise=8 kde_len=0 keyidx=0 encr=0)
1326479921.843794: WPA: Use EAPOL-Key timeout of 2000 ms (retry counter 2)
1326479921.844032: vap0: Event TX_STATUS (18) received
1326479921.903800: 1326479921.903817: WPA: 00:99:00:00:00:a3 WPA_PTK entering state PTKSTART
1326479921.903954: 1326479921.903965: WPA: Send EAPOL(version=2 secure=0 mic=0 ack=1 install=0 pairwise=8 kde_len=0 keyidx=0 encr=0)
1326479921.904067: WPA: Use EAPOL-Key timeout of 2000 ms (retry counter 2)
1326479921.904643: vap0: Event TX_STATUS (18) received
1326479921.925756: 1326479921.925772: WPA: 00:99:00:00:00:c2 WPA_PTK entering state PTKSTART
1326479921.925870: 1326479921.925879: WPA: 00:99:00:00:00:c2 WPA_PTK entering state DISCONNECT
1326479921.925913: wpa_sta_disconnect STA 00:99:00:00:00:c2
1326479921.925946: hostapd_wpa_auth_disconnect: WPA authenticator requests disconnect: STA 00:99:00:00:00:c2 reason 2
1326479921.926142: WPA: 00:99:00:00:00:c2 WPA_PTK entering state DISCONNECTED
1326479921.926301: WPA: 00:99:00:00:00:c2 WPA_PTK entering state INITIALIZE
1326479921.926398: wpa_driver_nl80211_set_key: ifindex=10 alg=0 addr=0x855aa50 key_idx=0 set_tx=1 seq_len=0 key_len=0
1326479921.926455:    addr=00:99:00:00:00:c2
1326479921.926800: 1326479921.926868: vap0: Event TX_STATUS (18) received
1326479921.926923: mgmt::deauth cb
1326479921.926954: STA 00:99:00:00:00:c2 acknowledged deauth
1326479921.927025: Removing STA 00:99:00:00:00:c2 from kernel driver
1326479921.946731: 1326479921.946759: 1326479921.946955: wpa_driver_nl80211_set_key: ifindex=10 alg=0 addr=0x855aa50 key_idx=0 set_tx=1 seq_len=0 key_len=0
1326479921.947064:    addr=00:99:00:00:00:c2
1326479921.947866: vap0: Station 00:99:00:00:00:b4 has been active 1s ago
1326479921.948056: nl80211: Event message available
1326479921.948118: nl80211: Delete station 00:99:00:00:00:c2
1326479922.047808: vap0: Station 00:99:00:00:00:af has been active 0s ago
1326479922.125359: 1326479922.125374: WPA: 00:99:00:00:00:c0 WPA_PTK entering state PTKSTART
1326479922.125512: 1326479922.125523: WPA: 00:99:00:00:00:c0 WPA_PTK entering state DISCONNECT
1326479922.125566: wpa_sta_disconnect STA 00:99:00:00:00:c0
1326479922.125599: hostapd_wpa_auth_disconnect: WPA authenticator requests disconnect: STA 00:99:00:00:00:c0 reason 2
1326479922.125796: WPA: 00:99:00:00:00:c0 WPA_PTK entering state DISCONNECTED
1326479922.125853: WPA: 00:99:00:00:00:c0 WPA_PTK entering state INITIALIZE
1326479922.125957: wpa_driver_nl80211_set_key: ifindex=10 alg=0 addr=0x8556230 key_idx=0 set_tx=1 seq_len=0 key_len=0
1326479922.126018:    addr=00:99:00:00:00:c0
1326479922.126325: 1326479922.126395: vap0: Event TX_STATUS (18) received
1326479922.126457: mgmt::deauth cb
1326479922.126616: STA 00:99:00:00:00:c0 acknowledged deauth
1326479922.126734: Removing STA 00:99:00:00:00:c0 from kernel driver
1326479922.145803: 1326479922.145828: 1326479922.145880: wpa_driver_nl80211_set_key: ifindex=10 alg=0 addr=0x8556230 key_idx=0 set_tx=1 seq_len=0 key_len=0
1326479922.146098:    addr=00:99:00:00:00:c0
1326479922.147178: vap0: Station 00:99:00:00:00:ae has been active 0s ago
1326479922.147447: nl80211: Event message available
1326479922.147676: nl80211: Delete station 00:99:00:00:00:c0
1326479922.147866: 1326479922.147881: WPA: 00:99:00:00:00:af WPA_PTK entering state PTKSTART
1326479922.148040: 1326479922.148050: WPA: Send EAPOL(version=2 secure=0 mic=0 ack=1 install=0 pairwise=8 kde_len=0 keyidx=0 encr=0)
1326479922.148254: WPA: Use EAPOL-Key timeout of 2000 ms (retry counter 3)
1326479922.150237: vap0: Event TX_STATUS (18) received
1326479922.193578: 1326479922.193595: WPA: 00:99:00:00:00:b8 WPA_PTK entering state PTKSTART
1326479922.193701: 1326479922.193757: WPA: 00:99:00:00:00:b8 WPA_PTK entering state DISCONNECT
1326479922.193852: wpa_sta_disconnect STA 00:99:00:00:00:b8
1326479922.193886: hostapd_wpa_auth_disconnect: WPA authenticator requests disconnect: STA 00:99:00:00:00:b8 reason 2
1326479922.194076: WPA: 00:99:00:00:00:b8 WPA_PTK entering state DISCONNECTED
1326479922.194192: WPA: 00:99:00:00:00:b8 WPA_PTK entering state INITIALIZE
1326479922.194334: wpa_driver_nl80211_set_key: ifindex=10 alg=0 addr=0x85470a0 key_idx=0 set_tx=1 seq_len=0 key_len=0
1326479922.194396:    addr=00:99:00:00:00:b8
1326479922.194787: 1326479922.194857: vap0: Event TX_STATUS (18) received
1326479922.195024: mgmt::deauth cb
1326479922.195057: STA 00:99:00:00:00:b8 acknowledged deauth
1326479922.195137: Removing STA 00:99:00:00:00:b8 from kernel driver
1326479922.216876: 1326479922.216901: 1326479922.216962: wpa_driver_nl80211_set_key: ifindex=10 alg=0 addr=0x85470a0 key_idx=0 set_tx=1 seq_len=0 key_len=0
1326479922.217457:    addr=00:99:00:00:00:b8
1326479922.218254: nl80211: Event message available
1326479922.218406: nl80211: Delete station 00:99:00:00:00:b8
1326479922.283686: vap0: Station 00:99:00:00:00:ad has been active 0s ago
1326479922.300670: 1326479922.300687: WPA: 00:99:00:00:00:cb WPA_PTK entering state PTKSTART
1326479922.300785: 1326479922.300794: WPA: Send EAPOL(version=2 secure=0 mic=0 ack=1 install=0 pairwise=8 kde_len=0 keyidx=0 encr=0)
1326479922.300893: WPA: Use EAPOL-Key timeout of 2000 ms (retry counter 3)
1326479922.302009: vap0: Event TX_STATUS (18) received
1326479922.325812: 1326479922.325828: WPA: 00:99:00:00:00:b2 WPA_PTK entering state PTKSTART
1326479922.325930: 1326479922.325940: WPA: 00:99:00:00:00:b2 WPA_PTK entering state DISCONNECT
1326479922.325973: wpa_sta_disconnect STA 00:99:00:00:00:b2
1326479922.326006: hostapd_wpa_auth_disconnect: WPA authenticator requests disconnect: STA 00:99:00:00:00:b2 reason 2
1326479922.326202: WPA: 00:99:00:00:00:b2 WPA_PTK entering state DISCONNECTED
1326479922.326339: WPA: 00:99:00:00:00:b2 WPA_PTK entering state INITIALIZE
1326479922.326441: wpa_driver_nl80211_set_key: ifindex=10 alg=0 addr=0x85624e0 key_idx=0 set_tx=1 seq_len=0 key_len=0
1326479922.326559:    addr=00:99:00:00:00:b2
1326479922.326900: 1326479922.326970: vap0: Event TX_STATUS (18) received
1326479922.327029: mgmt::deauth cb
1326479922.327060: STA 00:99:00:00:00:b2 acknowledged deauth
1326479922.327138: Removing STA 00:99:00:00:00:b2 from kernel driver
1326479922.345864: 1326479922.345889: 1326479922.345959: wpa_driver_nl80211_set_key: ifindex=10 alg=0 addr=0x85624e0 key_idx=0 set_tx=1 seq_len=0 key_len=0
1326479922.346783:    addr=00:99:00:00:00:b2
1326479922.347565: vap0: Station 00:99:00:00:00:ac has been active 0s ago
1326479922.347783: nl80211: Event message available
1326479922.347865: nl80211: Delete station 00:99:00:00:00:b2
1326479922.373093: 1326479922.373111: WPA: 00:99:00:00:00:bf WPA_PTK entering state PTKSTART
1326479922.373209: 1326479922.373220: WPA: Send EAPOL(version=2 secure=0 mic=0 ack=1 install=0 pairwise=8 kde_len=0 keyidx=0 encr=0)
1326479922.373320: WPA: Use EAPOL-Key timeout of 2000 ms (retry counter 3)
1326479922.373598: vap0: Event TX_STATUS (18) received
1326479922.440509: 1326479922.440524: WPA: 00:99:00:00:00:b0 WPA_PTK entering state PTKSTART
1326479922.440629: 1326479922.440640: WPA: 00:99:00:00:00:b0 WPA_PTK entering state DISCONNECT
1326479922.440674: wpa_sta_disconnect STA 00:99:00:00:00:b0
1326479922.440707: hostapd_wpa_auth_disconnect: WPA authenticator requests disconnect: STA 00:99:00:00:00:b0 reason 2
1326479922.440910: WPA: 00:99:00:00:00:b0 WPA_PTK entering state DISCONNECTED
1326479922.440976: WPA: 00:99:00:00:00:b0 WPA_PTK entering state INITIALIZE
1326479922.441074: wpa_driver_nl80211_set_key: ifindex=10 alg=0 addr=0x85310a8 key_idx=0 set_tx=1 seq_len=0 key_len=0
1326479922.441134:    addr=00:99:00:00:00:b0
1326479922.441448: 1326479922.441626: vap0: Event TX_STATUS (18) received
1326479922.441690: mgmt::deauth cb
1326479922.441724: STA 00:99:00:00:00:b0 acknowledged deauth
1326479922.441807: Removing STA 00:99:00:00:00:b0 from kernel driver
1326479922.459798: 1326479922.459823: 1326479922.459876: wpa_driver_nl80211_set_key: ifindex=10 alg=0 addr=0x85310a8 key_idx=0 set_tx=1 seq_len=0 key_len=0
1326479922.460083:    addr=00:99:00:00:00:b0
1326479922.460859: nl80211: Event message available
1326479922.461199: nl80211: Delete station 00:99:00:00:00:b0
1326479922.503998: 1326479922.504014: WPA: 00:99:00:00:00:be WPA_PTK entering state PTKSTART
1326479922.504119: 1326479922.504130: WPA: Send EAPOL(version=2 secure=0 mic=0 ack=1 install=0 pairwise=8 kde_len=0 keyidx=0 encr=0)
1326479922.504301: WPA: Use EAPOL-Key timeout of 2000 ms (retry counter 3)
1326479922.508353: vap0: Event TX_STATUS (18) received
1326479922.524573: 1326479922.524588: WPA: 00:99:00:00:00:aa WPA_PTK entering state PTKSTART
1326479922.524686: 1326479922.524695: WPA: 00:99:00:00:00:aa WPA_PTK entering state DISCONNECT
1326479922.524727: wpa_sta_disconnect STA 00:99:00:00:00:aa
1326479922.524759: hostapd_wpa_auth_disconnect: WPA authenticator requests disconnect: STA 00:99:00:00:00:aa reason 2
1326479922.524950: WPA: 00:99:00:00:00:aa WPA_PTK entering state DISCONNECTED
1326479922.525010: WPA: 00:99:00:00:00:aa WPA_PTK entering state INITIALIZE
1326479922.525109: wpa_driver_nl80211_set_key: ifindex=10 alg=0 addr=0x8553ad8 key_idx=0 set_tx=1 seq_len=0 key_len=0
1326479922.525168:    addr=00:99:00:00:00:aa
1326479922.525595: 1326479922.525668: vap0: Event TX_STATUS (18) received
1326479922.525754: mgmt::deauth cb
1326479922.525790: STA 00:99:00:00:00:aa acknowledged deauth
1326479922.525886: Removing STA 00:99:00:00:00:aa from kernel driver
1326479922.544106: 1326479922.544132: 1326479922.544201: wpa_driver_nl80211_set_key: ifindex=10 alg=0 addr=0x8553ad8 key_idx=0 set_tx=1 seq_len=0 key_len=0
1326479922.545065:    addr=00:99:00:00:00:aa
1326479922.545909: vap0: Station 00:99:00:00:00:ab has been active 0s ago
1326479922.546112: nl80211: Event message available
1326479922.546171: nl80211: Delete station 00:99:00:00:00:aa
1326479922.583421: vap0: Station 00:99:00:00:00:a5 has been active 0s ago
1326479922.615506: 1326479922.615526: WPA: 00:99:00:00:00:ba WPA_PTK entering state PTKSTART
1326479922.615629: 1326479922.615639: WPA: Send EAPOL(version=2 secure=0 mic=0 ack=1 install=0 pairwise=8 kde_len=0 keyidx=0 encr=0)
1326479922.615736: WPA: Use EAPOL-Key timeout of 2000 ms (retry counter 3)
1326479922.616312: vap0: Event TX_STATUS (18) received
1326479922.682089: 1326479922.682107: WPA: 00:99:00:00:00:a9 WPA_PTK entering state PTKSTART
1326479922.682210: 1326479922.682219: WPA: 00:99:00:00:00:a9 WPA_PTK entering state DISCONNECT
1326479922.682252: wpa_sta_disconnect STA 00:99:00:00:00:a9
1326479922.682285: hostapd_wpa_auth_disconnect: WPA authenticator requests disconnect: STA 00:99:00:00:00:a9 reason 2
1326479922.682505: WPA: 00:99:00:00:00:a9 WPA_PTK entering state DISCONNECTED
1326479922.682560: WPA: 00:99:00:00:00:a9 WPA_PTK entering state INITIALIZE
1326479922.682654: wpa_driver_nl80211_set_key: ifindex=10 alg=0 addr=0x850c710 key_idx=0 set_tx=1 seq_len=0 key_len=0
1326479922.682711:    addr=00:99:00:00:00:a9
1326479922.682979: 1326479922.683049: vap0: Event TX_STATUS (18) received
1326479922.683104: mgmt::deauth cb
1326479922.683137: STA 00:99:00:00:00:a9 acknowledged deauth
1326479922.683206: Removing STA 00:99:00:00:00:a9 from kernel driver
1326479922.702805: 1326479922.702829: 1326479922.702873: wpa_driver_nl80211_set_key: ifindex=10 alg=0 addr=0x850c710 key_idx=0 set_tx=1 seq_len=0 key_len=0
1326479922.703369:    addr=00:99:00:00:00:a9
1326479922.704163: 1326479922.704178: WPA: 00:99:00:00:00:b9 WPA_PTK entering state PTKSTART
1326479922.704620: 1326479922.704631: WPA: Send EAPOL(version=2 secure=0 mic=0 ack=1 install=0 pairwise=8 kde_len=0 keyidx=0 encr=0)
1326479922.705126: WPA: Use EAPOL-Key timeout of 2000 ms (retry counter 3)
1326479922.705519: nl80211: Event message available
1326479922.706056: nl80211: Delete station 00:99:00:00:00:a9
1326479922.710656: vap0: Event TX_STATUS (18) received
1326479922.733203: 1326479922.733220: WPA: 00:99:00:00:00:a8 WPA_PTK entering state PTKSTART
1326479922.733326: 1326479922.733335: WPA: 00:99:00:00:00:a8 WPA_PTK entering state DISCONNECT
1326479922.733412: wpa_sta_disconnect STA 00:99:00:00:00:a8
1326479922.733455: hostapd_wpa_auth_disconnect: WPA authenticator requests disconnect: STA 00:99:00:00:00:a8 reason 2
1326479922.734127: WPA: 00:99:00:00:00:a8 WPA_PTK entering state DISCONNECTED
1326479922.734183: WPA: 00:99:00:00:00:a8 WPA_PTK entering state INITIALIZE
1326479922.734325: wpa_driver_nl80211_set_key: ifindex=10 alg=0 addr=0x853a8a0 key_idx=0 set_tx=1 seq_len=0 key_len=0
1326479922.734386:    addr=00:99:00:00:00:a8
1326479922.735069: 1326479922.735140: vap0: Event TX_STATUS (18) received
1326479922.735204: mgmt::deauth cb
1326479922.735236: STA 00:99:00:00:00:a8 acknowledged deauth
1326479922.735308: Removing STA 00:99:00:00:00:a8 from kernel driver

Thanks,
Ben

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