Skip site navigation (1)Skip section navigation (2)
Date:      Fri, 05 Aug 2005 09:08:37 -0700
From:      Sam Leffler <sam@errno.com>
To:        "Robert C. Noland III" <rnoland@2hip.net>
Cc:        freebsd-current@freebsd.org
Subject:   Re: ath + wep issue
Message-ID:  <42F38F05.9080301@errno.com>
In-Reply-To: <1123194363.3878.14.camel@bbeng-laptop.acs.internap.com>
References:  <1123020549.3017.32.camel@bbeng-laptop.acs.internap.com>	<42F031E1.3080806@errno.com>	<1123106915.1052.36.camel@bbeng-laptop.acs.internap.com>	<42F1A1BD.1090103@errno.com> <1123194363.3878.14.camel@bbeng-laptop.acs.internap.com>

next in thread | previous in thread | raw e-mail | index | archive | help
Robert C. Noland III wrote:
> On Wed, 2005-08-03 at 22:03 -0700, Sam Leffler wrote:
> 
>>Robert C. Noland III wrote:
>>
>>>Ok, on the ath card the issue seems to be related to the interaction
>>>with the AP and the roaming mode...  This problem is exacerbated by the
>>>fact that I sometimes manage to get the card into a state where I can
>>>see outbound 802.11 frames with tcpdump, but never see inbound packets,
>>>i.e. probe responses...  Those are the instances when it scans
>>>forever... Ejecting the card and re-inserting gets me back to a useful
>>>state.
>>>
>>>This is long, sorry...
>>>
>>>This is what happens when I plug the card in and wpa_supplicant tries to
>>>configure the card.
>>>
>>>Aug  3 12:02:39 bbeng-laptop kernel: ath0: <Atheros 5212> mem
>>>0xf4010000-0xf401ffff irq 11 at device 0.0 on cardbus1
>>>Aug  3 12:02:39 bbeng-laptop kernel: ath0: Ethernet address:
>>>00:12:17:6e:fc:18
>>>Aug  3 12:02:39 bbeng-laptop kernel: ath0: mac 5.9 phy 4.3 radio 3.6
>>>Aug  3 12:03:13 bbeng-laptop kernel: ath0: ieee80211_newstate: INIT ->
>>>SCAN
>>>Aug  3 12:03:13 bbeng-laptop kernel: ath0: ieee80211_newstate: SCAN ->
>>>SCAN
>>>Aug  3 12:03:18 bbeng-laptop last message repeated 28 times
>>>Aug  3 12:03:18 bbeng-laptop kernel: ath0: ieee80211_newstate: SCAN ->
>>>AUTH
>>>Aug  3 12:03:23 bbeng-laptop kernel: ath0: ieee80211_newstate: AUTH ->
>>>SCAN
>>>Aug  3 12:03:23 bbeng-laptop kernel: ath0: ieee80211_newstate: SCAN ->
>>>AUTH
>>>Aug  3 12:03:28 bbeng-laptop kernel: ath0: ieee80211_newstate: AUTH ->
>>>SCAN
>>>Aug  3 12:03:28 bbeng-laptop kernel: ath0: ieee80211_newstate: INIT ->
>>>SCAN
>>>Aug  3 12:03:28 bbeng-laptop kernel: ath0: ieee80211_newstate: SCAN ->
>>>SCAN
>>>Aug  3 12:03:33 bbeng-laptop last message repeated 28 times
>>>Aug  3 12:03:39 bbeng-laptop kernel: ath0: ieee80211_newstate: INIT ->
>>>SCAN
>>>Aug  3 12:03:39 bbeng-laptop kernel: ath0: ieee80211_newstate: SCAN ->
>>>SCAN
>>>Aug  3 12:03:44 bbeng-laptop last message repeated 28 times
>>>Aug  3 12:03:50 bbeng-laptop kernel: ath0: ieee80211_newstate: INIT ->
>>>SCAN
>>>Aug  3 12:03:50 bbeng-laptop kernel: ath0: ieee80211_newstate: SCAN ->
>>>SCAN
>>>Aug  3 12:03:55 bbeng-laptop last message repeated 28 times
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: ieee80211_newstate: SCAN ->
>>>AUTH
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: ieee80211_newstate: AUTH ->
>>>ASSOC
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: [00:0d:93:e9:cf:d4] assoc
>>>success: long preamble, long slot time
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: ieee80211_newstate: ASSOC ->
>>>RUN
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: link state changed to UP
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: [00:0d:93:e9:cf:d4] recv
>>>disassociated (reason 9)
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: ieee80211_newstate: RUN ->
>>>ASSOC
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: link state changed to DOWN
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: [00:0d:93:e9:cf:d4] recv
>>>disassociated (reason 7)
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: ieee80211_newstate: ASSOC ->
>>>ASSOC
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: ieee80211_newstate: invalid
>>>transition
> 
> 
> What about this ASSOC -> ASSOC transition with wpa_supplicant?

