Bug 10605

Summary: ath5k driver disconnects sporadic with WPA-PSK and does not reconnect again
Product: Drivers Reporter: Helge Deller (helge.deller)
Component: network-wirelessAssignee: drivers_network-wireless (drivers_network-wireless)
Status: CLOSED CODE_FIX    
Severity: normal CC: deller, gary.trakhman, korn-kernel.org
Priority: P1    
Hardware: All   
OS: Linux   
Kernel Version: 2.6.25, 2.6.26-rc1 Subsystem:
Regression: --- Bisected commit-id:
Attachments: monitor mode tcpdump log collated with kernel log

Description Helge Deller 2008-05-05 15:29:49 UTC
Latest working kernel version: none
Earliest failing kernel version: 2.6.25 (first kernel which included ath5k)
Distribution: Fedora 7
Hardware Environment: HP NC6000 Laptop w/ built-in ath5k

Problem Description:
Laptop with built-in AR5212 network card:
02:04.0 Ethernet controller: Atheros Communications, Inc. AR5212 802.11abg NIC (rev 01)
        Subsystem: Compaq Computer Corporation Unknown device 00e5
        Flags: medium devsel, IRQ 11
        Memory at 90080000 (32-bit, non-prefetchable) [size=64K]
        Capabilities: [44] Power Management version 2

ath5k driver connects to my WPA-PSK wifi router, but after some time (and after adding some more wifi load), the ath5k driver just disconnects again and fails to reconnect. Only "rmmod ath5k" and "modprobe ath5k" brings it back again.

