No subject


Sat Oct 15 18:41:40 EDT 2011


e authentication frames from the AP.  However, I guess since all traffic is=
 stalled, perhaps this is just a symptom of the root problem.  I'm trying t=
o determine if this might be some kind of unicast vs. multicast, or bridge,=
 or nl80211, or bandwidth issue.

I have captured normal and debug logs + tcpdump output both during normal o=
peration and during the problem, and would very much appreciate any help an=
yone would be willing to offer!

Configuration snippet:

interface=3Dath1
driver=3Dnl80211
bridge=3Deth2
ssid=3DWG-Switzerland
ignore_broadcast_ssid=3D0
bssid=3D00:90:7f:8b:13:e6
wpa=3D2
eapol_version=3D2
wpa_passphrase=3D*********
wpa_key_mgmt=3DWPA-PSK
wpa_pairwise=3DCCMP
beacon_int=3D200
wpa_group_rekey=3D86400
wpa_gmk_rekey=3D86400
wpa_strict_rekey=3D0
hw_mode=3Dg
ieee80211n=3D1
channel=3D5
rts_threshold=3D2346
fragm_threshold=3D2346
wme_enabled=3D1

and the bridge looks like this:

bridge name	bridge id		STP enabled	interfaces
eth2		8000.00907f8b13e2	no		eth2-phy
							ath1


Here is what a normal association and authentication looks like, when the p=
roblem is not occurring:

Syslog output:

Feb  2 12:18:39 2012 My-AP local3.debug hostapd: ath1: STA f8:1e:df:e1:ea:7=
e IEEE 802.11: authentication OK (open system)
Feb  2 12:18:39 2012 My-AP local3.debug hostapd: ath1: STA f8:1e:df:e1:ea:7=
e WPA: event 0 notification
Feb  2 12:18:39 2012 My-AP local3.debug hostapd: ath1: STA f8:1e:df:e1:ea:7=
e MLME: MLME-AUTHENTICATE.indication(f8:1e:df:e1:ea:7e, OPEN_SYSTEM)
Feb  2 12:18:39 2012 My-AP local3.debug hostapd: ath1: STA f8:1e:df:e1:ea:7=
e MLME: MLME-DELETEKEYS.request(f8:1e:df:e1:ea:7e)
Feb  2 12:18:39 2012 My-AP local3.info hostapd: ath1: STA f8:1e:df:e1:ea:7e=
 IEEE 802.11: authenticated
Feb  2 12:18:39 2012 My-AP local3.debug hostapd: ath1: STA f8:1e:df:e1:ea:7=
e IEEE 802.11: association OK (aid 15)
Feb  2 12:18:39 2012 My-AP local3.info hostapd: ath1: STA f8:1e:df:e1:ea:7e=
 IEEE 802.11: associated (aid 15)
Feb  2 12:18:39 2012 My-AP local3.debug hostapd: ath1: STA f8:1e:df:e1:ea:7=
e MLME: MLME-ASSOCIATE.indication(f8:1e:df:e1:ea:7e)
Feb  2 12:18:39 2012 My-AP local3.debug hostapd: ath1: STA f8:1e:df:e1:ea:7=
e MLME: MLME-DELETEKEYS.request(f8:1e:df:e1:ea:7e)
Feb  2 12:18:39 2012 My-AP local3.debug hostapd: ath1: STA f8:1e:df:e1:ea:7=
e WPA: event 1 notification
Feb  2 12:18:39 2012 My-AP local3.debug hostapd: ath1: STA f8:1e:df:e1:ea:7=
e WPA: event 4 notification
Feb  2 12:18:39 2012 My-AP local3.debug hostapd: ath1: STA f8:1e:df:e1:ea:7=
e WPA: sending 1/4 msg of 4-Way Handshake
Feb  2 12:18:39 2012 My-AP local3.debug hostapd: ath1: STA f8:1e:df:e1:ea:7=
e WPA: received EAPOL-Key frame (2/4 Pairwise)
Feb  2 12:18:39 2012 My-AP local3.debug hostapd: ath1: STA f8:1e:df:e1:ea:7=
e WPA: sending 3/4 msg of 4-Way Handshake
Feb  2 12:18:39 2012 My-AP local3.debug hostapd: ath1: STA f8:1e:df:e1:ea:7=
e WPA: received EAPOL-Key frame (4/4 Pairwise)
Feb  2 12:18:39 2012 My-AP local3.debug hostapd: ath1: STA f8:1e:df:e1:ea:7=
e IEEE 802.1X: authorizing port
Feb  2 12:18:39 2012 My-AP local3.info hostapd: ath1: STA f8:1e:df:e1:ea:7e=
 RADIUS: starting accounting session 4F2AECAD-0000002D