Looks like I missed pulling in code from p4 to DTRT on the ASSOC->ASSOC 
transition; it should try to reassoc but currently does nothing.  That 
would explain the looping.

> 
> 
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: [00:0d:93:e9:cf:d4] recv
>>>disassociated (reason 7)
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: ieee80211_newstate: ASSOC ->
>>>ASSOC
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: ieee80211_newstate: invalid
>>>transition
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: [00:0d:93:e9:cf:d4] recv
>>>disassociated (reason 7)
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: ieee80211_newstate: ASSOC ->
>>>ASSOC
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: ieee80211_newstate: invalid
>>>transition
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: [00:0d:93:e9:cf:d4] recv
>>>disassociated (reason 7)
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: ieee80211_newstate: ASSOC ->
>>>ASSOC
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: ieee80211_newstate: invalid
>>>transition
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: [00:0d:93:e9:cf:d4] recv
>>>disassociated (reason 7)
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: ieee80211_newstate: ASSOC ->
>>>ASSOC
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: ieee80211_newstate: invalid
>>>transition
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: [00:0d:93:e9:cf:d4] recv
>>>disassociated (reason 7)
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: ieee80211_newstate: ASSOC ->
>>>ASSOC
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: ieee80211_newstate: invalid
>>>transition
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: [00:0d:93:e9:cf:d4] recv
>>>disassociated (reason 7)
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: ieee80211_newstate: ASSOC ->
>>>ASSOC
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: ieee80211_newstate: invalid
>>>transition
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: [00:0d:93:e9:cf:d4] recv
>>>disassociated (reason 7)
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: ieee80211_newstate: ASSOC ->
>>>ASSOC
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: ieee80211_newstate: invalid
>>>transition
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: [00:0d:93:e9:cf:d4] recv
>>>disassociated (reason 7)
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: ieee80211_newstate: ASSOC ->
>>>ASSOC
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: ieee80211_newstate: invalid
>>>transition
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: ieee80211_newstate: INIT ->
>>>SCAN
>>>Aug  3 12:03:56 bbeng-laptop kernel: ath0: ieee80211_newstate: SCAN ->
>>>SCAN
>>>Aug  3 12:03:59 bbeng-laptop last message repeated 15 times
>>>Aug  3 12:03:59 bbeng-laptop kernel: ath0: ieee80211_newstate: SCAN ->
>>>INIT
>>>
>>>It continues scanning, but never associates again...
>>
>>The error responses from the ap seem to indicate dropped frames.  What 
>>does ifconfig ath0 list scan show for the rssi?  If possible you might 
>>try moving the ap to channel 6 or 11.
> 
> 
> bbeng-laptop# ifconfig ath0 list scan
> SSID            BSSID              CHAN RATE  S:N   INT CAPS
> test001          00:0d:93:e9:cf:d4    1   11M 30:0   100 EP  
> test001          00:0d:93:e9:bf:c1    1   11M 14:0   100 EP  
> 

So the ap that you're using has rssi 30 which is very strong (assuming I 
read the logs correctly above).