System log reports:
ACPI: PCI Interrupt 0000:02:04.0[A] -> Link [C0C6] -> GSI 11 (level, low) -> IRQ 11
ath5k_pci 0000:02:04.0: registered as 'phy0'
phy0: Selected rate control algorithm 'pid'
ath5k phy0: Atheros AR5213 chip found (MAC: 0x56, PHY: 0x41)
ath5k phy0: RF5111 5GHz radio found (0x17)
ath5k phy0: RF2111 2GHz radio found (0x23)
udev: renamed network interface wlan0 to wlan1
wlan1: Initial auth_alg=0
wlan1: authenticate with AP 00:50:18:3b:2b:04
wlan1: RX authentication from 00:50:18:3b:2b:04 (alg=0 transaction=2 status=0)
wlan1: authenticated
wlan1: associate with AP 00:50:18:3b:2b:04
wlan1: RX AssocResp from 00:50:18:3b:2b:04 (capab=0x471 status=0 aid=1)
wlan1: associated
wlan1: switched to short barker preamble (BSSID=00:50:18:3b:2b:04)
wlan1: invalid Michael MIC in data frame from 00:15:0c:e1:c0:96
wlan1: invalid Michael MIC in data frame from 00:15:0c:e1:c0:96
wlan1: RX disassociation from 00:50:18:3b:2b:04 (reason=1)
wlan1: disassociated
wlan1: RX disassociation from 00:50:18:3b:2b:04 (reason=7)
wlan1: RX disassociation from 00:50:18:3b:2b:04 (reason=7)
wlan1: RX disassociation from 00:50:18:3b:2b:04 (reason=7)
wlan1: RX disassociation from 00:50:18:3b:2b:04 (reason=7)
wlan1: deauthenticate(reason=14)
wlan1: associate with AP 00:50:18:3b:2b:04
wlan1: RX deauthentication from 00:50:18:3b:2b:04 (reason=9)
wlan1: deauthenticated
wlan1: authenticate with AP 00:50:18:3b:2b:04
wlan1: RX authentication from 00:50:18:3b:2b:04 (alg=0 transaction=2 status=0)
wlan1: authenticated
wlan1: associate with AP 00:50:18:3b:2b:04
wlan1: RX AssocResp from 00:50:18:3b:2b:04 (capab=0x451 status=1 aid=1)
wlan1: AP denied association (code=1)
wlan1: associate with AP 00:50:18:3b:2b:04
wlan1: RX AssocResp from 00:50:18:3b:2b:04 (capab=0x451 status=1 aid=1)
wlan1: AP denied association (code=1)
wlan1: associate with AP 00:50:18:3b:2b:04
wlan1: RX AssocResp from 00:50:18:3b:2b:04 (capab=0x451 status=1 aid=1)
wlan1: AP denied association (code=1)
wlan1: association with AP 00:50:18:3b:2b:04 timed out
wlan1: Initial auth_alg=0
wlan1: authenticate with AP 00:50:18:3b:2b:04
wlan1: RX authentication from 00:50:18:3b:2b:04 (alg=0 transaction=2 status=0)
wlan1: authenticated
wlan1: associate with AP 00:50:18:3b:2b:04
wlan1: RX AssocResp from 00:50:18:3b:2b:04 (capab=0x451 status=1 aid=1)
wlan1: AP denied association (code=1)
wlan1: associate with AP 00:50:18:3b:2b:04
wlan1: RX AssocResp from 00:50:18:3b:2b:04 (capab=0x451 status=1 aid=1)
wlan1: AP denied association (code=1)
wlan1: associate with AP 00:50:18:3b:2b:04
wlan1: RX AssocResp from 00:50:18:3b:2b:04 (capab=0x451 status=1 aid=1)
wlan1: AP denied association (code=1)
wlan1: association with AP 00:50:18:3b:2b:04 timed out
wlan1: Initial auth_alg=0
wlan1: authenticate with AP 00:50:18:3b:2b:04
wlan1: RX authentication from 00:50:18:3b:2b:04 (alg=0 transaction=2 status=0)
wlan1: authenticated
wlan1: associate with AP 00:50:18:3b:2b:04
wlan1: RX AssocResp from 00:50:18:3b:2b:04 (capab=0x451 status=1 aid=1)
wlan1: AP denied association (code=1)
wlan1: associate with AP 00:50:18:3b:2b:04
wlan1: RX AssocResp from 00:50:18:3b:2b:04 (capab=0x451 status=1 aid=1)
wlan1: AP denied association (code=1)
wlan1: associate with AP 00:50:18:3b:2b:04
wlan1: RX AssocResp from 00:50:18:3b:2b:04 (capab=0x451 status=1 aid=1)
wlan1: AP denied association (code=1)
wlan1: association with AP 00:50:18:3b:2b:04 timed out
wlan1: Initial auth_alg=0
wlan1: authenticate with AP 00:50:18:3b:2b:04
wlan1: RX authentication from 00:50:18:3b:2b:04 (alg=0 transaction=2 status=0)
wlan1: authenticated
wlan1: associate with AP 00:50:18:3b:2b:04
wlan1: RX AssocResp from 00:50:18:3b:2b:04 (capab=0x451 status=1 aid=1)
wlan1: AP denied association (code=1)
wlan1: associate with AP 00:50:18:3b:2b:04
wlan1: RX AssocResp from 00:50:18:3b:2b:04 (capab=0x451 status=1 aid=1)
wlan1: AP denied association (code=1)
wlan1: associate with AP 00:50:18:3b:2b:04
wlan1: RX AssocResp from 00:50:18:3b:2b:04 (capab=0x451 status=1 aid=1)
wlan1: AP denied association (code=1)
wlan1: association with AP 00:50:18:3b:2b:04 timed out
wlan1: Initial auth_alg=0
wlan1: authenticate with AP 00:50:18:3b:2b:04
wlan1: RX authentication from 00:50:18:3b:2b:04 (alg=0 transaction=2 status=0)
wlan1: authenticated
wlan1: associate with AP 00:50:18:3b:2b:04
wlan1: RX AssocResp from 00:50:18:3b:2b:04 (capab=0x471 status=0 aid=1)
wlan1: associated
wlan1: switched to short barker preamble (BSSID=00:50:18:3b:2b:04)

A prism54-based cardbus card with the p54 driver connects on the same laptop and wifi configuration without problems and stays connected for hours.

