2011-05-04 15:38:49

by Seth Forshee

Subject: ath5k regression associating with APs in 2.6.38

I've been investigating some reports of a regression in associating with
APs with AR2413 in 2.6.38. Association repeatedly fails with some
"direct probe to x timed out" messages (see syslog excerpt below),
although it will generally associate eventually, after many tries.

Bisection identifies 8aec7af (ath5k: Support synth-only channel change
for AR2413/AR5413) as offending commit. Prior to this commit there are
no direct probe messages at all in the logs. I've also found that
forcing fast to false at the top of ath5k_hw_reset() fixes the issue.
I'm not sure what the connection is between this commit and the
timeouts. Any suggestions?

Thanks,
Seth


May 4 09:32:15 AcerAspire5100 wpa_supplicant[757]: Trying to associate with c0:3f:0e:b9:f3:b2 (SSID='aureola' freq=2452 MHz)
May 4 09:32:15 AcerAspire5100 kernel: [ 120.063271] wlan0: direct probe to c0:3f:0e:b9:f3:b2 (try 1/3)
May 4 09:32:16 AcerAspire5100 kernel: [ 120.260074] wlan0: direct probe to c0:3f:0e:b9:f3:b2 (try 2/3)
May 4 09:32:16 AcerAspire5100 kernel: [ 120.460084] wlan0: direct probe to c0:3f:0e:b9:f3:b2 (try 3/3)
May 4 09:32:16 AcerAspire5100 kernel: [ 120.660082] wlan0: direct probe to c0:3f:0e:b9:f3:b2 timed out
May 4 09:32:25 AcerAspire5100 wpa_supplicant[757]: Authentication with c0:3f:0e:b9:f3:b2 timed out.

2011-05-04 17:31:14

by John W. Linville

Subject: Re: ath5k regression associating with APs in 2.6.38

On Wed, May 04, 2011 at 10:38:19AM -0500, Seth Forshee wrote:
> I've been investigating some reports of a regression in associating with
> APs with AR2413 in 2.6.38. Association repeatedly fails with some
> "direct probe to x timed out" messages (see syslog excerpt below),
> although it will generally associate eventually, after many tries.
>
> Bisection identifies 8aec7af (ath5k: Support synth-only channel change
> for AR2413/AR5413) as offending commit. Prior to this commit there are
> no direct probe messages at all in the logs. I've also found that
> forcing fast to false at the top of ath5k_hw_reset() fixes the issue.
> I'm not sure what the connection is between this commit and the
> timeouts. Any suggestions?

Have you tried reverting that commit on top of 2.6.38? Can you
recreate the issue with 2.6.39-rc6 (or later)?

John
--
John W. Linville Someday the world will need a hero, and you
[email protected] might be all we have. Be ready.

2011-05-04 19:26:57

by Seth Forshee

Subject: Re: ath5k regression associating with APs in 2.6.38

On Wed, May 04, 2011 at 01:27:17PM -0400, John W. Linville wrote:
> On Wed, May 04, 2011 at 10:38:19AM -0500, Seth Forshee wrote:
> > I've been investigating some reports of a regression in associating with
> > APs with AR2413 in 2.6.38. Association repeatedly fails with some
> > "direct probe to x timed out" messages (see syslog excerpt below),
> > although it will generally associate eventually, after many tries.
> >
> > Bisection identifies 8aec7af (ath5k: Support synth-only channel change
> > for AR2413/AR5413) as offending commit. Prior to this commit there are
> > no direct probe messages at all in the logs. I've also found that
> > forcing fast to false at the top of ath5k_hw_reset() fixes the issue.
> > I'm not sure what the connection is between this commit and the
> > timeouts. Any suggestions?
>
> Have you tried reverting that commit on top of 2.6.38? Can you
> recreate the issue with 2.6.39-rc6 (or later)?

I started to revert that commit, but it wasn't straight-forward due to
later changes. Forcing fast to false in ath5k_hw_reset() acts as a
functional revert of sorts since that should force it back to a full
reset for all channel changes, and it's much simpler than working out
the right way to revert the commit. I think the results suggest strongly
that a revert is likely to fix the problem. I can finish the work to
revert if you'd still like to see the results.

Testing a previous .39-rc kernel still exhibited the failure. I don't
recall which one it was and apparently forgot to make note of it. I'll
request testing against rc6.

Thanks,
Seth

2011-05-04 20:09:06

by Nick Kossifidis

Subject: Re: ath5k regression associating with APs in 2.6.38

2011/5/4 Seth Forshee <[email protected]>:
> On Wed, May 04, 2011 at 01:27:17PM -0400, John W. Linville wrote:
>> On Wed, May 04, 2011 at 10:38:19AM -0500, Seth Forshee wrote:
>> > I've been investigating some reports of a regression in associating with
>> > APs with AR2413 in 2.6.38. Association repeatedly fails with some
>> > "direct probe to x timed out" messages (see syslog excerpt below),
>> > although it will generally associate eventually, after many tries.
>> >
>> > Bisection identifies 8aec7af (ath5k: Support synth-only channel change
>> > for AR2413/AR5413) as offending commit. Prior to this commit there are
>> > no direct probe messages at all in the logs. I've also found that
>> > forcing fast to false at the top of ath5k_hw_reset() fixes the issue.
>> > I'm not sure what the connection is between this commit and the
>> > timeouts. Any suggestions?
>>
>> Have you tried reverting that commit on top of 2.6.38?  Can you
>> recreate the issue with 2.6.39-rc6 (or later)?
>
> I started to revert that commit, but it wasn't straight-forward due to
> later changes. Forcing fast to false in ath5k_hw_reset() acts as a
> functional revert of sorts since that should force it back to a full
> reset for all channel changes, and it's much simpler than working out
> the right way to revert the commit. I think the results suggest strongly
> that a revert is likely to fix the problem. I can finish the work to
> revert if you'd still like to see the results.
>
> Testing a previous .39-rc kernel still exhibited the failure. I don't
> recall which one it was and apparently forgot to make note of it. I'll
> request testing against rc6.
>
> Thanks,
> Seth
>

Do you get scan results ?
Can you enable ATH5K_DEBUG_RESET and see what you get ?

--
GPG ID: 0xD21DB2DB
As you read this post global entropy rises. Have Fun ;-)
Nick

2011-05-05 13:52:26

by Seth Forshee

Subject: Re: ath5k regression associating with APs in 2.6.38

On Wed, May 04, 2011 at 11:09:03PM +0300, Nick Kossifidis wrote:
> 2011/5/4 Seth Forshee <[email protected]>:
> > On Wed, May 04, 2011 at 01:27:17PM -0400, John W. Linville wrote:
> >> On Wed, May 04, 2011 at 10:38:19AM -0500, Seth Forshee wrote:
> >> > I've been investigating some reports of a regression in associating with
> >> > APs with AR2413 in 2.6.38. Association repeatedly fails with some
> >> > "direct probe to x timed out" messages (see syslog excerpt below),
> >> > although it will generally associate eventually, after many tries.
> >> >
> >> > Bisection identifies 8aec7af (ath5k: Support synth-only channel change
> >> > for AR2413/AR5413) as offending commit. Prior to this commit there are
> >> > no direct probe messages at all in the logs. I've also found that
> >> > forcing fast to false at the top of ath5k_hw_reset() fixes the issue.
> >> > I'm not sure what the connection is between this commit and the
> >> > timeouts. Any suggestions?
> >>
> >> Have you tried reverting that commit on top of 2.6.38?  Can you
> >> recreate the issue with 2.6.39-rc6 (or later)?
> >
> > I started to revert that commit, but it wasn't straight-forward due to
> > later changes. Forcing fast to false in ath5k_hw_reset() acts as a
> > functional revert of sorts since that should force it back to a full
> > reset for all channel changes, and it's much simpler than working out
> > the right way to revert the commit. I think the results suggest strongly
> > that a revert is likely to fix the problem. I can finish the work to
> > revert if you'd still like to see the results.
> >
> > Testing a previous .39-rc kernel still exhibited the failure. I don't
> > recall which one it was and apparently forgot to make note of it. I'll
> > request testing against rc6.
> >
> > Thanks,
> > Seth
> >
>
> Do you get scan results ?
> Can you enable ATH5K_DEBUG_RESET and see what you get ?

2.6.39-rc6 still fails. A more comprehensive log with ATH5K_DEBUG_RESET
enabled is below.

Scanning looks to be failing according to this log. I was thinking that
I saw successfull scans in some of the previous logs, but I'll have to
go back and check to be sure.

Thanks,
Seth


