Assoc problems

Fri Mar 26 15:35:20 PST 2004

I started to have strange problem: when I try to associate
with my AP, in AP syslog I see:

kernel: wlan0: STA 00:05:5d:fa:58:2b TX rate lowered to 55
kernel: wlan0: 00:05:5d:fa:58:2b auth_cb - frame was not ACKed
kernel: wlan0: 00:05:5d:fa:58:2b auth_cb - frame was not ACKed
kernel: wlan0: STA 00:05:5d:fa:58:2b TX rate lowered to 20
kernel: wlan0: 00:05:5d:fa:58:2b auth_cb - frame was not ACKed
kernel: wlan0: 00:05:5d:fa:58:2b auth_cb - frame was not ACKed
kernel: wlan0: STA 00:05:5d:fa:58:2b TX rate lowered to 10
kernel: wlan0: 00:05:5d:fa:58:2b auth_cb - frame was not ACKed
...
kernel: wlan0: 00:05:5d:fa:58:2b auth_cb - STA authenticated
kernel: wlan0: 00:05:5d:fa:58:2b assoc_cb - STA associated

It's utterly strange because it never happened before,
there is no packet loss, AP and STA are standing only
few meters apart and whet STA do associate, which can take
10 mins or more, I get:

Link Quality:48/92  Signal level:-62 dBm  Noise level:-97 dBm

I must have changed something in my setup...

I gathered version info and captured radio traffic
with third card in monitor mode:

AP:  kernel 2.6.2 hostap 0.1.2 firmware 1.8.0
STA: kernel 2.6.5-rc1 hostap 0.1.3 firmware 1.5.6

<AP> = AP mac address
<STA> = STA mac address
<BC> = ff:ff:ff:ff:ff:ff

# tcpdump -nleiwlan0 -s0
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on wlan0, link-type IEEE802_11 (802.11), capture size 65535 bytes
06:41:21.518360 BSSID:<AP> DA:<AP> SA:<STA> Authentication (Open System)-1: Succesful
06:41:21.519688 RA:<STA> Acknowledgment
06:41:21.713023 BSSID:<AP> DA:<BC> SA:<AP> Beacon (ear) [1.0* 2.0* 5.5* 11.0* Mbit] ESS CH: 6, PRIVACY
06:41:21.714033 BSSID:<AP> DA:<STA> SA:<AP> Authentication (Open System)-2:
06:41:21.715042 BSSID:<AP> DA:<STA> SA:<AP> Authentication (Open System)-2:
06:41:21.716059 BSSID:<AP> DA:<STA> SA:<AP> Authentication (Open System)-2:
06:41:21.718696 RA:<STA> TA:<AP> Request-To-Send
06:41:21.721260 RA:<STA> TA:<AP> Request-To-Send
06:41:22.041730 BSSID:<AP> DA:<BC> SA:<AP> Beacon (ear) [1.0* 2.0* 5.5* 11.0* Mbit] ESS CH: 6, PRIVACY
06:41:22.050137 unknown IEEE802.11 frame type (3)(header) unknown IEEE802.11 frame type (3)unknown 802.11 frame type (3)
06:41:22.370474 BSSID:<AP> DA:<BC> SA:<AP> Beacon (ear) [1.0* 2.0* 5.5* 11.0* Mbit] ESS CH: 6, PRIVACY
06:41:22.680988 BSSID:<BC> DA:<BC> SA:<STA> Probe Request (ear) [1.0* 2.0* 5.5 11.0 Mbit]
06:41:22.699450 BSSID:<AP> DA:<BC> SA:<AP> Beacon (ear) [1.0* 2.0* 5.5* 11.0* Mbit] ESS CH: 6, PRIVACY
06:41:22.744293 BSSID:<AP> DA:<STA> SA:<AP> Probe Response (ear)  [1.0* 2.0* 5.5* 11.0* Mbit] CH: 6, PRIVACY
06:41:22.745723 BSSID:<AP> DA:<STA> SA:<AP> Probe Response (ear)  [1.0* 2.0* 5.5* 11.0* Mbit] CH: 6, PRIVACY
06:41:22.746940 BSSID:<AP> DA:<STA> SA:<AP> Probe Response (ear)  [1.0* 2.0* 5.5* 11.0* Mbit] CH: 6, PRIVACY

