Bug 14267

Going to do a bisect when I get a chance. The issue appeared somewhere between 2.6.30 and 2.6.31 and is still present in 2.6.31.1.

Created attachment 23266 [details]
Part of bisect log

I tried to do a bisect on the bug but since it only appears after a certain time it was hard to be sure what was good. When reading this bisect log please remember that the bad sections are confirmed while the good ones might be bad (just didnt wait long enough).
Hopefully this will atleast shorten down the time for someone doing another bisect.

On Monday 05 October 2009, Justin Mattock wrote:
> On Thu, Oct 1, 2009 at 12:56 PM, Rafael J. Wysocki <rjw@sisk.pl> wrote:
> > This message has been generated automatically as a part of a report
> > of regressions introduced between 2.6.30 and 2.6.31.
> >
> > The following bug entry is on the current list of known regressions
> > introduced between 2.6.30 and 2.6.31.  Please verify if it still should
> > be listed and let me know (either way).
> >
> >
> > Bug-Entry       : http://bugzilla.kernel.org/show_bug.cgi?id=14267
> > Subject         : Disassociating atheros wlan
> > Submitter       : Kristoffer Ericson <kristoffer.ericson@gmail.com>
> > Date            : 2009-09-24 10:16 (8 days old)
> > References      : http://marc.info/?l=linux-kernel&m=125378723723384&w=4
> >
> >
> >
> 
> Sorry for the delay
> (spent some time in bodie).
> yes it should be still open.

At the moment I'm seeing two messages
1) No probe response from AP xx:xx:xx:xx:xx after 500ms, disconnecting.

2) wlan0 deauthenticating by local choice (reason=3) 

I have seen the Disassociating message, but can't remember when.
At the moment I'll do a bisect for these two, and then go from there.
(maybe I saw the  Disassociating message after a while of running the internet off of the card).

I've seen both, although 1. (with disassociating instead of disconnecting) stands for approx 90%.

Under usual internet load (casual browsing) it happens after 15-30mins, takes longer if internet isnt active. I run through my 3G modem (ppp0) and allow my gf to use my internet through wireless (wlan0).
When I bisected (without using my internet, due to problems) it could take anywhere between 30min - 2 hours before I got that message. 
On my 2.6.30 kernel I essentially never saw it even after 48hours of uptime.

At the moment ill see if I can do the bisect for:
No probe response from AP xx:xx:xx:xx:xx after 500ms, disconnecting.
(hopefully I do this correctly i.g. at one point I might have not of waited long enough to see if this fires off and gave a git bisect good, kind of what happened to you)

o.k. I'll try a bisect from 2.6.30 to current.
(hopefully I don't get confused with good/bad this time on the bisect)

shoot something happened between: 2.6.31-rc1-00001-g245acb8 and 2.6.31-03427-g2195d28 

git bisect start
# bad: [df58bee21ed218cb7dfb561a590b1bd2a99531cf] Merge branch 'x86-mce-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/linux-2.6-tip
git bisect bad df58bee21ed218cb7dfb561a590b1bd2a99531cf
# good: [07a2039b8eb0af4ff464efd3dfd95de5c02648c6] Linux 2.6.30
git bisect good 07a2039b8eb0af4ff464efd3dfd95de5c02648c6
# good: [245acb87729bc76ba65c7476665c01837e0cdccb] ipsec: Fix name of CAST algorithm
git bisect good 245acb87729bc76ba65c7476665c01837e0cdccb
# good: [6ace40effd34331a604c5eeae90838cf8dd7eb8f] V4L/DVB (12316): v4l: add V4L2_CAP_RDS_OUTPUT and V4L2_CAP_MODULATOR caps
git bisect good 6ace40effd34331a604c5eeae90838cf8dd7eb8f

[    8.586423] ath9k: Unknown symbol ath_rxbuf_alloc
[    8.610849] ath9k: Unknown symbol ath_regd_get_band_ctl
[    8.634718] ath9k: Unknown symbol ath_reg_notifier_apply
[    8.657832] ath9k: Unknown symbol ath_is_world_regd
[    8.680578] ath9k: Unknown symbol ath_regd_init


besides this 2.6.30 looks like a good starting point, but If I keep hitting this *.h issue(unkown symbol), could take longer than expected.

(In reply to comment #8)
> shoot something happened between: 2.6.31-rc1-00001-g245acb8 and
> 2.6.31-03427-g2195d28 
> 
> git bisect start
> # bad: [df58bee21ed218cb7dfb561a590b1bd2a99531cf] Merge branch
> 'x86-mce-for-linus' of
> git://git.kernel.org/pub/scm/linux/kernel/git/tip/linux-2.6-tip
> git bisect bad df58bee21ed218cb7dfb561a590b1bd2a99531cf
> # good: [07a2039b8eb0af4ff464efd3dfd95de5c02648c6] Linux 2.6.30
> git bisect good 07a2039b8eb0af4ff464efd3dfd95de5c02648c6
> # good: [245acb87729bc76ba65c7476665c01837e0cdccb] ipsec: Fix name of CAST
> algorithm
> git bisect good 245acb87729bc76ba65c7476665c01837e0cdccb
> # good: [6ace40effd34331a604c5eeae90838cf8dd7eb8f] V4L/DVB (12316): v4l: add
> V4L2_CAP_RDS_OUTPUT and V4L2_CAP_MODULATOR caps
> git bisect good 6ace40effd34331a604c5eeae90838cf8dd7eb8f
> 
> [    8.586423] ath9k: Unknown symbol ath_rxbuf_alloc
> [    8.610849] ath9k: Unknown symbol ath_regd_get_band_ctl
> [    8.634718] ath9k: Unknown symbol ath_reg_notifier_apply
> [    8.657832] ath9k: Unknown symbol ath_is_world_regd
> [    8.680578] ath9k: Unknown symbol ath_regd_init
> 
> 
> besides this 2.6.30 looks like a good starting point, but If I keep hitting
> this *.h issue(unkown symbol), could take longer than expected.

Still don't understand why this happened, my only guess is something to
do with doing the bisect in my own working branch, maybe something went
astray...

Created attachment 23313 [details]
git-bisected from 2.6.30 to current HEAD.

Here's my git log from 2.6.30 to the current HEAD. personally I think it's off
by a few due to the inconsistency of this type, hopefully it's in the vicinity of what might be causing these issues.
Please look at them and give feedback. If I need to do another bisect
let me know(just point out to me what I need to look for with this, since this issue seems to be tricky).  below is what git bisect said was the problem
(I'm not convinced that it is, but could be wrong).


ab1faead50d09165b58c2854997c7205ca9c0d22 is the first bad commit
commit ab1faead50d09165b58c2854997c7205ca9c0d22
Author: Johannes Berg <johannes@sipsolutions.net>
Date:   Wed Jul 1 21:41:17 2009 +0200

    mac80211: remove dead code, clean up
    
    With mac80211 now always controlled by an external SME,
    a lot of code is dead -- SSID, BSSID, channel selection
    is always done externally, etc. Additionally, rename
    IEEE80211_STA_TKIP_WEP_USED to IEEE80211_STA_DISABLE_11N
    and clean up the code a bit.
    
    Signed-off-by: Johannes Berg <johannes@sipsolutions.net>
    Signed-off-by: John W. Linville <linville@tuxdriver.com>

:040000 040000 f54510842d8d7dda1ec785adce24db67882a5e33 1dc7d91f8ce18060117bfb76c8b0131e86bed885 M      net

Good work, will give it a go later next week once I get back to my apartment. Atleast we got an area to work with so should be able to pin it down eventually.

Cool thanks,
towards the end of the bisect was too tired to start testing single commits to see.(hopefully this gets us in the vicinity though) 
tomorrow Ill plug-in some single commits to see.

I have the same problem with the b43 driver – can’t get connected more than 1min with a 2.6.32-rc3 kernel (same error), works fine with a 2.6.30.

If you can, I attached my bisect log to the bugreport, thumb through and individually try reverting some commits to see.(was in the process of doing so, but got distracted with other things).
If none of the commits listed with the bisect log work. then you'll probably have to do a bisect of your own to see..(shouldn't take too long).

Having the same issue here (ath9k on an Eee 1000HE), just wanted to add that it happens at school all the time, sometimes as soon as I connect (unsecured 802.11g).  However, at home I have yet to see it happen (WPA2 802.11n).

Hopefully that's useful to someone.  I've been trying to track down the source of my wireless problems in 2.6.31+, my rfkill issues seem to be clearing up now, but this is the newest major problem.

On Monday 26 October 2009, Kristoffer Ericson wrote:
> On Mon, 26 Oct 2009 20:31:55 +0100 (CET)
> "Rafael J. Wysocki" <rjw@sisk.pl> wrote:
> 
> > This message has been generated automatically as a part of a report
> > of regressions introduced between 2.6.30 and 2.6.31.
> > 
> > The following bug entry is on the current list of known regressions
> > introduced between 2.6.30 and 2.6.31.  Please verify if it still should
> > be listed and let me know (either way).
> > 
> > 
> > Bug-Entry   : http://bugzilla.kernel.org/show_bug.cgi?id=14267
> > Subject             : Disassociating atheros wlan
> > Submitter   : Kristoffer Ericson <kristoffer.ericson@gmail.com>
> > Date                : 2009-09-24 10:16 (33 days old)
> > References  : http://marc.info/?l=linux-kernel&m=125378723723384&w=4
> > 
> > 
> 
> Still valid and should remain.

On Tuesday 17 November 2009, Kristoffer Ericson wrote:
> On Mon, 16 Nov 2009 16:53:18 -0800
> "Justin P. Mattock" <justinmattock@gmail.com> wrote:
> 
> > Rafael J. Wysocki wrote:
> > > This message has been generated automatically as a part of a report
> > > of regressions introduced between 2.6.30 and 2.6.31.
> > >
> > > The following bug entry is on the current list of known regressions
> > > introduced between 2.6.30 and 2.6.31.  Please verify if it still should
> > > be listed and let me know (either way).
> > >
> > >
> > > Bug-Entry : http://bugzilla.kernel.org/show_bug.cgi?id=14267
> > > Subject           : Disassociating atheros wlan
> > > Submitter : Kristoffer Ericson<kristoffer.ericson@gmail.com>
> > > Date              : 2009-09-24 10:16 (54 days old)
> > > References        :
> http://marc.info/?l=linux-kernel&m=125378723723384&w=4
> > >
> > >
> > >
> > >    
> > I'm not sure(I've been procrastinating on this one
> > with reverting commits to see if it helps
> > the guy that reported this).
> > 
> >  From over here though there never was a problem
> > on my side with the wireless connection(maybe a few disconnects,
> > but nothing too harsh).
> > 
> > At this point the best thing to do is to see what the
> > response is from the two gentlemen who where really
> > hitting this and seem to be running into issues
> > then go from there.
> 
> Im still hitting this so basicly using 2.6.30 until it get sorted. Will try
> and make
> some time to test the different commits. Last time I waited for it to
> disconnect which
> could take 10-40min. Since it depends on the network load Im now going to
> increase
> the load to see if I hit it quicker (and thus finding the error commit).
> 
> So in short, its still valid and I will try and make time to fix it :)

hmm.. looking at my bisect-log, seems there was more to it there
whats in there now(must have done something wrong with the upload).

On Wednesday 18 November 2009, Christoph Hellwig wrote:
> On Tue, Nov 17, 2009 at 12:01:19AM +0100, Rafael J. Wysocki wrote:
> > This message has been generated automatically as a part of a report
> > of regressions introduced between 2.6.30 and 2.6.31.
> > 
> > The following bug entry is on the current list of known regressions
> > introduced between 2.6.30 and 2.6.31.  Please verify if it still should
> > be listed and let me know (either way).
> 
> FYI I see exactly the same symptoms - tons of probe timeouts, usually
> very shortly after the association.  But I see this with an Intel 5100
> AGN so it's either mac80211-related or coincidence.  I now went back to
> 2.6.31 which is perfectly fine for about half an hour.  I'll try to
> bisect it down a bit, but many .32-rc releases hang on very early in
> ACPI code on this box which might make it a pain or impossible.