kernel: [ 23.421242] ath5k 0000:06:02.0: PCI INT A -> GSI 22 (level, low) -> IRQ 22
kernel: [ 23.421312] ath5k 0000:06:02.0: registered as 'phy0'
kernel: [ 24.132959] ath: EEPROM regdomain: 0x63
kernel: [ 24.132962] ath: EEPROM indicates we should expect a direct regpair map
kernel: [ 24.132967] ath: Country alpha2 being used: 00
kernel: [ 24.132969] ath: Regpair used: 0x63
kernel: [ 24.136125] cfg80211: Updating information on frequency 2412 MHz for a 20 MHz width channel with regulatory rule:
kernel: [ 24.136131] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
kernel: [ 24.136134] cfg80211: Updating information on frequency 2417 MHz for a 20 MHz width channel with regulatory rule:
kernel: [ 24.136137] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
kernel: [ 24.136140] cfg80211: Updating information on frequency 2422 MHz for a 20 MHz width channel with regulatory rule:
kernel: [ 24.136143] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
kernel: [ 24.136146] cfg80211: Updating information on frequency 2427 MHz for a 20 MHz width channel with regulatory rule:
kernel: [ 24.136149] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
kernel: [ 24.136151] cfg80211: Updating information on frequency 2432 MHz for a 20 MHz width channel with regulatory rule:
kernel: [ 24.136155] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
kernel: [ 24.136157] cfg80211: Updating information on frequency 2437 MHz for a 20 MHz width channel with regulatory rule:
kernel: [ 24.136160] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
kernel: [ 24.136163] cfg80211: Updating information on frequency 2442 MHz for a 20 MHz width channel with regulatory rule:
kernel: [ 24.136166] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
kernel: [ 24.136168] cfg80211: Updating information on frequency 2447 MHz for a 20 MHz width channel with regulatory rule:
kernel: [ 24.136172] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
kernel: [ 24.136174] cfg80211: Updating information on frequency 2452 MHz for a 20 MHz width channel with regulatory rule:
kernel: [ 24.136177] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
kernel: [ 24.136180] cfg80211: Updating information on frequency 2457 MHz for a 20 MHz width channel with regulatory rule:
kernel: [ 24.136183] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
kernel: [ 24.136186] cfg80211: Updating information on frequency 2462 MHz for a 20 MHz width channel with regulatory rule:
kernel: [ 24.136189] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
kernel: [ 24.136191] cfg80211: Updating information on frequency 2467 MHz for a 20 MHz width channel with regulatory rule:
kernel: [ 24.136195] cfg80211: 2457000 KHz - 2482000 KHz @ KHz), (N/A mBi, 2000 mBm)
kernel: [ 24.136197] cfg80211: Updating information on frequency 2472 MHz for a 20 MHz width channel with regulatory rule:
kernel: [ 24.136200] cfg80211: 2457000 KHz - 2482000 KHz @ KHz), (N/A mBi, 2000 mBm)
kernel: [ 24.136203] cfg80211: Disabling freq 2484 MHz as custom regd has no rule that fits a 20 MHz wide channel
kernel: [ 24.136404] cfg80211: Ignoring regulatory request Set by core since the driver uses its own custom regulatory domain
kernel: [ 24.393924] ieee80211 phy0: Selected rate control algorithm 'minstrel_ht'
kernel: [ 24.394588] ath5k phy0: Atheros AR2413 chip found (MAC: 0x78, PHY: 0x45)
...
NetworkManager[725]: <info> (wlan0): driver supports SSID scans (scan_capa 0x01).
NetworkManager[725]: <info> (wlan0): new 802.11 WiFi device (driver: 'ath5k' ifindex: 3)
NetworkManager[725]: <info> (wlan0): exported as /org/freedesktop/NetworkManager/Devices/1
NetworkManager[725]: <info> (wlan0): now managed
NetworkManager[725]: <info> (wlan0): device state change: 1 -> 2 (reason 2)
NetworkManager[725]: <info> (wlan0): bringing up device.
NetworkManager[725]: <info> (wlan0): preparing device.
NetworkManager[725]: <info> (wlan0): deactivating device (reason: 2).
NetworkManager[725]: supplicant_interface_acquire: assertion `mgr_state == NM_SUPPLICANT_MANAGER_STATE_IDLE' failed
kernel: [ 25.149294] ADDRCONF(NETDEV_UP): wlan0: link is not ready
...
NetworkManager[725]: <info> Trying to start the supplicant...
...
NetworkManager[725]: <info> (wlan0): supplicant manager state: down -> idle
NetworkManager[725]: <info> (wlan0): device state change: 2 -> 3 (reason 0)
NetworkManager[725]: <info> (wlan0): supplicant interface state: starting -> ready
...
NetworkManager[725]: <info> (wlan0): device state change: 3 -> 2 (reason 0)
NetworkManager[725]: <info> (wlan0): deactivating device (reason: 0).
NetworkManager[725]: <info> (wlan0): taking down device.
NetworkManager[725]: <info> (wlan0): bringing up device.
kernel: [ 104.430292] ath5k phy0: (ath5k_init_hw:2522): mode 2
kernel: [ 104.430297] ath5k phy0: (ath5k_stop_locked:2481): invalid 0
kernel: [ 104.431000] ath5k phy0: (ath5k_reset:2648): resetting
kernel: [ 104.434475] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
kernel: [ 104.434683] ath5k phy0: (ath5k_rfkill_disable:42): rfkill disable (gpio:0 polarity:0)
kernel: [ 104.435759] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2412 -> 2412 MHz)
kernel: [ 104.435762] ath5k phy0: (ath5k_reset:2648): resetting
kernel: [ 104.436845] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
kernel: [ 104.437191] ath5k phy0: (ath5k_conf_tx:602): Configure tx [queue 0], aifs: 2, cw_min: 7, cw_max: 15, txop: 102
kernel: [ 104.437212] ath5k phy0: (ath5k_conf_tx:602): Configure tx [queue 1], aifs: 2, cw_min: 15, cw_max: 31, txop: 188
kernel: [ 104.438337] ADDRCONF(NETDEV_UP): wlan0: link is not ready
NetworkManager[725]: <info> (wlan0): supplicant interface state: starting -> ready
NetworkManager[725]: <info> (wlan0): device state change: 2 -> 3 (reason 42)
wpa_supplicant[745]: Failed to initiate AP scan.
kernel: [ 125.188087] net_ratelimit: 41 callbacks suppressed
kernel: [ 125.188100] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2412 -> 2417 MHz)
kernel: [ 125.188109] ath5k phy0: (ath5k_reset:2648): resetting
kernel: [ 125.291007] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
kernel: [ 125.344076] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2417 -> 2422 MHz)
kernel: [ 125.344090] ath5k phy0: (ath5k_reset:2648): resetting
kernel: [ 125.447014] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
kernel: [ 125.500078] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2422 -> 2427 MHz)
kernel: [ 125.500091] ath5k phy0: (ath5k_reset:2648): resetting
kernel: [ 125.602999] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
kernel: [ 125.656070] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2427 -> 2432 MHz)
kernel: [ 155.188052] net_ratelimit: 29 callbacks suppressed
kernel: [ 155.188058] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2412 -> 2417 MHz)
kernel: [ 155.188061] ath5k phy0: (ath5k_reset:2648): resetting
kernel: [ 155.290844] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
kernel: [ 155.344032] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2417 -> 2422 MHz)
kernel: [ 155.344038] ath5k phy0: (ath5k_reset:2648): resetting
kernel: [ 155.446810] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
kernel: [ 155.500031] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2422 -> 2427 MHz)
kernel: [ 155.500036] ath5k phy0: (ath5k_reset:2648): resetting
kernel: [ 155.602811] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
kernel: [ 155.656033] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2427 -> 2432 MHz)
kernel: [ 195.184088] net_ratelimit: 29 callbacks suppressed
kernel: [ 195.184102] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2412 -> 2417 MHz)
kernel: [ 195.184110] ath5k phy0: (ath5k_reset:2648): resetting
kernel: [ 195.287022] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
kernel: [ 195.340066] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2417 -> 2422 MHz)
kernel: [ 195.340079] ath5k phy0: (ath5k_reset:2648): resetting
kernel: [ 195.442967] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
kernel: [ 195.496076] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2422 -> 2427 MHz)
kernel: [ 195.496088] ath5k phy0: (ath5k_reset:2648): resetting
kernel: [ 195.599009] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
kernel: [ 195.652078] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2427 -> 2432 MHz)
kernel: [ 245.188077] net_ratelimit: 29 callbacks suppressed
kernel: [ 245.188091] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2412 -> 2417 MHz)
kernel: [ 245.188100] ath5k phy0: (ath5k_reset:2648): resetting
kernel: [ 245.290997] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
kernel: [ 245.344084] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2417 -> 2422 MHz)
kernel: [ 245.344092] ath5k phy0: (ath5k_reset:2648): resetting
kernel: [ 245.446882] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
kernel: [ 245.500053] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2422 -> 2427 MHz)
kernel: [ 245.500058] ath5k phy0: (ath5k_reset:2648): resetting
kernel: [ 245.602808] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
kernel: [ 245.656046] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2427 -> 2432 MHz)
kernel: [ 305.188050] net_ratelimit: 29 callbacks suppressed
kernel: [ 305.188063] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2412 -> 2417 MHz)
kernel: [ 305.188071] ath5k phy0: (ath5k_reset:2648): resetting
kernel: [ 305.290945] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
kernel: [ 305.344070] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2417 -> 2422 MHz)
kernel: [ 305.344082] ath5k phy0: (ath5k_reset:2648): resetting
kernel: [ 305.446943] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
kernel: [ 305.500047] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2422 -> 2427 MHz)
kernel: [ 305.500058] ath5k phy0: (ath5k_reset:2648): resetting
kernel: [ 305.602967] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
kernel: [ 305.656090] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2427 -> 2432 MHz)
NetworkManager[725]: <info> (wlan0): device state change: 3 -> 2 (reason 0)
NetworkManager[725]: <info> (wlan0): deactivating device (reason: 0).
NetworkManager[725]: <info> (wlan0): taking down device.
kernel: [ 310.887530] net_ratelimit: 29 callbacks suppressed
kernel: [ 310.887535] ath5k phy0: (ath5k_stop_locked:2481): invalid 0
kernel: [ 310.990264] ath5k phy0: (ath5k_stop_hw:2619): putting device to sleep
kernel: [ 310.990554] ath5k phy0: (ath5k_rfkill_enable:51): rfkill enable (gpio:0 polarity:0)
NetworkManager[725]: <info> (wlan0): bringing up device.
kernel: [ 315.755891] ath5k phy0: (ath5k_init_hw:2522): mode 2
kernel: [ 315.755903] ath5k phy0: (ath5k_stop_locked:2481): invalid 0
kernel: [ 315.756624] ath5k phy0: (ath5k_reset:2648): resetting
kernel: [ 315.760236] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
kernel: [ 315.760474] ath5k phy0: (ath5k_rfkill_disable:42): rfkill disable (gpio:0 polarity:0)
kernel: [ 315.762566] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2412 -> 2412 MHz)
kernel: [ 315.762574] ath5k phy0: (ath5k_reset:2648): resetting
kernel: [ 315.764972] ADDRCONF(NETDEV_UP): wlan0: link is not ready
NetworkManager[725]: <info> (wlan0): supplicant interface state: starting -> ready
NetworkManager[725]: <info> (wlan0): device state change: 2 -> 3 (reason 42)
wpa_supplicant[745]: Failed to initiate AP scan.
kernel: [ 316.036068] net_ratelimit: 8 callbacks suppressed
kernel: [ 316.036080] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2417 -> 2422 MHz)
kernel: [ 316.036089] ath5k phy0: (ath5k_reset:2648): resetting
kernel: [ 316.140039] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
kernel: [ 316.196067] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2422 -> 2427 MHz)
kernel: [ 316.196079] ath5k phy0: (ath5k_reset:2648): resetting
kernel: [ 316.298940] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
kernel: [ 316.352063] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2427 -> 2432 MHz)
kernel: [ 316.352071] ath5k phy0: (ath5k_reset:2648): resetting
kernel: [ 316.455003] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
kernel: [ 316.508080] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2432 -> 2437 MHz)
kernel: [ 336.188067] net_ratelimit: 26 callbacks suppressed
kernel: [ 336.188080] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2412 -> 2417 MHz)
kernel: [ 336.188088] ath5k phy0: (ath5k_reset:2648): resetting
kernel: [ 336.290966] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
kernel: [ 336.344059] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2417 -> 2422 MHz)
kernel: [ 336.344068] ath5k phy0: (ath5k_reset:2648): resetting
kernel: [ 336.446912] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
kernel: [ 336.500068] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2422 -> 2427 MHz)
kernel: [ 336.500077] ath5k phy0: (ath5k_reset:2648): resetting
kernel: [ 336.602937] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
kernel: [ 336.656058] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2427 -> 2432 MHz)
kernel: [ 366.188084] net_ratelimit: 29 callbacks suppressed
kernel: [ 366.188097] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2412 -> 2417 MHz)
kernel: [ 366.188105] ath5k phy0: (ath5k_reset:2648): resetting
kernel: [ 366.290999] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
kernel: [ 366.344099] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2417 -> 2422 MHz)
kernel: [ 366.344112] ath5k phy0: (ath5k_reset:2648): resetting
kernel: [ 366.447030] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
kernel: [ 366.500094] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2422 -> 2427 MHz)
kernel: [ 366.500106] ath5k phy0: (ath5k_reset:2648): resetting
kernel: [ 366.603008] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
kernel: [ 366.656103] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2427 -> 2432 MHz)

2011-05-05 14:30:46

by Nick Kossifidis

Subject: Re: ath5k regression associating with APs in 2.6.38

2011/5/5 Seth Forshee <[email protected]>:
> On Wed, May 04, 2011 at 11:09:03PM +0300, Nick Kossifidis wrote:
>> 2011/5/4 Seth Forshee <[email protected]>:
>> > On Wed, May 04, 2011 at 01:27:17PM -0400, John W. Linville wrote:
>> >> On Wed, May 04, 2011 at 10:38:19AM -0500, Seth Forshee wrote:
>> >> > I've been investigating some reports of a regression in associating with
>> >> > APs with AR2413 in 2.6.38. Association repeatedly fails with some
>> >> > "direct probe to x timed out" messages (see syslog excerpt below),
>> >> > although it will generally associate eventually, after many tries.
>> >> >
>> >> > Bisection identifies 8aec7af (ath5k: Support synth-only channel change
>> >> > for AR2413/AR5413) as offending commit. Prior to this commit there are
>> >> > no direct probe messages at all in the logs. I've also found that
>> >> > forcing fast to false at the top of ath5k_hw_reset() fixes the issue.
>> >> > I'm not sure what the connection is between this commit and the
>> >> > timeouts. Any suggestions?
>> >>
>> >> Have you tried reverting that commit on top of 2.6.38?  Can you
>> >> recreate the issue with 2.6.39-rc6 (or later)?
>> >
>> > I started to revert that commit, but it wasn't straight-forward due to
>> > later changes. Forcing fast to false in ath5k_hw_reset() acts as a
>> > functional revert of sorts since that should force it back to a full
>> > reset for all channel changes, and it's much simpler than working out
>> > the right way to revert the commit. I think the results suggest strongly
>> > that a revert is likely to fix the problem. I can finish the work to
>> > revert if you'd still like to see the results.
>> >
>> > Testing a previous .39-rc kernel still exhibited the failure. I don't
>> > recall which one it was and apparently forgot to make note of it. I'll
>> > request testing against rc6.
>> >
>> > Thanks,
>> > Seth
>> >
>>
>> Do you get scan results ?
>> Can you enable ATH5K_DEBUG_RESET and see what you get ?
>
> 2.6.39-rc6 still fails. A more comprehensive log with ATH5K_DEBUG_RESET
> enabled is below.
>
> Scanning looks to be failing according to this log. I was thinking that
> I saw successfull scans in some of the previous logs, but I'll have to
> go back and check to be sure.
>
> Thanks,
> Seth
>
>
> kernel: [   23.421242] ath5k 0000:06:02.0: PCI INT A -> GSI 22 (level, low) -> IRQ 22
> kernel: [   23.421312] ath5k 0000:06:02.0: registered as 'phy0'
> kernel: [   24.132959] ath: EEPROM regdomain: 0x63
> kernel: [   24.132962] ath: EEPROM indicates we should expect a direct regpair map
> kernel: [   24.132967] ath: Country alpha2 being used: 00
> kernel: [   24.132969] ath: Regpair used: 0x63
> kernel: [   24.136125] cfg80211: Updating information on frequency 2412 MHz for a 20 MHz width channel with regulatory rule:
> kernel: [   24.136131] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
> kernel: [   24.136134] cfg80211: Updating information on frequency 2417 MHz for a 20 MHz width channel with regulatory rule:
> kernel: [   24.136137] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
> kernel: [   24.136140] cfg80211: Updating information on frequency 2422 MHz for a 20 MHz width channel with regulatory rule:
> kernel: [   24.136143] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
> kernel: [   24.136146] cfg80211: Updating information on frequency 2427 MHz for a 20 MHz width channel with regulatory rule:
> kernel: [   24.136149] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
> kernel: [   24.136151] cfg80211: Updating information on frequency 2432 MHz for a 20 MHz width channel with regulatory rule:
> kernel: [   24.136155] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
> kernel: [   24.136157] cfg80211: Updating information on frequency 2437 MHz for a 20 MHz width channel with regulatory rule:
> kernel: [   24.136160] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
> kernel: [   24.136163] cfg80211: Updating information on frequency 2442 MHz for a 20 MHz width channel with regulatory rule:
> kernel: [   24.136166] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
> kernel: [   24.136168] cfg80211: Updating information on frequency 2447 MHz for a 20 MHz width channel with regulatory rule:
> kernel: [   24.136172] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
> kernel: [   24.136174] cfg80211: Updating information on frequency 2452 MHz for a 20 MHz width channel with regulatory rule:
> kernel: [   24.136177] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
> kernel: [   24.136180] cfg80211: Updating information on frequency 2457 MHz for a 20 MHz width channel with regulatory rule:
> kernel: [   24.136183] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
> kernel: [   24.136186] cfg80211: Updating information on frequency 2462 MHz for a 20 MHz width channel with regulatory rule:
> kernel: [   24.136189] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
> kernel: [   24.136191] cfg80211: Updating information on frequency 2467 MHz for a 20 MHz width channel with regulatory rule:
> kernel: [   24.136195] cfg80211: 2457000 KHz - 2482000 KHz @  KHz), (N/A mBi, 2000 mBm)
> kernel: [   24.136197] cfg80211: Updating information on frequency 2472 MHz for a 20 MHz width channel with regulatory rule:
> kernel: [   24.136200] cfg80211: 2457000 KHz - 2482000 KHz @  KHz), (N/A mBi, 2000 mBm)
> kernel: [   24.136203] cfg80211: Disabling freq 2484 MHz as custom regd has no rule that fits a 20 MHz wide channel
> kernel: [   24.136404] cfg80211: Ignoring regulatory request Set by core since the driver uses its own custom regulatory domain
> kernel: [   24.393924] ieee80211 phy0: Selected rate control algorithm 'minstrel_ht'
> kernel: [   24.394588] ath5k phy0: Atheros AR2413 chip found (MAC: 0x78, PHY: 0x45)
> ...
> NetworkManager[725]: <info> (wlan0): driver supports SSID scans (scan_capa 0x01).
> NetworkManager[725]: <info> (wlan0): new 802.11 WiFi device (driver: 'ath5k' ifindex: 3)
> NetworkManager[725]: <info> (wlan0): exported as /org/freedesktop/NetworkManager/Devices/1
> NetworkManager[725]: <info> (wlan0): now managed
> NetworkManager[725]: <info> (wlan0): device state change: 1 -> 2 (reason 2)
> NetworkManager[725]: <info> (wlan0): bringing up device.
> NetworkManager[725]: <info> (wlan0): preparing device.
> NetworkManager[725]: <info> (wlan0): deactivating device (reason: 2).
> NetworkManager[725]: supplicant_interface_acquire: assertion `mgr_state == NM_SUPPLICANT_MANAGER_STATE_IDLE' failed
> kernel: [   25.149294] ADDRCONF(NETDEV_UP): wlan0: link is not ready
> ...
> NetworkManager[725]: <info> Trying to start the supplicant...
> ...
> NetworkManager[725]: <info> (wlan0): supplicant manager state:  down -> idle
> NetworkManager[725]: <info> (wlan0): device state change: 2 -> 3 (reason 0)
> NetworkManager[725]: <info> (wlan0): supplicant interface state:  starting -> ready
> ...
> NetworkManager[725]: <info> (wlan0): device state change: 3 -> 2 (reason 0)
> NetworkManager[725]: <info> (wlan0): deactivating device (reason: 0).
> NetworkManager[725]: <info> (wlan0): taking down device.
> NetworkManager[725]: <info> (wlan0): bringing up device.
> kernel: [  104.430292] ath5k phy0: (ath5k_init_hw:2522): mode 2
> kernel: [  104.430297] ath5k phy0: (ath5k_stop_locked:2481): invalid 0
> kernel: [  104.431000] ath5k phy0: (ath5k_reset:2648): resetting
> kernel: [  104.434475] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
> kernel: [  104.434683] ath5k phy0: (ath5k_rfkill_disable:42): rfkill disable (gpio:0 polarity:0)
> kernel: [  104.435759] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2412 -> 2412 MHz)
> kernel: [  104.435762] ath5k phy0: (ath5k_reset:2648): resetting
> kernel: [  104.436845] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
> kernel: [  104.437191] ath5k phy0: (ath5k_conf_tx:602): Configure tx [queue 0],  aifs: 2, cw_min: 7, cw_max: 15, txop: 102
> kernel: [  104.437212] ath5k phy0: (ath5k_conf_tx:602): Configure tx [queue 1],  aifs: 2, cw_min: 15, cw_max: 31, txop: 188
> kernel: [  104.438337] ADDRCONF(NETDEV_UP): wlan0: link is not ready
> NetworkManager[725]: <info> (wlan0): supplicant interface state:  starting -> ready
> NetworkManager[725]: <info> (wlan0): device state change: 2 -> 3 (reason 42)
> wpa_supplicant[745]: Failed to initiate AP scan.
> kernel: [  125.188087] net_ratelimit: 41 callbacks suppressed
> kernel: [  125.188100] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2412 -> 2417 MHz)
> kernel: [  125.188109] ath5k phy0: (ath5k_reset:2648): resetting
> kernel: [  125.291007] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
> kernel: [  125.344076] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2417 -> 2422 MHz)
> kernel: [  125.344090] ath5k phy0: (ath5k_reset:2648): resetting
> kernel: [  125.447014] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
> kernel: [  125.500078] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2422 -> 2427 MHz)
> kernel: [  125.500091] ath5k phy0: (ath5k_reset:2648): resetting
> kernel: [  125.602999] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
> kernel: [  125.656070] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2427 -> 2432 MHz)
> kernel: [  155.188052] net_ratelimit: 29 callbacks suppressed
> kernel: [  155.188058] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2412 -> 2417 MHz)
> kernel: [  155.188061] ath5k phy0: (ath5k_reset:2648): resetting
> kernel: [  155.290844] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
> kernel: [  155.344032] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2417 -> 2422 MHz)
> kernel: [  155.344038] ath5k phy0: (ath5k_reset:2648): resetting
> kernel: [  155.446810] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
> kernel: [  155.500031] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2422 -> 2427 MHz)
> kernel: [  155.500036] ath5k phy0: (ath5k_reset:2648): resetting
> kernel: [  155.602811] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
> kernel: [  155.656033] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2427 -> 2432 MHz)
> kernel: [  195.184088] net_ratelimit: 29 callbacks suppressed
> kernel: [  195.184102] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2412 -> 2417 MHz)
> kernel: [  195.184110] ath5k phy0: (ath5k_reset:2648): resetting
> kernel: [  195.287022] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
> kernel: [  195.340066] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2417 -> 2422 MHz)
> kernel: [  195.340079] ath5k phy0: (ath5k_reset:2648): resetting
> kernel: [  195.442967] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
> kernel: [  195.496076] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2422 -> 2427 MHz)
> kernel: [  195.496088] ath5k phy0: (ath5k_reset:2648): resetting
> kernel: [  195.599009] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
> kernel: [  195.652078] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2427 -> 2432 MHz)
> kernel: [  245.188077] net_ratelimit: 29 callbacks suppressed
> kernel: [  245.188091] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2412 -> 2417 MHz)
> kernel: [  245.188100] ath5k phy0: (ath5k_reset:2648): resetting
> kernel: [  245.290997] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
> kernel: [  245.344084] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2417 -> 2422 MHz)
> kernel: [  245.344092] ath5k phy0: (ath5k_reset:2648): resetting
> kernel: [  245.446882] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
> kernel: [  245.500053] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2422 -> 2427 MHz)
> kernel: [  245.500058] ath5k phy0: (ath5k_reset:2648): resetting
> kernel: [  245.602808] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
> kernel: [  245.656046] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2427 -> 2432 MHz)
> kernel: [  305.188050] net_ratelimit: 29 callbacks suppressed
> kernel: [  305.188063] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2412 -> 2417 MHz)
> kernel: [  305.188071] ath5k phy0: (ath5k_reset:2648): resetting
> kernel: [  305.290945] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
> kernel: [  305.344070] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2417 -> 2422 MHz)
> kernel: [  305.344082] ath5k phy0: (ath5k_reset:2648): resetting
> kernel: [  305.446943] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
> kernel: [  305.500047] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2422 -> 2427 MHz)
> kernel: [  305.500058] ath5k phy0: (ath5k_reset:2648): resetting
> kernel: [  305.602967] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
> kernel: [  305.656090] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2427 -> 2432 MHz)
> NetworkManager[725]: <info> (wlan0): device state change: 3 -> 2 (reason 0)
> NetworkManager[725]: <info> (wlan0): deactivating device (reason: 0).
> NetworkManager[725]: <info> (wlan0): taking down device.
> kernel: [  310.887530] net_ratelimit: 29 callbacks suppressed
> kernel: [  310.887535] ath5k phy0: (ath5k_stop_locked:2481): invalid 0
> kernel: [  310.990264] ath5k phy0: (ath5k_stop_hw:2619): putting device to sleep
> kernel: [  310.990554] ath5k phy0: (ath5k_rfkill_enable:51): rfkill enable (gpio:0 polarity:0)
> NetworkManager[725]: <info> (wlan0): bringing up device.
> kernel: [  315.755891] ath5k phy0: (ath5k_init_hw:2522): mode 2
> kernel: [  315.755903] ath5k phy0: (ath5k_stop_locked:2481): invalid 0
> kernel: [  315.756624] ath5k phy0: (ath5k_reset:2648): resetting
> kernel: [  315.760236] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
> kernel: [  315.760474] ath5k phy0: (ath5k_rfkill_disable:42): rfkill disable (gpio:0 polarity:0)
> kernel: [  315.762566] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2412 -> 2412 MHz)
> kernel: [  315.762574] ath5k phy0: (ath5k_reset:2648): resetting
> kernel: [  315.764972] ADDRCONF(NETDEV_UP): wlan0: link is not ready
> NetworkManager[725]: <info> (wlan0): supplicant interface state:  starting -> ready
> NetworkManager[725]: <info> (wlan0): device state change: 2 -> 3 (reason 42)
> wpa_supplicant[745]: Failed to initiate AP scan.
> kernel: [  316.036068] net_ratelimit: 8 callbacks suppressed
> kernel: [  316.036080] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2417 -> 2422 MHz)
> kernel: [  316.036089] ath5k phy0: (ath5k_reset:2648): resetting
> kernel: [  316.140039] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
> kernel: [  316.196067] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2422 -> 2427 MHz)
> kernel: [  316.196079] ath5k phy0: (ath5k_reset:2648): resetting
> kernel: [  316.298940] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
> kernel: [  316.352063] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2427 -> 2432 MHz)
> kernel: [  316.352071] ath5k phy0: (ath5k_reset:2648): resetting
> kernel: [  316.455003] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
> kernel: [  316.508080] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2432 -> 2437 MHz)
> kernel: [  336.188067] net_ratelimit: 26 callbacks suppressed
> kernel: [  336.188080] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2412 -> 2417 MHz)
> kernel: [  336.188088] ath5k phy0: (ath5k_reset:2648): resetting
> kernel: [  336.290966] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
> kernel: [  336.344059] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2417 -> 2422 MHz)
> kernel: [  336.344068] ath5k phy0: (ath5k_reset:2648): resetting
> kernel: [  336.446912] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
> kernel: [  336.500068] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2422 -> 2427 MHz)
> kernel: [  336.500077] ath5k phy0: (ath5k_reset:2648): resetting
> kernel: [  336.602937] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
> kernel: [  336.656058] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2427 -> 2432 MHz)
> kernel: [  366.188084] net_ratelimit: 29 callbacks suppressed
> kernel: [  366.188097] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2412 -> 2417 MHz)
> kernel: [  366.188105] ath5k phy0: (ath5k_reset:2648): resetting
> kernel: [  366.290999] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
> kernel: [  366.344099] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2417 -> 2422 MHz)
> kernel: [  366.344112] ath5k phy0: (ath5k_reset:2648): resetting
> kernel: [  366.447030] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
> kernel: [  366.500094] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2422 -> 2427 MHz)
> kernel: [  366.500106] ath5k phy0: (ath5k_reset:2648): resetting
> kernel: [  366.603008] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
> kernel: [  366.656103] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2427 -> 2432 MHz)
>
>