Steps to reproduce:
- modprobe ath5k
- Tell KNetworkmanager to use ath5k-based driver.
Comment 1 Helge Deller 2008-05-05 15:33:13 UTC
Already reported once here:
http://thread.gmane.org/gmane.linux.kernel.wireless.general/12738
Comment 2 Helge Deller 2008-05-05 15:38:58 UTC
Same problem was reported by others here: http://madwifi.org/ticket/1773   and here: http://madwifi.org/ticket/1773 (german)
Comment 3 Helge Deller 2008-05-05 15:40:19 UTC
The second (german) link from comment #2 should have been: http://groups.google.com/group/de.comp.os.unix.linux.hardware/browse_thread/thread/979eaf9288fcb928
Comment 4 Helge Deller 2008-05-12 13:34:01 UTC
I tested the patch by Bob Copeland in http://permalink.gmane.org/gmane.linux.drivers.ath5k.devel/843
and it fixes this problem.
It would be great if the patch could go into 2.6.26, since then it would be the first kernel which supportes WPA with ath5k...
Comment 5 Helge Deller 2008-05-16 13:35:05 UTC
Updated patch is here:
http://permalink.gmane.org/gmane.linux.kernel.wireless.general/14684
Comment 6 Helge Deller 2008-05-22 23:37:32 UTC
was just fixed with commit a0abb93bf9dc590b031a1123f3e6c6c225c1cdd1 into Linux kernel 2.6.26-rc3. Thanks!
Comment 7 Gary Trakhman 2009-04-30 03:53:19 UTC
I seem to be having a similar problem with 2.6.30-rc3 on ubuntu jaunty.

dmesg While viewing a hulu video:  
[19652.168794] ath5k phy1: Atheros AR2425 chip found (MAC: 0xe2, PHY: 0x70)
[19656.152973] ADDRCONF(NETDEV_UP): wlan0: link is not ready
[19657.221913] wlan0: direct probe to AP 00:15:c7:ab:5c:20 try 1
[19657.424745] wlan0: direct probe to AP 00:15:c7:ab:5c:20 try 2
[19657.621040] wlan0: direct probe to AP 00:15:c7:ab:5c:20 try 3
[19657.820090] wlan0: direct probe to AP 00:15:c7:ab:5c:20 timed out
[19661.224356] wlan0: authenticate with AP 00:18:74:49:4b:11
[19661.225649] wlan0: authenticated
[19661.225656] wlan0: associate with AP 00:18:74:49:4b:11
[19661.424068] wlan0: associate with AP 00:18:74:49:4b:11
[19661.624078] wlan0: associate with AP 00:18:74:49:4b:11
[19661.824066] wlan0: association with AP 00:18:74:49:4b:11 timed out
[19672.304688] wlan0: authenticate with AP 00:18:74:49:4b:11
[19672.304739] wlan0: authenticate with AP 00:18:74:49:4b:11
[19672.305969] wlan0: authenticated
[19672.305975] wlan0: associate with AP 00:18:74:49:4b:11
[19672.309317] wlan0: RX AssocResp from 00:18:74:49:4b:11 (capab=0x431 status=0 aid=1)
[19672.309323] wlan0: associated
[19672.310721] ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[19683.100037] wlan0: no IPv6 routers present
[19685.760764] wlan0: authenticate with AP 00:18:74:49:4b:14
[19685.764384] wlan0: authenticated
[19685.764391] wlan0: associate with AP 00:18:74:49:4b:14
[19685.964076] wlan0: associate with AP 00:18:74:49:4b:14
[19686.164077] wlan0: associate with AP 00:18:74:49:4b:14
[19686.364097] wlan0: association with AP 00:18:74:49:4b:14 timed out
[19696.894815] wlan0: authenticate with AP 00:18:74:49:4b:14
[19696.896087] wlan0: authenticated
[19696.896094] wlan0: associate with AP 00:18:74:49:4b:14
[19696.898848] wlan0: RX AssocResp from 00:18:74:49:4b:14 (capab=0x431 status=0 aid=1)
[19696.898850] wlan0: associated
[20016.081046] wlan0: beacon loss from AP 00:18:74:49:4b:14 - sending probe request
[20018.081070] wlan0: no probe response from AP 00:18:74:49:4b:14 - disassociating
[20020.285604] wlan0: authenticate with AP 00:15:c7:ab:0c:24
[20020.286813] wlan0: authenticated
[20020.286815] wlan0: associate with AP 00:15:c7:ab:0c:24
[20020.290036] wlan0: RX ReassocResp from 00:15:c7:ab:0c:24 (capab=0x431 status=0 aid=33)
[20020.290039] wlan0: associated
[20112.215937] wlan0: authenticate with AP 00:18:74:49:4b:14
[20112.217289] wlan0: authenticated
[20112.217293] wlan0: associate with AP 00:18:74:49:4b:14
[20112.220226] wlan0: RX ReassocResp from 00:18:74:49:4b:14 (capab=0x431 status=0 aid=1)
[20112.220229] wlan0: associated
Comment 8 Gary Trakhman 2009-04-30 04:24:56 UTC
I seem to be having a similar problem with 2.6.30-rc3 on ubuntu jaunty with Network Manager, WPA mschapv2 authentication.  Drops out for 30 seconds or so even though connection is Full strength.  WEP works fine.