> 
>>>When I "wpa_cli term" wpa_supplicant, it leaves the card like this...
>>>
>>>ath0: flags=8802<BROADCAST,SIMPLEX,MULTICAST> mtu 1500
>>>        inet6 fe80::212:17ff:fe6e:fc18%ath0 prefixlen 64 scopeid 0x3 
>>>        inet 0.0.0.0 netmask 0xff000000 broadcast 255.255.255.255
>>>        ether 00:12:17:6e:fc:18
>>>        media: IEEE 802.11 Wireless Ethernet autoselect (autoselect)
>>>        status: no carrier
>>>        ssid ""
>>>        authmode OPEN privacy OFF deftxkey 1 txpowmax 34 roaming DEVICE
>>>        bintval 100
>>>
>>>NOTE: roaming is set to DEVICE
>>
>>That's just wpa_supplicant; it should be fixed to restore the previous 
>>settings instead of blindly forcing a fixed value on cleanup.
>>
>>
>>>bbeng-laptop# ifconfig ath0 ssid "test001" authmode shared wepmode on
>>>weptxkey 1 wepkey "xxxxx"
>>>
>>>Aug  3 13:50:20 bbeng-laptop kernel: ath0: ieee80211_newstate: INIT ->
>>>SCAN
>>>Aug  3 13:50:20 bbeng-laptop kernel: ath0: ieee80211_newstate: SCAN ->
>>>SCAN
>>>Aug  3 13:50:51 bbeng-laptop last message repeated 151 times
>>>Aug  3 13:52:52 bbeng-laptop last message repeated 593 times
>>>
>>>card not seeing probe responses... later test same state below...
>>>
>>>Aug  3 15:29:00 bbeng-laptop kernel: ath0: ieee80211_newstate: INIT ->
>>>SCAN
>>>Aug  3 15:29:00 bbeng-laptop kernel: ath0: ieee80211_newstate: SCAN ->
>>>SCAN
>>>Aug  3 15:29:06 bbeng-laptop last message repeated 28 times
>>>Aug  3 15:29:06 bbeng-laptop kernel: ath0: ieee80211_newstate: SCAN ->
>>>AUTH
>>>Aug  3 15:29:06 bbeng-laptop kernel: ath0: ieee80211_newstate: AUTH ->
>>>ASSOC
>>>Aug  3 15:29:06 bbeng-laptop kernel: ath0: [00:0d:93:e9:cf:d4] assoc
>>>success: long preamble, long slot time
>>>Aug  3 15:29:06 bbeng-laptop kernel: ath0: ieee80211_newstate: ASSOC ->
>>>RUN
>>>Aug  3 15:29:06 bbeng-laptop kernel: ath0: link state changed to UP
>>>Aug  3 15:29:06 bbeng-laptop kernel: ath0: [00:0d:93:e9:cf:d4] recv
>>>disassociated (reason 9)
>>>Aug  3 15:29:06 bbeng-laptop kernel: ath0: ieee80211_newstate: RUN ->
>>>ASSOC
>>>Aug  3 15:29:06 bbeng-laptop kernel: ath0: link state changed to DOWN
>>>
>>>ath0: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> mtu 1500
>>>        inet6 fe80::212:17ff:fe6e:fc18%ath0 prefixlen 64 scopeid 0x3 
>>>        inet 0.0.0.0 netmask 0xff000000 broadcast 255.255.255.255
>>>        ether 00:12:17:6e:fc:18
>>>        media: IEEE 802.11 Wireless Ethernet autoselect (DS/1Mbps)
>>>        status: no carrier
>>>        ssid test001 channel 1
>>>        authmode SHARED privacy ON deftxkey 1 wepkey 1:104-bit txpowmax
>>>46
>>>        protmode CTS roaming DEVICE bintval 100
>>>
>>>lights on card blinking like it is associated and no further scanning.
>>
>>The card was left in ASSOC state so the lights reflect that.  Because 
>>roaming was set to device nothing progressed.  But the basic problem is 
>>still you don't appear to be getting frames through to the ap.
>>
>>
>>>bbeng-laptop# ifconfig ath0 roaming auto
>>>
>>>Aug  3 14:07:36 bbeng-laptop kernel: ath0: ieee80211_newstate: INIT ->
>>>SCAN
>>>Aug  3 14:07:36 bbeng-laptop kernel: ath0: ieee80211_newstate: SCAN ->
>>>SCAN
>>>Aug  3 14:07:42 bbeng-laptop last message repeated 28 times
>>>Aug  3 14:07:42 bbeng-laptop kernel: ath0: ieee80211_newstate: SCAN ->
>>>AUTH
>>>Aug  3 14:07:42 bbeng-laptop kernel: ath0: ieee80211_newstate: AUTH ->
>>>ASSOC
>>>Aug  3 14:07:42 bbeng-laptop kernel: ath0: [00:0d:93:e9:cf:d4] assoc
>>>success: long preamble, long slot time
>>>Aug  3 14:07:42 bbeng-laptop kernel: ath0: ieee80211_newstate: ASSOC ->
>>>RUN
>>>Aug  3 14:07:42 bbeng-laptop kernel: ath0: link state changed to UP
>>>Aug  3 14:07:42 bbeng-laptop kernel: ath0: [00:0d:93:e9:cf:d4] recv
>>>disassociated (reason 9)
>>>Aug  3 14:07:42 bbeng-laptop kernel: ath0: ieee80211_newstate: RUN ->
>>>ASSOC
>>>Aug  3 14:07:42 bbeng-laptop kernel: ath0: link state changed to DOWN
>>>Aug  3 14:07:42 bbeng-laptop kernel: ath0: [00:0d:93:e9:cf:d4] assoc
>>>success: long preamble, long slot time
>>>Aug  3 14:07:42 bbeng-laptop kernel: ath0: ieee80211_newstate: ASSOC ->
>>>RUN
>>>Aug  3 14:07:42 bbeng-laptop kernel: ath0: link state changed to UP
>>>Aug  3 14:07:42 bbeng-laptop kernel: ath0: [00:0d:93:e9:cf:d4] recv
>>>disassociated (reason 9)
>>>Aug  3 14:07:42 bbeng-laptop kernel: ath0: ieee80211_newstate: RUN ->
>>>ASSOC
>>>Aug  3 14:07:42 bbeng-laptop kernel: ath0: link state changed to DOWN
>>>Aug  3 14:07:42 bbeng-laptop kernel: ath0: [00:0d:93:e9:cf:d4] assoc
>>>success: long preamble, long slot time
>>>Aug  3 14:07:42 bbeng-laptop kernel: ath0: ieee80211_newstate: ASSOC ->
>>>RUN
>>>Aug  3 14:07:42 bbeng-laptop kernel: ath0: link state changed to UP
>>>
>>>It's all good now... 
>>>
>>>ath0: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> mtu 1500
>>>        inet6 fe80::212:17ff:fe6e:fc18%ath0 prefixlen 64 scopeid 0x3 
>>>        inet 0.0.0.0 netmask 0xff000000 broadcast 255.255.255.255
>>>        ether 00:12:17:6e:fc:18
>>>        media: IEEE 802.11 Wireless Ethernet autoselect (DS/1Mbps)
>>>        status: associated
>>>        ssid test001 channel 1 bssid 00:0d:93:e9:cf:d4
>>>        authmode SHARED privacy ON deftxkey 1 wepkey 1:104-bit txpowmax
>>>46
>>>        protmode CTS bintval 100
>>>
>>>I either have or can provide tcpdumps of each specific case if that
>>>helps more, but I figure this message is long enough already.
>>
>>Better would be a 3rd sta sniffing traffic and also recording rssi 
>>(collect -y IEEE802_11_RADIO).  Your problem seems unrelated to wep or 
>>roaming mode; you appear to just not get frames through reliably.  When 
>>this happens I look at stats on the sta and the ap.  athstats can be 
>>useful here; something like
>>
>>athstats 1
> 
> 
> athstats 1 while running ping -f

