hostap/Ath9k - repeated SSID probe requests with certain devices

Tue May 4 09:12:11 PDT 2010

Hi,

I'm having a problem and Google can't immediately point me to an answer - so I'm wondering if anybody here can help. I'm trying to get an Android phone working with my Openwrt router.

I seem to have a problem where Wifi stops working, and the client device repeatedly sends SSID probe requests. It's almost as if the probe response isn't correct, or being received, or something.

The problem seems to occur as follows:

- Associate with AP
- Get HTC Hero phone to ping AP.
- First few pings work (maybe for 11 seconds or so)
- hostapd reports a lot of probe request messages, one per second. Meanwhile no ping responses are received.
- device receives out of order ping responses, with response time of 13 secs or so!

I'm trying to figure out where the problem is occuring. I'm not sure if it occurs at the hostapd end, the wpa_supplicant end or somewhere in the transport.

I have an Apple Macbook which also can be "a bit funny sometimes" - it sometimes won't associate with the AP. I notice that the Macbook can also frequently send probe requests when pinging - though these don't seem to affect pings - there's 0% packet loss. The AP does however seem to work perfectly with a Nokia E51 phone

This makes me wonder if it's possible to fix the problem at the AP end, rather than at the ends of the two clients.

I'm using a Linksys WRT160NL router, running openwrt SVN build r21293. This uses hostapd v0.7.2 and the Ath9k driver, with kernel 2.6.32.12

In this example I have the HTC Hero with address 192.168.1.4 and the router 192.168.1.1.
The Hero uses a TI wl1251 wifi chip, with Android built wpa_supplicant v0.5.11
The Macbook uses whatever magic is supplied by OS X Snow Leopard.

I've set the AP to use 802.11g mode, as I believe 802.11n is still "dodgy" on the ath9k.
Setting wpa=0 or 1 or 2 makes no difference in the hostapd config file.

I've heard that the same phone works ok with hostapd on an ath5k based router, but my problem seems very similar to the Android bug at

http://code.google.com/p/android/issues/detail?id=1698#c27

I'm just trying to figure out why this only appears on certain devices.

Of course, it could be an Ath9k problem too - but I'm a bit in the dark and wondering if anyone can help!

Of course, in the time I've been writing this message it's now working fine, with 0% packet loss. Sigh. 

Thanks,

Colin

hero: ping 192.168.1.1

64 bytes from 192.168.1.1: icmp_seq=27 ttl=64 time=43.9 ms
64 bytes from 192.168.1.1: icmp_seq=28 ttl=64 time=66.2 ms
64 bytes from 192.168.1.1: icmp_seq=29 ttl=64 time=89.1 ms
>From 192.168.1.4 icmp_seq=63 Destination Host Unreachable
>From 192.168.1.4 icmp_seq=64 Destination Host Unreachable
>From 192.168.1.4 icmp_seq=65 Destination Host Unreachable
>From 192.168.1.4 icmp_seq=66 Destination Host Unreachable
>From 192.168.1.4 icmp_seq=67 Destination Host Unreachable
>From 192.168.1.4 icmp_seq=68 Destination Host Unreachable
>From 192.168.1.4 icmp_seq=69 Destination Host Unreachable
>From 192.168.1.4 icmp_seq=70 Destination Host Unreachable
>From 192.168.1.4 icmp_seq=71 Destination Host Unreachable
64 bytes from 192.168.1.1: icmp_seq=56 ttl=64 time=16673 ms
64 bytes from 192.168.1.1: icmp_seq=57 ttl=64 time=15675 ms
64 bytes from 192.168.1.1: icmp_seq=58 ttl=64 time=14677 ms
64 bytes from 192.168.1.1: icmp_seq=59 ttl=64 time=13679 ms
64 bytes from 192.168.1.1: icmp_seq=60 ttl=64 time=12679 ms
64 bytes from 192.168.1.1: icmp_seq=61 ttl=64 time=11678 ms
64 bytes from 192.168.1.1: icmp_seq=62 ttl=64 time=10679 ms
64 bytes from 192.168.1.1: icmp_seq=72 ttl=64 time=644 ms

Nice quick ping responses :-)

Running hostapd -ddt hostapd-phy0.conf shows:

< Cut startup stuff >
1272986224.153814: AP-STA-CONNECTED 00:23:76:20:f6:xx
1272986224.154702: wlan0: STA 00:23:76:20:f6:xx IEEE 802.1X: authorizing port
1272986224.154849: wlan0: STA 00:23:76:20:f6:xx WPA: pairwise key handshake completed (RSN)

< pings work OK - hostapd is silent >
then pings stop working, and hostapd reports every second:

