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:

[...included in part 1...]

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

And here is what it looks like during the traffic-stall/failed association/=
authentication problem:

Feb  2 12:28:56 2012 WG-Switzerland local3.debug hostapd: ath1: STA f8:1e:d=
f:e1:ea:7e IEEE 802.11: authentication OK (open system)
Feb  2 12:28:56 2012 WG-Switzerland local3.debug hostapd: ath1: STA f8:1e:d=
f:e1:ea:7e MLME: MLME-AUTHENTICATE.indication(f8:1e:df:e1:ea:7e, OPEN_SYSTE=
M)
Feb  2 12:28:56 2012 WG-Switzerland local3.debug hostapd: ath1: STA f8:1e:d=
f:e1:ea:7e MLME: MLME-DELETEKEYS.request(f8:1e:df:e1:ea:7e)
Feb  2 12:28:56 2012 WG-Switzerland local3.info hostapd: ath1: STA f8:1e:df=
:e1:ea:7e IEEE 802.11: authenticated
Feb  2 12:28:56 2012 WG-Switzerland local3.debug hostapd: ath1: STA f8:1e:d=
f:e1:ea:7e IEEE 802.11: association OK (aid 9)
Feb  2 12:28:56 2012 WG-Switzerland local3.info hostapd: ath1: STA f8:1e:df=
:e1:ea:7e IEEE 802.11: associated (aid 9)
Feb  2 12:28:56 2012 WG-Switzerland local3.debug hostapd: ath1: STA f8:1e:d=
f:e1:ea:7e MLME: MLME-ASSOCIATE.indication(f8:1e:df:e1:ea:7e)
Feb  2 12:28:56 2012 WG-Switzerland local3.debug hostapd: ath1: STA f8:1e:d=
f:e1:ea:7e MLME: MLME-DELETEKEYS.request(f8:1e:df:e1:ea:7e)
Feb  2 12:28:56 2012 WG-Switzerland local3.debug hostapd: ath1: STA f8:1e:d=
f:e1:ea:7e WPA: event 1 notification
Feb  2 12:28:56 2012 WG-Switzerland local3.debug hostapd: ath1: STA f8:1e:d=
f:e1:ea:7e WPA: start authentication
Feb  2 12:28:56 2012 WG-Switzerland local3.debug hostapd: ath1: STA f8:1e:d=
f:e1:ea:7e IEEE 802.1X: unauthorizing port
Feb  2 12:28:56 2012 WG-Switzerland local3.debug hostapd: ath1: STA f8:1e:d=
f:e1:ea:7e WPA: sending 1/4 msg of 4-Way Handshake
Feb  2 12:28:56 2012 WG-Switzerland local3.debug hostapd: ath1: STA f8:1e:d=
f:e1:ea:7e WPA: EAPOL-Key timeout
Feb  2 12:28:56 2012 WG-Switzerland local3.debug hostapd: ath1: STA f8:1e:d=
f:e1:ea:7e WPA: sending 1/4 msg of 4-Way Handshake
Feb  2 12:28:57 2012 WG-Switzerland local3.debug hostapd: ath1: STA f8:1e:d=
f:e1:ea:7e WPA: EAPOL-Key timeout
Feb  2 12:28:57 2012 WG-Switzerland local3.debug hostapd: ath1: STA f8:1e:d=
f:e1:ea:7e WPA: sending 1/4 msg of 4-Way Handshake
Feb  2 12:28:58 2012 WG-Switzerland local3.debug hostapd: ath1: STA f8:1e:d=
f:e1:ea:7e WPA: EAPOL-Key timeout
Feb  2 12:28:58 2012 WG-Switzerland local3.debug hostapd: ath1: STA f8:1e:d=
f:e1:ea:7e WPA: sending 1/4 msg of 4-Way Handshake
Feb  2 12:28:59 2012 WG-Switzerland local3.debug hostapd: ath1: STA f8:1e:d=
f:e1:ea:7e WPA: EAPOL-Key timeout
Feb  2 12:28:59 2012 WG-Switzerland local3.debug hostapd: ath1: STA f8:1e:d=
f:e1:ea:7e IEEE 802.1X: unauthorizing port
Feb  2 12:28:59 2012 WG-Switzerland local3.info hostapd: ath1: STA f8:1e:df=
:e1:ea:7e IEEE 802.11: deauthenticated due to local deauth request

Debug log output:

1328214536.456760: STA f8:1e:df:e1:ea:7e sent probe request for our SSID
1328214536.458806: mgmt::proberesp cb
1328214536.545170: mgmt::auth
1328214536.545189: authentication: STA=3Df8:1e:df:e1:ea:7e auth_alg=3D0 aut=
h_transaction=3D1 status_code=3D0 wep=3D0
1328214536.545208:   New STA
1328214536.545255: ath1: STA f8:1e:df:e1:ea:7e IEEE 802.11: authentication =
OK (open system)
1328214536.546208: authentication reply: STA=3Df8:1e:df:e1:ea:7e auth_alg=
=3D0 auth_transaction=3D2 resp=3D0 (IE len=3D0)
1328214536.548071: mgmt::auth cb
1328214536.548105: ath1: STA f8:1e:df:e1:ea:7e IEEE 802.11: authenticated
1328214536.550284: mgmt::assoc_req
1328214536.550299: association request: STA=3Df8:1e:df:e1:ea:7e capab_info=
=3D0x431 listen_interval=3D10
1328214536.550317: unknown vendor specific information element ignored (ven=
dor OUI 00:10:18 len=3D9)
1328214536.550331: WMM IE - hexdump(len=3D7): 00 50 f2 02 00 01 00
1328214536.550349: Validating WMM IE: OUI 00:50:f2  OUI type 2  OUI sub-typ=
e 0  version 1  QoS info 0x0
1328214536.550388:   new AID 9
1328214536.550396: HT: STA f8:1e:df:e1:ea:7e HT Capabilities Info: 0x186c
1328214536.550407: update_sta_ht STA f8:1e:df:e1:ea:7e - no greenfield, num=
 of non-gf stations 9
1328214536.550419: update_sta_ht STA f8:1e:df:e1:ea:7e - 20 MHz HT, num of =
20MHz HT STAs 20
1328214536.550431: hostapd_ht_operation_update current operation mode=3D0x1=
7
1328214536.550438: hostapd_ht_operation_update new operation mode=3D0x17 ch=
anges=3D0
1328214536.550462: ath1: STA f8:1e:df:e1:ea:7e IEEE 802.11: association OK =
(aid 9)
1328214536.552644: mgmt::assoc_resp cb
1328214536.552681: ath1: STA f8:1e:df:e1:ea:7e IEEE 802.11: associated (aid=
 9)
1328214536.553604: wpa_driver_nl80211_set_key: ifindex=3D13 alg=3D0 addr=3D=
0x100a9438 key_idx=3D0 set_tx=3D1 seq_len=3D0 key_len=3D0
1328214536.553645:    addr=3Df8:1e:df:e1:ea:7e
1328214536.561794: ath1: STA f8:1e:df:e1:ea:7e WPA: event 1 notification
1328214536.562207: wpa_driver_nl80211_set_key: ifindex=3D13 alg=3D0 addr=3D=
0x100a9438 key_idx=3D0 set_tx=3D1 seq_len=3D0 key_len=3D0
1328214536.562239:    addr=3Df8:1e:df:e1:ea:7e
1328214536.562360: ath1: STA f8:1e:df:e1:ea:7e WPA: start authentication
1328214536.562637: WPA: f8:1e:df:e1:ea:7e WPA_PTK entering state INITIALIZE
1328214536.562702: wpa_driver_nl80211_set_key: ifindex=3D13 alg=3D0 addr=3D=
0x100a9438 key_idx=3D0 set_tx=3D1 seq_len=3D0 key_len=3D0
1328214536.562729:    addr=3Df8:1e:df:e1:ea:7e
1328214536.562935: ath1: STA f8:1e:df:e1:ea:7e IEEE 802.1X: unauthorizing p=
ort
1328214536.563207: WPA: f8:1e:df:e1:ea:7e WPA_PTK_GROUP entering state IDLE
1328214536.563226: WPA: f8:1e:df:e1:ea:7e WPA_PTK entering state AUTHENTICA=
TION
1328214536.563241: WPA: f8:1e:df:e1:ea:7e WPA_PTK entering state AUTHENTICA=
TION2
1328214536.563254: WPA: f8:1e:df:e1:ea:7e WPA_PTK entering state INITPSK
1328214536.563267: WPA: f8:1e:df:e1:ea:7e WPA_PTK entering state PTKSTART
1328214536.563294: ath1: STA f8:1e:df:e1:ea:7e WPA: sending 1/4 msg of 4-Wa=
y Handshake
1328214536.563532: WPA: Send EAPOL(version=3D2 secure=3D0 mic=3D0 ack=3D1 i=
nstall=3D0 pairwise=3D8 kde_len=3D0 keyidx=3D0 encr=3D0)
1328214536.563629: nl80211: Event message available
1328214536.563670: nl80211: Ignored unknown event (cmd=3D19)
1328214536.663744: ath1: STA f8:1e:df:e1:ea:7e WPA: EAPOL-Key timeout
1328214536.664125: WPA: f8:1e:df:e1:ea:7e WPA_PTK entering state PTKSTART
1328214536.664158: ath1: STA f8:1e:df:e1:ea:7e WPA: sending 1/4 msg of 4-Wa=
y Handshake
1328214536.664397: WPA: Send EAPOL(version=3D2 secure=3D0 mic=3D0 ack=3D1 i=
nstall=3D0 pairwise=3D8 kde_len=3D0 keyidx=3D0 encr=3D0)
1328214537.664675: ath1: STA f8:1e:df:e1:ea:7e WPA: EAPOL-Key timeout
1328214537.665048: WPA: f8:1e:df:e1:ea:7e WPA_PTK entering state PTKSTART
1328214537.665081: ath1: STA f8:1e:df:e1:ea:7e WPA: sending 1/4 msg of 4-Wa=
y Handshake
1328214537.665318: WPA: Send EAPOL(version=3D2 secure=3D0 mic=3D0 ack=3D1 i=
nstall=3D0 pairwise=3D8 kde_len=3D0 keyidx=3D0 encr=3D0)
1328214538.665477: ath1: STA f8:1e:df:e1:ea:7e WPA: EAPOL-Key timeout
1328214538.665877: WPA: f8:1e:df:e1:ea:7e WPA_PTK entering state PTKSTART
1328214538.665911: ath1: STA f8:1e:df:e1:ea:7e WPA: sending 1/4 msg of 4-Wa=
y Handshake
1328214538.666152: WPA: Send EAPOL(version=3D2 secure=3D0 mic=3D0 ack=3D1 i=
nstall=3D0 pairwise=3D8 kde_len=3D0 keyidx=3D0 encr=3D0)

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