Hmm I don't see any errors from reset/phy code, can you disable
Network Manager/wpa-supplicant and test connection on an open network
using iw ? It 'll give us a better picture...

If iw doesn't return any scan results we are probably hitting a PHY/RF
error specific to your device (not all vendors follow the reference
design). Maybe we should follow a blacklist/whitelist approach for
this feature.

--
GPG ID: 0xD21DB2DB
As you read this post global entropy rises. Have Fun ;-)
Nick

2011-05-05 14:54:48

by Seth Forshee

Subject: Re: ath5k regression associating with APs in 2.6.38

On Thu, May 05, 2011 at 05:30:42PM +0300, Nick Kossifidis wrote:
> Hmm I don't see any errors from reset/phy code, can you disable
> Network Manager/wpa-supplicant and test connection on an open network
> using iw ? It 'll give us a better picture...
>
> If iw doesn't return any scan results we are probably hitting a PHY/RF
> error specific to your device (not all vendors follow the reference
> design). Maybe we should follow a blacklist/whitelist approach for
> this feature.

Will do. I just got another log from my tester, which is more typical of
what he's been getting. I've pasted a portion of it below. The full log
can be viewed at

https://launchpadlibrarian.net/71137619/20110504_020639rc6%23201105050227_boot4_syslog

Thanks,
Seth