Er, well I meant to collect stats during the time that you looked to be 
losing packets; not after you have an association setup.  And using ping 
-f isn't going to answer any questions; I wanted to see what was going 
on with the exchange of management frames.  But thanks...

> 
> 19927 packets transmitted, 19926 packets received, 0% packet loss
> round-trip min/avg/max/stddev = 1.259/1.613/9.182/0.266 ms
> 
>    input   output altrate   short    long xretry crcerr crypt  phyerr
> rssi rate
>     7047     7020       1       0      53      0    348     0       0
> 33  11M
	<...snip...>
> 
>>will give you a rolling display of stats together with current rssi. 
>>Sometimes you can see obvious problems like high retransmit rates or big 
>>bursts of noise.  If the frame count on the ap goes up as you transmit 
>>then it's likely you're not hearing the ACK's coming back.  If the ap 
>>doesn't hear your frames (as appears to be happening) then it can either 
>>be noise, misconfig (e.g. 11g parameters like protection wrong in a 
>>mixed b/g bss), or possibly low tx power by the sta.  The latter would 
>>appear as low rssi on recv'd frames at the ap and/or a 3rd sta.
>>
>>I don't see an indication of what you're using for an ap.  Also remove 
>>everything like crypto and shared key auth for testing--get 
>>communication working before adding more variables.  Figuring out 
>>communication problems can be hard w/o a good test environment and tools.
> 
> 
> It is an apple airport extreme, unfortunately I don't have access to
> it's config...
> 
> This situation is 100 percent predictable, with wpa_supplicant produces
> the first result, every time, static w/ roaming DEVICE produces the same
> state every time as well, and static w/ roaming auto works.

	<...snip...>

The wpa_supplicant issue is just a bug that I can fix; it's excercising 
the internal state machine differently than when things happen entirely 
in the kernel.  I will also fix wpa_supplicant to restore the roaming 
state.  Thank you.

	Sam



Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?42F38F05.9080301>