12:28:56.436388 1.0 Mb/s 2432 MHz 11g 0us BSSID:ff:ff:ff:ff:ff:ff DA:ff:ff:=
ff:ff:ff:ff SA:f8:1e:df:e1:ea:7e Probe Request (WG-Switzerland) [1.0 2.0 5.=
5 11.0 Mbit][|802.11]
       0x0000:  000e 5747 2d53 7769 747a 6572 6c61 6e64  ..WG-Switzerland
       0x0010:  0104 0204 0b16 3208 0c12 1824 3048 606c  ......2....$0H`l
       0x0020:  2d1a 6c18 1bff ff00 0000 0000 0000 0000  -.l.............
       0x0030:  0000 0000 0000 0000 0000 0000 dd09 0010  ................
       0x0040:  1802 0010 0100 00dd 1e00 904c 336c 181b  ...........L3l..
       0x0050:  ffff 0000 0000 0000 0000 0000 0000 0000  ................
       0x0060:  0000 0000 0000 00                        .......
12:28:56.437483 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 Probe Response (WG-Switzerland) [1.0* 2.=
0* 5.5* 11.0* 6.0 9.0 12.0 18.0 Mbit] CH: 5, PRIVACY[|802.11]
       0x0000:  0000 0000 0000 0000 c800 1104 000e 5747  ..............WG
       0x0010:  2d53 7769 747a 6572 6c61 6e64 0108 8284  -Switzerland....
       0x0020:  8b96 0c12 1824 0301 052a 0104 3204 3048  .....$...*..2.0H
       0x0030:  606c 3014 0100 000f ac04 0100 000f ac04  `l0.............
       0x0040:  0100 000f ac02 0c00 2d1a 0c00 1bff ffff  ........-.......
       0x0050:  0000 0000 0000 0000 0001 0000 0000 0000  ................
       0x0060:  0000 0000 3d16 0500 1700 0000 0000 0000  ....=3D...........
       0x0070:  0000 0000 0000 0000 0000 0000 dd18 0050  ...............P
       0x0080:  f202 0101 0000 03a4 0000 27a4 0000 4243  ..........'...BC
       0x0090:  5e00 6232 2f00                           ^.b2/.
