Re: /dev/ath log messages

From: Eric Anderson <anderson_at_centtech.com>
Date: Mon, 09 Jan 2006 11:08:50 -0600
Sam Leffler wrote:

> Eric Anderson wrote:
>
>> Sam Leffler wrote:
>>
>>> Eric Anderson wrote:
>>>
>>>> Beech Rintoul wrote:
>>>>
>>>>> I have noticed that for about the past month or so I've been 
>>>>> getting hundreds of the following every day in /var/log/messages:
>>>>>
>>>>> +ath0: link state changed to DOWN
>>>>> +ath0: link state changed to UP
>>>>>
>>>>> It doesn't seem to affect connectivity, but it's really annoying 
>>>>> in the security report. Is there anything I can do to stop this? 
>>>>> I'm running -CURRENT from yesterday. I have built Sam's new 
>>>>> drivers, but this problem started long before that and was not 
>>>>> affected by the upgrade. The lease on the AP I'm connecting to is 
>>>>> good for 24 hours so I don't think that's an issue. I looked at 
>>>>> the traffic with ethereal and everything looks normal. I'm getting 
>>>>> sorely tempted to go back to isc-dhclient and see if this goes 
>>>>> away, but I thought I would ask here first.
>>>>>
>>>>>  
>>>>>
>>>>
>>>> I've noticed something recently too - my ath device frequently 
>>>> stops working, and I get this in messages:
>>>>
>>>> Jan  6 06:19:48 neutrino kernel: ath0: link state changed to DOWN
>>>> Jan  6 06:20:35 neutrino kernel: ath0: device timeout
>>>> Jan  6 06:20:56 neutrino kernel: ath0: device timeout
>>>> Jan  6 06:21:06 neutrino kernel: ath0: device timeout
>>>> Jan  6 06:21:59 neutrino last message repeated 2 times
>>>> Jan  6 06:22:25 neutrino kernel: ath0: device timeout
>>>> Jan  6 06:23:03 neutrino kernel: ath0: link state changed to UP
>>>> Jan  6 06:41:35 neutrino kernel: ath0: link state changed to DOWN
>>>> Jan  6 06:42:03 neutrino kernel: Memory modified after free 
>>>> 0xc5402000(2048) val=11600000 _at_ 0xc5402000
>>>> Jan  6 06:42:04 neutrino kernel: ath0: link state changed to UP
>>>> Jan  6 06:42:08 neutrino kernel: ath0: device timeout
>>>> Jan  6 06:42:09 neutrino kernel: ath0: link state changed to DOWN
>>>> Jan  6 06:43:12 neutrino kernel: ath0: link state changed to UP
>>>> Jan  6 06:43:17 neutrino kernel: ath0: device timeout
>>>> Jan  6 06:43:17 neutrino kernel: ath0: link state changed to DOWN
>>>> Jan  6 06:43:33 neutrino kernel: ath0: device timeout
>>>> Jan  6 06:44:10 neutrino kernel: ath0: device timeout
>>>> [and so on]
>>>>
>>>>
>>>> I would say this started happening for me in the last 2 weeks.
>>>
>>>
>>>
>>>
>>> Device timeouts should not happen; it means the driver submitted a 
>>> packet to the card and didn't get a tx complete interrupt back in 5 
>>> seconds.
>>>
>>> It's unclear if the "modified after free" msgs is related and w/o 
>>> more diagnostic info it's really hard to say why you're seeing 
>>> device timeouts.
>>
>>
>>
>>
>> Ok - wasn't sure if was related or not, so I posted it anyway.  
>> Before about 2 weeks ago, ath has been rock solid for me.
>
>
> The last change I made to the ath driver was >1 month ago and that was 
> to delete code.  Recent changes to the net80211 layer mostly add code 
> that is not yet used.  If a code change is affecting operation it 
> seems likely it's elsewhere in the system.  If you can rollback code 
> to the point where things work and they return to operation then 
> perhaps you can pinpoint the problem if it's s/w.
>
>>
>>>
>>>>
>>>> I'm running -current from Jan 4th.  All kinds of system information 
>>>> is here:
>>>>
>>>> http://googlebit.com/freebsd/
>>>
>>>
>>>
>>>
>>> Most of the useful info is not there.  No boot dmsg or indication of 
>>> what your network config is.  No indication of the hal version or 
>>> the mac+phy revs. yada yada yada...
>>
>>
>>
>>
>> Yea, I see that now.  Sorry - here's dmesg.boot:
>> http://googlebit.com/freebsd/dmesg.boot-20060106
>>
>> And some additional info:
>> /etc/rc.conf snippet:
>> ifconfig_em0="DHCP"
>> ifconfig_ath0="WPA DHCP"
>>
>> /etc/wpa_supplicant.conf:
>> ctrl_interface=/var/run/wpa_supplicant
>> ctrl_interface_group=wheel
>>
>> network={
>>    ssid="centtech"
>>    key_mgmt=NONE
>>    wep_key0=0E...CD
>>    wep_tx_keyidx=0
>>    scan_ssid=1
>>    priority=5
>> }
>>
>> $ kldstat
>> Id Refs Address    Size     Name
>> 1   36 0xc0400000 7707a4   kernel
>> 2    2 0xc0b71000 1e198    linux.ko
>> 3    1 0xc0b90000 125a0    if_ath.ko
>> 4    3 0xc0ba3000 26b70    ath_hal.ko
>> 5    2 0xc0bca000 472c     ath_rate.ko
>> 6    1 0xc0bcf000 55e8     snd_ich.ko
>> 7    2 0xc0bd5000 268b8    sound.ko
>> 8    1 0xc0bfc000 56e4     acpi_video.ko
>> 9    3 0xc0c02000 63c94    acpi.ko
>> 10    1 0xc0c66000 2730     acpi_sony.ko
>> 11    1 0xc0c69000 2fac     wlan_wep.ko
>> 12    1 0xc0c6c000 416c     atapicam.ko
>> 13    1 0xc0c71000 3694     ucom.ko
>> 14    1 0xc0c75000 9454     cpufreq.ko
>> 15    6 0xc0c7f000 d3b0     netgraph.ko
>> 16    1 0xc0c8d000 8550     ng_ubt.ko
>> 17    1 0xc0c96000 68f8     vkbd.ko
>> 18    1 0xc53bd000 6000     linprocfs.ko
>> 19    4 0xc56be000 2000     ng_bluetooth.ko
>> 20    1 0xc56ec000 d000     ng_hci.ko
>> 21    1 0xc5712000 10000    ng_l2cap.ko
>> 22    1 0xc5722000 1a000    ng_btsocket.ko
>> 23    1 0xc5744000 4000     ng_socket.ko
>>
>> I have several AP's I roam on, but I am about 10ft from the closest 
>> AP which I seem to stick with.  This also happens at home where I 
>> have a single AP (same brand and model).
>>
>> Unloading and reloading the modules helped once if I recall 
>> correctly, but not usually.  Rebooting the computer does help, but 
>> only for some period of time, sometimes many hours, but usually not 
>> that long.
>>
>> Anything else I can provide?
>
>
> You mean like your network config?  I see you're using wpa but 11g, 
> 11a, 11b?  Have you tried operating w/o WPA?  Different channel?  
> Different card?  Since there don't appear to be code changes related 
> to your issue you need to work on isolating what's changed or is failing.
>
>     Sam