dmesg While viewing a hulu video:  
[19652.168794] ath5k phy1: Atheros AR2425 chip found (MAC: 0xe2, PHY: 0x70)
[19656.152973] ADDRCONF(NETDEV_UP): wlan0: link is not ready
[19657.221913] wlan0: direct probe to AP 00:15:c7:ab:5c:20 try 1
[19657.424745] wlan0: direct probe to AP 00:15:c7:ab:5c:20 try 2
[19657.621040] wlan0: direct probe to AP 00:15:c7:ab:5c:20 try 3
[19657.820090] wlan0: direct probe to AP 00:15:c7:ab:5c:20 timed out
[19661.224356] wlan0: authenticate with AP 00:18:74:49:4b:11
[19661.225649] wlan0: authenticated
[19661.225656] wlan0: associate with AP 00:18:74:49:4b:11
[19661.424068] wlan0: associate with AP 00:18:74:49:4b:11
[19661.624078] wlan0: associate with AP 00:18:74:49:4b:11
[19661.824066] wlan0: association with AP 00:18:74:49:4b:11 timed out
[19672.304688] wlan0: authenticate with AP 00:18:74:49:4b:11
[19672.304739] wlan0: authenticate with AP 00:18:74:49:4b:11
[19672.305969] wlan0: authenticated
[19672.305975] wlan0: associate with AP 00:18:74:49:4b:11
[19672.309317] wlan0: RX AssocResp from 00:18:74:49:4b:11 (capab=0x431 status=0 aid=1)
[19672.309323] wlan0: associated
[19672.310721] ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[19683.100037] wlan0: no IPv6 routers present
[19685.760764] wlan0: authenticate with AP 00:18:74:49:4b:14
[19685.764384] wlan0: authenticated
[19685.764391] wlan0: associate with AP 00:18:74:49:4b:14
[19685.964076] wlan0: associate with AP 00:18:74:49:4b:14
[19686.164077] wlan0: associate with AP 00:18:74:49:4b:14
[19686.364097] wlan0: association with AP 00:18:74:49:4b:14 timed out
[19696.894815] wlan0: authenticate with AP 00:18:74:49:4b:14
[19696.896087] wlan0: authenticated
[19696.896094] wlan0: associate with AP 00:18:74:49:4b:14
[19696.898848] wlan0: RX AssocResp from 00:18:74:49:4b:14 (capab=0x431 status=0 aid=1)
[19696.898850] wlan0: associated
[20016.081046] wlan0: beacon loss from AP 00:18:74:49:4b:14 - sending probe request
[20018.081070] wlan0: no probe response from AP 00:18:74:49:4b:14 - disassociating
[20020.285604] wlan0: authenticate with AP 00:15:c7:ab:0c:24
[20020.286813] wlan0: authenticated
[20020.286815] wlan0: associate with AP 00:15:c7:ab:0c:24
[20020.290036] wlan0: RX ReassocResp from 00:15:c7:ab:0c:24 (capab=0x431 status=0 aid=33)
[20020.290039] wlan0: associated
[20112.215937] wlan0: authenticate with AP 00:18:74:49:4b:14
[20112.217289] wlan0: authenticated
[20112.217293] wlan0: associate with AP 00:18:74:49:4b:14
[20112.220226] wlan0: RX ReassocResp from 00:18:74:49:4b:14 (capab=0x431 status=0 aid=1)
[20112.220229] wlan0: associated
Comment 9 Andras Korn 2009-07-25 12:15:04 UTC
I'm still seeing the problem with 2.6.31-rc4 (well, the version of it that Ubuntu karmic ships anyway), and it's weirder than I previously thought.

I have a Lenovo Thinkpad with iwlagn that normally doesn't have any wifi connection issues. Additionally, I have an Acer Aspire ONE netbook with an "Atheros Communications Inc. AR5001" (168c:001c) adapter; plus I have a USB stick with an RT73 chip.

When I use the Atheros adapter of the netbook, it disconnects sporadically from my AP (an old low-end Micronet device, set to WPA-PSK). If I use the rt73usb stick, things are fine.

