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:
[...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