No subject
bogus at does.not.exist.com
bogus at does.not.exist.com
Sat Oct 15 15:41:40 PDT 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