Feb  2 12:18:39 2012 My-AP local3.info hostapd: ath1: STA f8:1e:df:e1:ea:7e=
 WPA: pairwise key handshake completed (RSN)

Debug log output:

1328213919.439887: mgmt::auth
1328213919.439908: authentication: STA=3Df8:1e:df:e1:ea:7e auth_alg=3D0 aut=
h_transaction=3D1 status_code=3D0 wep=3D0
1328213919.439962: ath1: STA f8:1e:df:e1:ea:7e IEEE 802.11: authentication =
OK (open system)
1328213919.440071: ath1: STA f8:1e:df:e1:ea:7e WPA: event 0 notification
1328213919.440177: wpa_driver_nl80211_set_key: ifindex=3D13 alg=3D0 addr=3D=
0x100a8448 key_idx=3D0 set_tx=3D1 seq_len=3D0 key_len=3D0
1328213919.440209:    addr=3Df8:1e:df:e1:ea:7e
1328213919.449917: wpa_driver_nl80211_set_key: ifindex=3D13 alg=3D0 addr=3D=
0x100a8448 key_idx=3D0 set_tx=3D1 seq_len=3D0 key_len=3D0
1328213919.449949:    addr=3Df8:1e:df:e1:ea:7e
1328213919.450034: authentication reply: STA=3Df8:1e:df:e1:ea:7e auth_alg=
=3D0 auth_transaction=3D2 resp=3D0 (IE len=3D0)
1328213919.451090: mgmt::auth cb
1328213919.451127: ath1: STA f8:1e:df:e1:ea:7e IEEE 802.11: authenticated
1328213919.453270: mgmt::assoc_req
1328213919.453285: association request: STA=3Df8:1e:df:e1:ea:7e capab_info=
=3D0x431 listen_interval=3D10
1328213919.453303: unknown vendor specific information element ignored (ven=
dor OUI 00:10:18 len=3D9)
1328213919.453317: WMM IE - hexdump(len=3D7): 00 50 f2 02 00 01 00
1328213919.453335: Validating WMM IE: OUI 00:50:f2  OUI type 2  OUI sub-typ=
e 0  version 1  QoS info 0x0
1328213919.453365:   old AID 15
1328213919.453372: HT: STA f8:1e:df:e1:ea:7e HT Capabilities Info: 0x186c
1328213919.453384: update_sta_ht STA f8:1e:df:e1:ea:7e - no greenfield, num=
 of non-gf stations 9
1328213919.453395: update_sta_ht STA f8:1e:df:e1:ea:7e - 20 MHz HT, num of =
20MHz HT STAs 20
1328213919.453407: hostapd_ht_operation_update current operation mode=3D0x1=
7
1328213919.453414: hostapd_ht_operation_update new operation mode=3D0x17 ch=
anges=3D0
1328213919.453439: ath1: STA f8:1e:df:e1:ea:7e IEEE 802.11: association OK =
(aid 15)
1328213919.455650: mgmt::assoc_resp cb
1328213919.455685: ath1: STA f8:1e:df:e1:ea:7e IEEE 802.11: associated (aid=
 15)
