* ath5k regression associating with APs in 2.6.38
@ 2011-05-04 15:38 Seth Forshee
2011-05-04 17:27 ` John W. Linville
[not found] ` <20110504172716.GC18541@tuxdriver.com>
0 siblings, 2 replies; 15+ messages in thread
From: Seth Forshee @ 2011-05-04 15:38 UTC (permalink / raw)
To: Jiri Slaby, Nick Kossifidis, Luis R. Rodriguez, Bob Copeland
Cc: John W. Linville, linux-wireless, ath5k-devel, netdev,
linux-kernel
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.
^ permalink raw reply [flat|nested] 15+ messages in thread* Re: ath5k regression associating with APs in 2.6.38 2011-05-04 15:38 ath5k regression associating with APs in 2.6.38 Seth Forshee @ 2011-05-04 17:27 ` John W. Linville [not found] ` <20110504172716.GC18541@tuxdriver.com> 1 sibling, 0 replies; 15+ messages in thread From: John W. Linville @ 2011-05-04 17:27 UTC (permalink / raw) To: Jiri Slaby, Nick Kossifidis, Luis R. Rodriguez, Bob Copeland, linux-wireless 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 linville@tuxdriver.com might be all we have. Be ready. ^ permalink raw reply [flat|nested] 15+ messages in thread
[parent not found: <20110504172716.GC18541@tuxdriver.com>]
* Re: ath5k regression associating with APs in 2.6.38 [not found] ` <20110504172716.GC18541@tuxdriver.com> @ 2011-05-04 19:26 ` Seth Forshee 2011-05-04 20:09 ` Nick Kossifidis [not found] ` <BANLkTimEmBRyxbZgffJMrH4TTc4f6peuTg@mail.gmail.com> 0 siblings, 2 replies; 15+ messages in thread From: Seth Forshee @ 2011-05-04 19:26 UTC (permalink / raw) To: John W. Linville Cc: Jiri Slaby, Nick Kossifidis, Luis R. Rodriguez, Bob Copeland, linux-wireless, ath5k-devel, netdev, linux-kernel 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 ^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: ath5k regression associating with APs in 2.6.38 2011-05-04 19:26 ` Seth Forshee @ 2011-05-04 20:09 ` Nick Kossifidis [not found] ` <BANLkTimEmBRyxbZgffJMrH4TTc4f6peuTg@mail.gmail.com> 1 sibling, 0 replies; 15+ messages in thread From: Nick Kossifidis @ 2011-05-04 20:09 UTC (permalink / raw) To: John W. Linville, Jiri Slaby, Nick Kossifidis, Luis R. Rodriguez, Bob Copeland 2011/5/4 Seth Forshee <seth.forshee@canonical.com>: > 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 ^ permalink raw reply [flat|nested] 15+ messages in thread
[parent not found: <BANLkTimEmBRyxbZgffJMrH4TTc4f6peuTg@mail.gmail.com>]
* Re: ath5k regression associating with APs in 2.6.38 [not found] ` <BANLkTimEmBRyxbZgffJMrH4TTc4f6peuTg@mail.gmail.com> @ 2011-05-05 13:52 ` Seth Forshee 2011-05-05 14:30 ` Nick Kossifidis [not found] ` <BANLkTinkiTQU2k7vBEc0JPGa01AUVCvp2Q@mail.gmail.com> 0 siblings, 2 replies; 15+ messages in thread From: Seth Forshee @ 2011-05-05 13:52 UTC (permalink / raw) To: Nick Kossifidis, John W. Linville Cc: Jiri Slaby, Luis R. Rodriguez, Bob Copeland, linux-wireless, ath5k-devel, netdev, linux-kernel On Wed, May 04, 2011 at 11:09:03PM +0300, Nick Kossifidis wrote: > 2011/5/4 Seth Forshee <seth.forshee@canonical.com>: > > 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) ^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: ath5k regression associating with APs in 2.6.38 2011-05-05 13:52 ` Seth Forshee @ 2011-05-05 14:30 ` Nick Kossifidis [not found] ` <BANLkTinkiTQU2k7vBEc0JPGa01AUVCvp2Q@mail.gmail.com> 1 sibling, 0 replies; 15+ messages in thread From: Nick Kossifidis @ 2011-05-05 14:30 UTC (permalink / raw) To: Nick Kossifidis, John W. Linville, Jiri Slaby, Luis R. Rodriguez, Bob Copeland 2011/5/5 Seth Forshee <seth.forshee@canonical.com>: > On Wed, May 04, 2011 at 11:09:03PM +0300, Nick Kossifidis wrote: >> 2011/5/4 Seth Forshee <seth.forshee@canonical.com>: >> > 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 ^ permalink raw reply [flat|nested] 15+ messages in thread
[parent not found: <BANLkTinkiTQU2k7vBEc0JPGa01AUVCvp2Q@mail.gmail.com>]
* Re: ath5k regression associating with APs in 2.6.38 [not found] ` <BANLkTinkiTQU2k7vBEc0JPGa01AUVCvp2Q@mail.gmail.com> @ 2011-05-05 14:54 ` Seth Forshee 2011-05-05 15:01 ` Justin P. Mattock 2011-05-09 7:02 ` Seth Forshee 2 siblings, 0 replies; 15+ messages in thread From: Seth Forshee @ 2011-05-05 14:54 UTC (permalink / raw) To: Nick Kossifidis Cc: John W. Linville, Jiri Slaby, Luis R. Rodriguez, Bob Copeland, linux-wireless, ath5k-devel, netdev, linux-kernel 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 ^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: ath5k regression associating with APs in 2.6.38 [not found] ` <BANLkTinkiTQU2k7vBEc0JPGa01AUVCvp2Q@mail.gmail.com> 2011-05-05 14:54 ` Seth Forshee @ 2011-05-05 15:01 ` Justin P. Mattock 2011-05-05 15:15 ` Nick Kossifidis 2011-05-09 7:02 ` Seth Forshee 2 siblings, 1 reply; 15+ messages in thread From: Justin P. Mattock @ 2011-05-05 15:01 UTC (permalink / raw) To: Nick Kossifidis Cc: John W. Linville, Jiri Slaby, Luis R. Rodriguez, Bob Copeland, linux-wireless, ath5k-devel, netdev, linux-kernel On 05/05/2011 07:30 AM, Nick Kossifidis wrote: > 2011/5/5 Seth Forshee<seth.forshee@canonical.com>: >> On Wed, May 04, 2011 at 11:09:03PM +0300, Nick Kossifidis wrote: >>> 2011/5/4 Seth Forshee<seth.forshee@canonical.com>: >>>> 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 ^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: ath5k regression associating with APs in 2.6.38 2011-05-05 15:01 ` Justin P. Mattock @ 2011-05-05 15:15 ` Nick Kossifidis 0 siblings, 0 replies; 15+ messages in thread From: Nick Kossifidis @ 2011-05-05 15:15 UTC (permalink / raw) To: Justin P. Mattock Cc: John W. Linville, Jiri Slaby, Luis R. Rodriguez, Bob Copeland, linux-wireless, ath5k-devel, netdev, linux-kernel 2011/5/5 Justin P. Mattock <justinmattock@gmail.com>: > On 05/05/2011 07:30 AM, Nick Kossifidis wrote: >> >> 2011/5/5 Seth Forshee<seth.forshee@canonical.com>: >>> >>> On Wed, May 04, 2011 at 11:09:03PM +0300, Nick Kossifidis wrote: >>>> >>>> 2011/5/4 Seth Forshee<seth.forshee@canonical.com>: >>>>> >>>>> 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 ^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: ath5k regression associating with APs in 2.6.38 [not found] ` <BANLkTinkiTQU2k7vBEc0JPGa01AUVCvp2Q@mail.gmail.com> 2011-05-05 14:54 ` Seth Forshee 2011-05-05 15:01 ` Justin P. Mattock @ 2011-05-09 7:02 ` Seth Forshee 2011-05-17 16:57 ` Seth Forshee 2 siblings, 1 reply; 15+ messages in thread From: Seth Forshee @ 2011-05-09 7:02 UTC (permalink / raw) To: Nick Kossifidis Cc: John W. Linville, Jiri Slaby, Luis R. Rodriguez, Bob Copeland, linux-wireless, ath5k-devel, netdev, linux-kernel 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) ^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: ath5k regression associating with APs in 2.6.38 2011-05-09 7:02 ` Seth Forshee @ 2011-05-17 16:57 ` Seth Forshee 2011-05-17 17:14 ` Nick Kossifidis [not found] ` <BANLkTi=8ZRUVWn3FLAMtPh=4yY1F0k6i9w@mail.gmail.com> 0 siblings, 2 replies; 15+ messages in thread From: Seth Forshee @ 2011-05-17 16:57 UTC (permalink / raw) To: Nick Kossifidis Cc: John W. Linville, Jiri Slaby, Luis R. Rodriguez, Bob Copeland, linux-wireless, ath5k-devel, netdev, linux-kernel 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 ^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: ath5k regression associating with APs in 2.6.38 2011-05-17 16:57 ` Seth Forshee @ 2011-05-17 17:14 ` Nick Kossifidis [not found] ` <BANLkTi=8ZRUVWn3FLAMtPh=4yY1F0k6i9w@mail.gmail.com> 1 sibling, 0 replies; 15+ messages in thread From: Nick Kossifidis @ 2011-05-17 17:14 UTC (permalink / raw) To: Nick Kossifidis, John W. Linville, Jiri Slaby, Luis R. Rodriguez, Bob Copeland 2011/5/17 Seth Forshee <seth.forshee@canonical.com>: > 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 ^ permalink raw reply [flat|nested] 15+ messages in thread
[parent not found: <BANLkTi=8ZRUVWn3FLAMtPh=4yY1F0k6i9w@mail.gmail.com>]
* Re: ath5k regression associating with APs in 2.6.38 [not found] ` <BANLkTi=8ZRUVWn3FLAMtPh=4yY1F0k6i9w@mail.gmail.com> @ 2011-05-17 18:50 ` Seth Forshee 2011-05-19 21:28 ` Seth Forshee 2011-05-31 17:31 ` [ath5k-devel] " Felix Fietkau 1 sibling, 1 reply; 15+ messages in thread From: Seth Forshee @ 2011-05-17 18:50 UTC (permalink / raw) To: Nick Kossifidis Cc: John W. Linville, Jiri Slaby, Luis R. Rodriguez, Bob Copeland, linux-wireless, ath5k-devel, netdev, linux-kernel On Tue, May 17, 2011 at 08:14:34PM +0300, Nick Kossifidis wrote: > 2011/5/17 Seth Forshee <seth.forshee@canonical.com>: > > 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! ^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: ath5k regression associating with APs in 2.6.38 2011-05-17 18:50 ` Seth Forshee @ 2011-05-19 21:28 ` Seth Forshee 0 siblings, 0 replies; 15+ messages in thread From: Seth Forshee @ 2011-05-19 21:28 UTC (permalink / raw) To: Nick Kossifidis Cc: John W. Linville, Jiri Slaby, Luis R. Rodriguez, Bob Copeland, linux-wireless, ath5k-devel, netdev, linux-kernel 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 <seth.forshee@canonical.com>: > > > 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 ^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: [ath5k-devel] ath5k regression associating with APs in 2.6.38 [not found] ` <BANLkTi=8ZRUVWn3FLAMtPh=4yY1F0k6i9w@mail.gmail.com> 2011-05-17 18:50 ` Seth Forshee @ 2011-05-31 17:31 ` Felix Fietkau 1 sibling, 0 replies; 15+ messages in thread From: Felix Fietkau @ 2011-05-31 17:31 UTC (permalink / raw) To: Nick Kossifidis Cc: John W. Linville, Jiri Slaby, Luis R. Rodriguez, Bob Copeland, linux-wireless, ath5k-devel, netdev, linux-kernel On 2011-05-17 7:14 PM, Nick Kossifidis wrote: > 2011/5/17 Seth Forshee<seth.forshee@canonical.com>: >> 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 ^ permalink raw reply [flat|nested] 15+ messages in thread
end of thread, other threads:[~2011-05-31 17:31 UTC | newest]
Thread overview: 15+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2011-05-04 15:38 ath5k regression associating with APs in 2.6.38 Seth Forshee
2011-05-04 17:27 ` John W. Linville
[not found] ` <20110504172716.GC18541@tuxdriver.com>
2011-05-04 19:26 ` Seth Forshee
2011-05-04 20:09 ` Nick Kossifidis
[not found] ` <BANLkTimEmBRyxbZgffJMrH4TTc4f6peuTg@mail.gmail.com>
2011-05-05 13:52 ` Seth Forshee
2011-05-05 14:30 ` Nick Kossifidis
[not found] ` <BANLkTinkiTQU2k7vBEc0JPGa01AUVCvp2Q@mail.gmail.com>
2011-05-05 14:54 ` Seth Forshee
2011-05-05 15:01 ` Justin P. Mattock
2011-05-05 15:15 ` Nick Kossifidis
2011-05-09 7:02 ` Seth Forshee
2011-05-17 16:57 ` Seth Forshee
2011-05-17 17:14 ` Nick Kossifidis
[not found] ` <BANLkTi=8ZRUVWn3FLAMtPh=4yY1F0k6i9w@mail.gmail.com>
2011-05-17 18:50 ` Seth Forshee
2011-05-19 21:28 ` Seth Forshee
2011-05-31 17:31 ` [ath5k-devel] " Felix Fietkau
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).