May 5 08:57:16 AcerAspire5100 NetworkManager[703]: <info> (wlan0): new 802.11 WiFi device (driver: 'ath5k' ifindex: 3)
May 5 08:57:16 AcerAspire5100 NetworkManager[703]: <info> (wlan0): exported as /org/freedesktop/NetworkManager/Devices/1
May 5 08:57:16 AcerAspire5100 NetworkManager[703]: <info> (wlan0): now managed
May 5 08:57:16 AcerAspire5100 NetworkManager[703]: <info> (wlan0): device state change: 1 -> 2 (reason 2)
May 5 08:57:16 AcerAspire5100 NetworkManager[703]: <info> (wlan0): bringing up device.
May 5 08:57:16 AcerAspire5100 NetworkManager[703]: <info> (wlan0): preparing device.
May 5 08:57:16 AcerAspire5100 NetworkManager[703]: <info> (wlan0): deactivating device (reason: 2).
May 5 08:57:16 AcerAspire5100 NetworkManager[703]: supplicant_interface_acquire: assertion `mgr_state == NM_SUPPLICANT_MANAGER_STATE_IDLE' failed
May 5 08:57:16 AcerAspire5100 kernel: [ 25.844302] ADDRCONF(NETDEV_UP): wlan0: link is not ready
May 5 08:57:16 AcerAspire5100 NetworkManager[703]: <info> modem-manager is now available
May 5 08:57:16 AcerAspire5100 NetworkManager[703]: <warn> bluez error getting default adapter: The name org.bluez was not provided by any .service files
May 5 08:57:16 AcerAspire5100 NetworkManager[703]: <info> Trying to start the supplicant...
May 5 08:57:16 AcerAspire5100 NetworkManager[703]: <info> (wlan0): supplicant manager state: down -> idle
May 5 08:57:16 AcerAspire5100 NetworkManager[703]: <info> (wlan0): device state change: 2 -> 3 (reason 0)
May 5 08:57:16 AcerAspire5100 NetworkManager[703]: <info> (wlan0): supplicant interface state: starting -> ready
...
May 5 08:57:38 AcerAspire5100 NetworkManager[703]: <info> Activation (wlan0) starting connection 'Auto aureola'
May 5 08:57:38 AcerAspire5100 NetworkManager[703]: <info> (wlan0): device state change: 3 -> 4 (reason 0)
May 5 08:57:38 AcerAspire5100 NetworkManager[703]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
May 5 08:57:38 AcerAspire5100 NetworkManager[703]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
May 5 08:57:38 AcerAspire5100 NetworkManager[703]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
May 5 08:57:38 AcerAspire5100 NetworkManager[703]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
May 5 08:57:38 AcerAspire5100 NetworkManager[703]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
May 5 08:57:38 AcerAspire5100 NetworkManager[703]: <info> (wlan0): device state change: 4 -> 5 (reason 0)
May 5 08:57:38 AcerAspire5100 NetworkManager[703]: <info> Activation (wlan0/wireless): access point 'Auto aureola' has security, but secrets are required.
May 5 08:57:38 AcerAspire5100 NetworkManager[703]: <info> (wlan0): device state change: 5 -> 6 (reason 0)
May 5 08:57:38 AcerAspire5100 NetworkManager[703]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
May 5 08:57:39 AcerAspire5100 NetworkManager[703]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
May 5 08:57:39 AcerAspire5100 NetworkManager[703]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
May 5 08:57:39 AcerAspire5100 NetworkManager[703]: <info> (wlan0): device state change: 6 -> 4 (reason 0)
May 5 08:57:39 AcerAspire5100 NetworkManager[703]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
May 5 08:57:39 AcerAspire5100 NetworkManager[703]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
May 5 08:57:39 AcerAspire5100 NetworkManager[703]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
May 5 08:57:39 AcerAspire5100 NetworkManager[703]: <info> (wlan0): device state change: 4 -> 5 (reason 0)
May 5 08:57:39 AcerAspire5100 NetworkManager[703]: <info> Activation (wlan0/wireless): connection 'Auto aureola' has security, and secrets exist. No new secrets needed.
May 5 08:57:39 AcerAspire5100 NetworkManager[703]: <info> Config: added 'ssid' value 'aureola'
May 5 08:57:39 AcerAspire5100 NetworkManager[703]: <info> Config: added 'scan_ssid' value '1'
May 5 08:57:39 AcerAspire5100 NetworkManager[703]: <info> Config: added 'key_mgmt' value 'WPA-PSK'
May 5 08:57:39 AcerAspire5100 NetworkManager[703]: <info> Config: added 'psk' value '<omitted>'
May 5 08:57:39 AcerAspire5100 NetworkManager[703]: nm_setting_802_1x_get_pkcs11_engine_path: assertion `NM_IS_SETTING_802_1X (setting)' failed
May 5 08:57:39 AcerAspire5100 NetworkManager[703]: nm_setting_802_1x_get_pkcs11_module_path: assertion `NM_IS_SETTING_802_1X (setting)' failed
May 5 08:57:39 AcerAspire5100 NetworkManager[703]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
May 5 08:57:39 AcerAspire5100 NetworkManager[703]: <info> Config: set interface ap_scan to 1
May 5 08:57:39 AcerAspire5100 NetworkManager[703]: <info> (wlan0): supplicant connection state: inactive -> scanning
May 5 08:57:41 AcerAspire5100 wpa_supplicant[734]: Trying to associate with c0:3f:0e:b9:f3:b2 (SSID='aureola' freq=2452 MHz)
May 5 08:57:41 AcerAspire5100 NetworkManager[703]: <info> (wlan0): supplicant connection state: scanning -> associating
May 5 08:57:41 AcerAspire5100 kernel: [ 51.261113] wlan0: direct probe to c0:3f:0e:b9:f3:b2 (try 1/3)
May 5 08:57:41 AcerAspire5100 kernel: [ 51.460049] wlan0: direct probe to c0:3f:0e:b9:f3:b2 (try 2/3)
May 5 08:57:41 AcerAspire5100 kernel: [ 51.660091] wlan0: direct probe to c0:3f:0e:b9:f3:b2 (try 3/3)
May 5 08:57:42 AcerAspire5100 kernel: [ 51.860048] wlan0: direct probe to c0:3f:0e:b9:f3:b2 timed out
May 5 08:57:51 AcerAspire5100 wpa_supplicant[734]: Authentication with c0:3f:0e:b9:f3:b2 timed out.
May 5 08:57:51 AcerAspire5100 NetworkManager[703]: <info> (wlan0): supplicant connection state: associating -> disconnected
May 5 08:57:51 AcerAspire5100 NetworkManager[703]: <info> (wlan0): supplicant connection state: disconnected -> scanning
May 5 08:57:51 AcerAspire5100 kernel: [ 61.396045] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2452 -> 2412 MHz)
May 5 08:57:51 AcerAspire5100 kernel: [ 61.396051] ath5k phy0: (ath5k_reset:2648): resetting
May 5 08:57:51 AcerAspire5100 kernel: [ 61.397135] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
May 5 08:57:51 AcerAspire5100 kernel: [ 61.452053] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2412 -> 2417 MHz)
May 5 08:57:51 AcerAspire5100 kernel: [ 61.452059] ath5k phy0: (ath5k_reset:2648): resetting
May 5 08:57:51 AcerAspire5100 kernel: [ 61.453143] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
May 5 08:57:51 AcerAspire5100 kernel: [ 61.508053] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2417 -> 2422 MHz)
May 5 08:57:51 AcerAspire5100 kernel: [ 61.508059] ath5k phy0: (ath5k_reset:2648): resetting
May 5 08:57:51 AcerAspire5100 kernel: [ 61.509143] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
May 5 08:57:51 AcerAspire5100 kernel: [ 61.564045] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2422 -> 2427 MHz)
May 5 08:57:52 AcerAspire5100 wpa_supplicant[734]: Trying to associate with c0:3f:0e:b9:f3:b2 (SSID='aureola' freq=2452 MHz)
May 5 08:57:52 AcerAspire5100 NetworkManager[703]: <info> (wlan0): supplicant connection state: scanning -> associating
May 5 08:57:52 AcerAspire5100 kernel: [ 62.364741] wlan0: direct probe to c0:3f:0e:b9:f3:b2 (try 1/3)
May 5 08:57:52 AcerAspire5100 kernel: [ 62.564061] wlan0: direct probe to c0:3f:0e:b9:f3:b2 (try 2/3)
May 5 08:57:53 AcerAspire5100 kernel: [ 62.764058] wlan0: direct probe to c0:3f:0e:b9:f3:b2 (try 3/3)
May 5 08:57:53 AcerAspire5100 kernel: [ 62.964061] wlan0: direct probe to c0:3f:0e:b9:f3:b2 timed out
May 5 08:58:02 AcerAspire5100 wpa_supplicant[734]: Authentication with c0:3f:0e:b9:f3:b2 timed out.
May 5 08:58:02 AcerAspire5100 NetworkManager[703]: <info> (wlan0): supplicant connection state: associating -> disconnected

2011-05-05 15:03:19

by Justin P. Mattock

Subject: Re: ath5k regression associating with APs in 2.6.38

On 05/05/2011 07:30 AM, Nick Kossifidis wrote:
> 2011/5/5 Seth Forshee<[email protected]>:
>> On Wed, May 04, 2011 at 11:09:03PM +0300, Nick Kossifidis wrote:
>>> 2011/5/4 Seth Forshee<[email protected]>:
>>>> On Wed, May 04, 2011 at 01:27:17PM -0400, John W. Linville wrote:
>>>>> On Wed, May 04, 2011 at 10:38:19AM -0500, Seth Forshee wrote:
>>>>>> I've been investigating some reports of a regression in associating with
>>>>>> APs with AR2413 in 2.6.38. Association repeatedly fails with some
>>>>>> "direct probe to x timed out" messages (see syslog excerpt below),
>>>>>> although it will generally associate eventually, after many tries.
>>>>>>
>>>>>> Bisection identifies 8aec7af (ath5k: Support synth-only channel change
>>>>>> for AR2413/AR5413) as offending commit. Prior to this commit there are
>>>>>> no direct probe messages at all in the logs. I've also found that
>>>>>> forcing fast to false at the top of ath5k_hw_reset() fixes the issue.
>>>>>> I'm not sure what the connection is between this commit and the
>>>>>> timeouts. Any suggestions?
>>>>>
>>>>> Have you tried reverting that commit on top of 2.6.38? Can you
>>>>> recreate the issue with 2.6.39-rc6 (or later)?
>>>>
>>>> I started to revert that commit, but it wasn't straight-forward due to
>>>> later changes. Forcing fast to false in ath5k_hw_reset() acts as a
>>>> functional revert of sorts since that should force it back to a full
>>>> reset for all channel changes, and it's much simpler than working out
>>>> the right way to revert the commit. I think the results suggest strongly
>>>> that a revert is likely to fix the problem. I can finish the work to
>>>> revert if you'd still like to see the results.
>>>>
>>>> Testing a previous .39-rc kernel still exhibited the failure. I don't
>>>> recall which one it was and apparently forgot to make note of it. I'll
>>>> request testing against rc6.
>>>>
>>>> Thanks,
>>>> Seth
>>>>
>>>
>>> Do you get scan results ?
>>> Can you enable ATH5K_DEBUG_RESET and see what you get ?
>>
>> 2.6.39-rc6 still fails. A more comprehensive log with ATH5K_DEBUG_RESET
>> enabled is below.
>>
>> Scanning looks to be failing according to this log. I was thinking that
>> I saw successfull scans in some of the previous logs, but I'll have to
>> go back and check to be sure.
>>
>> Thanks,
>> Seth
>>
>>
>> kernel: [ 23.421242] ath5k 0000:06:02.0: PCI INT A -> GSI 22 (level, low) -> IRQ 22
>> kernel: [ 23.421312] ath5k 0000:06:02.0: registered as 'phy0'
>> kernel: [ 24.132959] ath: EEPROM regdomain: 0x63
>> kernel: [ 24.132962] ath: EEPROM indicates we should expect a direct regpair map
>> kernel: [ 24.132967] ath: Country alpha2 being used: 00
>> kernel: [ 24.132969] ath: Regpair used: 0x63
>> kernel: [ 24.136125] cfg80211: Updating information on frequency 2412 MHz for a 20 MHz width channel with regulatory rule:
>> kernel: [ 24.136131] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
>> kernel: [ 24.136134] cfg80211: Updating information on frequency 2417 MHz for a 20 MHz width channel with regulatory rule:
>> kernel: [ 24.136137] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
>> kernel: [ 24.136140] cfg80211: Updating information on frequency 2422 MHz for a 20 MHz width channel with regulatory rule:
>> kernel: [ 24.136143] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
>> kernel: [ 24.136146] cfg80211: Updating information on frequency 2427 MHz for a 20 MHz width channel with regulatory rule:
>> kernel: [ 24.136149] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
>> kernel: [ 24.136151] cfg80211: Updating information on frequency 2432 MHz for a 20 MHz width channel with regulatory rule:
>> kernel: [ 24.136155] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
>> kernel: [ 24.136157] cfg80211: Updating information on frequency 2437 MHz for a 20 MHz width channel with regulatory rule:
>> kernel: [ 24.136160] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
>> kernel: [ 24.136163] cfg80211: Updating information on frequency 2442 MHz for a 20 MHz width channel with regulatory rule:
>> kernel: [ 24.136166] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
>> kernel: [ 24.136168] cfg80211: Updating information on frequency 2447 MHz for a 20 MHz width channel with regulatory rule:
>> kernel: [ 24.136172] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
>> kernel: [ 24.136174] cfg80211: Updating information on frequency 2452 MHz for a 20 MHz width channel with regulatory rule:
>> kernel: [ 24.136177] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
>> kernel: [ 24.136180] cfg80211: Updating information on frequency 2457 MHz for a 20 MHz width channel with regulatory rule:
>> kernel: [ 24.136183] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
>> kernel: [ 24.136186] cfg80211: Updating information on frequency 2462 MHz for a 20 MHz width channel with regulatory rule:
>> kernel: [ 24.136189] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
>> kernel: [ 24.136191] cfg80211: Updating information on frequency 2467 MHz for a 20 MHz width channel with regulatory rule:
>> kernel: [ 24.136195] cfg80211: 2457000 KHz - 2482000 KHz @ KHz), (N/A mBi, 2000 mBm)
>> kernel: [ 24.136197] cfg80211: Updating information on frequency 2472 MHz for a 20 MHz width channel with regulatory rule:
>> kernel: [ 24.136200] cfg80211: 2457000 KHz - 2482000 KHz @ KHz), (N/A mBi, 2000 mBm)
>> kernel: [ 24.136203] cfg80211: Disabling freq 2484 MHz as custom regd has no rule that fits a 20 MHz wide channel
>> kernel: [ 24.136404] cfg80211: Ignoring regulatory request Set by core since the driver uses its own custom regulatory domain
>> kernel: [ 24.393924] ieee80211 phy0: Selected rate control algorithm 'minstrel_ht'
>> kernel: [ 24.394588] ath5k phy0: Atheros AR2413 chip found (MAC: 0x78, PHY: 0x45)
>> ...
>> NetworkManager[725]:<info> (wlan0): driver supports SSID scans (scan_capa 0x01).
>> NetworkManager[725]:<info> (wlan0): new 802.11 WiFi device (driver: 'ath5k' ifindex: 3)
>> NetworkManager[725]:<info> (wlan0): exported as /org/freedesktop/NetworkManager/Devices/1
>> NetworkManager[725]:<info> (wlan0): now managed
>> NetworkManager[725]:<info> (wlan0): device state change: 1 -> 2 (reason 2)
>> NetworkManager[725]:<info> (wlan0): bringing up device.
>> NetworkManager[725]:<info> (wlan0): preparing device.
>> NetworkManager[725]:<info> (wlan0): deactivating device (reason: 2).
>> NetworkManager[725]: supplicant_interface_acquire: assertion `mgr_state == NM_SUPPLICANT_MANAGER_STATE_IDLE' failed
>> kernel: [ 25.149294] ADDRCONF(NETDEV_UP): wlan0: link is not ready
>> ...
>> NetworkManager[725]:<info> Trying to start the supplicant...
>> ...
>> NetworkManager[725]:<info> (wlan0): supplicant manager state: down -> idle
>> NetworkManager[725]:<info> (wlan0): device state change: 2 -> 3 (reason 0)
>> NetworkManager[725]:<info> (wlan0): supplicant interface state: starting -> ready
>> ...
>> NetworkManager[725]:<info> (wlan0): device state change: 3 -> 2 (reason 0)
>> NetworkManager[725]:<info> (wlan0): deactivating device (reason: 0).
>> NetworkManager[725]:<info> (wlan0): taking down device.
>> NetworkManager[725]:<info> (wlan0): bringing up device.
>> kernel: [ 104.430292] ath5k phy0: (ath5k_init_hw:2522): mode 2
>> kernel: [ 104.430297] ath5k phy0: (ath5k_stop_locked:2481): invalid 0
>> kernel: [ 104.431000] ath5k phy0: (ath5k_reset:2648): resetting
>> kernel: [ 104.434475] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
>> kernel: [ 104.434683] ath5k phy0: (ath5k_rfkill_disable:42): rfkill disable (gpio:0 polarity:0)
>> kernel: [ 104.435759] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2412 -> 2412 MHz)
>> kernel: [ 104.435762] ath5k phy0: (ath5k_reset:2648): resetting
>> kernel: [ 104.436845] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
>> kernel: [ 104.437191] ath5k phy0: (ath5k_conf_tx:602): Configure tx [queue 0], aifs: 2, cw_min: 7, cw_max: 15, txop: 102
>> kernel: [ 104.437212] ath5k phy0: (ath5k_conf_tx:602): Configure tx [queue 1], aifs: 2, cw_min: 15, cw_max: 31, txop: 188
>> kernel: [ 104.438337] ADDRCONF(NETDEV_UP): wlan0: link is not ready
>> NetworkManager[725]:<info> (wlan0): supplicant interface state: starting -> ready
>> NetworkManager[725]:<info> (wlan0): device state change: 2 -> 3 (reason 42)
>> wpa_supplicant[745]: Failed to initiate AP scan.
>> kernel: [ 125.188087] net_ratelimit: 41 callbacks suppressed
>> kernel: [ 125.188100] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2412 -> 2417 MHz)
>> kernel: [ 125.188109] ath5k phy0: (ath5k_reset:2648): resetting
>> kernel: [ 125.291007] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
>> kernel: [ 125.344076] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2417 -> 2422 MHz)
>> kernel: [ 125.344090] ath5k phy0: (ath5k_reset:2648): resetting
>> kernel: [ 125.447014] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
>> kernel: [ 125.500078] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2422 -> 2427 MHz)
>> kernel: [ 125.500091] ath5k phy0: (ath5k_reset:2648): resetting
>> kernel: [ 125.602999] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
>> kernel: [ 125.656070] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2427 -> 2432 MHz)
>> kernel: [ 155.188052] net_ratelimit: 29 callbacks suppressed
>> kernel: [ 155.188058] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2412 -> 2417 MHz)
>> kernel: [ 155.188061] ath5k phy0: (ath5k_reset:2648): resetting
>> kernel: [ 155.290844] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
>> kernel: [ 155.344032] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2417 -> 2422 MHz)
>> kernel: [ 155.344038] ath5k phy0: (ath5k_reset:2648): resetting
>> kernel: [ 155.446810] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
>> kernel: [ 155.500031] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2422 -> 2427 MHz)
>> kernel: [ 155.500036] ath5k phy0: (ath5k_reset:2648): resetting
>> kernel: [ 155.602811] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
>> kernel: [ 155.656033] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2427 -> 2432 MHz)
>> kernel: [ 195.184088] net_ratelimit: 29 callbacks suppressed
>> kernel: [ 195.184102] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2412 -> 2417 MHz)
>> kernel: [ 195.184110] ath5k phy0: (ath5k_reset:2648): resetting
>> kernel: [ 195.287022] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
>> kernel: [ 195.340066] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2417 -> 2422 MHz)
>> kernel: [ 195.340079] ath5k phy0: (ath5k_reset:2648): resetting
>> kernel: [ 195.442967] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
>> kernel: [ 195.496076] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2422 -> 2427 MHz)
>> kernel: [ 195.496088] ath5k phy0: (ath5k_reset:2648): resetting
>> kernel: [ 195.599009] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
>> kernel: [ 195.652078] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2427 -> 2432 MHz)
>> kernel: [ 245.188077] net_ratelimit: 29 callbacks suppressed
>> kernel: [ 245.188091] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2412 -> 2417 MHz)
>> kernel: [ 245.188100] ath5k phy0: (ath5k_reset:2648): resetting
>> kernel: [ 245.290997] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
>> kernel: [ 245.344084] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2417 -> 2422 MHz)
>> kernel: [ 245.344092] ath5k phy0: (ath5k_reset:2648): resetting
>> kernel: [ 245.446882] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
>> kernel: [ 245.500053] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2422 -> 2427 MHz)
>> kernel: [ 245.500058] ath5k phy0: (ath5k_reset:2648): resetting
>> kernel: [ 245.602808] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
>> kernel: [ 245.656046] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2427 -> 2432 MHz)
>> kernel: [ 305.188050] net_ratelimit: 29 callbacks suppressed
>> kernel: [ 305.188063] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2412 -> 2417 MHz)
>> kernel: [ 305.188071] ath5k phy0: (ath5k_reset:2648): resetting
>> kernel: [ 305.290945] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
>> kernel: [ 305.344070] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2417 -> 2422 MHz)
>> kernel: [ 305.344082] ath5k phy0: (ath5k_reset:2648): resetting
>> kernel: [ 305.446943] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
>> kernel: [ 305.500047] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2422 -> 2427 MHz)
>> kernel: [ 305.500058] ath5k phy0: (ath5k_reset:2648): resetting
>> kernel: [ 305.602967] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
>> kernel: [ 305.656090] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2427 -> 2432 MHz)
>> NetworkManager[725]:<info> (wlan0): device state change: 3 -> 2 (reason 0)
>> NetworkManager[725]:<info> (wlan0): deactivating device (reason: 0).
>> NetworkManager[725]:<info> (wlan0): taking down device.
>> kernel: [ 310.887530] net_ratelimit: 29 callbacks suppressed
>> kernel: [ 310.887535] ath5k phy0: (ath5k_stop_locked:2481): invalid 0
>> kernel: [ 310.990264] ath5k phy0: (ath5k_stop_hw:2619): putting device to sleep
>> kernel: [ 310.990554] ath5k phy0: (ath5k_rfkill_enable:51): rfkill enable (gpio:0 polarity:0)
>> NetworkManager[725]:<info> (wlan0): bringing up device.
>> kernel: [ 315.755891] ath5k phy0: (ath5k_init_hw:2522): mode 2
>> kernel: [ 315.755903] ath5k phy0: (ath5k_stop_locked:2481): invalid 0
>> kernel: [ 315.756624] ath5k phy0: (ath5k_reset:2648): resetting
>> kernel: [ 315.760236] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
>> kernel: [ 315.760474] ath5k phy0: (ath5k_rfkill_disable:42): rfkill disable (gpio:0 polarity:0)
>> kernel: [ 315.762566] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2412 -> 2412 MHz)
>> kernel: [ 315.762574] ath5k phy0: (ath5k_reset:2648): resetting
>> kernel: [ 315.764972] ADDRCONF(NETDEV_UP): wlan0: link is not ready
>> NetworkManager[725]:<info> (wlan0): supplicant interface state: starting -> ready
>> NetworkManager[725]:<info> (wlan0): device state change: 2 -> 3 (reason 42)
>> wpa_supplicant[745]: Failed to initiate AP scan.
>> kernel: [ 316.036068] net_ratelimit: 8 callbacks suppressed
>> kernel: [ 316.036080] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2417 -> 2422 MHz)
>> kernel: [ 316.036089] ath5k phy0: (ath5k_reset:2648): resetting
>> kernel: [ 316.140039] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
>> kernel: [ 316.196067] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2422 -> 2427 MHz)
>> kernel: [ 316.196079] ath5k phy0: (ath5k_reset:2648): resetting
>> kernel: [ 316.298940] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
>> kernel: [ 316.352063] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2427 -> 2432 MHz)
>> kernel: [ 316.352071] ath5k phy0: (ath5k_reset:2648): resetting
>> kernel: [ 316.455003] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
>> kernel: [ 316.508080] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2432 -> 2437 MHz)
>> kernel: [ 336.188067] net_ratelimit: 26 callbacks suppressed
>> kernel: [ 336.188080] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2412 -> 2417 MHz)
>> kernel: [ 336.188088] ath5k phy0: (ath5k_reset:2648): resetting
>> kernel: [ 336.290966] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
>> kernel: [ 336.344059] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2417 -> 2422 MHz)
>> kernel: [ 336.344068] ath5k phy0: (ath5k_reset:2648): resetting
>> kernel: [ 336.446912] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
>> kernel: [ 336.500068] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2422 -> 2427 MHz)
>> kernel: [ 336.500077] ath5k phy0: (ath5k_reset:2648): resetting
>> kernel: [ 336.602937] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
>> kernel: [ 336.656058] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2427 -> 2432 MHz)
>> kernel: [ 366.188084] net_ratelimit: 29 callbacks suppressed
>> kernel: [ 366.188097] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2412 -> 2417 MHz)
>> kernel: [ 366.188105] ath5k phy0: (ath5k_reset:2648): resetting
>> kernel: [ 366.290999] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
>> kernel: [ 366.344099] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2417 -> 2422 MHz)
>> kernel: [ 366.344112] ath5k phy0: (ath5k_reset:2648): resetting
>> kernel: [ 366.447030] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
>> kernel: [ 366.500094] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2422 -> 2427 MHz)
>> kernel: [ 366.500106] ath5k phy0: (ath5k_reset:2648): resetting
>> kernel: [ 366.603008] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32 rx_bufsize 2368
>> kernel: [ 366.656103] ath5k phy0: (ath5k_chan_set:434): channel set, resetting (2427 -> 2432 MHz)
>>
>>
>
> Hmm I don't see any errors from reset/phy code, can you disable
> Network Manager/wpa-supplicant and test connection on an open network
> using iw ? It 'll give us a better picture...
>
> If iw doesn't return any scan results we are probably hitting a PHY/RF
> error specific to your device (not all vendors follow the reference
> design). Maybe we should follow a blacklist/whitelist approach for
> this feature.
>