12:28:56.439544 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 Probe Response (WG-Switzerland) [1.0* 2.0* 5=
.5* 11.0* 6.0 9.0 12.0 18.0 Mbit] CH: 5, PRIVACY[|802.11]
       0x0000:  0000 0000 0000 0000 c800 1104 000e 5747  ..............WG
       0x0010:  2d53 7769 747a 6572 6c61 6e64 0108 8284  -Switzerland....
       0x0020:  8b96 0c12 1824 0301 052a 0104 3204 3048  .....$...*..2.0H
       0x0030:  606c 3014 0100 000f ac04 0100 000f ac04  `l0.............
       0x0040:  0100 000f ac02 0c00 2d1a 0c00 1bff ffff  ........-.......
       0x0050:  0000 0000 0000 0000 0001 0000 0000 0000  ................
       0x0060:  0000 0000 3d16 0500 1700 0000 0000 0000  ....=3D...........
       0x0070:  0000 0000 0000 0000 0000 0000 dd18 0050  ...............P
       0x0080:  f202 0101 0000 03a4 0000 27a4 0000 4243  ..........'...BC
       0x0090:  5e00 6232 2f00                           ^.b2/.
12:28:56.456558 1.0 Mb/s 2432 MHz 11g 0us BSSID:ff:ff:ff:ff:ff:ff DA:ff:ff:=
ff:ff:ff:ff SA:f8:1e:df:e1:ea:7e Probe Request (WG-Switzerland) [1.0 2.0 5.=
5 11.0 Mbit][|802.11]
       0x0000:  000e 5747 2d53 7769 747a 6572 6c61 6e64  ..WG-Switzerland
       0x0010:  0104 0204 0b16 3208 0c12 1824 3048 606c  ......2....$0H`l
       0x0020:  2d1a 6c18 1bff ff00 0000 0000 0000 0000  -.l.............
       0x0030:  0000 0000 0000 0000 0000 0000 dd09 0010  ................
       0x0040:  1802 0010 0100 00dd 1e00 904c 336c 181b  ...........L3l..
       0x0050:  ffff 0000 0000 0000 0000 0000 0000 0000  ................
       0x0060:  0000 0000 0000 00                        .......
12:28:56.456707 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 Probe Response (WG-Switzerland) [1.0* 2.=
0* 5.5* 11.0* 6.0 9.0 12.0 18.0 Mbit] CH: 5, PRIVACY[|802.11]
       0x0000:  0000 0000 0000 0000 c800 1104 000e 5747  ..............WG
       0x0010:  2d53 7769 747a 6572 6c61 6e64 0108 8284  -Switzerland....
       0x0020:  8b96 0c12 1824 0301 052a 0104 3204 3048  .....$...*..2.0H
       0x0030:  606c 3014 0100 000f ac04 0100 000f ac04  `l0.............
       0x0040:  0100 000f ac02 0c00 2d1a 0c00 1bff ffff  ........-.......
       0x0050:  0000 0000 0000 0000 0001 0000 0000 0000  ................
       0x0060:  0000 0000 3d16 0500 1700 0000 0000 0000  ....=3D...........
       0x0070:  0000 0000 0000 0000 0000 0000 dd18 0050  ...............P
       0x0080:  f202 0101 0000 03a4 0000 27a4 0000 4243  ..........'...BC
       0x0090:  5e00 6232 2f00                           ^.b2/.
12:28:56.458753 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 Probe Response (WG-Switzerland) [1.0* 2.0* 5=
.5* 11.0* 6.0 9.0 12.0 18.0 Mbit] CH: 5, PRIVACY[|802.11]
       0x0000:  0000 0000 0000 0000 c800 1104 000e 5747  ..............WG
       0x0010:  2d53 7769 747a 6572 6c61 6e64 0108 8284  -Switzerland....
       0x0020:  8b96 0c12 1824 0301 052a 0104 3204 3048  .....$...*..2.0H
       0x0030:  606c 3014 0100 000f ac04 0100 000f ac04  `l0.............
       0x0040:  0100 000f ac02 0c00 2d1a 0c00 1bff ffff  ........-.......
       0x0050:  0000 0000 0000 0000 0001 0000 0000 0000  ................
       0x0060:  0000 0000 3d16 0500 1700 0000 0000 0000  ....=3D...........
       0x0070:  0000 0000 0000 0000 0000 0000 dd18 0050  ...............P
       0x0080:  f202 0101 0000 03a4 0000 27a4 0000 4243  ..........'...BC
       0x0090:  5e00 6232 2f00                           ^.b2/.
12:28:56.545089 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:28:56.546257 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:=20
       0x0000:  0000 0200 0000                           ......
12:28:56.548007 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:28:56.550197 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:28:56.550806 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(9) : PRIVACY : Succes=
ful[|802.11]
       0x0000:  1104 0000 09c0 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:28:56.552571 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(9) : PRIVACY : Succesful[=
|802.11]
       0x0000:  1104 0000 09c0 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:28:59.666784 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 DeAuthentication: Previous authenticatio=
n no longer valid
       0x0000:  0200                                     ..
12:28:59.667765 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 DeAuthentication: Previous authentication no=
 longer valid
       0x0000:  0200                                     ..


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