1328213919.456541: wpa_driver_nl80211_set_key: ifindex=3D13 alg=3D0 addr=3D=
0x100a8448 key_idx=3D0 set_tx=3D1 seq_len=3D0 key_len=3D0
1328213919.456575:    addr=3Df8:1e:df:e1:ea:7e
1328213919.481439: ath1: STA f8:1e:df:e1:ea:7e WPA: event 1 notification
1328213919.481899: wpa_driver_nl80211_set_key: ifindex=3D13 alg=3D0 addr=3D=
0x100a8448 key_idx=3D0 set_tx=3D1 seq_len=3D0 key_len=3D0
1328213919.481931:    addr=3Df8:1e:df:e1:ea:7e
1328213919.482056: ath1: STA f8:1e:df:e1:ea:7e WPA: event 4 notification
1328213919.482378: wpa_driver_nl80211_set_key: ifindex=3D13 alg=3D0 addr=3D=
0x100a8448 key_idx=3D0 set_tx=3D1 seq_len=3D0 key_len=3D0
1328213919.483235:    addr=3Df8:1e:df:e1:ea:7e
1328213919.483338: WPA: f8:1e:df:e1:ea:7e WPA_PTK entering state AUTHENTICA=
TION2
1328213919.483357: WPA: f8:1e:df:e1:ea:7e WPA_PTK entering state INITPSK
1328213919.483370: WPA: f8:1e:df:e1:ea:7e WPA_PTK entering state PTKSTART
1328213919.483401: ath1: STA f8:1e:df:e1:ea:7e WPA: sending 1/4 msg of 4-Wa=
y Handshake
1328213919.483483: WPA: Send EAPOL(version=3D2 secure=3D0 mic=3D0 ack=3D1 i=
nstall=3D0 pairwise=3D8 kde_len=3D0 keyidx=3D0 encr=3D0)
1328213919.483700: nl80211: Event message available
1328213919.483742: nl80211: Ignored unknown event (cmd=3D20)
1328213919.483801: nl80211: Event message available
1328213919.483833: nl80211: Ignored unknown event (cmd=3D19)
1328213919.495637: IEEE 802.1X: f8:1e:df:e1:ea:7e TX status - version=3D2 t=
ype=3D3 length=3D95 - ack=3D1
1328213919.498559: mgmt::action cb
1328213919.502058: IEEE 802.1X: 121 bytes from f8:1e:df:e1:ea:7e
1328213919.502074:    IEEE 802.1X: version=3D1 type=3D3 length=3D117
1328213919.502124: ath1: STA f8:1e:df:e1:ea:7e WPA: received EAPOL-Key fram=
e (2/4 Pairwise)
1328213919.502479: WPA: f8:1e:df:e1:ea:7e WPA_PTK entering state PTKCALCNEG=
OTIATING
1328213919.502601: WPA: PTK derivation - A1=3D00:90:7f:8b:13:e6 A2=3Df8:1e:=
df:e1:ea:7e
1328213919.502617: WPA: PMK - hexdump(len=3D32): b9 ef 5a 26 36 fd 0b da 39=
 79 cut cut
1328213919.502668: WPA: PTK - hexdump(len=3D48): 2c 57 62 ba 55 84 60 45 50=
 7b cut cut
1328213919.502779: WPA: f8:1e:df:e1:ea:7e WPA_PTK entering state PTKCALCNEG=
OTIATING2
1328213919.502792: WPA: f8:1e:df:e1:ea:7e WPA_PTK entering state PTKINITNEG=
OTIATING
1328213919.503023: ath1: STA f8:1e:df:e1:ea:7e WPA: sending 3/4 msg of 4-Wa=
y Handshake
1328213919.503321: WPA: Send EAPOL(version=3D2 secure=3D1 mic=3D1 ack=3D1 i=
nstall=3D1 pairwise=3D8 kde_len=3D46 keyidx=3D1 encr=3D1)
1328213919.503349: Plaintext EAPOL-Key Key Data - hexdump(len=3D56): (I cut=
 this out!)