yeah Im getting this over here with my macbook pro. all of a sudden
internet craps out, unable to reconnect.. reboot is the only way to get
back online.
dmesg here:
http://fpaste.org/mwGn/

I can try bisecting, but might take a while due to this occuring every
few days or so.

Justin P. Mattock

2011-05-05 15:15:49

by Nick Kossifidis

Subject: Re: ath5k regression associating with APs in 2.6.38

2011/5/5 Justin P. Mattock <[email protected]>:
> On 05/05/2011 07:30 AM, Nick Kossifidis wrote:
>>
>> 2011/5/5 Seth Forshee<[email protected]>:
>>>
>>> On Wed, May 04, 2011 at 11:09:03PM +0300, Nick Kossifidis wrote:
>>>>
>>>> 2011/5/4 Seth Forshee<[email protected]>:
>>>>>
>>>>> On Wed, May 04, 2011 at 01:27:17PM -0400, John W. Linville wrote:
>>>>>>
>>>>>> On Wed, May 04, 2011 at 10:38:19AM -0500, Seth Forshee wrote:
>>>>>>>
>>>>>>> I've been investigating some reports of a regression in associating
>>>>>>> with
>>>>>>> APs with AR2413 in 2.6.38. Association repeatedly fails with some
>>>>>>> "direct probe to x timed out" messages (see syslog excerpt below),
>>>>>>> although it will generally associate eventually, after many tries.
>>>>>>>
>>>>>>> Bisection identifies 8aec7af (ath5k: Support synth-only channel
>>>>>>> change
>>>>>>> for AR2413/AR5413) as offending commit. Prior to this commit there
>>>>>>> are
>>>>>>> no direct probe messages at all in the logs. I've also found that
>>>>>>> forcing fast to false at the top of ath5k_hw_reset() fixes the issue.
>>>>>>> I'm not sure what the connection is between this commit and the
>>>>>>> timeouts. Any suggestions?
>>>>>>
>>>>>> Have you tried reverting that commit on top of 2.6.38?  Can you
>>>>>> recreate the issue with 2.6.39-rc6 (or later)?
>>>>>
>>>>> I started to revert that commit, but it wasn't straight-forward due to
>>>>> later changes. Forcing fast to false in ath5k_hw_reset() acts as a
>>>>> functional revert of sorts since that should force it back to a full
>>>>> reset for all channel changes, and it's much simpler than working out
>>>>> the right way to revert the commit. I think the results suggest
>>>>> strongly
>>>>> that a revert is likely to fix the problem. I can finish the work to
>>>>> revert if you'd still like to see the results.
>>>>>
>>>>> Testing a previous .39-rc kernel still exhibited the failure. I don't
>>>>> recall which one it was and apparently forgot to make note of it. I'll
>>>>> request testing against rc6.
>>>>>
>>>>> Thanks,
>>>>> Seth
>>>>>
>>>>
>>>> Do you get scan results ?
>>>> Can you enable ATH5K_DEBUG_RESET and see what you get ?
>>>
>>> 2.6.39-rc6 still fails. A more comprehensive log with ATH5K_DEBUG_RESET
>>> enabled is below.
>>>
>>> Scanning looks to be failing according to this log. I was thinking that
>>> I saw successfull scans in some of the previous logs, but I'll have to
>>> go back and check to be sure.
>>>
>>> Thanks,
>>> Seth
>>>
>>>
>>> kernel: [   23.421242] ath5k 0000:06:02.0: PCI INT A ->  GSI 22 (level,
>>> low) ->  IRQ 22
>>> kernel: [   23.421312] ath5k 0000:06:02.0: registered as 'phy0'
>>> kernel: [   24.132959] ath: EEPROM regdomain: 0x63
>>> kernel: [   24.132962] ath: EEPROM indicates we should expect a direct
>>> regpair map
>>> kernel: [   24.132967] ath: Country alpha2 being used: 00
>>> kernel: [   24.132969] ath: Regpair used: 0x63
>>> kernel: [   24.136125] cfg80211: Updating information on frequency 2412
>>> MHz for a 20 MHz width channel with regulatory rule:
>>> kernel: [   24.136131] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A
>>> mBi, 2000 mBm)
>>> kernel: [   24.136134] cfg80211: Updating information on frequency 2417
>>> MHz for a 20 MHz width channel with regulatory rule:
>>> kernel: [   24.136137] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A
>>> mBi, 2000 mBm)
>>> kernel: [   24.136140] cfg80211: Updating information on frequency 2422
>>> MHz for a 20 MHz width channel with regulatory rule:
>>> kernel: [   24.136143] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A
>>> mBi, 2000 mBm)
>>> kernel: [   24.136146] cfg80211: Updating information on frequency 2427
>>> MHz for a 20 MHz width channel with regulatory rule:
>>> kernel: [   24.136149] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A
>>> mBi, 2000 mBm)
>>> kernel: [   24.136151] cfg80211: Updating information on frequency 2432
>>> MHz for a 20 MHz width channel with regulatory rule:
>>> kernel: [   24.136155] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A
>>> mBi, 2000 mBm)
>>> kernel: [   24.136157] cfg80211: Updating information on frequency 2437
>>> MHz for a 20 MHz width channel with regulatory rule:
>>> kernel: [   24.136160] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A
>>> mBi, 2000 mBm)
>>> kernel: [   24.136163] cfg80211: Updating information on frequency 2442
>>> MHz for a 20 MHz width channel with regulatory rule:
>>> kernel: [   24.136166] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A
>>> mBi, 2000 mBm)
>>> kernel: [   24.136168] cfg80211: Updating information on frequency 2447
>>> MHz for a 20 MHz width channel with regulatory rule:
>>> kernel: [   24.136172] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A
>>> mBi, 2000 mBm)
>>> kernel: [   24.136174] cfg80211: Updating information on frequency 2452
>>> MHz for a 20 MHz width channel with regulatory rule:
>>> kernel: [   24.136177] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A
>>> mBi, 2000 mBm)
>>> kernel: [   24.136180] cfg80211: Updating information on frequency 2457
>>> MHz for a 20 MHz width channel with regulatory rule:
>>> kernel: [   24.136183] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A
>>> mBi, 2000 mBm)
>>> kernel: [   24.136186] cfg80211: Updating information on frequency 2462
>>> MHz for a 20 MHz width channel with regulatory rule:
>>> kernel: [   24.136189] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A
>>> mBi, 2000 mBm)
>>> kernel: [   24.136191] cfg80211: Updating information on frequency 2467
>>> MHz for a 20 MHz width channel with regulatory rule:
>>> kernel: [   24.136195] cfg80211: 2457000 KHz - 2482000 KHz @  KHz), (N/A
>>> mBi, 2000 mBm)
>>> kernel: [   24.136197] cfg80211: Updating information on frequency 2472
>>> MHz for a 20 MHz width channel with regulatory rule:
>>> kernel: [   24.136200] cfg80211: 2457000 KHz - 2482000 KHz @  KHz), (N/A
>>> mBi, 2000 mBm)
>>> kernel: [   24.136203] cfg80211: Disabling freq 2484 MHz as custom regd
>>> has no rule that fits a 20 MHz wide channel
>>> kernel: [   24.136404] cfg80211: Ignoring regulatory request Set by core
>>> since the driver uses its own custom regulatory domain
>>> kernel: [   24.393924] ieee80211 phy0: Selected rate control algorithm
>>> 'minstrel_ht'
>>> kernel: [   24.394588] ath5k phy0: Atheros AR2413 chip found (MAC: 0x78,
>>> PHY: 0x45)
>>> ...
>>> NetworkManager[725]:<info>  (wlan0): driver supports SSID scans
>>> (scan_capa 0x01).
>>> NetworkManager[725]:<info>  (wlan0): new 802.11 WiFi device (driver:
>>> 'ath5k' ifindex: 3)
>>> NetworkManager[725]:<info>  (wlan0): exported as
>>> /org/freedesktop/NetworkManager/Devices/1
>>> NetworkManager[725]:<info>  (wlan0): now managed
>>> NetworkManager[725]:<info>  (wlan0): device state change: 1 ->  2 (reason
>>> 2)
>>> NetworkManager[725]:<info>  (wlan0): bringing up device.
>>> NetworkManager[725]:<info>  (wlan0): preparing device.
>>> NetworkManager[725]:<info>  (wlan0): deactivating device (reason: 2).
>>> NetworkManager[725]: supplicant_interface_acquire: assertion `mgr_state
>>> == NM_SUPPLICANT_MANAGER_STATE_IDLE' failed
>>> kernel: [   25.149294] ADDRCONF(NETDEV_UP): wlan0: link is not ready
>>> ...
>>> NetworkManager[725]:<info>  Trying to start the supplicant...
>>> ...
>>> NetworkManager[725]:<info>  (wlan0): supplicant manager state:  down ->
>>>  idle
>>> NetworkManager[725]:<info>  (wlan0): device state change: 2 ->  3 (reason
>>> 0)
>>> NetworkManager[725]:<info>  (wlan0): supplicant interface state:
>>>  starting ->  ready
>>> ...
>>> NetworkManager[725]:<info>  (wlan0): device state change: 3 ->  2 (reason
>>> 0)
>>> NetworkManager[725]:<info>  (wlan0): deactivating device (reason: 0).
>>> NetworkManager[725]:<info>  (wlan0): taking down device.
>>> NetworkManager[725]:<info>  (wlan0): bringing up device.
>>> kernel: [  104.430292] ath5k phy0: (ath5k_init_hw:2522): mode 2
>>> kernel: [  104.430297] ath5k phy0: (ath5k_stop_locked:2481): invalid 0
>>> kernel: [  104.431000] ath5k phy0: (ath5k_reset:2648): resetting
>>> kernel: [  104.434475] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32
>>> rx_bufsize 2368
>>> kernel: [  104.434683] ath5k phy0: (ath5k_rfkill_disable:42): rfkill
>>> disable (gpio:0 polarity:0)
>>> kernel: [  104.435759] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2412 ->  2412 MHz)
>>> kernel: [  104.435762] ath5k phy0: (ath5k_reset:2648): resetting
>>> kernel: [  104.436845] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32
>>> rx_bufsize 2368
>>> kernel: [  104.437191] ath5k phy0: (ath5k_conf_tx:602): Configure tx
>>> [queue 0],  aifs: 2, cw_min: 7, cw_max: 15, txop: 102
>>> kernel: [  104.437212] ath5k phy0: (ath5k_conf_tx:602): Configure tx
>>> [queue 1],  aifs: 2, cw_min: 15, cw_max: 31, txop: 188
>>> kernel: [  104.438337] ADDRCONF(NETDEV_UP): wlan0: link is not ready
>>> NetworkManager[725]:<info>  (wlan0): supplicant interface state:
>>>  starting ->  ready
>>> NetworkManager[725]:<info>  (wlan0): device state change: 2 ->  3 (reason
>>> 42)
>>> wpa_supplicant[745]: Failed to initiate AP scan.
>>> kernel: [  125.188087] net_ratelimit: 41 callbacks suppressed
>>> kernel: [  125.188100] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2412 ->  2417 MHz)
>>> kernel: [  125.188109] ath5k phy0: (ath5k_reset:2648): resetting
>>> kernel: [  125.291007] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32
>>> rx_bufsize 2368
>>> kernel: [  125.344076] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2417 ->  2422 MHz)
>>> kernel: [  125.344090] ath5k phy0: (ath5k_reset:2648): resetting
>>> kernel: [  125.447014] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32
>>> rx_bufsize 2368
>>> kernel: [  125.500078] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2422 ->  2427 MHz)
>>> kernel: [  125.500091] ath5k phy0: (ath5k_reset:2648): resetting
>>> kernel: [  125.602999] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32
>>> rx_bufsize 2368
>>> kernel: [  125.656070] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2427 ->  2432 MHz)
>>> kernel: [  155.188052] net_ratelimit: 29 callbacks suppressed
>>> kernel: [  155.188058] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2412 ->  2417 MHz)
>>> kernel: [  155.188061] ath5k phy0: (ath5k_reset:2648): resetting
>>> kernel: [  155.290844] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32
>>> rx_bufsize 2368
>>> kernel: [  155.344032] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2417 ->  2422 MHz)
>>> kernel: [  155.344038] ath5k phy0: (ath5k_reset:2648): resetting
>>> kernel: [  155.446810] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32
>>> rx_bufsize 2368
>>> kernel: [  155.500031] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2422 ->  2427 MHz)
>>> kernel: [  155.500036] ath5k phy0: (ath5k_reset:2648): resetting
>>> kernel: [  155.602811] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32
>>> rx_bufsize 2368
>>> kernel: [  155.656033] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2427 ->  2432 MHz)
>>> kernel: [  195.184088] net_ratelimit: 29 callbacks suppressed
>>> kernel: [  195.184102] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2412 ->  2417 MHz)
>>> kernel: [  195.184110] ath5k phy0: (ath5k_reset:2648): resetting
>>> kernel: [  195.287022] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32
>>> rx_bufsize 2368
>>> kernel: [  195.340066] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2417 ->  2422 MHz)
>>> kernel: [  195.340079] ath5k phy0: (ath5k_reset:2648): resetting
>>> kernel: [  195.442967] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32
>>> rx_bufsize 2368
>>> kernel: [  195.496076] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2422 ->  2427 MHz)
>>> kernel: [  195.496088] ath5k phy0: (ath5k_reset:2648): resetting
>>> kernel: [  195.599009] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32
>>> rx_bufsize 2368
>>> kernel: [  195.652078] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2427 ->  2432 MHz)
>>> kernel: [  245.188077] net_ratelimit: 29 callbacks suppressed
>>> kernel: [  245.188091] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2412 ->  2417 MHz)
>>> kernel: [  245.188100] ath5k phy0: (ath5k_reset:2648): resetting
>>> kernel: [  245.290997] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32
>>> rx_bufsize 2368
>>> kernel: [  245.344084] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2417 ->  2422 MHz)
>>> kernel: [  245.344092] ath5k phy0: (ath5k_reset:2648): resetting
>>> kernel: [  245.446882] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32
>>> rx_bufsize 2368
>>> kernel: [  245.500053] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2422 ->  2427 MHz)
>>> kernel: [  245.500058] ath5k phy0: (ath5k_reset:2648): resetting
>>> kernel: [  245.602808] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32
>>> rx_bufsize 2368
>>> kernel: [  245.656046] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2427 ->  2432 MHz)
>>> kernel: [  305.188050] net_ratelimit: 29 callbacks suppressed
>>> kernel: [  305.188063] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2412 ->  2417 MHz)
>>> kernel: [  305.188071] ath5k phy0: (ath5k_reset:2648): resetting
>>> kernel: [  305.290945] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32
>>> rx_bufsize 2368
>>> kernel: [  305.344070] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2417 ->  2422 MHz)
>>> kernel: [  305.344082] ath5k phy0: (ath5k_reset:2648): resetting
>>> kernel: [  305.446943] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32
>>> rx_bufsize 2368
>>> kernel: [  305.500047] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2422 ->  2427 MHz)
>>> kernel: [  305.500058] ath5k phy0: (ath5k_reset:2648): resetting
>>> kernel: [  305.602967] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32
>>> rx_bufsize 2368
>>> kernel: [  305.656090] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2427 ->  2432 MHz)
>>> NetworkManager[725]:<info>  (wlan0): device state change: 3 ->  2 (reason
>>> 0)
>>> NetworkManager[725]:<info>  (wlan0): deactivating device (reason: 0).
>>> NetworkManager[725]:<info>  (wlan0): taking down device.
>>> kernel: [  310.887530] net_ratelimit: 29 callbacks suppressed
>>> kernel: [  310.887535] ath5k phy0: (ath5k_stop_locked:2481): invalid 0
>>> kernel: [  310.990264] ath5k phy0: (ath5k_stop_hw:2619): putting device
>>> to sleep
>>> kernel: [  310.990554] ath5k phy0: (ath5k_rfkill_enable:51): rfkill
>>> enable (gpio:0 polarity:0)
>>> NetworkManager[725]:<info>  (wlan0): bringing up device.
>>> kernel: [  315.755891] ath5k phy0: (ath5k_init_hw:2522): mode 2
>>> kernel: [  315.755903] ath5k phy0: (ath5k_stop_locked:2481): invalid 0
>>> kernel: [  315.756624] ath5k phy0: (ath5k_reset:2648): resetting
>>> kernel: [  315.760236] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32
>>> rx_bufsize 2368
>>> kernel: [  315.760474] ath5k phy0: (ath5k_rfkill_disable:42): rfkill
>>> disable (gpio:0 polarity:0)
>>> kernel: [  315.762566] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2412 ->  2412 MHz)
>>> kernel: [  315.762574] ath5k phy0: (ath5k_reset:2648): resetting
>>> kernel: [  315.764972] ADDRCONF(NETDEV_UP): wlan0: link is not ready
>>> NetworkManager[725]:<info>  (wlan0): supplicant interface state:
>>>  starting ->  ready
>>> NetworkManager[725]:<info>  (wlan0): device state change: 2 ->  3 (reason
>>> 42)
>>> wpa_supplicant[745]: Failed to initiate AP scan.
>>> kernel: [  316.036068] net_ratelimit: 8 callbacks suppressed
>>> kernel: [  316.036080] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2417 ->  2422 MHz)
>>> kernel: [  316.036089] ath5k phy0: (ath5k_reset:2648): resetting
>>> kernel: [  316.140039] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32
>>> rx_bufsize 2368
>>> kernel: [  316.196067] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2422 ->  2427 MHz)
>>> kernel: [  316.196079] ath5k phy0: (ath5k_reset:2648): resetting
>>> kernel: [  316.298940] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32
>>> rx_bufsize 2368
>>> kernel: [  316.352063] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2427 ->  2432 MHz)
>>> kernel: [  316.352071] ath5k phy0: (ath5k_reset:2648): resetting
>>> kernel: [  316.455003] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32
>>> rx_bufsize 2368
>>> kernel: [  316.508080] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2432 ->  2437 MHz)
>>> kernel: [  336.188067] net_ratelimit: 26 callbacks suppressed
>>> kernel: [  336.188080] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2412 ->  2417 MHz)
>>> kernel: [  336.188088] ath5k phy0: (ath5k_reset:2648): resetting
>>> kernel: [  336.290966] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32
>>> rx_bufsize 2368
>>> kernel: [  336.344059] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2417 ->  2422 MHz)
>>> kernel: [  336.344068] ath5k phy0: (ath5k_reset:2648): resetting
>>> kernel: [  336.446912] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32
>>> rx_bufsize 2368
>>> kernel: [  336.500068] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2422 ->  2427 MHz)
>>> kernel: [  336.500077] ath5k phy0: (ath5k_reset:2648): resetting
>>> kernel: [  336.602937] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32
>>> rx_bufsize 2368
>>> kernel: [  336.656058] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2427 ->  2432 MHz)
>>> kernel: [  366.188084] net_ratelimit: 29 callbacks suppressed
>>> kernel: [  366.188097] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2412 ->  2417 MHz)
>>> kernel: [  366.188105] ath5k phy0: (ath5k_reset:2648): resetting
>>> kernel: [  366.290999] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32
>>> rx_bufsize 2368
>>> kernel: [  366.344099] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2417 ->  2422 MHz)
>>> kernel: [  366.344112] ath5k phy0: (ath5k_reset:2648): resetting
>>> kernel: [  366.447030] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32
>>> rx_bufsize 2368
>>> kernel: [  366.500094] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2422 ->  2427 MHz)
>>> kernel: [  366.500106] ath5k phy0: (ath5k_reset:2648): resetting
>>> kernel: [  366.603008] ath5k phy0: (ath5k_rx_start:1099): cachelsz 32
>>> rx_bufsize 2368
>>> kernel: [  366.656103] ath5k phy0: (ath5k_chan_set:434): channel set,
>>> resetting (2427 ->  2432 MHz)
>>>
>>>
>>
>> Hmm I don't see any errors from reset/phy code, can you disable
>> Network Manager/wpa-supplicant and test connection on an open network
>> using iw ? It 'll give us a better picture...
>>
>> If iw doesn't return any scan results we are probably hitting a PHY/RF
>> error specific to your device (not all vendors follow the reference
>> design). Maybe we should follow a blacklist/whitelist approach for
>> this feature.
>>
>
> yeah Im getting this over here with my macbook pro. all of a sudden internet
> craps out, unable to reconnect.. reboot is the only way to get back online.
> dmesg here:
> http://fpaste.org/mwGn/
>
> I can try bisecting, but might take a while due to this occuring every few
> days or so.
>
> Justin P. Mattock
>

[ 26.219909] ath9k 0000:03:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17

Different card, different driver...

--
GPG ID: 0xD21DB2DB
As you read this post global entropy rises. Have Fun ;-)
Nick

2011-05-09 07:02:47

by Seth Forshee

Subject: Re: ath5k regression associating with APs in 2.6.38

On Thu, May 05, 2011 at 05:30:42PM +0300, Nick Kossifidis wrote:
> Hmm I don't see any errors from reset/phy code, can you disable
> Network Manager/wpa-supplicant and test connection on an open network
> using iw ? It 'll give us a better picture...
>
> If iw doesn't return any scan results we are probably hitting a PHY/RF
> error specific to your device (not all vendors follow the reference
> design). Maybe we should follow a blacklist/whitelist approach for
> this feature.

I got the results back from my tester. He was able to get scan results,
but it took multiple tries and the direct probe failures appear in the
log. He didn't enable ATH5K_DEBUG_RESET this time; let me know if you
need that and I'll request he retest with the extra debug logs enabled.


[ 25.070218] ath5k 0000:06:02.0: PCI INT A -> GSI 22 (level, low) -> IRQ 22
[ 25.070290] ath5k 0000:06:02.0: registered as 'phy0'
[ 25.830368] ath: EEPROM regdomain: 0x63
[ 25.830372] ath: EEPROM indicates we should expect a direct regpair map
[ 25.830376] ath: Country alpha2 being used: 00
[ 25.830378] ath: Regpair used: 0x63
[ 25.830382] cfg80211: Updating information on frequency 2412 MHz for a 20 MHz width channel with regulatory rule:
[ 25.830386] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
[ 25.830388] cfg80211: Updating information on frequency 2417 MHz for a 20 MHz width channel with regulatory rule:
[ 25.830392] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
[ 25.830394] cfg80211: Updating information on frequency 2422 MHz for a 20 MHz width channel with regulatory rule:
[ 25.830397] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
[ 25.830400] cfg80211: Updating information on frequency 2427 MHz for a 20 MHz width channel with regulatory rule:
[ 25.830403] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
[ 25.830405] cfg80211: Updating information on frequency 2432 MHz for a 20 MHz width channel with regulatory rule:
[ 25.830409] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
[ 25.830411] cfg80211: Updating information on frequency 2437 MHz for a 20 MHz width channel with regulatory rule:
[ 25.830414] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
[ 25.830417] cfg80211: Updating information on frequency 2442 MHz for a 20 MHz width channel with regulatory rule:
[ 25.830420] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
[ 25.830423] cfg80211: Updating information on frequency 2447 MHz for a 20 MHz width channel with regulatory rule:
[ 25.830426] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
[ 25.830428] cfg80211: Updating information on frequency 2452 MHz for a 20 MHz width channel with regulatory rule:
[ 25.830431] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
[ 25.830434] cfg80211: Updating information on frequency 2457 MHz for a 20 MHz width channel with regulatory rule:
[ 25.830437] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
[ 25.830440] cfg80211: Updating information on frequency 2462 MHz for a 20 MHz width channel with regulatory rule:
[ 25.830443] cfg80211: 2402000 KHz - 2472000 KHz @ KHz), (N/A mBi, 2000 mBm)
[ 25.830445] cfg80211: Updating information on frequency 2467 MHz for a 20 MHz width channel with regulatory rule:
[ 25.830449] cfg80211: 2457000 KHz - 2482000 KHz @ KHz), (N/A mBi, 2000 mBm)
[ 25.830451] cfg80211: Updating information on frequency 2472 MHz for a 20 MHz width channel with regulatory rule:
[ 25.830454] cfg80211: 2457000 KHz - 2482000 KHz @ KHz), (N/A mBi, 2000 mBm)
[ 25.830457] cfg80211: Disabling freq 2484 MHz as custom regd has no rule that fits a 20 MHz wide channel
[ 25.842012] cfg80211: Ignoring regulatory request Set by core since the driver uses its own custom regulatory domain
[ 26.048048] ieee80211 phy0: Selected rate control algorithm 'minstrel_ht'
[ 26.051154] ath5k phy0: Atheros AR2413 chip found (MAC: 0x78, PHY: 0x45)
[ 133.492866] ADDRCONF(NETDEV_UP): wlan0: link is not ready
[ 278.050097] wlan0: direct probe to c0:3f:0e:b9:f3:b2 (try 1/3)
[ 278.248082] wlan0: direct probe to c0:3f:0e:b9:f3:b2 (try 2/3)
[ 278.448111] wlan0: direct probe to c0:3f:0e:b9:f3:b2 (try 3/3)
[ 278.648084] wlan0: direct probe to c0:3f:0e:b9:f3:b2 timed out
[ 283.920272] wlan0: direct probe to c2:3f:0e:b9:f3:b3 (try 1/3)
[ 284.120232] wlan0: direct probe to c2:3f:0e:b9:f3:b3 (try 2/3)
[ 284.320074] wlan0: direct probe to c2:3f:0e:b9:f3:b3 (try 3/3)
[ 284.520081] wlan0: direct probe to c2:3f:0e:b9:f3:b3 timed out
[ 295.029501] wlan0: direct probe to c2:3f:0e:b9:f3:b3 (try 1/3)
[ 295.228085] wlan0: direct probe to c2:3f:0e:b9:f3:b3 (try 2/3)
[ 295.428086] wlan0: direct probe to c2:3f:0e:b9:f3:b3 (try 3/3)
[ 295.628099] wlan0: direct probe to c2:3f:0e:b9:f3:b3 timed out
[ 306.137353] wlan0: direct probe to c2:3f:0e:b9:f3:b3 (try 1/3)
[ 306.336092] wlan0: direct probe to c2:3f:0e:b9:f3:b3 (try 2/3)
[ 306.536097] wlan0: direct probe to c2:3f:0e:b9:f3:b3 (try 3/3)
[ 306.736099] wlan0: direct probe to c2:3f:0e:b9:f3:b3 timed out
[ 317.245279] wlan0: direct probe to c2:3f:0e:b9:f3:b3 (try 1/3)
[ 317.444097] wlan0: direct probe to c2:3f:0e:b9:f3:b3 (try 2/3)
[ 317.644111] wlan0: direct probe to c2:3f:0e:b9:f3:b3 (try 3/3)
[ 317.844091] wlan0: direct probe to c2:3f:0e:b9:f3:b3 timed out
[ 328.348112] wlan0: direct probe to c2:3f:0e:b9:f3:b3 (try 1/3)
[ 328.548171] wlan0: direct probe to c2:3f:0e:b9:f3:b3 (try 2/3)
[ 328.748109] wlan0: direct probe to c2:3f:0e:b9:f3:b3 (try 3/3)
[ 328.948095] wlan0: direct probe to c2:3f:0e:b9:f3:b3 timed out
[ 339.453369] wlan0: direct probe to c2:3f:0e:b9:f3:b3 (try 1/3)
[ 339.652085] wlan0: direct probe to c2:3f:0e:b9:f3:b3 (try 2/3)
[ 339.852082] wlan0: direct probe to c2:3f:0e:b9:f3:b3 (try 3/3)
[ 340.052092] wlan0: direct probe to c2:3f:0e:b9:f3:b3 timed out
[ 344.316878] wlan0: direct probe to c0:3f:0e:b9:f3:b2 (try 1/3)
[ 344.516064] wlan0: direct probe to c0:3f:0e:b9:f3:b2 (try 2/3)
[ 344.716125] wlan0: direct probe to c0:3f:0e:b9:f3:b2 (try 3/3)
[ 344.916101] wlan0: direct probe to c0:3f:0e:b9:f3:b2 timed out
[ 355.421554] wlan0: direct probe to c0:3f:0e:b9:f3:b2 (try 1/3)
[ 355.620092] wlan0: direct probe to c0:3f:0e:b9:f3:b2 (try 2/3)
[ 355.820642] wlan0: direct probe to c0:3f:0e:b9:f3:b2 (try 3/3)
[ 356.020054] wlan0: direct probe to c0:3f:0e:b9:f3:b2 timed out
[ 366.521629] wlan0: direct probe to c0:3f:0e:b9:f3:b2 (try 1/3)
[ 366.720085] wlan0: direct probe to c0:3f:0e:b9:f3:b2 (try 2/3)
[ 366.920080] wlan0: direct probe to c0:3f:0e:b9:f3:b2 (try 3/3)
[ 367.120367] wlan0: direct probe to c0:3f:0e:b9:f3:b2 timed out
[ 433.347401] ADDRCONF(NETDEV_UP): wlan0: link is not ready
[ 468.143619] wlan0: direct probe to c2:3f:0e:b9:f3:b3 (try 1/3)
[ 468.340073] wlan0: direct probe to c2:3f:0e:b9:f3:b3 (try 2/3)
[ 468.540069] wlan0: direct probe to c2:3f:0e:b9:f3:b3 (try 3/3)
[ 468.740069] wlan0: direct probe to c2:3f:0e:b9:f3:b3 timed out
[ 482.093842] wlan0: authenticate with c2:3f:0e:b9:f3:b3 (try 1)
[ 482.095325] wlan0: authenticated
[ 482.095384] wlan0: associate with c2:3f:0e:b9:f3:b3 (try 1)
[ 482.097657] wlan0: RX AssocResp from c2:3f:0e:b9:f3:b3 (capab=0x401 status=0 aid=1)
[ 482.097666] wlan0: associated
[ 482.099748] ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[ 492.416050] wlan0: no IPv6 routers present
[ 547.281613] wlan0: deauthenticating from c2:3f:0e:b9:f3:b3 by local choice (reason=3)
[ 547.281973] cfg80211: All devices are disconnected, going to restore regulatory settings
[ 547.281984] cfg80211: Restoring regulatory settings
[ 547.283060] cfg80211: Calling CRDA to update world regulatory domain
[ 547.311427] cfg80211: Ignoring regulatory request Set by core since the driver uses its own custom regulatory domain
[ 547.311446] cfg80211: World regulatory domain updated:
[ 547.311451] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
[ 547.311461] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[ 547.311469] cfg80211: (2457000 KHz - 2482000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
[ 547.311477] cfg80211: (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
[ 547.311484] cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[ 547.311492] cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)

2011-05-17 16:57:39

by Seth Forshee

Subject: Re: ath5k regression associating with APs in 2.6.38

On Mon, May 09, 2011 at 09:02:30AM +0200, Seth Forshee wrote:
> On Thu, May 05, 2011 at 05:30:42PM +0300, Nick Kossifidis wrote:
> > Hmm I don't see any errors from reset/phy code, can you disable
> > Network Manager/wpa-supplicant and test connection on an open network
> > using iw ? It 'll give us a better picture...
> >
> > If iw doesn't return any scan results we are probably hitting a PHY/RF
> > error specific to your device (not all vendors follow the reference
> > design). Maybe we should follow a blacklist/whitelist approach for
> > this feature.
>
> I got the results back from my tester. He was able to get scan results,
> but it took multiple tries and the direct probe failures appear in the
> log. He didn't enable ATH5K_DEBUG_RESET this time; let me know if you
> need that and I'll request he retest with the extra debug logs enabled.

I got some more feedback. Most of the time iw does not get scan results,
but even when it does connecting to the AP isn't always successful. The
tester did note that he doesn't seem to have any trouble if his machine
is within a few feet of his AP. Let me know if you'd like something else
tested.

I noticed that bugzilla #31922 (ath5k: Decreased throughput in IBSS or
802.11n mode) is also fixed by reverting 8aec7af9. It seems like the
synth-only channel changes are resulting in poor connection quality.
Maybe that patch needs to be reverted?

Thanks,
Seth

2011-05-17 17:14:37

by Nick Kossifidis

Subject: Re: ath5k regression associating with APs in 2.6.38

2011/5/17 Seth Forshee <[email protected]>:
> On Mon, May 09, 2011 at 09:02:30AM +0200, Seth Forshee wrote:
>> On Thu, May 05, 2011 at 05:30:42PM +0300, Nick Kossifidis wrote:
>> > Hmm I don't see any errors from reset/phy code, can you disable
>> > Network Manager/wpa-supplicant and test connection on an open network
>> > using iw ? It 'll give us a better picture...
>> >
>> > If iw doesn't return any scan results we are probably hitting a PHY/RF
>> > error specific to your device (not all vendors follow the reference
>> > design). Maybe we should follow a blacklist/whitelist approach for
>> > this feature.
>>
>> I got the results back from my tester. He was able to get scan results,
>> but it took multiple tries and the direct probe failures appear in the
>> log. He didn't enable ATH5K_DEBUG_RESET this time; let me know if you
>> need that and I'll request he retest with the extra debug logs enabled.
>
> I got some more feedback. Most of the time iw does not get scan results,
> but even when it does connecting to the AP isn't always successful. The
> tester did note that he doesn't seem to have any trouble if his machine
> is within a few feet of his AP. Let me know if you'd like something else
> tested.
>
> I noticed that bugzilla #31922 (ath5k: Decreased throughput in IBSS or
> 802.11n mode) is also fixed by reverting 8aec7af9. It seems like the
> synth-only channel changes are resulting in poor connection quality.
> Maybe that patch needs to be reverted?
>
> Thanks,
> Seth
>
>

http://www.kernel.org/pub/linux/kernel/people/mickflemm/01-fast-chan-switch-modparm

--
GPG ID: 0xD21DB2DB
As you read this post global entropy rises. Have Fun ;-)
Nick

2011-05-17 18:50:49

by Seth Forshee

Subject: Re: ath5k regression associating with APs in 2.6.38

On Tue, May 17, 2011 at 08:14:34PM +0300, Nick Kossifidis wrote:
> 2011/5/17 Seth Forshee <[email protected]>:
> > On Mon, May 09, 2011 at 09:02:30AM +0200, Seth Forshee wrote:
> >> On Thu, May 05, 2011 at 05:30:42PM +0300, Nick Kossifidis wrote:
> >> > Hmm I don't see any errors from reset/phy code, can you disable
> >> > Network Manager/wpa-supplicant and test connection on an open network
> >> > using iw ? It 'll give us a better picture...
> >> >
> >> > If iw doesn't return any scan results we are probably hitting a PHY/RF
> >> > error specific to your device (not all vendors follow the reference
> >> > design). Maybe we should follow a blacklist/whitelist approach for
> >> > this feature.
> >>
> >> I got the results back from my tester. He was able to get scan results,
> >> but it took multiple tries and the direct probe failures appear in the
> >> log. He didn't enable ATH5K_DEBUG_RESET this time; let me know if you
> >> need that and I'll request he retest with the extra debug logs enabled.
> >
> > I got some more feedback. Most of the time iw does not get scan results,
> > but even when it does connecting to the AP isn't always successful. The
> > tester did note that he doesn't seem to have any trouble if his machine
> > is within a few feet of his AP. Let me know if you'd like something else
> > tested.
> >
> > I noticed that bugzilla #31922 (ath5k: Decreased throughput in IBSS or
> > 802.11n mode) is also fixed by reverting 8aec7af9. It seems like the
> > synth-only channel changes are resulting in poor connection quality.
> > Maybe that patch needs to be reverted?
> >
> > Thanks,
> > Seth
> >
> >
>
> http://www.kernel.org/pub/linux/kernel/people/mickflemm/01-fast-chan-switch-modparm

That looks like it should do the trick. I'll request some testing with
it and let you know how it goes. Thanks!

2011-05-19 21:28:31

by Seth Forshee

Subject: Re: ath5k regression associating with APs in 2.6.38

On Tue, May 17, 2011 at 01:50:32PM -0500, Seth Forshee wrote:
> On Tue, May 17, 2011 at 08:14:34PM +0300, Nick Kossifidis wrote:
> > 2011/5/17 Seth Forshee <[email protected]>:
> > > On Mon, May 09, 2011 at 09:02:30AM +0200, Seth Forshee wrote:
> > >> On Thu, May 05, 2011 at 05:30:42PM +0300, Nick Kossifidis wrote:
> > >> > Hmm I don't see any errors from reset/phy code, can you disable
> > >> > Network Manager/wpa-supplicant and test connection on an open network
> > >> > using iw ? It 'll give us a better picture...
> > >> >
> > >> > If iw doesn't return any scan results we are probably hitting a PHY/RF
> > >> > error specific to your device (not all vendors follow the reference
> > >> > design). Maybe we should follow a blacklist/whitelist approach for
> > >> > this feature.
> > >>
> > >> I got the results back from my tester. He was able to get scan results,
> > >> but it took multiple tries and the direct probe failures appear in the
> > >> log. He didn't enable ATH5K_DEBUG_RESET this time; let me know if you
> > >> need that and I'll request he retest with the extra debug logs enabled.
> > >
> > > I got some more feedback. Most of the time iw does not get scan results,
> > > but even when it does connecting to the AP isn't always successful. The
> > > tester did note that he doesn't seem to have any trouble if his machine
> > > is within a few feet of his AP. Let me know if you'd like something else
> > > tested.
> > >
> > > I noticed that bugzilla #31922 (ath5k: Decreased throughput in IBSS or
> > > 802.11n mode) is also fixed by reverting 8aec7af9. It seems like the
> > > synth-only channel changes are resulting in poor connection quality.
> > > Maybe that patch needs to be reverted?
> > >
> > > Thanks,
> > > Seth
> > >
> > >
> >
> > http://www.kernel.org/pub/linux/kernel/people/mickflemm/01-fast-chan-switch-modparm
>
> That looks like it should do the trick. I'll request some testing with
> it and let you know how it goes. Thanks!

I've received feedback from a number of testers that the patch fixes the
wireless problems they've been seeing since upgrading to 2.6.38, so this
fix looks good from my perspective.

Thanks,
Seth

2011-05-31 17:31:31

by Felix Fietkau

Subject: Re: [ath5k-devel] ath5k regression associating with APs in 2.6.38

On 2011-05-17 7:14 PM, Nick Kossifidis wrote:
> 2011/5/17 Seth Forshee<[email protected]>:
>> On Mon, May 09, 2011 at 09:02:30AM +0200, Seth Forshee wrote:
>>> On Thu, May 05, 2011 at 05:30:42PM +0300, Nick Kossifidis wrote:
>>> > Hmm I don't see any errors from reset/phy code, can you disable
>>> > Network Manager/wpa-supplicant and test connection on an open network
>>> > using iw ? It 'll give us a better picture...
>>> >
>>> > If iw doesn't return any scan results we are probably hitting a PHY/RF
>>> > error specific to your device (not all vendors follow the reference
>>> > design). Maybe we should follow a blacklist/whitelist approach for
>>> > this feature.
>>>
>>> I got the results back from my tester. He was able to get scan results,
>>> but it took multiple tries and the direct probe failures appear in the
>>> log. He didn't enable ATH5K_DEBUG_RESET this time; let me know if you
>>> need that and I'll request he retest with the extra debug logs enabled.
>>
>> I got some more feedback. Most of the time iw does not get scan results,
>> but even when it does connecting to the AP isn't always successful. The
>> tester did note that he doesn't seem to have any trouble if his machine
>> is within a few feet of his AP. Let me know if you'd like something else
>> tested.
>>
>> I noticed that bugzilla #31922 (ath5k: Decreased throughput in IBSS or
>> 802.11n mode) is also fixed by reverting 8aec7af9. It seems like the
>> synth-only channel changes are resulting in poor connection quality.
>> Maybe that patch needs to be reverted?
>>
>> Thanks,
>> Seth
>>
>>
>
> http://www.kernel.org/pub/linux/kernel/people/mickflemm/01-fast-chan-switch-modparm
Disabling fast channel change also fixed a reproducible crash on
Broadcom based MIPS boards with some cards (AR2413, I think).

- Felix