man!! my bad I must have been tired that day(uploaded the wrong bisect file). below is the bisect log 
(I don't want to upload because I'm afraid I'll screw up again)

/* macbook pro ati chipset with AR5008 Wireless Network Adapter (rev 01) */

git bisect start
# bad: [36a07902c2134649c4af7f07980413ffb1a56085] Merge branch 'upstream-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/jgar
zik/libata-dev
git bisect bad 36a07902c2134649c4af7f07980413ffb1a56085
# good: [07a2039b8eb0af4ff464efd3dfd95de5c02648c6] Linux 2.6.30
git bisect good 07a2039b8eb0af4ff464efd3dfd95de5c02648c6
# good: [4abf27add86e5b7c37dca1fb4dd9a740b4332a84] Merge branch 'for-rmk' of git://git.marvell.com/orion into devel-stable
git bisect good 4abf27add86e5b7c37dca1fb4dd9a740b4332a84
# bad: [ada3fa15057205b7d3f727bba5cd26b5912e350f] Merge branch 'for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tj/percpu
git bisect bad ada3fa15057205b7d3f727bba5cd26b5912e350f
# good: [ea47689e74a1637fac4f5fc44890f3662c976849] V4L/DVB (12720): em28xx-cards: Add vendor/product id for Kworld DVD Maker 2
git bisect good ea47689e74a1637fac4f5fc44890f3662c976849
# bad: [44364a035a4f7c5b58fd96b1a90b52746d1aab6b] s2io.c: use kzalloc
git bisect bad 44364a035a4f7c5b58fd96b1a90b52746d1aab6b
# bad: [d7e7d229c7d1395283e1e1fda8727af60ca6f4ad] ath9k: add initial hardware support for ar9271
git bisect bad d7e7d229c7d1395283e1e1fda8727af60ca6f4ad
# bad: [4b9631a4734e25e37c83e72c3e0ffcbb08de5791] rt2x00: Remove DEVICE_STATE_DISABLED_RADIO_HW
git bisect bad 4b9631a4734e25e37c83e72c3e0ffcbb08de5791
# bad: [3354a0f6a3ced6957dfb9f689ad075cfa8fd272f] iwlwifi: Check HW ready before prepare card.
git bisect bad 3354a0f6a3ced6957dfb9f689ad075cfa8fd272f
# good: [1e6f172fccbf1194bad4b2aeae437ec3189a3f08] wl12xx: remove unused wl12xx_hw_init_mem_config()
git bisect good 1e6f172fccbf1194bad4b2aeae437ec3189a3f08
# good: [5217c571c898371c540e49671600d54346b2e123] orinoco: convert mode setting to cfg80211
git bisect good 5217c571c898371c540e49671600d54346b2e123
# good: [6829c878ecd24ff0ae41b4668c7e9d0f11b66942] cfg80211: emulate connect with auth/assoc
git bisect good 6829c878ecd24ff0ae41b4668c7e9d0f11b66942
# bad: [0eb14647fc6b56f73efb28a72ca0c7cc03a653f9] cfg80211: reset auth algorithm
git bisect bad 0eb14647fc6b56f73efb28a72ca0c7cc03a653f9
# good: [8990646d2fafeacfacba4a4b1073a4216662089a] cfg80211: implement get_wireless_stats
git bisect good 8990646d2fafeacfacba4a4b1073a4216662089a
# good: [6dc1cb0319997648f59b0f46b9e093e779f0353d] mac80211: remove auth algorithm retry
git bisect good 6dc1cb0319997648f59b0f46b9e093e779f0353d
# bad: [e45cd82ace91b71bc690ba78a0ebea17edfaabef] cfg80211: send events for userspace SME
git bisect bad e45cd82ace91b71bc690ba78a0ebea17edfaabef
# bad: [ab1faead50d09165b58c2854997c7205ca9c0d22] mac80211: remove dead code, clean up
git bisect bad ab1faead50d09165b58c2854997c7205ca9c0d22

hmm.. just threw my old system away on this machine, and threw in a new one.
except this time changed  No Forced Preemption (Server) to
Voluntary Kernel Preemption (Desktop) and set the time freq to 1000

upon loading up and running music/firefox etc.. the wireless/wpa_supplicant kept
disconnecting(really noticeably this time). I'll have to try another bisect on this.(the time to recreate this varies from right off the bat, to around 20/30min)

Take a look here: http://bugzilla.kernel.org/show_bug.cgi?id=13807

It seems like that might be helping some people.

hmm, sounds like pretty much same bug as this. I can understand why that patch works, but it doesnt really fix the underlying issue. 

"ath9k: DMA failed to stop in 10 ms AR_CR=0x00000024 AR_DIAG_SW=0x40000020" might be worth looking at.

Ive pretty much setup a testground now, so will give it a go tommorow. Justin, please go ahead and bisect and we'll see if we end up at same point (or atleast are).

in the process of doing another. above is the bisect from the other system.
keep in mind the recreation of this was way different than that of what I'm seeing now.(could of been the change of the .config, or something else).

In any case hopefully I can get somewhere on this, but then again you never know.

Whew I'm just now finishing up the bisect...(took a while).
Anyways reverting the commit below that the bisection found fixes the crappy connections that I've been experiencing.(didn't see this drastic of internet 
disconnects with the other machine because my .config was different i.g. changing  No Forced Preemption (Server) to Voluntary Kernel Preemption (Desktop) and changing the timer to 1000 but keep in mind that's just a guess)

below is the commit that's breaks my machine, reverting fixes it(but still need
to run the machine longer to make sure)and also the bisect log


75e6c3b72b3ab01c47629f3fbd0fed4e6550bf3a is the first bad commit
commit 75e6c3b72b3ab01c47629f3fbd0fed4e6550bf3a
Author: Johannes Berg <johannes@sipsolutions.net>
Date:   Fri Jul 31 11:18:13 2009 +0200

    cfg80211: lower dynamic PS timeout to 100ms
    
    The default of 500ms is pretty high, and leads
    to the device being awake at least 50% of the
    time under such light traffic conditions as a
    simple 1 second interval ping. Reduce to just
    100ms -- it should have a similar effect while
    providing a better sleep time.
    
    Signed-off-by: Johannes Berg <johannes@sipsolutions.net>
    Reviewed-by: Kalle Valo <kalle.valo@iki.fi>
    Signed-off-by: John W. Linville <linville@tuxdriver.com>

:040000 040000 52984337716157e60f8cec1ea9b28a8b102e4513 816e9331ef9ba0ebca266712b95a88abfff3bf35 M      net