The part where it gets strange is that when using the Atheros adapter, the Thinkpad with the iwlagn adapter is also disconnected whenever the Atheros is disconnected, and the kernel messages are roughly the same. This leads me to believe that the Atheros card sends something that confuses the AP so thoroughly that it disassociates all clients.

Here is a somewhat collated kernel log of the two (gehenna is the Thinkpad with awlagn, cherub is the Aspire One with ath5k):

Jul 25 12:50:02 cherub kernel: [  789.872172] wlan0: deauthenticated (Reason: 14)
Jul 25 12:50:03 cherub kernel: [  790.872229] wlan0: direct probe to AP 00:0d:88:c9:04:7f try 1
Jul 25 12:50:03 cherub kernel: [  790.877046] wlan0 direct probe responded
Jul 25 12:50:03 cherub kernel: [  790.877066] wlan0: authenticate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:03 cherub kernel: [  790.878647] wlan0: authenticated
Jul 25 12:50:03 cherub kernel: [  790.878666] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:03 cherub kernel: [  790.882951] wlan0: RX ReassocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:03 cherub kernel: [  790.882974] wlan0: AP denied association (code=12)
Jul 25 12:50:03 cherub kernel: [  791.076089] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:03 cherub kernel: [  791.078269] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:03 cherub kernel: [  791.078280] wlan0: AP denied association (code=12)
Jul 25 12:50:03 cherub kernel: [  791.276089] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:03 cherub kernel: [  791.278304] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:03 cherub kernel: [  791.278317] wlan0: AP denied association (code=12)
Jul 25 12:50:03 cherub kernel: [  791.476142] wlan0: association with AP 00:0d:88:c9:04:7f timed out
Jul 25 12:50:03 gehenna kernel: [172503.744312] wlan0: deauthenticated
Jul 25 12:50:03 gehenna kernel: [172503.862001] wlan0: authenticate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:03 gehenna kernel: [172503.862001] wlan0: authenticate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:03 gehenna kernel: [172503.865172] wlan0: authenticated
Jul 25 12:50:03 gehenna kernel: [172503.865172] wlan0: authenticated
Jul 25 12:50:03 gehenna kernel: [172503.865180] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:03 gehenna kernel: [172503.865180] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:03 gehenna kernel: [172503.867671] wlan0: RX ReassocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:03 gehenna kernel: [172503.867671] wlan0: RX ReassocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:03 gehenna kernel: [172503.867676] wlan0: AP denied association (code=12)
Jul 25 12:50:03 gehenna kernel: [172504.064122] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:03 gehenna kernel: [172504.066625] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:03 gehenna kernel: [172504.066630] wlan0: AP denied association (code=12)
Jul 25 12:50:03 gehenna kernel: [172504.266455] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:03 gehenna kernel: [172504.268936] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:03 gehenna kernel: [172504.268942] wlan0: AP denied association (code=12)
Jul 25 12:50:03 gehenna kernel: [172504.464109] wlan0: association with AP 00:0d:88:c9:04:7f timed out
Jul 25 12:50:05 cherub kernel: [  793.392087] wlan0: authenticate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:05 cherub kernel: [  793.393630] wlan0: authenticated
Jul 25 12:50:05 cherub kernel: [  793.393641] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:05 cherub kernel: [  793.395992] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:05 cherub kernel: [  793.396090] wlan0: AP denied association (code=12)
Jul 25 12:50:05 cherub kernel: [  793.593070] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:05 cherub kernel: [  793.595271] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:05 cherub kernel: [  793.595288] wlan0: AP denied association (code=12)
Jul 25 12:50:06 cherub kernel: [  793.792154] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:06 cherub kernel: [  793.794355] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:06 cherub kernel: [  793.794367] wlan0: AP denied association (code=12)
Jul 25 12:50:06 cherub kernel: [  793.992123] wlan0: association with AP 00:0d:88:c9:04:7f timed out
Jul 25 12:50:11 cherub kernel: [  799.735558] wlan0: authenticate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:11 cherub kernel: [  799.737146] wlan0: authenticated
Jul 25 12:50:11 cherub kernel: [  799.737158] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:11 cherub kernel: [  799.739570] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:11 cherub kernel: [  799.739580] wlan0: AP denied association (code=12)
Jul 25 12:50:12 cherub kernel: [  799.937398] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:12 cherub kernel: [  799.939649] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:12 cherub kernel: [  799.939661] wlan0: AP denied association (code=12)
Jul 25 12:50:12 cherub kernel: [  800.136464] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:12 cherub kernel: [  800.138630] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:12 cherub kernel: [  800.138643] wlan0: AP denied association (code=12)
Jul 25 12:50:12 cherub kernel: [  800.336313] wlan0: association with AP 00:0d:88:c9:04:7f timed out
Jul 25 12:50:13 gehenna kernel: [172514.839886] wlan0: authenticate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:13 gehenna kernel: [172514.845369] wlan0: authenticate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:13 gehenna kernel: [172514.845391] wlan0: authenticated
Jul 25 12:50:13 gehenna kernel: [172514.845398] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:13 gehenna kernel: [172514.849864] wlan0: deauthenticated
Jul 25 12:50:14 cherub kernel: [  802.358728] wlan0: authenticate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:14 cherub kernel: [  802.360344] wlan0: authenticated
Jul 25 12:50:14 cherub kernel: [  802.360354] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:14 cherub kernel: [  802.362660] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:14 cherub kernel: [  802.362672] wlan0: AP denied association (code=12)
Jul 25 12:50:14 cherub kernel: [  802.561053] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:14 cherub kernel: [  802.563191] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:14 cherub kernel: [  802.563202] wlan0: AP denied association (code=12)
Jul 25 12:50:14 cherub kernel: [  802.749983] r8169: eth0: link down
Jul 25 12:50:14 cherub kernel: [  802.751248] ADDRCONF(NETDEV_UP): eth0: link is not ready
Jul 25 12:50:14 gehenna kernel: [172515.848135] wlan0: direct probe to AP 00:0d:88:c9:04:7f try 1
Jul 25 12:50:14 gehenna kernel: [172515.850888] wlan0 direct probe responded
Jul 25 12:50:14 gehenna kernel: [172515.850896] wlan0: authenticate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:14 gehenna kernel: [172515.853187] wlan0: authenticated
Jul 25 12:50:14 gehenna kernel: [172515.853194] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:14 gehenna kernel: [172515.855648] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:14 gehenna kernel: [172515.855654] wlan0: AP denied association (code=12)
Jul 25 12:50:14 gehenna kernel: [172516.052120] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:14 gehenna kernel: [172516.054631] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:14 gehenna kernel: [172516.054637] wlan0: AP denied association (code=12)
Jul 25 12:50:14 gehenna kernel: [172516.255595] wlan0: association with AP 00:0d:88:c9:04:7f timed out
Jul 25 12:50:15 cherub kernel: [  802.761081] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:15 cherub kernel: [  802.763250] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:15 cherub kernel: [  802.763263] wlan0: AP denied association (code=12)
Jul 25 12:50:15 cherub kernel: [  802.777180] wlan0: deauthenticating by local choice (reason=3)
Jul 25 12:50:15 cherub kernel: [  802.977157] ADDRCONF(NETDEV_UP): wlan0: link is not ready
Jul 25 12:50:15 cherub kernel: [  803.125857] ADDRCONF(NETDEV_UP): wlan0: link is not ready
Jul 25 12:50:15 gehenna kernel: [172516.871389] iwlagn: MAC is in deep sleep!
Jul 25 12:50:15 gehenna kernel: [172517.393083] Registered led device: iwl-phy0:radio
Jul 25 12:50:15 gehenna kernel: [172517.393128] Registered led device: iwl-phy0:assoc
Jul 25 12:50:15 gehenna kernel: [172517.393171] Registered led device: iwl-phy0:RX
Jul 25 12:50:15 gehenna kernel: [172517.393210] Registered led device: iwl-phy0:TX
Jul 25 12:50:15 gehenna kernel: [172517.447710] ADDRCONF(NETDEV_UP): wlan0: link is not ready
Jul 25 12:50:15 gehenna kernel: [172517.572860] iwlagn: MAC is in deep sleep!
Jul 25 12:50:16 cherub kernel: [  804.482073] wlan0: authenticate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:16 cherub kernel: [  804.483676] wlan0: authenticated
Jul 25 12:50:16 cherub kernel: [  804.483687] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:16 cherub kernel: [  804.486022] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:16 cherub kernel: [  804.486034] wlan0: AP denied association (code=12)
Jul 25 12:50:16 cherub kernel: [  804.681062] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:16 cherub kernel: [  804.683234] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:16 cherub kernel: [  804.683250] wlan0: AP denied association (code=12)
Jul 25 12:50:17 cherub kernel: [  804.881052] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:17 cherub kernel: [  804.883228] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:17 cherub kernel: [  804.883240] wlan0: AP denied association (code=12)
Jul 25 12:50:17 cherub kernel: [  805.081077] wlan0: association with AP 00:0d:88:c9:04:7f timed out
Jul 25 12:50:22 cherub kernel: [  810.198669] wlan0: authenticate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:22 cherub kernel: [  810.201878] wlan0: authenticated
Jul 25 12:50:22 cherub kernel: [  810.201890] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:22 cherub kernel: [  810.204118] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:22 cherub kernel: [  810.204132] wlan0: AP denied association (code=12)
Jul 25 12:50:22 cherub kernel: [  810.401069] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:22 cherub kernel: [  810.403237] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:22 cherub kernel: [  810.403247] wlan0: AP denied association (code=12)
Jul 25 12:50:22 cherub kernel: [  810.603699] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:22 cherub kernel: [  810.605875] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:22 cherub kernel: [  810.605885] wlan0: AP denied association (code=12)
Jul 25 12:50:23 cherub kernel: [  810.800086] wlan0: association with AP 00:0d:88:c9:04:7f timed out
Jul 25 12:50:27 cherub kernel: [  815.530784] wlan0: authenticate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:27 cherub kernel: [  815.532320] wlan0: authenticated
Jul 25 12:50:27 cherub kernel: [  815.532330] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:27 cherub kernel: [  815.534644] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:27 cherub kernel: [  815.534656] wlan0: AP denied association (code=12)
Jul 25 12:50:27 cherub kernel: [  815.733107] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:27 cherub kernel: [  815.735329] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:27 cherub kernel: [  815.735353] wlan0: AP denied association (code=12)
Jul 25 12:50:28 cherub kernel: [  815.933190] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:28 cherub kernel: [  815.935757] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:28 cherub kernel: [  815.935769] wlan0: AP denied association (code=12)
Jul 25 12:50:28 cherub kernel: [  816.133077] wlan0: association with AP 00:0d:88:c9:04:7f timed out
Jul 25 12:50:34 cherub kernel: [  821.871385] wlan0: authenticate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:34 cherub kernel: [  821.872889] wlan0: authenticated
Jul 25 12:50:34 cherub kernel: [  821.872899] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:34 cherub kernel: [  821.875211] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:34 cherub kernel: [  821.875223] wlan0: AP denied association (code=12)
Jul 25 12:50:34 cherub kernel: [  822.069237] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:34 cherub kernel: [  822.082858] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:34 cherub kernel: [  822.082882] wlan0: AP denied association (code=12)
Jul 25 12:50:34 cherub kernel: [  822.272563] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:34 cherub kernel: [  822.277168] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:34 cherub kernel: [  822.277191] wlan0: AP denied association (code=12)
Jul 25 12:50:34 cherub kernel: [  822.472596] wlan0: association with AP 00:0d:88:c9:04:7f timed out
Jul 25 12:50:40 cherub kernel: [  828.230154] wlan0: authenticate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:40 cherub kernel: [  828.231663] wlan0: authenticated
Jul 25 12:50:40 cherub kernel: [  828.231674] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:40 cherub kernel: [  828.233971] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:40 cherub kernel: [  828.233984] wlan0: AP denied association (code=12)
Jul 25 12:50:40 cherub kernel: [  828.428102] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:40 cherub kernel: [  828.430260] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:40 cherub kernel: [  828.430269] wlan0: AP denied association (code=12)
Jul 25 12:50:40 cherub kernel: [  828.628129] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:40 cherub kernel: [  828.630323] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:40 cherub kernel: [  828.630336] wlan0: AP denied association (code=12)
Jul 25 12:50:41 cherub kernel: [  828.828161] wlan0: association with AP 00:0d:88:c9:04:7f timed out
Jul 25 12:50:46 cherub kernel: [  834.571290] wlan0: authenticate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:46 cherub kernel: [  834.572777] wlan0: authenticated
Jul 25 12:50:46 cherub kernel: [  834.572787] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:46 cherub kernel: [  834.575439] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:46 cherub kernel: [  834.575451] wlan0: AP denied association (code=12)
Jul 25 12:50:47 cherub kernel: [  834.773098] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:47 cherub kernel: [  834.775290] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:47 cherub kernel: [  834.775302] wlan0: AP denied association (code=12)
Jul 25 12:50:47 cherub kernel: [  834.973105] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:47 cherub kernel: [  834.975332] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:47 cherub kernel: [  834.975344] wlan0: AP denied association (code=12)
Jul 25 12:50:47 cherub kernel: [  835.173847] wlan0: association with AP 00:0d:88:c9:04:7f timed out
Jul 25 12:50:53 cherub kernel: [  840.910630] wlan0: authenticate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:53 cherub kernel: [  840.912167] wlan0: authenticated
Jul 25 12:50:53 cherub kernel: [  840.912177] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:53 cherub kernel: [  840.914560] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:53 cherub kernel: [  840.914571] wlan0: AP denied association (code=12)
Jul 25 12:50:53 cherub kernel: [  841.113138] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:53 cherub kernel: [  841.115324] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:53 cherub kernel: [  841.115337] wlan0: AP denied association (code=12)
Jul 25 12:50:53 cherub kernel: [  841.313067] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:53 cherub kernel: [  841.315260] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:53 cherub kernel: [  841.315273] wlan0: AP denied association (code=12)
Jul 25 12:50:53 cherub kernel: [  841.513094] wlan0: association with AP 00:0d:88:c9:04:7f timed out
Jul 25 12:50:59 cherub kernel: [  847.251447] wlan0: authenticate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:59 cherub kernel: [  847.253151] wlan0: authenticated
Jul 25 12:50:59 cherub kernel: [  847.253163] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:59 cherub kernel: [  847.255313] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:59 cherub kernel: [  847.255326] wlan0: AP denied association (code=12)
Jul 25 12:50:59 cherub kernel: [  847.453085] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:59 cherub kernel: [  847.455274] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:59 cherub kernel: [  847.455287] wlan0: AP denied association (code=12)
Jul 25 12:50:59 cherub kernel: [  847.653122] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:50:59 cherub kernel: [  847.655346] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=12 aid=0)
Jul 25 12:50:59 cherub kernel: [  847.655367] wlan0: AP denied association (code=12)
Jul 25 12:51:00 cherub kernel: [  847.853077] wlan0: association with AP 00:0d:88:c9:04:7f timed out
Jul 25 12:51:05 cherub kernel: [  853.614448] wlan0: authenticate with AP 00:0d:88:c9:04:7f
Jul 25 12:51:05 cherub kernel: [  853.615982] wlan0: authenticated
Jul 25 12:51:05 cherub kernel: [  853.615991] wlan0: associate with AP 00:0d:88:c9:04:7f
Jul 25 12:51:05 cherub kernel: [  853.618490] wlan0: RX AssocResp from 00:0d:88:c9:04:7f (capab=0x431 status=0 aid=11)
Jul 25 12:51:05 cherub kernel: [  853.618502] wlan0: associated
Jul 25 12:51:05 cherub kernel: [  853.620221] ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Jul 25 12:51:16 cherub kernel: [  864.097036] wlan0: no IPv6 routers present
Jul 25 12:52:38 cherub kernel: [  945.861520] ath5k phy0: unsupported jumbo
Jul 25 12:52:38 cherub kernel: [  946.526479] ath5k phy0: unsupported jumbo
Jul 25 12:52:52 cherub kernel: [  959.945532] ath5k phy0: unsupported jumbo

I'll get more precise timestamps using socklog instead of syslogd if it makes sense.

I also tried to plug the rt73 usb stick into the aspire one, set it to monitor mode and capture the traffic when the ath5k is acting up.

I collated the output of tcpdump -nlvvve with the kernel log; I don't know if this is useful at all, but I'll attach the file.
Comment 10 Andras Korn 2009-07-25 12:59:37 UTC
Created attachment 22488 [details]
monitor mode tcpdump log collated with kernel log

Captured on the computer with the buggy ath5k driver, using an rt73usb adapter in monitor mode. The timestamps in the kernel log were provided by socklog/svlogd (there might be a lag of a few msec due to the pipe read/writes).

I removed the beacon frames on the assumption that they wouldn't be interesting.