1272986304.024058: STA 00:23:76:20:f6:xx sent probe request for our SSID
1272986304.024347: STA 00:23:76:20:f6:xx sent probe request for our SSID
1272986304.025740: mgmt::proberesp cb
1272986304.027284: mgmt::proberesp cb
1272986305.048316: STA 00:23:76:20:f6:xx sent probe request for our SSID
1272986305.048989: STA 00:23:76:20:f6:xx sent probe request for our SSID
1272986305.050308: mgmt::proberesp cb
1272986305.051772: mgmt::proberesp cb
1272986306.071965: STA 00:23:76:20:f6:xx sent probe request for our SSID
1272986306.072263: STA 00:23:76:20:f6:xx sent probe request for our SSID
1272986306.073645: mgmt::proberesp cb
1272986306.075093: mgmt::proberesp cb
1272986307.095992: STA 00:23:76:20:f6:xx sent probe request for our SSID
1272986307.096332: STA 00:23:76:20:f6:xx sent probe request for our SSID
1272986307.097669: mgmt::proberesp cb
1272986307.099119: mgmt::proberesp cb
1272986308.119975: STA 00:23:76:20:f6:xx sent probe request for our SSID
1272986308.120410: STA 00:23:76:20:f6:xx sent probe request for our SSID
1272986308.121760: mgmt::proberesp cb
1272986308.123226: mgmt::proberesp cb

tcpdump -s 0 -vv -i mon.wlan0 shows the same thing

15:46:07.698952 2.0 Mb/s 2432 MHz (0x0480) Pwr Mgmt 258us Probe Request (MrWouter) [1.0* 2.0* 5.5* 11.0* 22.0 Mbit]
15:46:07.699659 2.0 Mb/s 2432 MHz (0x0480) Pwr Mgmt 258us Probe Request (MrWouter) [1.0* 2.0* 5.5* 11.0* 22.0 Mbit]
15:46:07.699735 wep fragmented [0x0000000e] 0us Probe Response (MrWouter) [1.0* 2.0* 5.5* 11.0* 6.0 9.0 12.0 18.0 Mbit] CH: 5, PRIVACY
15:46:07.700069 wep fragmented [0x0000000e] 0us Probe Response (MrWouter) [1.0* 2.0* 5.5* 11.0* 6.0 9.0 12.0 18.0 Mbit] CH: 5, PRIVACY
15:46:07.701361 1.0 Mb/s [0x0000000f] 314us Probe Response (MrWouter) [1.0* 2.0* 5.5* 11.0* 6.0 9.0 12.0 18.0 Mbit] CH: 5, PRIVACY
15:46:07.702860 1.0 Mb/s [0x0000000f] 314us Probe Response (MrWouter) [1.0* 2.0* 5.5* 11.0* 6.0 9.0 12.0 18.0 Mbit] CH: 5, PRIVACY
15:46:08.729562 2.0 Mb/s 2432 MHz (0x0480) Pwr Mgmt 268us Probe Request (MrWouter) [1.0* 2.0* 5.5* 11.0* 22.0 Mbit]
15:46:08.730245 2.0 Mb/s 2432 MHz (0x0480) Pwr Mgmt 258us Probe Request (MrWouter) [1.0* 2.0* 5.5* 11.0* 22.0 Mbit]
15:46:08.730349 wep fragmented [0x0000000e] 0us Probe Response (MrWouter) [1.0* 2.0* 5.5* 11.0* 6.0 9.0 12.0 18.0 Mbit] CH: 5, PRIVACY
15:46:08.731077 wep fragmented [0x0000000e] 0us Probe Response (MrWouter) [1.0* 2.0* 5.5* 11.0* 6.0 9.0 12.0 18.0 Mbit] CH: 5, PRIVACY
15:46:08.733470 1.0 Mb/s [0x0000000f] 314us Probe Response (MrWouter) [1.0* 2.0* 5.5* 11.0* 6.0 9.0 12.0 18.0 Mbit] CH: 5, PRIVACY

The config file is

ctrl_interface=/var/run/hostapd-phy0
driver=nl80211
wmm_ac_bk_cwmin=4
wmm_ac_bk_cwmax=10
wmm_ac_bk_aifs=7
wmm_ac_bk_txop_limit=0
wmm_ac_bk_acm=0
wmm_ac_be_aifs=3
wmm_ac_be_cwmin=4
wmm_ac_be_cwmax=10
wmm_ac_be_txop_limit=0
wmm_ac_be_acm=0
wmm_ac_vi_aifs=2
wmm_ac_vi_cwmin=3
wmm_ac_vi_cwmax=4
wmm_ac_vi_txop_limit=94
wmm_ac_vi_acm=0
wmm_ac_vo_aifs=2
wmm_ac_vo_cwmin=2
wmm_ac_vo_cwmax=3
wmm_ac_vo_txop_limit=47
wmm_ac_vo_acm=0
tx_queue_data3_aifs=7
tx_queue_data3_cwmin=15
tx_queue_data3_cwmax=1023
tx_queue_data3_burst=0
tx_queue_data2_aifs=3
tx_queue_data2_cwmin=15
tx_queue_data2_cwmax=63
tx_queue_data2_burst=0
tx_queue_data1_aifs=1
tx_queue_data1_cwmin=7
tx_queue_data1_cwmax=15
tx_queue_data1_burst=3.0
tx_queue_data0_aifs=1
tx_queue_data0_cwmin=3
tx_queue_data0_cwmax=7
tx_queue_data0_burst=1.5
hw_mode=g
channel=5

ieee80211n=0
ht_capab=[HT20][SHORT-GI-40][DSSS_CCK-40][SHORT-GI-40][DSSS_CCK-40]

interface=wlan0
wpa_passphrase=xxxxxxxxx
wpa=2
wpa_pairwise=CCMP
ssid=MrWouter
bridge=br-lan
wmm_enabled=1
bssid=00:23:69:b9:ae:xx
ignore_broadcast_ssid=0