1328213919.505190: IEEE 802.1X: f8:1e:df:e1:ea:7e TX status - version=3D2 t=
ype=3D3 length=3D151 - ack=3D1
1328213919.507047: IEEE 802.1X: 99 bytes from f8:1e:df:e1:ea:7e
1328213919.507063:    IEEE 802.1X: version=3D1 type=3D3 length=3D95
1328213919.507102: ath1: STA f8:1e:df:e1:ea:7e WPA: received EAPOL-Key fram=
e (4/4 Pairwise)
1328213919.507495: WPA: f8:1e:df:e1:ea:7e WPA_PTK entering state PTKINITDON=
E
1328213919.507577: wpa_driver_nl80211_set_key: ifindex=3D13 alg=3D3 addr=3D=
0x100a8448 key_idx=3D0 set_tx=3D1 seq_len=3D0 key_len=3D16
1328213919.507611:    addr=3Df8:1e:df:e1:ea:7e
1328213919.507888: ath1: STA f8:1e:df:e1:ea:7e IEEE 802.1X: authorizing por=
t
1328213919.508467: ath1: STA f8:1e:df:e1:ea:7e WPA: pairwise key handshake =
completed (RSN)
1328213919.534808: mgmt::action cb
1328213919.546594: mgmt::action cb
1328213919.626467: unknown vendor specific information element ignored (ven=
dor OUI 00:10:18 len=3D9)
1328213919.710166: mgmt::action cb

tcpdump output (from the AP mon.ath1 interface):

12:18:39.439729 1.0 Mb/s 2432 MHz 11g 314us BSSID:00:90:7f:8b:13:e6 DA:00:9=
0:7f:8b:13:e6 SA:f8:1e:df:e1:ea:7e Authentication (Open System)-1: Succesfu=
l[|802.11]
       0x0000:  0000 0100 0000 dd09 0010 1802 0010 0100  ................
       0x0010:  00                                       .
12:18:39.450078 fragmented [bit 14] 0us BSSID:00:90:7f:8b:13:e6 DA:f8:1e:df=
:e1:ea:7e SA:00:90:7f:8b:13:e6 Authentication (Open System)-2:
        0x0000:  0000 0200 0000                           ......
12:18:39.451002 1.0 Mb/s [bit 15] 314us BSSID:00:90:7f:8b:13:e6 DA:f8:1e:df=
:e1:ea:7e SA:00:90:7f:8b:13:e6 Authentication (Open System)-2:=20
       0x0000:  0000 0200 0000                           ......
12:18:39.453165 1.0 Mb/s 2432 MHz 11g 314us BSSID:00:90:7f:8b:13:e6 DA:00:9=
0:7f:8b:13:e6 SA:f8:1e:df:e1:ea:7e Assoc Request (WG-Switzerland) [1.0* 2.0=
* 5.5* 11.0* 18.0 24.0 36.0 54.0 Mbit][|802.11]
       0x0000:  3104 0a00 000e 5747 2d53 7769 747a 6572  1.....WG-Switzer
       0x0010:  6c61 6e64 0108 8284 8b96 2430 486c 2102  land......$0Hl!.
       0x0020:  0713 2402 010b 3014 0100 000f ac04 0100  ..$...0.........
       0x0030:  000f ac04 0100 000f ac02 0000 3204 0c12  ............2...
       0x0040:  1860 2d1a 6c18 1bff ff00 0000 0000 0000  .`-.l...........
       0x0050:  0000 0000 0000 0000 0000 0000 0000 dd09  ................
       0x0060:  0010 1802 0010 0100 00dd 1e00 904c 336c  .............L3l
       0x0070:  181b ffff 0000 0000 0000 0000 0000 0000  ................
       0x0080:  0000 0000 0000 0000 00dd 0700 50f2 0200  ............P...
       0x0090:  0100                                     ..
12:18:39.453813 wep fragmented [bit 14] 0us BSSID:00:90:7f:8b:13:e6 DA:f8:1=
e:df:e1:ea:7e SA:00:90:7f:8b:13:e6 Assoc Response AID(f) : PRIVACY : Succes=
ful[|802.11]
       0x0000:  1104 0000 0fc0 0108 8284 8b96 0c12 1824  ...............$
       0x0010:  3204 3048 606c 2d1a 0c00 1bff ffff 0000  2.0H`l-.........
       0x0020:  0000 0000 0000 0001 0000 0000 0000 0000  ................
       0x0030:  0000 3d16 0500 1700 0000 0000 0000 0000  ..=3D.............
       0x0040:  0000 0000 0000 0000 0000 dd18 0050 f202  .............P..
       0x0050:  0101 0000 03a4 0000 27a4 0000 4243 5e00  ........'...BC^.
       0x0060:  6232 2f00                                b2/.