2 last packets were retries (verified later with tcpdump -v)
Why STA does not ACK them?

06:41:22.752239 RA:<STA> TA:<AP> Request-To-Send
06:41:22.752916 BSSID:<AP> DA:<STA> SA:<AP> Probe Response (ear)  [1.0* 2.0* 5.5* 11.0* Mbit] CH: 6, PRIVACY
06:41:22.757356 RA:<STA> TA:<AP> Request-To-Send
06:41:22.806449 BSSID:<BC> DA:<BC> SA:<STA> Probe Request (ear) [1.0* 2.0* 5.5 11.0 Mbit]
06:41:22.822973 BSSID:<BC> DA:<BC> SA:<STA> Probe Request (ear) [1.0* 2.0* 5.5 11.0 Mbit]
06:41:22.839360 BSSID:<BC> DA:<BC> SA:<STA> Probe Request (ear) [1.0* 2.0* 5.5 11.0 Mbit]
06:41:22.840215 BSSID:<AP> DA:<STA> SA:<AP> Probe Response (ear)  [1.0* 2.0* 5.5* 11.0* Mbit] CH: 6, PRIVACY
06:41:22.840687 RA:<AP> Acknowledgment
06:41:22.901714 BSSID:<BC> DA:<BC> SA:<STA> Probe Request (ear) [1.0* 2.0* 5.5 11.0 Mbit]
06:41:22.918193 BSSID:<BC> DA:<BC> SA:<STA> Probe Request (ear) [1.0* 2.0* 5.5 11.0 Mbit]
06:41:22.918676 BSSID:<AP> DA:<STA> SA:<AP> Probe Response (ear)  [1.0* 2.0* 5.5* 11.0* Mbit] CH: 6, PRIVACY
06:41:22.919910 BSSID:<AP> DA:<STA> SA:<AP> Probe Response (ear)  [1.0* 2.0* 5.5* 11.0* Mbit] CH: 6, PRIVACY
06:41:22.921706 BSSID:<AP> DA:<STA> SA:<AP> Probe Response (ear)  [1.0* 2.0* 5.5* 11.0* Mbit] CH: 6, PRIVACY
....
06:41:52.549704 BSSID:<BC> DA:<BC> SA:<STA> Probe Request (ear) [1.0* 2.0* 5.5 11.0 Mbit]
06:41:52.566404 BSSID:<BC> DA:<BC> SA:<STA> Probe Request (ear) [1.0* 2.0* 5.5 11.0 Mbit]
06:41:52.566861 BSSID:<AP> DA:<STA> SA:<AP> Probe Response (ear)  [1.0* 2.0* 5.5* 11.0* Mbit] CH: 6, PRIVACY
06:41:52.567852 BSSID:<AP> DA:<STA> SA:<AP> Probe Response (ear)  [1.0* 2.0* 5.5* 11.0* Mbit] CH: 6, PRIVACY
06:41:52.570766 BSSID:<AP> DA:<STA> SA:<AP> Probe Response (ear)  [1.0* 2.0* 5.5* 11.0* Mbit] CH: 6, PRIVACY
06:41:52.573574 RA:<STA> TA:<AP> Request-To-Send
06:41:52.574633 RA:<STA> TA:<AP> Request-To-Send
06:41:52.614522 BSSID:<AP> DA:<BC> SA:<AP> Beacon (ear) [1.0* 2.0* 5.5* 11.0* Mbit] ESS CH: 6, PRIVACY
06:41:52.629664 BSSID:<BC> DA:<BC> SA:<STA> Probe Request (ear) [1.0* 2.0* 5.5 11.0 Mbit]
06:41:52.645664 BSSID:<BC> DA:<BC> SA:<STA> Probe Request (ear) [1.0* 2.0* 5.5 11.0 Mbit]
06:41:52.662365 BSSID:<BC> DA:<BC> SA:<STA> Probe Request (ear) [1.0* 2.0* 5.5 11.0 Mbit]
06:41:52.662824 BSSID:<AP> DA:<STA> SA:<AP> Probe Response (ear)  [1.0* 2.0* 5.5* 11.0* Mbit] CH: 6, PRIVACY
06:41:52.664621 BSSID:<AP> DA:<STA> SA:<AP> Probe Response (ear)  [1.0* 2.0* 5.5* 11.0* Mbit] CH: 6, PRIVACY
06:41:52.667175 BSSID:<AP> DA:<STA> SA:<AP> Probe Response (ear)  [1.0* 2.0* 5.5* 11.0* Mbit] CH: 6, PRIVACY
06:41:52.670755 RA:<STA> TA:<AP> Request-To-Send
06:41:52.672378 RA:<STA> TA:<AP> Request-To-Send
06:41:52.724521 BSSID:<BC> DA:<BC> SA:<STA> Probe Request (ear) [1.0* 2.0* 5.5 11.0 Mbit]
06:41:52.725150 BSSID:<AP> DA:<STA> SA:<AP> Probe Response (ear)  [1.0* 2.0* 5.5* 11.0* Mbit] CH: 6, PRIVACY
06:41:52.726263 BSSID:<AP> DA:<STA> SA:<AP> Probe Response (ear)  [1.0* 2.0* 5.5* 11.0* Mbit] CH: 6, PRIVACY
06:41:52.727038 BSSID:<AP> DA:<STA> SA:<AP> Probe Response (ear)  [1.0* 2.0* 5.5* 11.0* Mbit] CH: 6, PRIVACY
06:41:52.728076 RA:<STA> TA:<AP> Request-To-Send
06:41:52.728752 BSSID:<AP> DA:<STA> SA:<AP> Probe Response (ear)  [1.0* 2.0* 5.5* 11.0* Mbit] CH: 6, PRIVACY
06:41:52.734669 RA:<STA> TA:<AP> Request-To-Send
06:41:52.734925 RA:<AP> Clear-To-Send
06:41:52.735352 BSSID:<AP> DA:<STA> SA:<AP> Probe Response (ear)  [1.0* 2.0* 5.5* 11.0* Mbit] CH: 6, PRIVACY
06:41:52.797436 BSSID:<AP> DA:<AP> SA:<STA> Authentication (Open System)-1: Succesful
06:41:52.797890 RA:<STA> Acknowledgment
06:41:52.897279 BSSID:<AP> DA:<STA> SA:<AP> Authentication (Open System)-2:
06:41:52.897575 RA:<AP> Acknowledgment
06:41:52.898821 BSSID:<AP> DA:<AP> SA:<STA> Assoc Request (ear) [1.0* 2.0* 5.5 11.0 Mbit]
06:41:52.899331 RA:<STA> Acknowledgment
06:41:52.943495 BSSID:<AP> DA:<BC> SA:<AP> Beacon (ear) [1.0* 2.0* 5.5* 11.0* Mbit] ESS CH: 6, PRIVACY
06:41:52.944074 BSSID:<AP> DA:<STA> SA:<AP> Assoc Response AID(2) :: Succesful
06:41:52.944375 RA:<AP> Acknowledgment
06:41:53.271969 BSSID:<AP> DA:<BC> SA:<AP> Beacon (ear) [1.0* 2.0* 5.5* 11.0* Mbit] ESS CH: 6, PRIVACY
06:41:53.600799 BSSID:<AP> DA:<BC> SA:<AP> Beacon (ear) [1.0* 2.0* 5.5* 11.0* Mbit] ESS CH: 6, PRIVACY
06:41:53.929475 BSSID:<AP> DA:<BC> SA:<AP> Beacon (ear) [1.0* 2.0* 5.5* 11.0* Mbit] ESS CH: 6, PRIVACY
...

I was lucky this time. It can run tens of minutes before association succeeds.

I tried hostap 0.1.2 and even CVS hostap-20030720 on STA, same results.
--
vda