I'm using wpa_supplicant for the setup and config, but WEP currently, no 
WPA.  My AP's are 11g, but I have them also enabling 11b support.   Each 
access point is set up to a different channel (mostly, there might be a 
duplicate channel on another floor, but I can't see it anyhow).   I have 
not yet tried a different card, since it's been working fine for a long 
time.  The one thing I *did* change, is I switched from a manual 
configuration in /etc/rc.conf to wpa_supplicant.conf.   Maybe my 
wpa_supplicant.conf file is not correct?

Using wpa_cli (which should be in the SEE ALSO section of the 
wpa_supplicant man page), and turning up debug messages, I see something 
like this:

[.. snip ..]
<2>Authentication with 00:00:00:00:00:00 timed out.
status
bssid=00:00:00:00:00:00
pairwise_cipher=WEP-104
group_cipher=WEP-104
key_mgmt=NONE
wpa_state=SCANNING
 > <2>Trying to associate with 00:80:c8:17:b3:26 (SSID='centtech' 
freq=2437 MHz)
<2>Trying to associate with 00:80:c8:17:b3:26 (SSID='centtech' freq=2437 
MHz)
reconfigure
OK
 > <2>Authentication with 00:00:00:00:00:00 timed out.
<2>Trying to associate with 00:80:c8:17:b3:26 (SSID='centtech' freq=2437 
MHz)
<2>Authentication with 00:00:00:00:00:00 timed out.
<2>Trying to associate with 00:80:c8:17:b3:26 (SSID='centtech' freq=2437 
MHz)
<2>Trying to associate with 00:80:c8:17:b3:26 (SSID='centtech' freq=2437 
MHz)
<2>Associated with 00:80:c8:17:b3:26
<2>Disconnect event - remove keys
<2>Trying to associate with 00:80:c8:17:b3:26 (SSID='centtech' freq=2437 
MHz)
<2>Trying to associate with 00:80:c8:17:b3:26 (SSID='centtech' freq=2437 
MHz)
<2>Authentication with 00:00:00:00:00:00 timed out.
<2>Trying to associate with 00:80:c8:17:b3:26 (SSID='centtech' freq=2437 
MHz)
<2>Authentication with 00:00:00:00:00:00 timed out.
<2>Trying to associate with 00:80:c8:17:b3:26 (SSID='centtech' freq=2437 
MHz)
<2>Trying to associate with 00:80:c8:17:b3:26 (SSID='centtech' freq=2437 
MHz)
<2>Authentication with 00:00:00:00:00:00 timed out.
<2>Trying to associate with 00:80:c8:17:b3:26 (SSID='centtech' freq=2437 
MHz)
<2>Authentication with 00:00:00:00:00:00 timed out.
<2>Trying to associate with 00:80:c8:17:b3:26 (SSID='centtech' freq=2437 
MHz)
<2>Authentication with 00:00:00:00:00:00 timed out.
<2>Trying to associate with 00:80:c8:17:b1:14 (SSID='centtech' freq=2422 
MHz)
<2>Associated with 00:80:c8:17:b1:14
<2>Disconnect event - remove keys
<2>Trying to associate with 00:11:95:f9:fb:c2 (SSID='centtech' freq=2462 
MHz)
<2>Trying to associate with 00:11:95:f9:fb:c2 (SSID='centtech' freq=2462 
MHz)
<2>Authentication with 00:00:00:00:00:00 timed out.
<2>Trying to associate with 00:80:c8:17:b3:26 (SSID='centtech' freq=2437 
MHz)
<2>Authentication with 00:00:00:00:00:00 timed out.
[..snip ..]

The access point nearest to me is '00:80:c8:17:b3:26'.

This also happens at home, where I have a single AP and no other nearby 
APs that I can detect.

What other information would you like?  Can I make wpa_supplicant log 
verbosely to /var/log/messages?

Thanks!
Eric



-- 
------------------------------------------------------------------------
Eric Anderson        Sr. Systems Administrator        Centaur Technology
Anything that works is better than anything that doesn't.
------------------------------------------------------------------------
Received on Mon Jan 09 2006 - 16:09:17 UTC

This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:38:50 UTC