12:18:39.455573 1.0 Mb/s [bit 15] 314us BSSID:00:90:7f:8b:13:e6 DA:f8:1e:df=
:e1:ea:7e SA:00:90:7f:8b:13:e6 Assoc Response AID(f) : PRIVACY : Succesful[=
|802.11]
       0x0000:  1104 0000 0fc0 0108 8284 8b96 0c12 1824  ...............$
       0x0010:  3204 3048 606c 2d1a 0c00 1bff ffff 0000  2.0H`l-.........
       0x0020:  0000 0000 0000 0001 0000 0000 0000 0000  ................
       0x0030:  0000 3d16 0500 1700 0000 0000 0000 0000  ..=3D.............
       0x0040:  0000 0000 0000 0000 0000 dd18 0050 f202  .............P..
       0x0050:  0101 0000 03a4 0000 27a4 0000 4243 5e00  ........'...BC^.
       0x0060:  6232 2f00                                b2/.
12:18:39.483540 fragmented [bit 14] 0us DA:f8:1e:df:e1:ea:7e BSSID:00:90:7f=
:8b:13:e6 SA:00:90:7f:8b:13:e6 LLC, dsap SNAP (0xaa) Individual, ssap SNAP =
(0xaa) Command, ctrl 0x03: oui Ethernet (0x000000), ethertype EAPOL (0x888e=
): EAPOL key (3) v2, len 95
       0x0000:  aaaa 0300 0000 888e 0203 005f 0200 8a00  ..........._....
       0x0010:  1000 0000 0000 0000 05c0 4bd4 50b5 cb48  ..........K.P..H
       0x0020:  I cut this part out!
       0x0030:  I cut this part out!
       0x0040:  0000 0000 0000 0000 0000 0000 0000 0000  ................
       0x0050:  0000 0000 0000 0000 0000 0000 0000 0000  ................
       0x0060:  0000 0000 0000 0000 0000 00              ...........
12:18:39.495520 0.0 Mb/s [bit 15] 0us DA:f8:1e:df:e1:ea:7e BSSID:00:90:7f:8=
b:13:e6 SA:00:90:7f:8b:13:e6 LLC, dsap SNAP (0xaa) Individual, ssap SNAP (0=
xaa) Command, ctrl 0x03: oui Ethernet (0x000000), ethertype EAPOL (0x888e):=
 EAPOL key (3) v2, len 95
       0x0000:  aaaa 0300 0000 888e 0203 005f 0200 8a00  ..........._....
       0x0010:  1000 0000 0000 0000 05c0 4bd4 50b5 cb48  ..........K.P..H
       0x0020:  I cut this part out!
       0x0030:  I cut this part out!
       0x0040:  0000 0000 0000 0000 0000 0000 0000 0000  ................
       0x0050:  0000 0000 0000 0000 0000 0000 0000 0000  ................
       0x0060:  0000 0000 0000 0000 0000 00              ...........
12:18:39.498478 1.0 Mb/s [bit 15] 314us BSSID:00:90:7f:8b:13:e6 DA:f8:1e:df=
:e1:ea:7e SA:00:90:7f:8b:13:e6 Action: BA ADDBA Response
       0x0000:  0301 8900 0002 1000 00                   .........
12:18:39.503598 fragmented [bit 14] 0us DA:f8:1e:df:e1:ea:7e BSSID:00:90:7f=
:8b:13:e6 SA:00:90:7f:8b:13:e6 LLC, dsap SNAP (0xaa) Individual, ssap SNAP =
(0xaa) Command, ctrl 0x03: oui Ethernet (0x000000), ethertype EAPOL (0x888e=
): EAPOL key (3) v2, len 151
       0x0000:  aaaa 0300 0000 888e 0203 0097 0213 ca00  ................
       0x0010:  1000 0000 0000 0000 06c0 4bd4 50b5 cb48  ..........K.P..H
       0x0020:  I cut this part out!
       0x0030:  I cut this part out!
       0x0040:  0000 0000 0000 0000 0092 2a00 0000 0000  ..........*.....
       0x0050:  0000 0000 0000 0000 00ea 8377 5de6 4ae3  ...........w].J.
       0x0060:  af8a 5cf5 16cd 5d04 1c00 385d 9cd6 a6a7  ..\...]...8]....
       0x0070:  6a72 35d8 b7e8 4753 1714 3cc7 8474 5cc0  jr5...GS..<..t\.
       0x0080:  870b d0d1 b7a9 e40f 0b9b 34b7 e9b1 0de8  ..........4.....
       0x0090:  256f bf7e 6d62 3178 6f13 dbb2 6715 52fd  %o.~mb1xo...g.R.
       0x00a0:  9ce4 d0                                  ...
12:18:39.505104 0.0 Mb/s [bit 15] 0us DA:f8:1e:df:e1:ea:7e BSSID:00:90:7f:8=
b:13:e6 SA:00:90:7f:8b:13:e6 LLC, dsap SNAP (0xaa) Individual, ssap SNAP (0=
xaa) Command, ctrl 0x03: oui Ethernet (0x000000), ethertype EAPOL (0x888e):=
 EAPOL key (3) v2, len 151
       0x0000:  aaaa 0300 0000 888e 0203 0097 0213 ca00  ................
       0x0010:  1000 0000 0000 0000 06c0 4bd4 50b5 cb48  ..........K.P..H
       0x0020:  I cut this part out!
       0x0030:  I cut this part out!
       0x0040:  0000 0000 0000 0000 0092 2a00 0000 0000  ..........*.....
       0x0050:  0000 0000 0000 0000 00ea 8377 5de6 4ae3  ...........w].J.
       0x0060:  af8a 5cf5 16cd 5d04 1c00 385d 9cd6 a6a7  ..\...]...8]....
       0x0070:  6a72 35d8 b7e8 4753 1714 3cc7 8474 5cc0  jr5...GS..<..t\.
       0x0080:  870b d0d1 b7a9 e40f 0b9b 34b7 e9b1 0de8  ..........4.....
       0x0090:  256f bf7e 6d62 3178 6f13 dbb2 6715 52fd  %o.~mb1xo...g.R.
       0x00a0:  9ce4 d0                                  ...
12:18:39.534681 1.0 Mb/s [bit 15] 314us BSSID:00:90:7f:8b:13:e6 DA:f8:1e:df=
:e1:ea:7e SA:00:90:7f:8b:13:e6 Action: BA ADDBA Request
       0x0000:  0300 0102 0000 0010 00                   .........


* * * * * * * * * * * * * * * * * * *

[...continued in part 2...]

I've tried capturing the client's side of the conversation, but so far have=
 not been able to.

Thanks for reading this far and for any help or advice!

-bp





More information about the HostAP mailing list