and the bisect log(don't want to upload because the last time things got messed up)




git bisect start
# bad: [a8a8a669ea13d792296737505adc43ccacf3a648] Merge branch 'i2c-pnx-fixes' of git://git.fluff.org/bjdooks/linux
git bisect bad a8a8a669ea13d792296737505adc43ccacf3a648
# good: [07a2039b8eb0af4ff464efd3dfd95de5c02648c6] Linux 2.6.30
git bisect good 07a2039b8eb0af4ff464efd3dfd95de5c02648c6
# good: [cda9856f1ca62484433b9f734cd0fd553a5e4850] Merge branch 'fix/hda' of git://git.kernel.org/pub/scm/linux/kernel/git/tiwai/sound-2.6
git bisect good cda9856f1ca62484433b9f734cd0fd553a5e4850
# bad: [ca043a66ae48c74fa628ec92178f7a54f5b9a106] Merge branch 'x86-fixes-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/linux-2.6-tip
git bisect bad ca043a66ae48c74fa628ec92178f7a54f5b9a106
# bad: [d7e9660ad9d5e0845f52848bce31bcf5cdcdea6b] Merge git://git.kernel.org/pub/scm/linux/kernel/git/davem/net-next-2.6
git bisect bad d7e9660ad9d5e0845f52848bce31bcf5cdcdea6b
# bad: [58f25468b5636c390ad2a58356b127c0055884b4] netxen: fix tx descriptor structure
git bisect bad 58f25468b5636c390ad2a58356b127c0055884b4
# bad: [bcba8eae12fce23686b84a56d19f5fc78bf182ae] cfg80211: Set WEP ciphers
git bisect bad bcba8eae12fce23686b84a56d19f5fc78bf182ae
# good: [e5108d075c705ed3336163d9ead2b8fe629f680d] iwlwifi: Led blinking counting both tx and rx
git bisect good e5108d075c705ed3336163d9ead2b8fe629f680d
# good: [ae6f53f25f9803212d1985b5eb5a03111f439c24] ath5k: update PCU opmode whenever a new interface is added
git bisect good ae6f53f25f9803212d1985b5eb5a03111f439c24
# bad: [bfe34ebbaa125f00da309f59cc9d30febe1e3115] Merge branch 'master' of git://git.kernel.org/pub/scm/linux/kernel/git/linville/wireless-next-2.6
git bisect bad bfe34ebbaa125f00da309f59cc9d30febe1e3115
# bad: [8df5d1b77395271dd9b75ed2b9aa9235f7589a0d] ath9k: move devid cache setting to ath_init()
git bisect bad 8df5d1b77395271dd9b75ed2b9aa9235f7589a0d
# bad: [75e6c3b72b3ab01c47629f3fbd0fed4e6550bf3a] cfg80211: lower dynamic PS timeout to 100ms
git bisect bad 75e6c3b72b3ab01c47629f3fbd0fed4e6550bf3a
# good: [7eaab7086c3a313d76c217f98bc610c523d9bc2c] rndis_wlan: reset device and restore multicast list on rndis_wlan_reset()
git bisect good 7eaab7086c3a313d76c217f98bc610c523d9bc2c
# good: [b7cfc5b35eed2fe8a5c45793e6e52ef0edddc824] rndis_wlan: rework key handling
git bisect good b7cfc5b35eed2fe8a5c45793e6e52ef0edddc824
# good: [4b44c8bc4d077f1a7a9e5e946a1400c3cbcadee7] cfg80211: do not iterate over rdev list on country IE hint
git bisect good 4b44c8bc4d077f1a7a9e5e946a1400c3cbcadee7
# good: [8b19e6ca3bac7e04e93fb73f561d670e77c5fae6] cfg80211: enable country IE support to all cfg80211 drivers
git bisect good 8b19e6ca3bac7e04e93fb73f561d670e77c5fae6
# good: [97cad51e191919b43aabdc85b83241b66c3fcf2c] iwlwifi: remove usage of orig_flags
git bisect good 97cad51e191919b43aabdc85b83241b66c3fcf2c



keep in mind theres also another issue that I've been seeing i.g. using wicd
manager the signal level will go from full to min, and then dhclient kicks in
workaround is to just click on []don't auto-connect on disconnect(until either somebody fixes/bisect's the issue.

Anyways hope this helps I'm off to beer land...

On Sunday 22 November 2009, Johannes Berg wrote:
> On Sat, 2009-11-21 at 09:38 -0800, Justin P. Mattock wrote:
> 
> > I did a bisect yesterday on this, and the results
> > seemed to have worked over here by reverting:
> > 
> > 75e6c3b72b3ab01c47629f3fbd0fed4e6550bf3a
> > cfg80211: lower dynamic PS timeout to 100ms
> > 
> > if Kristoffer can try reverting this one
> > to see, then we can go from there.
> 
> So that just means the driver is broken. Please run
> 
>       iwconfig wlan0 power off
> 
> to fix it then. And the patch below will disable it by default since
> it's broken.
> 
> johannes
> 
> --- wireless-testing.orig/drivers/net/wireless/ath/ath9k/main.c      
> 2009-11-22 11:44:41.000000000 +0100
> +++ wireless-testing/drivers/net/wireless/ath/ath9k/main.c    2009-11-22
> 11:45:26.000000000 +0100
> @@ -1893,6 +1893,8 @@ void ath_set_hw_capab(struct ath_softc *
>               BIT(NL80211_IFTYPE_ADHOC) |
>               BIT(NL80211_IFTYPE_MESH_POINT);
>  
> +     hw->wiphy->ps_default = false;
> +
>       hw->queues = 4;
>       hw->max_rates = 4;
>       hw->channel_change_time = 5000;

o.k. I couldn't wait try to out the internet in the hotel, and the patch.
(so I broke down and paid the 12$ for internet)...

So far I've been streaming the radio, streaming a movie for over a half hour,
and no signs of what I was hitting. I'll try and run this all day to see if there's any disconnects, or anything in dmesg(other than that I think it's o.k.).

Not in linux-2.6 yet, but...

commit 54ab040d24904d1fa2c0a6a27936b7c56a4efb24
Author: John W. Linville <linville@tuxdriver.com>
Date:   Mon Nov 23 16:15:19 2009 -0500

    ath9k: set ps_default as false
    
    Copied from original one-line patch here:
    
        http://bugzilla.kernel.org/show_bug.cgi?id=14267#c26
    
    Signed-off-by: John W. Linville <linville@tuxdriver.com>

(In reply to comment #25)
> 75e6c3b72b3ab01c47629f3fbd0fed4e6550bf3a is the first bad commit
> commit 75e6c3b72b3ab01c47629f3fbd0fed4e6550bf3a
> Author: Johannes Berg <johannes@sipsolutions.net>
> Date:   Fri Jul 31 11:18:13 2009 +0200

How can it be? This is a post-2.6.31 commit, but this bug is about 2.6.30->2.6.31 regression. Or am I missing something?

All's I know is the bisect pointed me there
(you got's me);

Although kristoffer, had pointed out that this did not help his issue out!
interesting to see if he had finished his bisect,or came closer to finding out what might happening over there.

(In reply to comment #30)
> Although kristoffer, had pointed out that this did not help his issue out!
> interesting to see if he had finished his bisect,or came closer to finding
> out
> what might happening over there.

So you tracked down a different issue. The original still remains, OK.

Kristoffer, was you able to proceed somehow with the bisection?

(In reply to comment #31)
> (In reply to comment #30)
> > Although kristoffer, had pointed out that this did not help his issue out!
> > interesting to see if he had finished his bisect,or came closer to finding
> out
> > what might happening over there.
> 
> So you tracked down a different issue. The original still remains, OK.
> 
> Kristoffer, was you able to proceed somehow with the bisection?

Unfortunantly no. However I did do a test build on vanilla 2.6.32 and it resolved my issues with disconnecting wlan0 it seems. It did introduce some other issues though (my mobile internet connection is now flaky).

I will try and do a bisect (stressed for time) but for now 2.6.32 seems to work nicely, used it for a day without a disconnect (usually takes 10-20min).

alright.. glad your system doesn't disconnect like it was.

Justin, we have a few set of fixes for power save and ath9k which I'd like to push for the 2.6.32.1 release. These are important fixes and would like to know if they fix your powersave issues *instead* of just disabling powersave completely from ath9k.

You can apply the patches from this directory:

http://kernel.org/pub/linux/kernel/people/mcgrof/patches/ath9k/2009-12-08/for-2.6.32/

Of these 3 fixes only 2 of them really apply to power save and will help AR9280. The other patch is a fix for AR9285 but just go ahead and apply it as well.

Then to re-enable PS by default you can apply this final patch:

http://kernel.org/pub/linux/kernel/people/mcgrof/patches/ath9k/2009-12-08/ath9k-ps-enable.patch

Or you can also just enable power save manually:

iwconfig wlan0 power on

Please let me know how this goes.

alright, let me apply the patches and see.

patches applied clean, Unfortunately I'm seeing what I saw before.
heres what wpa_supplicant looks like after this happens:

  sudo /sbin/wpa_supplicant -Dwext -i wlan0 -c /home/name/wire
CTRL-EVENT-SCAN-RESULTS 
Trying to associate with 00:1e:2a:00:67:f0 (SSID='JPM' freq=2422 MHz)
Associated with 00:1e:2a:00:67:f0
CTRL-EVENT-CONNECTED - Connection to 00:1e:2a:00:67:f0 completed (auth) [id=0 id_str=]
CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys
CTRL-EVENT-SCAN-RESULTS 
Trying to associate with 00:1e:2a:00:67:f0 (SSID='JPM' freq=2422 MHz)
Associated with 00:1e:2a:00:67:f0
CTRL-EVENT-CONNECTED - Connection to 00:1e:2a:00:67:f0 completed (reauth) [id=0 id_str=]
CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys
CTRL-EVENT-SCAN-RESULTS 
Trying to associate with 00:1e:2a:00:67:f0 (SSID='JPM' freq=2422 MHz)
Associated with 00:1e:2a:00:67:f0
CTRL-EVENT-CONNECTED - Connection to 00:1e:2a:00:67:f0 completed (reauth) [id=0 id_str=]



in dmesg I see this:

[  358.204130] No probe response from AP 00:1e:2a:00:67:f0 after 500ms, disconnecting.
[  360.766288] wlan0: direct probe to AP 00:1e:2a:00:67:f0 (try 1)
[  360.768856] wlan0: direct probe responded
[  360.768864] wlan0: authenticate with AP 00:1e:2a:00:67:f0 (try 1)
[  360.775450] wlan0: authenticated
[  360.775491] wlan0: associate with AP 00:1e:2a:00:67:f0 (try 1)
[  360.777853] wlan0: RX ReassocResp from 00:1e:2a:00:67:f0 (capab=0x431 status=0 aid=1)
[  360.777859] wlan0: associated
[  373.204137] No probe response from AP 00:1e:2a:00:67:f0 after 500ms, disconnecting.
[  375.764461] wlan0: direct probe to AP 00:1e:2a:00:67:f0 (try 1)
[  375.767035] wlan0: direct probe responded
[  375.767043] wlan0: authenticate with AP 00:1e:2a:00:67:f0 (try 1)
[  375.773555] wlan0: authenticated
[  375.773597] wlan0: associate with AP 00:1e:2a:00:67:f0 (try 1)
[  375.776089] wlan0: RX ReassocResp from 00:1e:2a:00:67:f0 (capab=0x431 status=0 aid=1)
[  375.776096] wlan0: associated


let me know if you want to tweak something with these patches?

Yeah please try applying this patch as well.

http://bombadil.infradead.org/~mcgrof/tmp/05-mac80211-Fix-dynamic-power-save-for-scanning.patch

still showing up:
CTRL-EVENT-SCAN-RESULTS 
Trying to associate with 00:1e:2a:00:67:f0 (SSID='JPM' freq=2422 MHz)
Associated with 00:1e:2a:00:67:f0
CTRL-EVENT-CONNECTED - Connection to 00:1e:2a:00:67:f0 completed (auth) [id=0 id_str=]
CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys
CTRL-EVENT-SCAN-RESULTS 
CTRL-EVENT-SCAN-RESULTS 
Trying to associate with 00:1e:2a:00:67:f0 (SSID='JPM' freq=2422 MHz)
Associated with 00:1e:2a:00:67:f0
CTRL-EVENT-CONNECTED - Connection to 00:1e:2a:00:67:f0 completed (reauth) [id=0 id_str=]


during the disconnect is when the radio craps out. hulu is still playing
without any disruptions. keep in mind when the disconnect happens the music
is only disconnected for just a few seconds, before the music reconnects.

running with just radio works fine, it's only under heavy load of listening to radio, and watching a movie at the same time(I know it's weird, but somehow have always done this(must be a SoCal thing));

Hm, OK -- this is odd.

Lets try a few things. The current logs you provide show nothing to indicate to me what ath9k could be doing wrong so we would need to increase verbosity on mac80211 and/or ath9k to dig deeper into this.

I am also curious about the version of wpa_supplicant you are using. Although this should not change matters much I have in few cases now have seen some odd issues cured with an upgrade on it.

So a simple test is if you can you try running a newer wpa_supplicant?

Then after doing a quick test with that then please use the same kernel / userespace that had the issues and enable:

CONFIG_MAC80211_DEBUG_MENU=y
CONFIG_MAC80211_VERBOSE_PS_DEBUG=y
CONFIG_ATH9K_DEBUG=y

First get info just with thew new found PS_DEBUG enabled and paste that. If that doesn't give us enough information we can then try to get down and dirty into ath9k by enabling a driver debug for power save:

sudo modprobe ath9k debug=0x00000800

This will enable all prints in the driver with ATH_DBG_PS.

If this doesn't give us any clues we can turn to enabling config debug as well, this is 0x00000200. So to enable both you would use:

sudo modprobe ath9k debug=0xa00

still seeing disconnects, but with this run(should of tested the other better), seems to fire within 5min of starting up, then another about 5/8 min later, then always around 30min(give or take) of running.

Seems the only real bad disconnect was the first, in of when the music crapped out. other than that seems to hold itself, when the disconnects happen.

here you go:
wpa_supplicant v0.6.8 (compiled using the cblfs page, .defconfig are as is nothing added or commented out).

here's dmesg (keep in mind it's a bit scattered due to the avc's being generated by SELinux);


[   37.441050] phy0: device now idle
[   38.552412] phy0: device no longer idle - scanning
[   41.000337] phy0: device now idle
[   41.004024] phy0: device no longer idle - in use
[   41.004033] wlan0: direct probe to AP 00:1e:2a:00:67:f0 (try 1)
[   41.004088] wlan0: deauthenticating from 00:1e:2a:00:67:f0 by local choice (reason=3)
[   41.004146] wlan0: direct probe to AP 00:1e:2a:00:67:f0 (try 1)
[   41.007932] wlan0: direct probe responded
[   41.007939] wlan0: authenticate with AP 00:1e:2a:00:67:f0 (try 1)
[   41.017375] wlan0: authenticated
[   41.017402] wlan0: associate with AP 00:1e:2a:00:67:f0 (try 1)
[   41.019771] wlan0: RX AssocResp from 00:1e:2a:00:67:f0 (capab=0x431 status=0 aid=1)
[   41.019777] wlan0: associated
[   41.019798] phy0: Allocated STA 00:1e:2a:00:67:f0
[   41.019812] phy0: Inserted STA 00:1e:2a:00:67:f0
[  213.704109] wlan0: detected beacon loss from AP - sending probe request
[  214.204095] No probe response from AP 00:1e:2a:00:67:f0 after 500ms, try 1
[  214.704109] No probe response from AP 00:1e:2a:00:67:f0 after 500ms, try 2
[  215.204095] No probe response from AP 00:1e:2a:00:67:f0 after 500ms, try 3
[  215.704140] No probe response from AP 00:1e:2a:00:67:f0 after 500ms, try 4
[  216.204109] No probe response from AP 00:1e:2a:00:67:f0 after 500ms, disconnecting.
[  216.204165] phy0: device now idle
[  216.204178] phy0: Removed STA 00:1e:2a:00:67:f0
[  216.208527] phy0: Destroyed STA 00:1e:2a:00:67:f0
[  216.311333] phy0: device no longer idle - scanning
[  218.804231] phy0: device now idle
[  223.805223] phy0: device no longer idle - scanning
[  226.259332] wlan0: direct probe to AP 00:1e:2a:00:67:f0 (try 1)
[  226.261890] wlan0: direct probe responded
[  226.261898] wlan0: authenticate with AP 00:1e:2a:00:67:f0 (try 1)
[  226.268552] wlan0: authenticated
[  226.268592] wlan0: associate with AP 00:1e:2a:00:67:f0 (try 1)
[  226.271034] wlan0: RX ReassocResp from 00:1e:2a:00:67:f0 (capab=0x431 status=0 aid=1)
[  226.271040] wlan0: associated
[  226.271062] phy0: Allocated STA 00:1e:2a:00:67:f0
[  226.271077] phy0: Inserted STA 00:1e:2a:00:67:f0
[  522.704130] wlan0: detected beacon loss from AP - sending probe request
[  523.204141] No probe response from AP 00:1e:2a:00:67:f0 after 500ms, try 1
[  523.704128] No probe response from AP 00:1e:2a:00:67:f0 after 500ms, try 2
[  524.204130] No probe response from AP 00:1e:2a:00:67:f0 after 500ms, try 3
[  524.704322] No probe response from AP 00:1e:2a:00:67:f0 after 500ms, try 4
[  525.204108] No probe response from AP 00:1e:2a:00:67:f0 after 500ms, disconnecting.
[  525.204166] phy0: device now idle
[  525.204179] phy0: Removed STA 00:1e:2a:00:67:f0
[  525.208767] phy0: Destroyed STA 00:1e:2a:00:67:f0
[  525.310719] phy0: device no longer idle - scanning
[  527.763011] phy0: device now idle
[  527.763221] phy0: device no longer idle - in use
[  527.763225] wlan0: direct probe to AP 00:1e:2a:00:67:f0 (try 1)
[  527.766437] wlan0: direct probe responded
[  527.766444] wlan0: authenticate with AP 00:1e:2a:00:67:f0 (try 1)
[  527.773196] wlan0: authenticated
[  527.773226] wlan0: associate with AP 00:1e:2a:00:67:f0 (try 1)
[  527.775539] wlan0: RX ReassocResp from 00:1e:2a:00:67:f0 (capab=0x431 status=0 aid=1)
[  527.775545] wlan0: associated
[  527.775566] phy0: Allocated STA 00:1e:2a:00:67:f0
[  527.775581] phy0: Inserted STA 00:1e:2a:00:67:f0

(remember the print numbers wont align because theirs SELinux avc's from wpa_supplicant. I can post those if needed)

the beacon loss is when the music craps out.

Thanks for the details. We'll need increased verbose debugging from the ath9k driver. No probe responses are coming back at all so we need to see what the driver sees and does.

Oh and far as a version of wpa_supplicant is convered, I was hoping something a little newer like the development snapshot. Seems even ubuntu 9.10 ships something newer, some the 0.6.9 is the latest stable release for example. Maybe even the development 0.7.0 snapshot. This should not matter though, am just curious.

The exact issue should hopefeully come out with ath9k debug flags enabled.

ok I'll look at the snapshot later on.
right now heres the debug using what you supplied:

[ 2543.492286] ath9k 0000:03:00.0: PCI INT A disabled
[ 2543.492422] ath9k: Driver unloaded

/sbin/modprobe ath9k debud***

[ 2585.113799] ath9k 0000:03:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17
[ 2585.113821] ath9k 0000:03:00.0: setting latency timer to 64
[ 2585.246170] ath: EEPROM regdomain: 0x64
[ 2585.246173] ath: EEPROM indicates we should expect a direct regpair map
[ 2585.246177] ath: Country alpha2 being used: 00
[ 2585.246178] ath: Regpair used: 0x64
[ 2585.247443] phy1: Selected rate control algorithm 'ath9k_rate_control'
[ 2585.248890] Registered led device: ath9k-phy1::radio
[ 2585.248948] Registered led device: ath9k-phy1::assoc
[ 2585.249148] Registered led device: ath9k-phy1::tx
[ 2585.249212] Registered led device: ath9k-phy1::rx
[ 2585.249231] phy1: Atheros AR5418 MAC/BB Rev:2 AR5133 RF Rev:81: mem=0xffffc90000120000, irq=17
[ 2595.949602] phy1: device no longer idle - scanning
[ 2598.395214] phy1: device now idle
[ 2598.399084] wlan0: deauthenticating from 00:1e:2a:00:67:f0 by local choice (reason=3)
[ 2598.399125] phy1: device no longer idle - in use
[ 2598.399129] wlan0: direct probe to AP 00:1e:2a:00:67:f0 (try 1)
[ 2598.402618] wlan0: direct probe responded
[ 2598.402625] wlan0: authenticate with AP 00:1e:2a:00:67:f0 (try 1)
[ 2598.409028] wlan0: authenticated
[ 2598.409072] wlan0: associate with AP 00:1e:2a:00:67:f0 (try 1)
[ 2598.411393] wlan0: RX AssocResp from 00:1e:2a:00:67:f0 (capab=0x431 status=0 aid=1)
[ 2598.411400] wlan0: associated
[ 2598.411418] phy1: Allocated STA 00:1e:2a:00:67:f0
[ 2598.411433] phy1: Inserted STA 00:1e:2a:00:67:f0
[ 2598.599284] ath9k: Reconfigure Beacon timers based on timestamp from the AP
[ 2725.701309] wlan0: detected beacon loss from AP - sending probe request
[ 2726.201338] No probe response from AP 00:1e:2a:00:67:f0 after 500ms, try 1
[ 2726.701312] No probe response from AP 00:1e:2a:00:67:f0 after 500ms, try 2
[ 2727.201098] No probe response from AP 00:1e:2a:00:67:f0 after 500ms, try 3
[ 2727.701353] No probe response from AP 00:1e:2a:00:67:f0 after 500ms, try 4
[ 2728.201105] No probe response from AP 00:1e:2a:00:67:f0 after 500ms, disconnecting.
[ 2728.201161] phy1: device now idle
[ 2728.201174] phy1: Removed STA 00:1e:2a:00:67:f0
[ 2728.205735] phy1: Destroyed STA 00:1e:2a:00:67:f0
[ 2728.307668] phy1: device no longer idle - scanning
[ 2730.791325] phy1: device now idle
[ 2735.796080] phy1: device no longer idle - scanning
[ 2738.249289] wlan0: direct probe to AP 00:1e:2a:00:67:f0 (try 1)
[ 2738.252519] wlan0: direct probe responded
[ 2738.252526] wlan0: authenticate with AP 00:1e:2a:00:67:f0 (try 1)
[ 2738.258999] wlan0: authenticated
[ 2738.259180] wlan0: associate with AP 00:1e:2a:00:67:f0 (try 1)
[ 2738.261512] wlan0: RX ReassocResp from 00:1e:2a:00:67:f0 (capab=0x431 status=0 aid=1)
[ 2738.261518] wlan0: associated
[ 2738.261548] phy1: Allocated STA 00:1e:2a:00:67:f0
[ 2738.261560] phy1: Inserted STA 00:1e:2a:00:67:f0
[ 2738.375217] ath9k: Reconfigure Beacon timers based on timestamp from the AP

let me know if I need to change .config and/or add some patches for this.

I'm heading out to dinner in a few, so if I don;t respond right away you'll know why.(once I get back I'll try the snapshot of wpa);

OK -- thanks a lot. Now please run with this enabled as well:

CONFIG_MAC80211_VERBOSE_DEBUG

I just noticed mac80211 on 2.6.32 drops *all* unacked frames frames when in power save mode, instead of trying to retransmit and if it does we should see a print like:

                printk(KERN_DEBUG "%s: dropped TX filtered frame, "
                       "queue_len=%d PS=%d @%lu\n",
                       wiphy_name(local->hw.wiphy),
                       skb_queue_len(&sta->tx_filtered),
                       !!test_sta_flags(sta, WLAN_STA_PS), jiffies);

I do wonder if the probe request we send out is actually hitting the AP. If the AP disassociated us without us noticing this the AP could technically start ignoring direct probe requests so if this is the case one possible solution would be to probe the AP all the time using the broadcast address instead of sending directed probes.

Just my current theory based on your minimal log outputs.

When you re-run your tests it'd be appreciated if you can run with ath9k debug enabled as well with config debug now. So:

sudo modprobe ath9k debug=0xa00

o.k.
CONFIG_MAC80211_VERBOSE_DEBUG=y
is set to y in my .config

should I have set something in kernel hacking.

if not I'll still run your debug for ath9k
and post it.

heres the output
(bit long)



[  306.448407] ath9k 0000:03:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17
[  306.448422] ath9k 0000:03:00.0: setting latency timer to 64
[  306.577801] ath9k: Eeprom VER: 14, REV: 4
[  306.578431] ath9k: Rate:  1Mbps, ratecode: 27
[  306.578434] ath9k: Rate:  2Mbps, ratecode: 26
[  306.578437] ath9k: Rate:  5Mbps, ratecode: 25
[  306.578439] ath9k: Rate: 11Mbps, ratecode: 24
[  306.578441] ath9k: Rate:  6Mbps, ratecode: 11
[  306.578443] ath9k: Rate:  9Mbps, ratecode: 15
[  306.578446] ath9k: Rate: 12Mbps, ratecode: 10
[  306.578448] ath9k: Rate: 18Mbps, ratecode: 14
[  306.578450] ath9k: Rate: 24Mbps, ratecode:  9
[  306.578452] ath9k: Rate: 36Mbps, ratecode: 13
[  306.578455] ath9k: Rate: 48Mbps, ratecode:  8
[  306.578457] ath9k: Rate: 54Mbps, ratecode: 12
[  306.578459] ath9k: Rate:  6Mbps, ratecode: 11
[  306.578461] ath9k: Rate:  9Mbps, ratecode: 15
[  306.578464] ath9k: Rate: 12Mbps, ratecode: 10
[  306.578466] ath9k: Rate: 18Mbps, ratecode: 14
[  306.578468] ath9k: Rate: 24Mbps, ratecode:  9
[  306.578470] ath9k: Rate: 36Mbps, ratecode: 13
[  306.578473] ath9k: Rate: 48Mbps, ratecode:  8
[  306.578475] ath9k: Rate: 54Mbps, ratecode: 12
[  306.578495] ath: EEPROM regdomain: 0x64
[  306.578497] ath: EEPROM indicates we should expect a direct regpair map
[  306.578501] ath: Country alpha2 being used: 00
[  306.578503] ath: Regpair used: 0x64
[  306.578507] ath9k: tx DMA: 512 buffers 1 desc/buf
[  306.578558] ath9k: tx DMA map: ffff880039760000 (77824) -> 0 (77824)
[  306.578591] ath9k: beacon DMA: 4 buffers 1 desc/buf
[  306.578595] ath9k: beacon DMA map: ffff88002fe7d000 (608) -> 0 (608)
[  306.578598] ath9k: cachelsz 256 rxbufsize 3904
[  306.578601] ath9k: rx DMA: 512 buffers 1 desc/buf
[  306.578651] ath9k: rx DMA map: ffff880031b80000 (77824) -> 0 (77824)
[  306.579286] phy1: Selected rate control algorithm 'ath9k_rate_control'
[  306.580361] Registered led device: ath9k-phy1::radio
[  306.580533] Registered led device: ath9k-phy1::assoc
[  306.580562] Registered led device: ath9k-phy1::tx
[  306.580585] Registered led device: ath9k-phy1::rx
[  306.580600] phy1: Atheros AR5418 MAC/BB Rev:2 AR5133 RF Rev:81: mem=0xffffc90000120000, irq=17
[  323.003706] ath9k: Starting driver with initial channel: 2412 MHz
[  323.008784] ath9k: Attach a VIF of type: 2
[  323.008811] ath9k: BSS Changed PREAMBLE 0
[  323.008816] ath9k: BSS Changed CTS PROT 0
[  323.011112] phy1: device now idle
[  323.011126] ath9k: Set channel: 2412 MHz
[  323.011132] ath9k: tx chmask: 1, rx chmask: 1
[  323.011244] ath9k: (2412 MHz) -> (2412 MHz), chanwidth: 0
[  323.014777] ath9k: Configure tx [queue/halq] [0/3],  aifs: 2, cw_min: 7, cw_max: 15, txop: 102
[  323.014792] ath9k: Configure tx [queue/halq] [1/2],  aifs: 2, cw_min: 15, cw_max: 31, txop: 188
[  323.014806] ath9k: Configure tx [queue/halq] [2/1],  aifs: 3, cw_min: 31, cw_max: 1023, txop: 0
[  323.014819] ath9k: Configure tx [queue/halq] [3/0],  aifs: 7, cw_min: 31, cw_max: 1023, txop: 0
[  323.014874] ath9k: Set HW RX filter: 0x207
[  323.015176] ath9k: Set HW RX filter: 0x207
[  324.122447] phy1: device no longer idle - scanning
[  324.122469] ath9k: Set HW RX filter: 0x17
[  324.252274] ath9k: Set channel: 2412 MHz
[  324.252279] ath9k: tx chmask: 5, rx chmask: 7
[  324.252386] ath9k: (2412 MHz) -> (2412 MHz), chanwidth: 0
[  324.316151] ath9k: Set channel: 2417 MHz
[  324.316158] ath9k: tx chmask: 5, rx chmask: 7
[  324.316291] ath9k: (2412 MHz) -> (2417 MHz), chanwidth: 0
[  324.376165] ath9k: Set channel: 2422 MHz
[  324.376172] ath9k: tx chmask: 5, rx chmask: 7
[  324.376306] ath9k: (2417 MHz) -> (2422 MHz), chanwidth: 0
[  324.436159] ath9k: Set channel: 2427 MHz
[  324.436167] ath9k: tx chmask: 5, rx chmask: 7
[  324.436324] ath9k: (2422 MHz) -> (2427 MHz), chanwidth: 0
[  324.496177] ath9k: Set channel: 2432 MHz
[  324.496185] ath9k: tx chmask: 5, rx chmask: 7
[  324.496323] ath9k: (2427 MHz) -> (2432 MHz), chanwidth: 0
[  324.556167] ath9k: Set channel: 2437 MHz
[  324.556175] ath9k: tx chmask: 5, rx chmask: 7
[  324.556321] ath9k: (2432 MHz) -> (2437 MHz), chanwidth: 0
[  324.616113] ath9k: Set channel: 2442 MHz
[  324.616121] ath9k: tx chmask: 5, rx chmask: 7
[  324.616233] ath9k: (2437 MHz) -> (2442 MHz), chanwidth: 0
[  324.676150] ath9k: Set channel: 2447 MHz
[  324.676157] ath9k: tx chmask: 5, rx chmask: 7
[  324.676291] ath9k: (2442 MHz) -> (2447 MHz), chanwidth: 0
[  324.736176] ath9k: Set channel: 2452 MHz
[  324.736185] ath9k: tx chmask: 5, rx chmask: 7
[  324.736344] ath9k: (2447 MHz) -> (2452 MHz), chanwidth: 0
[  324.796167] ath9k: Set channel: 2457 MHz
[  324.796175] ath9k: tx chmask: 5, rx chmask: 7
[  324.796323] ath9k: (2452 MHz) -> (2457 MHz), chanwidth: 0
[  324.856152] ath9k: Set channel: 2462 MHz
[  324.856160] ath9k: tx chmask: 5, rx chmask: 7
[  324.856295] ath9k: (2457 MHz) -> (2462 MHz), chanwidth: 0
[  324.916158] ath9k: Set channel: 5180 MHz
[  324.916167] ath9k: tx chmask: 5, rx chmask: 7
[  324.916324] ath9k: (2462 MHz) -> (5180 MHz), chanwidth: 0
[  325.045149] ath9k: Set channel: 5200 MHz
[  325.045156] ath9k: tx chmask: 5, rx chmask: 7
[  325.045292] ath9k: (5180 MHz) -> (5200 MHz), chanwidth: 0
[  325.170143] ath9k: Set channel: 5220 MHz
[  325.170151] ath9k: tx chmask: 5, rx chmask: 7
[  325.170283] ath9k: (5200 MHz) -> (5220 MHz), chanwidth: 0
[  325.295160] ath9k: Set channel: 5240 MHz
[  325.295168] ath9k: tx chmask: 5, rx chmask: 7
[  325.295317] ath9k: (5220 MHz) -> (5240 MHz), chanwidth: 0
[  325.420137] ath9k: Set channel: 5260 MHz
[  325.420144] ath9k: tx chmask: 5, rx chmask: 7
[  325.420270] ath9k: (5240 MHz) -> (5260 MHz), chanwidth: 0
[  325.545326] ath9k: Set channel: 5280 MHz
[  325.545333] ath9k: tx chmask: 5, rx chmask: 7
[  325.545447] ath9k: (5260 MHz) -> (5280 MHz), chanwidth: 0
[  325.670148] ath9k: Set channel: 5300 MHz
[  325.670155] ath9k: tx chmask: 5, rx chmask: 7
[  325.670289] ath9k: (5280 MHz) -> (5300 MHz), chanwidth: 0
[  325.795142] ath9k: Set channel: 5320 MHz
[  325.795150] ath9k: tx chmask: 5, rx chmask: 7
[  325.795283] ath9k: (5300 MHz) -> (5320 MHz), chanwidth: 0
[  325.920183] ath9k: Set channel: 5745 MHz
[  325.920192] ath9k: tx chmask: 5, rx chmask: 7
[  325.920333] ath9k: (5320 MHz) -> (5745 MHz), chanwidth: 0
[  326.049149] ath9k: Set channel: 5765 MHz
[  326.049155] ath9k: tx chmask: 5, rx chmask: 7
[  326.049287] ath9k: (5745 MHz) -> (5765 MHz), chanwidth: 0
[  326.178158] ath9k: Set channel: 5785 MHz
[  326.178167] ath9k: tx chmask: 5, rx chmask: 7
[  326.178330] ath9k: (5765 MHz) -> (5785 MHz), chanwidth: 0
[  326.307175] ath9k: Set channel: 5805 MHz
[  326.307183] ath9k: tx chmask: 5, rx chmask: 7
[  326.307322] ath9k: (5785 MHz) -> (5805 MHz), chanwidth: 0
[  326.436153] ath9k: Set channel: 5825 MHz
[  326.436160] ath9k: tx chmask: 5, rx chmask: 7
[  326.436295] ath9k: (5805 MHz) -> (5825 MHz), chanwidth: 0
[  326.565157] ath9k: Set channel: 2412 MHz
[  326.565166] ath9k: tx chmask: 5, rx chmask: 7
[  326.565317] ath9k: (5825 MHz) -> (2412 MHz), chanwidth: 0
[  326.569176] ath9k: Set HW RX filter: 0x207
[  326.569225] phy1: device now idle
[  326.569454] ath9k: Set channel: 2422 MHz
[  326.569461] ath9k: tx chmask: 1, rx chmask: 1
[  326.569572] ath9k: (2412 MHz) -> (2422 MHz), chanwidth: 0
[  326.573105] wlan0: deauthenticating from 00:1e:2a:00:67:f0 by local choice (reason=3)
[  326.574048] phy1: device no longer idle - in use
[  326.574057] wlan0: direct probe to AP 00:1e:2a:00:67:f0 (try 1)
[  326.576643] wlan0: direct probe responded
[  326.576651] wlan0: authenticate with AP 00:1e:2a:00:67:f0 (try 1)
[  326.583190] wlan0: authenticated
[  326.583232] wlan0: associate with AP 00:1e:2a:00:67:f0 (try 1)
[  326.585608] wlan0: RX AssocResp from 00:1e:2a:00:67:f0 (capab=0x431 status=0 aid=1)
[  326.585614] wlan0: associated
[  326.585637] phy1: Allocated STA 00:1e:2a:00:67:f0
[  326.585644] ath9k: Choosing rate table for mode: 1
[  326.585655] ath9k: RC Initialized with capabilities: 0x0
[  326.585663] phy1: Inserted STA 00:1e:2a:00:67:f0
[  326.585673] ath9k: Configure tx [queue/halq] [0/3],  aifs: 2, cw_min: 3, cw_max: 7, txop: 47
[  326.585689] ath9k: Configure tx [queue/halq] [1/2],  aifs: 2, cw_min: 7, cw_max: 15, txop: 94
[  326.585703] ath9k: Configure tx [queue/halq] [2/1],  aifs: 3, cw_min: 15, cw_max: 1023, txop: 0
[  326.585717] ath9k: Configure tx [queue/halq] [3/0],  aifs: 7, cw_min: 15, cw_max: 1023, txop: 0
[  326.585734] ath9k: RX filter 0x0 bssid 00:1e:2a:00:67:f0 aid 0x0
[  326.585740] ath9k: BSS Changed PREAMBLE 1
[  326.585744] ath9k: BSS Changed ASSOC 1
[  326.585749] ath9k: Bss Info ASSOC 1, bssid: 00:1e:2a:00:67:f0
[  326.589208] ath9k: Set HW Key
[  326.810185] ath9k: Reconfigure Beacon timers based on timestamp from the AP
[  331.563862] ath9k: Set HW RX filter: 0x207
[  331.563951] ath9k: Set HW RX filter: 0x207
[  334.307416] ath9k: Set HW RX filter: 0x207
[  334.307806] ath9k: Set HW RX filter: 0x207
[  375.704105] wlan0: detected beacon loss from AP - sending probe request
[  376.204111] No probe response from AP 00:1e:2a:00:67:f0 after 500ms, try 1
[  376.704280] No probe response from AP 00:1e:2a:00:67:f0 after 500ms, try 2
[  377.204336] No probe response from AP 00:1e:2a:00:67:f0 after 500ms, try 3
[  377.704096] No probe response from AP 00:1e:2a:00:67:f0 after 500ms, try 4
[  378.204102] No probe response from AP 00:1e:2a:00:67:f0 after 500ms, disconnecting.
[  378.204129] ath9k: Configure tx [queue/halq] [0/3],  aifs: 2, cw_min: 3, cw_max: 7, txop: 47
[  378.204146] ath9k: Configure tx [queue/halq] [1/2],  aifs: 2, cw_min: 7, cw_max: 15, txop: 94
[  378.204160] ath9k: Configure tx [queue/halq] [2/1],  aifs: 3, cw_min: 15, cw_max: 1023, txop: 0
[  378.204174] ath9k: Configure tx [queue/halq] [3/0],  aifs: 7, cw_min: 15, cw_max: 1023, txop: 0
[  378.204187] phy1: device now idle
[  378.204195] ath9k: BSS Changed PREAMBLE 0
[  378.204200] ath9k: BSS Changed CTS PROT 0
[  378.204204] ath9k: BSS Changed ASSOC 0
[  378.204209] ath9k: Bss Info DISASSOC
[  378.204217] phy1: Removed STA 00:1e:2a:00:67:f0
[  378.208382] phy1: Destroyed STA 00:1e:2a:00:67:f0
[  378.210348] ath9k: Set HW Key
[  378.310719] phy1: device no longer idle - scanning
[  378.310741] ath9k: Set HW RX filter: 0x17
[  378.440075] ath9k: Set channel: 2412 MHz
[  378.440084] ath9k: tx chmask: 5, rx chmask: 7
[  378.440199] ath9k: (2422 MHz) -> (2412 MHz), chanwidth: 0
[  378.500062] ath9k: Set channel: 2417 MHz
[  378.500071] ath9k: tx chmask: 5, rx chmask: 7
[  378.500185] ath9k: (2412 MHz) -> (2417 MHz), chanwidth: 0
[  378.560080] ath9k: Set channel: 2422 MHz
[  378.560089] ath9k: tx chmask: 5, rx chmask: 7
[  378.560202] ath9k: (2417 MHz) -> (2422 MHz), chanwidth: 0
[  378.620078] ath9k: Set channel: 2427 MHz
[  378.620087] ath9k: tx chmask: 5, rx chmask: 7
[  378.620201] ath9k: (2422 MHz) -> (2427 MHz), chanwidth: 0
[  378.680068] ath9k: Set channel: 2432 MHz
[  378.680077] ath9k: tx chmask: 5, rx chmask: 7
[  378.685212] ath9k: (2427 MHz) -> (2432 MHz), chanwidth: 0
[  378.746050] ath9k: Set channel: 2437 MHz
[  378.746058] ath9k: tx chmask: 5, rx chmask: 7
[  378.751094] ath9k: (2432 MHz) -> (2437 MHz), chanwidth: 0
[  378.811097] ath9k: Set channel: 2442 MHz
[  378.811105] ath9k: tx chmask: 5, rx chmask: 7
[  378.816355] ath9k: (2437 MHz) -> (2442 MHz), chanwidth: 0
[  378.877075] ath9k: Set channel: 2447 MHz
[  378.877084] ath9k: tx chmask: 5, rx chmask: 7
[  378.882221] ath9k: (2442 MHz) -> (2447 MHz), chanwidth: 0
[  378.943062] ath9k: Set channel: 2452 MHz
[  378.943072] ath9k: tx chmask: 5, rx chmask: 7
[  378.948129] ath9k: (2447 MHz) -> (2452 MHz), chanwidth: 0
[  379.008882] ath9k: Set channel: 2457 MHz
[  379.008891] ath9k: tx chmask: 5, rx chmask: 7
[  379.014128] ath9k: (2452 MHz) -> (2457 MHz), chanwidth: 0
[  379.074309] ath9k: Set channel: 2462 MHz
[  379.074317] ath9k: tx chmask: 5, rx chmask: 7
[  379.079352] ath9k: (2457 MHz) -> (2462 MHz), chanwidth: 0
[  379.139060] ath9k: Set channel: 5180 MHz
[  379.139067] ath9k: tx chmask: 5, rx chmask: 7
[  379.144288] ath9k: (2462 MHz) -> (5180 MHz), chanwidth: 0
[  379.273122] ath9k: Set channel: 5200 MHz
[  379.273132] ath9k: tx chmask: 5, rx chmask: 7
[  379.273249] ath9k: (5180 MHz) -> (5200 MHz), chanwidth: 0
[  379.398086] ath9k: Set channel: 5220 MHz
[  379.398095] ath9k: tx chmask: 5, rx chmask: 7
[  379.398211] ath9k: (5200 MHz) -> (5220 MHz), chanwidth: 0
[  379.523082] ath9k: Set channel: 5240 MHz
[  379.523091] ath9k: tx chmask: 5, rx chmask: 7
[  379.523207] ath9k: (5220 MHz) -> (5240 MHz), chanwidth: 0
[  379.648102] ath9k: Set channel: 5260 MHz
[  379.648111] ath9k: tx chmask: 5, rx chmask: 7
[  379.648228] ath9k: (5240 MHz) -> (5260 MHz), chanwidth: 0
[  379.773089] ath9k: Set channel: 5280 MHz
[  379.773098] ath9k: tx chmask: 5, rx chmask: 7
[  379.773214] ath9k: (5260 MHz) -> (5280 MHz), chanwidth: 0
[  379.898333] ath9k: Set channel: 5300 MHz
[  379.898341] ath9k: tx chmask: 5, rx chmask: 7
[  379.898457] ath9k: (5280 MHz) -> (5300 MHz), chanwidth: 0
[  380.023280] ath9k: Set channel: 5320 MHz
[  380.023285] ath9k: tx chmask: 5, rx chmask: 7
[  380.023394] ath9k: (5300 MHz) -> (5320 MHz), chanwidth: 0
[  380.149102] ath9k: Set channel: 5745 MHz
[  380.149112] ath9k: tx chmask: 5, rx chmask: 7
[  380.149228] ath9k: (5320 MHz) -> (5745 MHz), chanwidth: 0
[  380.278106] ath9k: Set channel: 5765 MHz
[  380.278115] ath9k: tx chmask: 5, rx chmask: 7
[  380.278231] ath9k: (5745 MHz) -> (5765 MHz), chanwidth: 0
[  380.407092] ath9k: Set channel: 5785 MHz
[  380.407100] ath9k: tx chmask: 5, rx chmask: 7
[  380.407217] ath9k: (5765 MHz) -> (5785 MHz), chanwidth: 0
[  380.535091] ath9k: Set channel: 5805 MHz
[  380.535100] ath9k: tx chmask: 5, rx chmask: 7
[  380.535216] ath9k: (5785 MHz) -> (5805 MHz), chanwidth: 0
[  380.663106] ath9k: Set channel: 5825 MHz
[  380.663115] ath9k: tx chmask: 5, rx chmask: 7
[  380.663231] ath9k: (5805 MHz) -> (5825 MHz), chanwidth: 0
[  380.792067] ath9k: Set channel: 2422 MHz
[  380.792075] ath9k: tx chmask: 5, rx chmask: 7
[  380.792191] ath9k: (5825 MHz) -> (2422 MHz), chanwidth: 0
[  380.796075] ath9k: Set HW RX filter: 0x207
[  380.796120] phy1: device now idle
[  385.801262] phy1: device no longer idle - scanning
[  385.801284] ath9k: Set HW RX filter: 0x17
[  385.931087] ath9k: Set channel: 2412 MHz
[  385.931095] ath9k: tx chmask: 5, rx chmask: 7
[  385.931209] ath9k: (2422 MHz) -> (2412 MHz), chanwidth: 0
[  385.995091] ath9k: Set channel: 2417 MHz
[  385.995100] ath9k: tx chmask: 5, rx chmask: 7
[  385.995213] ath9k: (2412 MHz) -> (2417 MHz), chanwidth: 0
[  386.056069] ath9k: Set channel: 2422 MHz
[  386.056078] ath9k: tx chmask: 5, rx chmask: 7
[  386.056191] ath9k: (2417 MHz) -> (2422 MHz), chanwidth: 0
[  386.116085] ath9k: Set channel: 2427 MHz
[  386.116094] ath9k: tx chmask: 5, rx chmask: 7
[  386.116208] ath9k: (2422 MHz) -> (2427 MHz), chanwidth: 0
[  386.176064] ath9k: Set channel: 2432 MHz
[  386.176073] ath9k: tx chmask: 5, rx chmask: 7
[  386.176185] ath9k: (2427 MHz) -> (2432 MHz), chanwidth: 0
[  386.236074] ath9k: Set channel: 2437 MHz
[  386.236082] ath9k: tx chmask: 5, rx chmask: 7
[  386.236194] ath9k: (2432 MHz) -> (2437 MHz), chanwidth: 0
[  386.296084] ath9k: Set channel: 2442 MHz
[  386.296094] ath9k: tx chmask: 5, rx chmask: 7
[  386.296208] ath9k: (2437 MHz) -> (2442 MHz), chanwidth: 0
[  386.357083] ath9k: Set channel: 2447 MHz
[  386.357091] ath9k: tx chmask: 5, rx chmask: 7
[  386.357204] ath9k: (2442 MHz) -> (2447 MHz), chanwidth: 0
[  386.417083] ath9k: Set channel: 2452 MHz
[  386.417092] ath9k: tx chmask: 5, rx chmask: 7
[  386.417205] ath9k: (2447 MHz) -> (2452 MHz), chanwidth: 0
[  386.477086] ath9k: Set channel: 2457 MHz
[  386.477094] ath9k: tx chmask: 5, rx chmask: 7
[  386.477207] ath9k: (2452 MHz) -> (2457 MHz), chanwidth: 0
[  386.537068] ath9k: Set channel: 2462 MHz
[  386.537076] ath9k: tx chmask: 5, rx chmask: 7
[  386.537189] ath9k: (2457 MHz) -> (2462 MHz), chanwidth: 0
[  386.597078] ath9k: Set channel: 5180 MHz
[  386.597087] ath9k: tx chmask: 5, rx chmask: 7
[  386.597200] ath9k: (2462 MHz) -> (5180 MHz), chanwidth: 0
[  386.726077] ath9k: Set channel: 5200 MHz
[  386.726086] ath9k: tx chmask: 5, rx chmask: 7
[  386.726202] ath9k: (5180 MHz) -> (5200 MHz), chanwidth: 0
[  386.852091] ath9k: Set channel: 5220 MHz
[  386.852100] ath9k: tx chmask: 5, rx chmask: 7
[  386.852216] ath9k: (5200 MHz) -> (5220 MHz), chanwidth: 0
[  386.978092] ath9k: Set channel: 5240 MHz
[  386.978101] ath9k: tx chmask: 5, rx chmask: 7
[  386.978217] ath9k: (5220 MHz) -> (5240 MHz), chanwidth: 0
[  387.103062] ath9k: Set channel: 5260 MHz
[  387.103071] ath9k: tx chmask: 5, rx chmask: 7
[  387.103187] ath9k: (5240 MHz) -> (5260 MHz), chanwidth: 0
[  387.228075] ath9k: Set channel: 5280 MHz
[  387.228085] ath9k: tx chmask: 5, rx chmask: 7
[  387.228201] ath9k: (5260 MHz) -> (5280 MHz), chanwidth: 0
[  387.353062] ath9k: Set channel: 5300 MHz
[  387.353071] ath9k: tx chmask: 5, rx chmask: 7
[  387.353187] ath9k: (5280 MHz) -> (5300 MHz), chanwidth: 0
[  387.478588] ath9k: Set channel: 5320 MHz
[  387.478595] ath9k: tx chmask: 5, rx chmask: 7
[  387.478718] ath9k: (5300 MHz) -> (5320 MHz), chanwidth: 0
[  387.604086] ath9k: Set channel: 5745 MHz
[  387.604096] ath9k: tx chmask: 5, rx chmask: 7
[  387.604212] ath9k: (5320 MHz) -> (5745 MHz), chanwidth: 0
[  387.733060] ath9k: Set channel: 5765 MHz
[  387.733070] ath9k: tx chmask: 5, rx chmask: 7
[  387.733186] ath9k: (5745 MHz) -> (5765 MHz), chanwidth: 0
[  387.862061] ath9k: Set channel: 5785 MHz
[  387.862070] ath9k: tx chmask: 5, rx chmask: 7
[  387.862185] ath9k: (5765 MHz) -> (5785 MHz), chanwidth: 0
[  387.991072] ath9k: Set channel: 5805 MHz
[  387.991081] ath9k: tx chmask: 5, rx chmask: 7
[  387.991197] ath9k: (5785 MHz) -> (5805 MHz), chanwidth: 0
[  388.120072] ath9k: Set channel: 5825 MHz
[  388.120081] ath9k: tx chmask: 5, rx chmask: 7
[  388.120218] ath9k: (5805 MHz) -> (5825 MHz), chanwidth: 0
[  388.249351] ath9k: Set channel: 2422 MHz
[  388.249360] ath9k: tx chmask: 5, rx chmask: 7
[  388.249476] ath9k: (5825 MHz) -> (2422 MHz), chanwidth: 0
[  388.253360] ath9k: Set channel: 2422 MHz
[  388.253368] ath9k: tx chmask: 5, rx chmask: 7
[  388.253488] ath9k: (2422 MHz) -> (2422 MHz), chanwidth: 0
[  388.257354] ath9k: Set HW RX filter: 0x207
[  388.257394] wlan0: direct probe to AP 00:1e:2a:00:67:f0 (try 1)
[  388.260124] wlan0: direct probe responded
[  388.260131] wlan0: authenticate with AP 00:1e:2a:00:67:f0 (try 1)
[  388.266509] wlan0: authenticated
[  388.266538] wlan0: associate with AP 00:1e:2a:00:67:f0 (try 1)
[  388.268836] wlan0: RX ReassocResp from 00:1e:2a:00:67:f0 (capab=0x431 status=0 aid=1)
[  388.268839] wlan0: associated
[  388.268852] phy1: Allocated STA 00:1e:2a:00:67:f0
[  388.268855] ath9k: Choosing rate table for mode: 1
[  388.268860] ath9k: RC Initialized with capabilities: 0x0
[  388.268864] phy1: Inserted STA 00:1e:2a:00:67:f0
[  388.268955] ath9k: Configure tx [queue/halq] [0/3],  aifs: 2, cw_min: 3, cw_max: 7, txop: 47
[  388.268965] ath9k: Configure tx [queue/halq] [1/2],  aifs: 2, cw_min: 7, cw_max: 15, txop: 94
[  388.268975] ath9k: Configure tx [queue/halq] [2/1],  aifs: 3, cw_min: 15, cw_max: 1023, txop: 0
[  388.268984] ath9k: Configure tx [queue/halq] [3/0],  aifs: 7, cw_min: 15, cw_max: 1023, txop: 0
[  388.268994] ath9k: RX filter 0x0 bssid 00:1e:2a:00:67:f0 aid 0x0
[  388.268997] ath9k: BSS Changed PREAMBLE 1
[  388.268999] ath9k: BSS Changed ASSOC 1
[  388.269001] ath9k: Bss Info ASSOC 1, bssid: 00:1e:2a:00:67:f0
[  388.272128] ath9k: Set HW Key
[  388.454894] ath9k: Reconfigure Beacon timers based on timestamp from the AP



FWIW: I'm about 5 feet from the router.

Great thanks, this helps a lot.

OK the only issue I see with the printed log is this:

[  326.585734] ath9k: RX filter 0x0 bssid 00:1e:2a:00:67:f0 aid 0x0

But that is updated right after with:

[  326.585749] ath9k: Bss Info ASSOC 1, bssid: 00:1e:2a:00:67:f0

so the old aid value is properly updated but until later during ath9k_bss_assoc_info().

Can't see any other thing which might help here. Lets try increasing the log completely now. Please try with:

sudo modprobe ath9k debug=0xffffffff

I also noticed this print output is for AR5418 while the original poster of this bug report was for AR9280. Kristoffer Ericson, can you test the patches as well? Do you still experiences the issues just as Justin?

Alright, I'll have a look tomorrow(too tired, need a beer, and need to sit and not think);

Created attachment 24111 [details]
debug

o.k. even out of complete laziness I still was curious to see what the output might be.(need to look tomorrow, but seems harder to reproduce under this option.

cut from dmesg, and what my log buffer will allow is attached:

[ 1760.066613] ath9k: TX complete: skb: ffff88002d971800
[ 1760.066623] ath9k: 0x0 => 0xf4041071
[ 1760.066628] ath9k: new IMR 0x918414b4
[ 1760.066638] ath9k: enable IER
[ 1760.066647] ath9k: AR_IMR 0x918414b4 IER 0x1
[ 1760.093935] ath9k: 0xf4041071 => 0x0
[ 1760.093944] ath9k: disable IER
[ 1760.093954] ath9k: new IMR 0x0
[ 1760.093995] ath9k: 0x0 => 0xf4041071
[ 1760.094000] ath9k: new IMR 0x918414b4
[ 1760.094009] ath9k: enable IER
[ 1760.094018] ath9k: AR_IMR 0x918414b4 IER 0x1
[ 1760.094097] ath9k: transmitting packet, skb: ffff88002e057100
[ 1760.094109] ath9k: qnum: 1, txq depth: 1
[ 1760.094114] ath9k: link[1] (ffff88003108d068)=0 (ffff88003108d100)
[ 1760.094121] ath9k: Enable TXE on queue: 1
[ 1760.094163] ath9k: 0xf4041071 => 0x0
[ 1760.094169] ath9k: disable IER
[ 1760.094179] ath9k: new IMR 0x0
[ 1760.094191] ath9k: tx queue 1 (3108d100), link ffff88003108d100
[ 1760.094198] ath9k: 0x0 => 0xf4041071
[ 1760.094203] ath9k: new IMR 0x918414b4
[ 1760.094212] ath9k: enable IER
[ 1760.094221] ath9k: AR_IMR 0x918414b4 IER 0x1
[ 1760.094245] ath9k: 0xf4041071 => 0x0
[ 1760.094249] ath9k: disable IER
[ 1760.094259] ath9k: new IMR 0x0
[ 1760.094291] ath9k: tx queue 1 (3108d100), link ffff88003108d100
[ 1760.094299] ath9k: TX complete: skb: ffff88002e057100
[ 1760.094732] ath9k: 0x0 => 0xf4041071
[ 1760.094737] ath9k: new IMR 0x918414b4
[ 1760.094746] ath9k: enable IER
[ 1760.094755] ath9k: AR_IMR 0x918414b4 IER 0x1
[ 1760.124410] ath9k: 0xf4041071 => 0x0
[ 1760.124419] ath9k: disable IER
[ 1760.124429] ath9k: new IMR 0x0
[ 1760.124476] ath9k: 0x0 => 0xf4041071
[ 1760.124481] ath9k: new IMR 0x918414b4
[ 1760.124491] ath9k: enable IER
[ 1760.124500] ath9k: AR_IMR 0x918414b4 IER 0x1
[ 1760.193066] ath9k: transmitting packet, skb: ffff880035b1b900
[ 1760.193082] ath9k: qnum: 1, txq depth: 1
[ 1760.193088] ath9k: link[1] (ffff88003108d100)=98 (ffff88003108d198)
[ 1760.193095] ath9k: Enable TXE on queue: 1
[ 1760.193105] ath9k: 0xf4041071 => 0xf4041171
[ 1760.193110] ath9k: 
[ 1760.193133] ath9k: 0xf4041071 => 0x0
[ 1760.193138] ath9k: disable IER
[ 1760.193148] ath9k: new IMR 0x0
[ 1760.193163] ath9k: tx queue 1 (3108d198), link ffff88003108d198
[ 1760.193170] ath9k: 0x0 => 0xf4041171
[ 1760.193175] ath9k: new IMR 0x918414b4
[ 1760.193184] ath9k: enable IER
[ 1760.193211] ath9k: 0xf4041171 => 0x0
[ 1760.193215] ath9k: disable IER
[ 1760.193225] ath9k: new IMR 0x0
[ 1760.193235] ath9k: AR_IMR 0x918414b4 IER 0x1
[ 1760.193243] ath9k: tx queue 1 (3108d198), link ffff88003108d198
[ 1760.193258] ath9k: TX complete: skb: ffff880035b1b900
[ 1760.193268] ath9k: 0x0 => 0xf4041171
[ 1760.193273] ath9k: new IMR 0x918414b4
[ 1760.193285] ath9k: enable IER
[ 1760.193296] ath9k: AR_IMR 0x918414b4 IER 0x1
[ 1760.193302] ath9k: AWAKE -> NETWORK SLEEP
[ 1760.193311] disable IER
[ 1760.193320] ath9k: new IMR 0x918414b4
[ 1760.193329] ath9k: enable IER
[ 1760.193353] ath9k: AR_IMR 0xdeadbeef IER 0xdeadbeef


didn't mean to be lazy(couple of beers does this to me);

Thanks so the relevant section of the log is (with my comments):

[  326.573105] wlan0: deauthenticating from 00:1e:2a:00:67:f0 by local choice
(reason=3)

Interesting -- so we first disassociate from the AP even if we haven't yet been associated.

[  326.574048] phy1: device no longer idle - in use
[  326.574057] wlan0: direct probe to AP 00:1e:2a:00:67:f0 (try 1)
[  326.576643] wlan0: direct probe responded
[  326.576651] wlan0: authenticate with AP 00:1e:2a:00:67:f0 (try 1)
[  326.583190] wlan0: authenticated
[  326.583232] wlan0: associate with AP 00:1e:2a:00:67:f0 (try 1)
[  326.585608] wlan0: RX AssocResp from 00:1e:2a:00:67:f0 (capab=0x431 status=0
aid=1)
[  326.585614] wlan0: associated
[  326.585637] phy1: Allocated STA 00:1e:2a:00:67:f0
[  326.585644] ath9k: Choosing rate table for mode: 1
[  326.585655] ath9k: RC Initialized with capabilities: 0x0
[  326.585663] phy1: Inserted STA 00:1e:2a:00:67:f0
[  326.585673] ath9k: Configure tx [queue/halq] [0/3],  aifs: 2, cw_min: 3,
cw_max: 7, txop: 47
[  326.585689] ath9k: Configure tx [queue/halq] [1/2],  aifs: 2, cw_min: 7,
cw_max: 15, txop: 94
[  326.585703] ath9k: Configure tx [queue/halq] [2/1],  aifs: 3, cw_min: 15,
cw_max: 1023, txop: 0
[  326.585717] ath9k: Configure tx [queue/halq] [3/0],  aifs: 7, cw_min: 15,
cw_max: 1023, txop: 0
[  326.585734] ath9k: RX filter 0x0 bssid 00:1e:2a:00:67:f0 aid 0x0
[  326.585740] ath9k: BSS Changed PREAMBLE 1
[  326.585744] ath9k: BSS Changed ASSOC 1
[  326.585749] ath9k: Bss Info ASSOC 1, bssid: 00:1e:2a:00:67:f0
[  326.589208] ath9k: Set HW Key

OK so up to here everything seems fine.

Then we get this:
[  326.810185] ath9k: Reconfigure Beacon timers based on timestamp from the AP

I'll need to look review this, curious if perhaps our initial timestamp is screwy.

[  331.563862] ath9k: Set HW RX filter: 0x207
[  331.563951] ath9k: Set HW RX filter: 0x207
[  334.307416] ath9k: Set HW RX filter: 0x207
[  334.307806] ath9k: Set HW RX filter: 0x207

Wonder why we set this 4 times.

[  375.704105] wlan0: detected beacon loss from AP - sending probe request

And no further information tells us why this happens.

[  376.204111] No probe response from AP 00:1e:2a:00:67:f0 after 500ms, try 1
[  376.704280] No probe response from AP 00:1e:2a:00:67:f0 after 500ms, try 2
[  377.204336] No probe response from AP 00:1e:2a:00:67:f0 after 500ms, try 3
[  377.704096] No probe response from AP 00:1e:2a:00:67:f0 after 500ms, try 4
[  378.204102] No probe response from AP 00:1e:2a:00:67:f0 after 500ms,
disconnecting.

And this is the final failure.

Unfortunately nothing new is telling is indicative of what may cause the issue.

Justin, just to confirm, if you load ath9k (without debugging parameters passed to ath9k), can you verify that this issue does not occur if prior to running wpa_supplicant manually you can first run:


iwconfig wlan0 power off

I'd also like you to provide the output of this command prior to running wpa_supplicant manually:

ps -ef| egrep -i "supplicant|Netwo|nm-app"

Which distribution is this on?

o.k. I gather that info for you
(apologize for the delay);

Interesting thing here(happened yesterday as well), is on a cold boot recreating the bug takes longer than when the machine is warmed up.
normally takes about 5min for the first disconnect, then in between 5-12 min after the 5min mark, then almost always at 30min or so of running.

With a cold boot the first disconnect took around 22-25 min.
(wondering if this is some cpu thing).

Anyways here's the info you wanted:

iwconfig wlan0 power off
system runs fine(running straight for 40 min without no signs of a disconnect
from wpa_supplicant).

ps -ef| egrep -i "supplicant|Netwo|nm-app"

root      1553  1349  0 21:42 pts/0    00:00:00 /sbin/wpa_supplicant -Dwext -i wlan0 -c /home/name/wire
name    1652  1538  0 22:20 pts/5    00:00:00 egrep -i supplicant|Netwo|nm-app

and config for wpa_supplicant
cat /home/name/wire

ap_scan=1
ctrl_interface=/var/run/wpa_supplicant
network={
                ssid="JPM"
                #ssid="attwifi"
       scan_ssid=0
       key_mgmt=NONE
       auth_alg=SHARED
        wep_key0=xxxxxxxxxxxxxxxxx
       wep_tx_keyidx=0
       priority=5
}
(this config is from wicd-client)

The system is a clfs system built a few weeks ago.
with this build I used these CFLAGS with every app except libflash

CFLAGS="-m64 -mtune=core2 -march=core2 -O2 -pipe -fomit-frame-pointer" CXXFLAGS="${CFLAGS}" MAKEOPTS="{-j3}"

gcc is = gcc version 4.4.2

any other info you need let me know.
I'll build the latest wpa_supplicant just to verify that.

Bug 14664 is a duplicate of this issue. I made some comments there:
http://bugzilla.kernel.org/show_bug.cgi?id=14664#c1

With power management off I ran the older kernel fine over night, no disconnect for over 13 hours.

I have now merged wireless-testing master into my kernel, latest in drivers/net/wireless/ath is commit e49dd47a04400e3b5c28f661f5674fa130de5357 from Dec 12.

This kernel defaults to power management off, per commit 900293de386ba193aed3eab95ddfaa044c9428c4 from Nov 23.

I booted, brought the interface up, set SSID using iwconfig (associated), set IP address, brought up a VPN, then ran iwconfig eth1 power on. After a few minutes I got 'No probe response', as with my previous kernel.

Disabled power management, brought eth1 down and up, restored route, restarted VPN and I am running fine now.

I am using an AR5008 according to lspci, "phy0: Atheros AR5416 MAC/BB Rev:2 AR5133 RF Rev:81: mem=0xf8320000, irq=21" (see bug 14664 for more dmesg output) in STA mode without any wpa_supplicant.

My kernel has CONFIG_NO_HZ and CONFIG_HZ=1000. CONFIG_MAC80211_VERBOSE_PS_DEBUG seems irrelevant since my card is not in AP mode, but I will enable all debugging mentioned above and follow up with output shortly.

*** Bug 14664 has been marked as a duplicate of this bug. ***

Sorry, but this issue is not fixed by disabling power management. Last night, my system disconnected again. Unfortunately I had not yet enabled full debugging, so this is all I have:

[16852.919277] phy0: Removed STA xx
[16852.919293] phy0: Destroyed STA xx
[16852.919303] eth1: deauthenticating from xx by local choice (reason=3)
[16852.919361] phy0: device now idle
[16852.922993] phy0: device no longer idle - scanning
[16856.216403] eth1: direct probe to AP yy (try 1)
[16856.219147] eth1: direct probe responded
[16856.219156] eth1: authenticate with AP yy (try 1)
[16856.221043] eth1: authenticated
[16856.221076] eth1: associate with AP yy (try 1)
[16856.223606] eth1: RX AssocResp from yy (capab=0x421 status=0 aid=1)
[16856.223614] eth1: associated
[16856.223636] phy0: Allocated STA yy
[16856.223662] phy0: Inserted STA yy
[16856.223673] phy0: WMM queue=2 aci=0 acm=0 aifs=2 cWmin=15 cWmax=1023 txop=64
[16856.223691] phy0: WMM queue=3 aci=1 acm=0 aifs=7 cWmin=15 cWmax=1023 txop=0
[16856.223709] phy0: WMM queue=1 aci=2 acm=0 aifs=2 cWmin=7 cWmax=15 txop=94
[16856.223726] phy0: WMM queue=0 aci=3 acm=0 aifs=2 cWmin=3 cWmax=7 txop=47
[30689.000039] eth1: detected beacon loss from AP - sending probe request
[30689.500038] No probe response from AP yy after 500ms, try 1
[30690.000669] No probe response from AP yy after 500ms, try 2
[30690.500036] No probe response from AP yy after 500ms, try 3
[30691.000044] No probe response from AP yy after 500ms, try 4
[30691.500041] No probe response from AP yy after 500ms, disconnecting.
[30691.500114] phy0: Removed STA yy
[30691.500127] phy0: Destroyed STA y
[30691.500136] phy0: device now idle

"xx" is the AP I was associated with before suspending, yy is the AP I manually associated with at home after resuming.

Created attachment 24207 [details]
dmesg output with debug=0xffffffff leading up to disconnect

This is with Power Management:off on the interface.

Peter you're using wireless-testing, that's different, please use linux-wireless to follow up on that and also be sure to include your device (AR5416, AR9280, etc) on your reports to the list.

Justin, any luck with a newer wpa_supplicant? I will note you are using AR5416, one of the older first generation 802.11n hardware devices by Atheros so it is likely your device may have an issue while AR9280 and newer devices will not.

The original reporter of this bug report though is Kristoffer Ericson and the device present on the report is AR9280. I haven't heard back from Kristoffer since we advised to test the new patches...

Justin, if you follow linux-wireless you will notice that Sujith recently posted some new patches in which he Cc'd stable. Those patches will eventually get merged onto the next 2.6.32.y release -- can you go ahead and just apply them on top of the other patches I asked you to merge. I haven't yet gotten a chance to gather those patches into a URL for users to apply... if someone can do that that would be appreciated.

I'd like to see this bug report closed and power save enable by default again on ath9k upstream.

(In reply to comment #58)
> Justin, any luck with a newer wpa_supplicant? I will note you are using
> AR5416,
> one of the older first generation 802.11n hardware devices by Atheros so it
> is
> likely your device may have an issue while AR9280 and newer devices will not.
> 
> The original reporter of this bug report though is Kristoffer Ericson and the
> device present on the report is AR9280. I haven't heard back from Kristoffer
> since we advised to test the new patches...

Sorry if Ive been not replying much. As I stated above Vanilla 2.6.32 seems to have solved the issue for me. Most likely we are not experiencing the same bug (me and justin). Would you like me to test any patches on 2.6.31 to see if it works?


> 
> Justin, if you follow linux-wireless you will notice that Sujith recently
> posted some new patches in which he Cc'd stable. Those patches will
> eventually
> get merged onto the next 2.6.32.y release -- can you go ahead and just apply
> them on top of the other patches I asked you to merge. I haven't yet gotten a
> chance to gather those patches into a URL for users to apply... if someone
> can
> do that that would be appreciated.
> 
> I'd like to see this bug report closed and power save enable by default again
> on ath9k upstream.

o.k. a bit late at the moment, but in the morning I'll clean the slate and start fresh. I want to close this as well.

Since I first saw this issue with .32-rc6, and I still do with wireless-testing, I thought it might be relevant to add my information here. I will go away onto mailing lists now, but it does seem like duplicated effort for one and the same issue. Thanks!

Well stable fixes are separate, development issues can be propagated into stable so if you are using wireless-testing due to the delta there it is just no worth trying to figure whether or not your issue pertains to the new code changes or something different.

For this bug report please keep the issue to 2.6.32.

So far it seems AR5416 remains with issues with ps enabled by default and AR9280 issue is gone.

Created attachment 24227 [details]
kernel-config-macbook-AR5008

here is my .config please look over to make sure I didn't forget anything.
(there was a similar bug report for wpa_supplicant, that I did, and came to the conclusion that I had missed something in my .config);

BTW: the card I have is AR5008

looking at the archives for linux-wireless I'm seeing a bunch of patches. searching Sujith gives me stuff from feb of 09. if anybody can where are these patches that where submitted via CC's so I can test them(the other patches are plugged in with 2.6.32-rc8, but break on current HEAD);

http://marc.info/?l=linux-wireless&r=3&b=200912&w=2

Patchwork has them in git am'able form:

http://patchwork.kernel.org/project/linux-wireless/list/

cool thanks.. threw in latest git wpa_supplicant, then I'll throw in these 6 patches on top of the other patches.

current HEAD over here is at 2.6.32-rc8

Hmm, are you using Linus' tree or downloading a tarball? 2.6.32.1 is already out, 2.6.32.2 is on its way. Some of the patches mentioned here will be merged on 2.6.31.2 but Sujiths' latest ones won't make it until 2.6.32.3.

using Linus's tree 
did a git reset --hard origin v2.6.32-rc8.
if you need me to pull a branch(wireless, or next) let me know.

Actually jump to hpa's tree now to get 2.6.32.y:

git://git.kernel.org/pub/scm/linux/kernel/git/hpa/linux-2.6-allstable.git

the master bring will always follow Linus so now that's 2.6.33-rc1, but hpa has branches for the stable 2.6.3x.y releases so do:

git checkout -b linux-2.6.32.y origin/linux-2.6.32.y

Then check git log on drivers/net/wireless/ath/ath9k/ for the latest patches merged, you can also check mac80211 (dynamic ps fix may or may not be there I forget, I don't think so).

alright.. at the moment plugging in sujith's patches.
then I'll go from there.

doing a git reset --hard v2.6.32-rc8
and then applying the first patches in comment #34 works fine,
but adding patches 1/6 from sujith error's out for me
main.c 1648 error common undeclared(first use in this function

I'll look around or to see if I can find the rest of "common" to add to the kernel to test these patches out on top of the patches on comment #34.

Nah don't bother that's a lot of code, those patches need to be backported to be applied to 2.6.32 it seems.

alright.. 
I'll pull allstable(as I type), and see how the wireless reacts.
then go from there

o.k. running linux-stable so far so good, up 7 min's and am not seeing a disconnect, will run her for an hour or two just to make sure.
BTW: I noticed powermanagement was off with iwconfig so before starting wpa_supplicant I went iwconfig wlan0 power on
(hopefully this is a go);

yeah 2.6.32.2 got a power management got disabled by default. BTW 2.6.32.2 was just released. You may want to:

git checkout master
git pull
git checkout linux-2.6.32.y
git rebase origin/linux-2.6.32.y
git revert 54ab040d24904d1fa2c0a6a27936b7c56a4efb24.

The last command reverts the patch which disable PS by default.

Are you using linux-stable git tree using the master branch or the 2.6.32.y branch?

damn it this thing fired off about 20mins into running.

heres -dd with wpa_supplicant(latest snapshot)


sudo /sbin/wpa_supplicant -D wext -i wlan0 -c /home/justin/wire -dd
Password:
Initializing interface 'wlan0' conf '/home/justin/wire' driver 'wext' ctrl_interface 'N/A' bridge 'N/A'
Configuration file '/home/justin/wire' -> '/home/justin/wire'
Reading configuration file '/home/justin/wire'
ap_scan=1
ctrl_interface='/var/run/wpa_supplicant'
Line: 3 - start of a new network block
ssid - hexdump_ascii(len=3):
     4a 50 4d                                          JPM             
scan_ssid=0 (0x0)
key_mgmt: 0x4
auth_alg: 0x2
wep_key0 - hexdump(len=13): [REMOVED]
wep_tx_keyidx=0 (0x0)
priority=5 (0x5)
Priority group 5
   id=0 ssid='JPM'
Interface wlan0 set UP - waiting a second for the driver to complete initialization
SIOCGIWRANGE: WE(compiled)=22 WE(source)=21 enc_capa=0xf
  capabilities: key_mgmt 0xf enc 0xf flags 0x0
netlink: Operstate: linkmode=1, operstate=5
Own MAC address: 00:19:e3:06:2c:16
wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
wpa_driver_wext_set_key: alg=0 key_idx=1 set_tx=0 seq_len=0 key_len=0
wpa_driver_wext_set_key: alg=0 key_idx=2 set_tx=0 seq_len=0 key_len=0
wpa_driver_wext_set_key: alg=0 key_idx=3 set_tx=0 seq_len=0 key_len=0
wpa_driver_wext_set_countermeasures
RSN: flushing PMKID list in the driver
Setting scan request: 0 sec 100000 usec
EAPOL: SUPP_PAE entering state DISCONNECTED
EAPOL: Supplicant port status: Unauthorized
EAPOL: KEY_RX entering state NO_KEY_RECEIVE
EAPOL: SUPP_BE entering state INITIALIZE
EAP: EAP entering state DISABLED
EAPOL: Supplicant port status: Unauthorized
EAPOL: Supplicant port status: Unauthorized
Added interface wlan0
RTM_NEWLINK: operstate=0 ifi_flags=0x1002 ()
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
Wireless event: cmd=0x8b19 len=16
ioctl[SIOCGIWSCAN]: Resource temporarily unavailable
Failed to get scan results
Failed to get scan results - try scanning again
Setting scan request: 1 sec 0 usec
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
Wireless event: cmd=0x8b06 len=12
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
Wireless event: cmd=0x8b1a len=48
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
Wireless event: cmd=0x8b19 len=16
ioctl[SIOCGIWSCAN]: Resource temporarily unavailable
Failed to get scan results
Failed to get scan results - try scanning again
Setting scan request: 1 sec 0 usec
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
Wireless event: cmd=0x8b19 len=16
Received 343 bytes of scan results (1 BSSes)
New scan results available
Selecting BSS from priority group 5
Try to find WPA-enabled AP
0: 00:1e:2a:00:67:f0 ssid='JPM' wpa_ie_len=0 rsn_ie_len=0 caps=0x11
   skip - no WPA/RSN IE
Try to find non-WPA AP
0: 00:1e:2a:00:67:f0 ssid='JPM' wpa_ie_len=0 rsn_ie_len=0 caps=0x11
   selected non-WPA AP 00:1e:2a:00:67:f0 ssid='JPM'
Trying to associate with 00:1e:2a:00:67:f0 (SSID='JPM' freq=2422 MHz)
Cancelling scan request
WPA: clearing own WPA/RSN IE
Automatic auth_alg selection: 0x1
Overriding auth_alg selection: 0x2
WPA: clearing AP WPA IE
WPA: clearing AP RSN IE
WPA: clearing own WPA/RSN IE
No keys have been configured - skip key clearing
wpa_driver_wext_set_key: alg=1 key_idx=0 set_tx=1 seq_len=0 key_len=13
State: DISCONNECTED -> ASSOCIATING
wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
netlink: Operstate: linkmode=-1, operstate=5
wpa_driver_wext_associate
wpa_driver_wext_set_drop_unencrypted
wpa_driver_wext_set_psk
Setting authentication timeout: 10 sec 0 usec
EAPOL: External notification - EAP success=0
EAPOL: Supplicant port status: Unauthorized
EAPOL: External notification - EAP fail=0
EAPOL: Supplicant port status: Unauthorized
EAPOL: External notification - portControl=ForceAuthorized
EAPOL: Supplicant port status: Unauthorized
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
Wireless event: cmd=0x8b06 len=12
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
Wireless event: cmd=0x8b04 len=16
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
Wireless event: cmd=0x8b1a len=19
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
Wireless event: cmd=0x8b19 len=16
Received 344 bytes of scan results (1 BSSes)
New scan results available
Selecting BSS from priority group 5
Try to find WPA-enabled AP
0: 00:1e:2a:00:67:f0 ssid='JPM' wpa_ie_len=0 rsn_ie_len=0 caps=0x11
   skip - no WPA/RSN IE
Try to find non-WPA AP
0: 00:1e:2a:00:67:f0 ssid='JPM' wpa_ie_len=0 rsn_ie_len=0 caps=0x11
   selected non-WPA AP 00:1e:2a:00:67:f0 ssid='JPM'
Already associated with the selected AP
RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
Wireless event: cmd=0x8c08 len=32
AssocResp IE wireless event - hexdump(len=16): 01 08 82 84 8b 96 0c 18 30 48 32 04 12 24 60 6c
RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
Wireless event: cmd=0x8b15 len=24
Wireless event: new AP: 00:1e:2a:00:67:f0
Association info event
resp_ies - hexdump(len=16): 01 08 82 84 8b 96 0c 18 30 48 32 04 12 24 60 6c
State: ASSOCIATING -> ASSOCIATED
wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
netlink: Operstate: linkmode=-1, operstate=5
Associated to a new BSS: BSSID=00:1e:2a:00:67:f0
Associated with 00:1e:2a:00:67:f0
WPA: Association event - clear replay counter
WPA: Clear old PTK
EAPOL: External notification - portEnabled=0
EAPOL: Supplicant port status: Unauthorized
EAPOL: External notification - portValid=0
EAPOL: Supplicant port status: Unauthorized
EAPOL: External notification - portEnabled=1
EAPOL: SUPP_PAE entering state S_FORCE_AUTH
EAPOL: Supplicant port status: Authorized
EAPOL: SUPP_BE entering state IDLE
Cancelling authentication timeout
State: ASSOCIATED -> COMPLETED
CTRL-EVENT-CONNECTED - Connection to 00:1e:2a:00:67:f0 completed (auth) [id=0 id_str=]
wpa_driver_wext_set_operstate: operstate 0->1 (UP)
netlink: Operstate: linkmode=-1, operstate=6
Cancelling scan request
RTM_NEWLINK: operstate=1 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
EAPOL: disable timer tick
RTM_NEWLINK: operstate=1 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
RTM_NEWLINK: operstate=1 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
Wireless event: cmd=0x8b15 len=24
Wireless event: new AP: 00:00:00:00:00:00
Setting scan request: 0 sec 100000 usec
Added BSSID 00:1e:2a:00:67:f0 into blacklist
CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys
State: COMPLETED -> DISCONNECTED
wpa_driver_wext_set_operstate: operstate 1->0 (DORMANT)
netlink: Operstate: linkmode=-1, operstate=5
EAPOL: External notification - portEnabled=0
EAPOL: SUPP_PAE entering state DISCONNECTED
EAPOL: Supplicant port status: Unauthorized
EAPOL: SUPP_BE entering state INITIALIZE
EAPOL: Supplicant port status: Unauthorized
EAPOL: External notification - portValid=0
EAPOL: Supplicant port status: Unauthorized
Trying to get current scan results first without requesting a new scan to speed up initial association
Received 0 bytes of scan results (0 BSSes)
Cached scan results are empty - not posting
Selecting BSS from priority group 5
Try to find WPA-enabled AP
Try to find non-WPA AP
No APs found - clear blacklist and try again
Removed BSSID 00:1e:2a:00:67:f0 from blacklist (clear)
Selecting BSS from priority group 5
Try to find WPA-enabled AP
Try to find non-WPA AP
No suitable network found
Setting scan request: 0 sec 0 usec
State: DISCONNECTED -> SCANNING
Starting AP scan for wildcard SSID
Scan requested (ret=0) - scan timeout 30 seconds
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
Wireless event: cmd=0x8b19 len=16
Received 1128 bytes of scan results (3 BSSes)
New scan results available
Selecting BSS from priority group 5
Try to find WPA-enabled AP
0: 00:24:56:2b:39:39 ssid='2WIRE336' wpa_ie_len=22 rsn_ie_len=0 caps=0x11
   skip - SSID mismatch
1: 00:26:50:3c:bc:d1 ssid='2WIRE689' wpa_ie_len=22 rsn_ie_len=0 caps=0x11
   skip - SSID mismatch
2: 00:1e:2a:00:67:f0 ssid='JPM' wpa_ie_len=0 rsn_ie_len=0 caps=0x11
   skip - no WPA/RSN IE
Try to find non-WPA AP
0: 00:24:56:2b:39:39 ssid='2WIRE336' wpa_ie_len=22 rsn_ie_len=0 caps=0x11
   skip - SSID mismatch
1: 00:26:50:3c:bc:d1 ssid='2WIRE689' wpa_ie_len=22 rsn_ie_len=0 caps=0x11
   skip - SSID mismatch
2: 00:1e:2a:00:67:f0 ssid='JPM' wpa_ie_len=0 rsn_ie_len=0 caps=0x11
   selected non-WPA AP 00:1e:2a:00:67:f0 ssid='JPM'
Trying to associate with 00:1e:2a:00:67:f0 (SSID='JPM' freq=2422 MHz)
Cancelling scan request
WPA: clearing own WPA/RSN IE
Automatic auth_alg selection: 0x1
Overriding auth_alg selection: 0x2
WPA: clearing AP WPA IE
WPA: clearing AP RSN IE
WPA: clearing own WPA/RSN IE
wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
wpa_driver_wext_set_key: alg=0 key_idx=1 set_tx=0 seq_len=0 key_len=0
wpa_driver_wext_set_key: alg=0 key_idx=2 set_tx=0 seq_len=0 key_len=0
wpa_driver_wext_set_key: alg=0 key_idx=3 set_tx=0 seq_len=0 key_len=0
wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
wpa_driver_wext_set_key: alg=1 key_idx=0 set_tx=1 seq_len=0 key_len=13
State: SCANNING -> ASSOCIATING
wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
netlink: Operstate: linkmode=-1, operstate=5
wpa_driver_wext_associate
wpa_driver_wext_set_drop_unencrypted
wpa_driver_wext_set_psk
Setting authentication timeout: 10 sec 0 usec
EAPOL: External notification - EAP success=0
EAPOL: Supplicant port status: Unauthorized
EAPOL: External notification - EAP fail=0
EAPOL: Supplicant port status: Unauthorized
EAPOL: External notification - portControl=ForceAuthorized
EAPOL: Supplicant port status: Unauthorized
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
Wireless event: cmd=0x8b06 len=12
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
Wireless event: cmd=0x8b04 len=16
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
Wireless event: cmd=0x8b1a len=19
RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
Wireless event: cmd=0x8c08 len=32
AssocResp IE wireless event - hexdump(len=16): 01 08 82 84 8b 96 0c 18 30 48 32 04 12 24 60 6c
RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
Wireless event: cmd=0x8b15 len=24
Wireless event: new AP: 00:1e:2a:00:67:f0
Association info event
resp_ies - hexdump(len=16): 01 08 82 84 8b 96 0c 18 30 48 32 04 12 24 60 6c
State: ASSOCIATING -> ASSOCIATED
wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
netlink: Operstate: linkmode=-1, operstate=5
Associated to a new BSS: BSSID=00:1e:2a:00:67:f0
Associated with 00:1e:2a:00:67:f0
WPA: Association event - clear replay counter
WPA: Clear old PTK
EAPOL: External notification - portEnabled=0
EAPOL: Supplicant port status: Unauthorized
EAPOL: External notification - portValid=0
EAPOL: Supplicant port status: Unauthorized
EAPOL: External notification - portEnabled=1
EAPOL: SUPP_PAE entering state S_FORCE_AUTH
EAPOL: Supplicant port status: Authorized
EAPOL: SUPP_BE entering state IDLE
Cancelling authentication timeout
State: ASSOCIATED -> COMPLETED
CTRL-EVENT-CONNECTED - Connection to 00:1e:2a:00:67:f0 completed (reauth) [id=0 id_str=]
wpa_driver_wext_set_operstate: operstate 0->1 (UP)
netlink: Operstate: linkmode=-1, operstate=6
Cancelling scan request
RTM_NEWLINK: operstate=1 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
^CCTRL-EVENT-TERMINATING - signal 2 received
Removing interface wlan0
wpa_driver_wext_deauthenticate
wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
wpa_driver_wext_set_key: alg=0 key_idx=1 set_tx=0 seq_len=0 key_len=0
wpa_driver_wext_set_key: alg=0 key_idx=2 set_tx=0 seq_len=0 key_len=0
wpa_driver_wext_set_key: alg=0 key_idx=3 set_tx=0 seq_len=0 key_len=0
wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
State: COMPLETED -> DISCONNECTED
wpa_driver_wext_set_operstate: operstate 1->0 (DORMANT)
netlink: Operstate: linkmode=-1, operstate=5
EAPOL: External notification - portEnabled=0
EAPOL: SUPP_PAE entering state DISCONNECTED
EAPOL: Supplicant port status: Unauthorized
EAPOL: SUPP_BE entering state INITIALIZE
EAPOL: Supplicant port status: Unauthorized
EAPOL: External notification - portValid=0
EAPOL: Supplicant port status: Unauthorized
wpa_driver_wext_set_countermeasures
No keys have been configured - skip key clearing
Cancelling scan request
Cancelling authentication timeout
netlink: Operstate: linkmode=0, operstate=6



I'm going to try and get rid of wpa_supplicant by just using no security feature on my router to see.

(In reply to comment #75)
> yeah 2.6.32.2 got a power management got disabled by default. BTW 2.6.32.2
> was
> just released. You may want to:
> 
> git checkout master
> git pull
> git checkout linux-2.6.32.y
> git rebase origin/linux-2.6.32.y
> git revert 54ab040d24904d1fa2c0a6a27936b7c56a4efb24.
> 
> The last command reverts the patch which disable PS by default.
> 
> Are you using linux-stable git tree using the master branch or the 2.6.32.y
> branch?

I just did a git clone the address you posted.(2.6.33-rc1)

Oh well, OK if that makes your AR5416 happy that's fine too. That's the same thing as Linus' tree when you use the master branch. The purpose of the tree I gave you was to see if you want to debug 2.6.32.y further. For the next 2.6.32.y you would need that tree.

Oh and you don't have to kill wpa_supplicant .. you should be fine with using it, in fact I recommend it as disconnections are inevitable, consider the AP detecting your idle for too long and it deassocs you.

For a non-encrypted network you can use something like:

ctrl_interface=/var/run/wpa_supplicant
ap_scan=1
network={
	ssid="foobar"
	scan_ssid=1
	key_mgmt=NONE
}


Another thing you can try is running wpa_supplicant with -D nl80211 instead of -D wext

alright.. well I leave wpa_supplicant as is for now.

I'll just wait and see if there's any other patches to test. As for looking at the code I can try, but am not familiar with it(hopefully one day);

might have missed a post.. but this should stay open.

Hello,

Having a problem with webcam disconnecting wlan device. Searching keyworld from kernel message lead me to this bug. Does anybody also think it is related to https://bugs.launchpad.net/linux/+bug/647501 ?

Thanks

tough to say.. right now running the latest Mainline and everything seems o.k.
(no disconnects etc...(although I do see the message in dmesg)from what I remember this was caused by having powersave turned on with the wireless driver. In your case iwconfig wlan* power off can let you know if this is the problem or not.
(over here I had radio streaming, plus hulu streaming then after a few mins everything would crap out for a few seconds, then go back to normal(once powersave was disabled everything streamed clean without disconnects)).

With power management disabled, this bug still exists on my AR5008 (DWA-522) hardware.  Notably this is currently included in the 2.6.32 source now frozen to ship with the next release of Debian, 6.0-Squeeze, which I have upgraded to.  

D-Link System Inc DWA-552 802.11n Xtreme N Desktop Adapter (rev A1)
ieee80211 phy0: Atheros AR5416 MAC/BB Rev:2 AR2133 RF Rev:81 

There is a downstream bug for Debian linked here where I have posted some additional details:
 http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=556009 

I am currently testing the 2010-10-20 compat-wireless against the Debian 2.6.32 kernel to see if this is actually resolved in the latest version with the hope that it works and a patch for 2.6.32 can be created somehow for ath9k, as I suspect that merging current compat-wireless is a show-stopper for the now-frozen Debian kernel.

Upgrade:

http://wireless.kernel.org/en/users/Download/stable/

Thank Luis.  I am already running the latest. If this tests okay, I'll try the June 2.6.32.16 compat-wireless linked above in hopes the narrower patchset might be close to what is in the current 2.6.32.24 kernel used by Debian.

I expect the newer ath9k I am using will work fine for *me*; I am happy about that.  
 
It is patching of the distribution kernel packages that I am trying to facilitate to enable an easily sustainable process to maintain the driver without risk to future kernel upgrades for enterprise use on Debian.

The simple/ideal solution would be to hand feed a small patchset to the Debian package maintainer.  Unfortunately it appears that the root cause/commit of this issue or a solution is not easily identifiable per Justin's attempts. (https://bugzilla.kernel.org/show_bug.cgi?id=14267#c71) 

I might assume it is less work to avoid AR5416+AR2133 than invest time in creating a suitable patch for the Debian kernel, noting this is probably the oldest non-legacy ath9k radio combination supported.

There are a few stable patches pending integration into 2.6.32 even for Power Save. The only way for a patch to make it into 2.6.32 is first to add it to Linus' tree.

If you are not familiar with this process, please read:

http://wireless.kernel.org/en/users/Documentation/Fix_Propagation

We have already tagged a lot of patches for stable consideration, it takes a while to propagate. But we cannot propagate features or new code. For that you'll need a newer kernel.

I used to recommend at least 2.6.32 for ath9k, today that has switched to 2.6.36, and if you're stuck on 2.6.32, you can use compat-wireless-2.6.36, which is why we created it.

What debian can do is make a compat-wireless package for users wishing to upgrade their 802.11 and BT subystem to 2.6.36, its what Ubuntu does with their linux-backports-modules package.

Well.. after upgrading to the latest 2010-10-20 compat-wireless, I am still seeing ath9k disconnect from my AP. 

Oct 21 20:28:10 maple kernel: [183437.317018] ieee80211 phy0: ath1: No probe response from AP 00:01:46:XX:XX:XX after 500ms, disconnecting.
Oct 21 22:39:12 maple kernel: [  539.316041] ieee80211 phy0: ath1: No probe response from AP 00:01:46:XX:XX:XX after 500ms, disconnecting.

maple:~# modinfo ath9k
filename:       /lib/modules/2.6.32-5-xen-amd64/updates/drivers/net/wireless/ath/ath9k/ath9k.ko

so the disabling of the powersave made no difference..over here disabling gave me a clean run of things.. I just loaded the latest Mainline and will have a look if the disconnect is happening as well over here.(will bisect again just to see when I have time, are you able to bisect? since the powersave option made no difference for you(maybe it's another commit)).

In my case, I don't have a working starting point, having moved directly into this bug from an older working madwifi+AR5001 hardware setup. I am going test out the published stable versions (linked above) between vanilla 2.6.32 and bleeding edge to see if I can find a working patch set.  I am going to try and setup another ath9k that does not have this issue at the same location to more effectively rule out any uniqueness at the AP.

I believe this issue is still there, but Atheros does not support this chipset and I am fairly sure that only they have access to the information that is needed to really fix this problem.

My guess is that RX just stops working at some point, causing the disassociation.

I have absolutely given up on using AR5416 as STA because of the lack of support and interest from Atheros. I'd suggest not wasting time on it. However, AR5416 works well as AP, so the card isn't completely useless.

I just finished testing against stable compat-wireless 2.6.32.16, 2.6.33.6, 2.6.34.1, 2.6.35-1 and 2.6.36-rc5-2-s in addition to the bleeding 2010-10-20. In every case I have this issue.  Using 2.6.35-1 I was able to watch a 1GB movie over wireless with only one interruption, so I am sticking with that for further testing, though today its down frequently. I might note 2.6.36-rc5 had speed issues for me in two separate tests over a reboot, but it is *rc* so that might be expected. 

My other ath9k (928X) is fine, as are all other devices and smartphones.

My AP is a DI-624M(v2.5). Its an AR5513 under the hood, and I have it set to pure 11g-only, 64bit WEP. Its defaults are Beacon 100ms, RTS 2313 B, Frag 2346 B, DTIM Interval 4, CTS Auto, Long Preamble with TX Rate auto, and power 100%/17dBM.

I picked this hardware because it appears to be an affordable and common PCI radio combo that supports ath9k.. and solve my many(5?) years workaround waiting to re-bridge my media VMs with wifi which I have not been able to do since pre_ng_madwifi with my AR5212 (DWL-G520 PCI) which this AR5416 replaced six months ago.

I did not experience a regression (never ran 2.6.31), as I saw similar issues running this device on ath5k on 2.6.26 (Debian 5.0) over the last six months, but it was far less frequent, to the point where I'd just run a quick ssh script from my phone to re-associate in seconds when it occurred.

s/ath5k/ath_pci/g on my #91 comment regarding the AR5416 on Debian 5.0 so the bug exists with this hardware and older madwifi 0.9.4+r3772.20080716-1.

Also s/AR5001/AR5212/g on my #89 comment (too many atheros chipsets around here).

I switched back to my old AR5212, and it is working OK so far with current compat-wireless ath5k on Debian 6.0 (ANI support for ath5k was not available previously), and I think I may be able to bridge it in STA mode too with a recent iw patch I just applied to my deb-src: http://www.spinics.net/lists/linux-wireless/msg56681.html.  

I'll stick my AR5416 into a wired Ubuntu desktop where it will receive the packaged compat-wireless updates so I can periodically test and provide feedback when I see updates here. I'd like to get back to better performance of the ath9k even on my 11g network.

Is this still an issue on >2.6.38-rc7  ?

Hey florian, 

I doubt it. Im currently using linux-next from first of march and its working well. Looks like thats equal to v2.6.38-rc6 so unless something big happend in -rc7 it should be fine, atleast on my end.

right now I am using the Mainline kernel and am seeing nothing like before. movie plays on hulu without stuttering/stopping after 15mins or so. will continue to watch and report anything.

Ok, cool. I'm closing this as unreproducible then.

Or... you don't happen to know which commit fixed it?

On Sat, Mar 5, 2011 at 3:42 PM,  <bugzilla-daemon@bugzilla.kernel.org> wrote:
> https://bugzilla.kernel.org/show_bug.cgi?id=14267
>
>
> Florian Mickler <florian@mickler.org> changed:
>
>           What    |Removed                     |Added
> ----------------------------------------------------------------------------
>             Status|NEEDINFO                    |CLOSED
>         Resolution|                            |UNREPRODUCIBLE
>
>
>
>
> --- Comment #96 from Florian Mickler <florian@mickler.org>  2011-03-05
> 23:42:11 ---
> Ok, cool. I'm closing this as unreproducible then.
>
> Or... you don't happen to know which commit fixed it?
>
> --
> Configure bugmail: https://bugzilla.kernel.org/userprefs.cgi?tab=email
> ------- You are receiving this mail because: -------
> You are on the CC list for the bug.
>

not sure what commit/merge fixed this.. heck this could even be with
the NetworkManager
itself(not sure though) i.e. when this was hitting I was using wicd,
and am now using NetworkManager.. but keep in mind this could be from
a commit.