2.6.31-rc5 regression: ath5k broken after suspend-to-ram

2.6.31-rc5 regression: ath5k broken after suspend-to-ram

[Johannes Stezenbach]

Hi,

On my old Thinkpad T42p running linux-2.6.31-rc5-246-g90bc1a6,
after suspend-to-RAM ath5k cannot associate to an AP using WPA
anymore.  It worked with kernel 2.6.29.1.  I'm not using network
manager etc. but connect manually with "ifup wlan0=foo" with the
following in /etc/network/interfaces:

iface foo inet dhcp
        #wpa-driver nl80211
        wpa-driver wext
        wpa-key-mgmt WPA-PSK
        wpa-ssid some string
        wpa-psk some key

If I use nl80211 the second ifup fails with
"SIOCSIFFLAGS: Input/output error" messages and the follwing
is in dmesg:

   ath5k phy0: failed to wakeup the MAC Chip
   ath5k phy0: can't reset hardware (-5)

With wext it does not give these errors, but the connection
is unstable after the second ifup.


# lspci -s 02:02.0 -v 
02:02.0 Ethernet controller: Atheros Communications Inc. AR5212 802.11abg NIC (rev 01)
	Subsystem: IBM Device 057e
	Flags: bus master, medium devsel, latency 168, IRQ 11
	Memory at c0210000 (32-bit, non-prefetchable) [size=64K]
	Capabilities: [44] Power Management version 2
	Kernel driver in use: ath5k
	Kernel modules: ath5k

dmesg after boot:

   cfg80211: Using static regulatory domain info
   cfg80211: Regulatory domain: US
           (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
           (2402000 KHz - 2472000 KHz @ 40000 KHz), (600 mBi, 2700 mBm)
           (5170000 KHz - 5190000 KHz @ 40000 KHz), (600 mBi, 2300 mBm)
           (5190000 KHz - 5210000 KHz @ 40000 KHz), (600 mBi, 2300 mBm)
           (5210000 KHz - 5230000 KHz @ 40000 KHz), (600 mBi, 2300 mBm)
           (5230000 KHz - 5330000 KHz @ 40000 KHz), (600 mBi, 2300 mBm)
           (5735000 KHz - 5835000 KHz @ 40000 KHz), (600 mBi, 3000 mBm)
   cfg80211: Calling CRDA for country: US
   ath5k 0000:02:02.0: PCI INT A -> Link[LNKC] -> GSI 11 (level, low) -> IRQ 11
   ath5k 0000:02:02.0: registered as 'phy0'
   ath: EEPROM regdomain: 0x62
   ath: EEPROM indicates we should expect a direct regpair map
   ath: Country alpha2 being used: 00
   ath: Regpair used: 0x62
   phy0: Selected rate control algorithm 'minstrel'
   Registered led device: ath5k-phy0::rx
   Registered led device: ath5k-phy0::tx
   ath5k phy0: Atheros AR5213A chip found (MAC: 0x59, PHY: 0x43)
   ath5k phy0: RF5112B multiband radio found (0x36)
   
   
syslog after ifup when it works:
   
   Aug  7 20:13:27 void wpa_supplicant[9932]: Failed to initiate AP scan.
   Aug  7 20:13:28 void wpa_supplicant[9932]: CTRL-EVENT-SCAN-RESULTS 
   Aug  7 20:13:28 void wpa_supplicant[9932]: Trying to associate with 00:00:00:00:00:00 (SSID='...' freq=2412 MHz)
   Aug  7 20:13:28 void wpa_supplicant[9932]: Association request to the driver failed
   Aug  7 20:13:28 void kernel: wlan0: authenticate with AP 00:00:00:00:00:00
   Aug  7 20:13:28 void kernel: wlan0: authenticated
   Aug  7 20:13:28 void kernel: wlan0: associate with AP 00:00:00:00:00:00
   Aug  7 20:13:28 void kernel: wlan0: RX AssocResp from 00:00:00:00:00:00 (capab=0x411 status=0 aid=1)
   Aug  7 20:13:28 void kernel: wlan0: associated
   Aug  7 20:13:28 void wpa_supplicant[9932]: Associated with 00:00:00:00:00:00
   Aug  7 20:13:28 void wpa_supplicant[9932]: WPA: Key negotiation completed with 00:00:00:00:00:00 [PTK=CCMP GTK=TKIP]
   Aug  7 20:13:28 void wpa_supplicant[9932]: CTRL-EVENT-CONNECTED - Connection to 00:00:00:00:00:00 completed (auth) [id=0 id_str=]
   
   
syslog after ifdown -> suspend -> resume -> ifup
   
   Aug  7 23:10:02 void wpa_supplicant[16215]: CTRL-EVENT-SCAN-RESULTS 
   Aug  7 23:10:02 void wpa_supplicant[16215]: Trying to associate with 00:00:00:00:00:00 (SSID='...' freq=2412 MHz)
   Aug  7 23:10:02 void wpa_supplicant[16215]: Association request to the driver failed
   Aug  7 23:10:07 void wpa_supplicant[16215]: Authentication with 00:00:00:00:00:00 timed out.
   Aug  7 23:10:07 void wpa_supplicant[16215]: Failed to initiate AP scan.
   Aug  7 23:10:08 void kernel: wlan0: authenticate with AP 00:00:00:00:00:00
   Aug  7 23:10:08 void kernel: wlan0: authenticated
   Aug  7 23:10:08 void kernel: wlan0: associate with AP 00:00:00:00:00:00
   Aug  7 23:10:08 void kernel: wlan0: RX AssocResp from 00:00:00:00:00:00 (capab=0x411 status=0 aid=1)
   Aug  7 23:10:08 void kernel: wlan0: associated
   Aug  7 23:10:08 void wpa_supplicant[16215]: Associated with 00:00:00:00:00:00
   Aug  7 23:10:08 void wpa_supplicant[16215]: WPA: Key negotiation completed with 00:00:00:00:00:00 [PTK=CCMP GTK=TKIP]
   Aug  7 23:10:08 void wpa_supplicant[16215]: CTRL-EVENT-CONNECTED - Connection to 00:00:00:00:00:00 completed (auth) [id=0 id_str=]
   Aug  7 23:10:12 void wpa_supplicant[16215]: CTRL-EVENT-SCAN-RESULTS 
   Aug  7 23:10:12 void wpa_supplicant[16215]: Trying to associate with 00:00:00:00:00:00 (SSID='...' freq=2412 MHz)
   Aug  7 23:10:12 void wpa_supplicant[16215]: Association request to the driver failed
   Aug  7 23:10:12 void wpa_supplicant[16215]: CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys
   Aug  7 23:10:17 void wpa_supplicant[16215]: Authentication with 00:00:00:00:00:00 timed out.
   (etc. -- repeats)
   
(The difference is the "Authentication with 00:00:00:00:00:00 timed out.")

   
To fix this I need to unload and reload the ath5k module
(with modprobe ath5k -r, so it actually unloads ath, mac80211
and cfg80211, too).  When I reload ath5k, it often fails with:
   
   ath5k 0000:02:02.0: PCI INT A -> Link[LNKC] -> GSI 11 (level, low) -> IRQ 11
   ath5k 0000:02:02.0: registered as 'phy0'
   ath5k phy0: failed to wakeup the MAC Chip
   ath5k 0000:02:02.0: PCI INT A disabled
   ath5k: probe of 0000:02:02.0 failed with error -5


Sometimes I can fix this by unloading + reloading again,
but often I need to unload, suspend, resume, reload to
get it back in a working state.

During resume the following is logged:

   ath5k 0000:02:02.0: restoring config space at offset 0x3 (was 0x5008, writing 0xa808)
   pm_op(): pci_pm_resume+0x0/0x79 returns -16
   PM: Device 0000:00:00.0 failed to resume: error -16

Not sure if this is causing the problem?

In case it matters:
  CONFIG_MAC80211_DEFAULT_PS=y
  CONFIG_MAC80211_DEFAULT_PS_VALUE=1


Thanks,
Johannes

Re: 2.6.31-rc5 regression: ath5k broken after suspend-to-ram

[Johannes Stezenbach]

On Fri, Aug 07, 2009 at 11:51:55PM +0200, Johannes Stezenbach wrote:
> 
> On my old Thinkpad T42p running linux-2.6.31-rc5-246-g90bc1a6,
> after suspend-to-RAM ath5k cannot associate to an AP using WPA
> anymore.  It worked with kernel 2.6.29.1.

FWFI, it also works with 2.6.30.  (I could not initialliy test
with 2.6.30 because suspend/resume is broken in that kernel,
but it can be fixed up with a workaround patch.)


Johannes

Re: 2.6.31-rc5 regression: ath5k broken after suspend-to-ram

[Bob Copeland]

On Fri, Aug 7, 2009 at 5:51 PM, Johannes Stezenbach<js@sig21.net> wrote:
> Hi,

Hi!

> If I use nl80211 the second ifup fails with
> "SIOCSIFFLAGS: Input/output error" messages and the follwing
> is in dmesg:
>
>   ath5k phy0: failed to wakeup the MAC Chip
>   ath5k phy0: can't reset hardware (-5)

Ok, does this patch help the above?

http://patchwork.kernel.org/patch/38550/

>   Aug  7 20:13:28 void wpa_supplicant[9932]: Trying to associate with 00:00:00:00:00:00 (SSID='...' freq=2412 MHz)

I assume in all cases you have elided the mac addresses and they
are the same in all of the examples?  (You can keep the first three
octets in the future, they are just vendor information.)

>   Aug  7 23:10:08 void kernel: wlan0: RX AssocResp from 00:00:00:00:00:00 (capab=0x411 status=0 aid=1)
>   Aug  7 23:10:08 void kernel: wlan0: associated
>   Aug  7 23:10:08 void wpa_supplicant[16215]: Associated with 00:00:00:00:00:00
>   Aug  7 23:10:08 void wpa_supplicant[16215]: WPA: Key negotiation completed with 00:00:00:00:00:00 [PTK=CCMP GTK=TKIP]
>   Aug  7 23:10:08 void wpa_supplicant[16215]: CTRL-EVENT-CONNECTED - Connection to 00:00:00:00:00:00 completed (auth) [id=0 id_str=]
>   Aug  7 23:10:12 void wpa_supplicant[16215]: CTRL-EVENT-SCAN-RESULTS
>   Aug  7 23:10:12 void wpa_supplicant[16215]: Trying to associate with 00:00:00:00:00:00 (SSID='...' freq=2412 MHz)

Hmm so it completed association... then 4 seconds later, got some
scan results and tried again.  Odd.

> During resume the following is logged:
>
>   ath5k 0000:02:02.0: restoring config space at offset 0x3 (was 0x5008, writing 0xa808)
>   pm_op(): pci_pm_resume+0x0/0x79 returns -16
>   PM: Device 0000:00:00.0 failed to resume: error -16
>
> Not sure if this is causing the problem?

-EBUSY... not sure.

> In case it matters:
>  CONFIG_MAC80211_DEFAULT_PS=y
>  CONFIG_MAC80211_DEFAULT_PS_VALUE=1

That's for 802.11 power saving which ath5k doesn't do yet, so it
doesn't matter here.

Ok thanks for the very detailed report, I'll take a look.  My
hardware suspends/resumes under 2.6.31, but I do have a few
differences in my setup compared to yours.

-- 
Bob Copeland %% www.bobcopeland.com

Re: 2.6.31-rc5 regression: ath5k broken after suspend-to-ram

[Johannes Stezenbach]

On Sun, Aug 09, 2009 at 12:06:03PM -0400, Bob Copeland wrote:
> On Fri, Aug 7, 2009 at 5:51 PM, Johannes Stezenbach<js@sig21.net> wrote:
> 
> > If I use nl80211 the second ifup fails with
> > "SIOCSIFFLAGS: Input/output error" messages and the follwing
> > is in dmesg:
> >
> >   ath5k phy0: failed to wakeup the MAC Chip
> >   ath5k phy0: can't reset hardware (-5)
> 
> Ok, does this patch help the above?
> 
> http://patchwork.kernel.org/patch/38550/

Yes, it helps a lot!  The above wakeup error is gone,
and as a result I can switch to use the wpa_supplicant
nl80211 driver.  With the nl80211 driver everything works.

However, with the wpa_supplicant wext driver the issue remains
that only the frst ifup after module load works, the second
ifup shows the association problem most of the time (but not always).
So this turns out to be a mix of two problems, with the wext one
not having anything to do with suspend/resume.

If you want me to test something wext related, let me know.
Otherwise I'm fine with using nl80211.


Thanks,
Johannes

Re: 2.6.31-rc5 regression: ath5k broken after suspend-to-ram

[Johannes Stezenbach]

On Sun, Aug 09, 2009 at 07:04:01PM +0200, Johannes Stezenbach wrote:
> With the nl80211 driver everything works.

Although it might not be that important I though I should
report the following observations when using
wpa_supplicant with the nl80211 driver onn ath5k:

1. wpa_supplicant complains about "Could not configure driver
   to use managed mode" and "Failed to set interface wlan0 mode"
   (but it works anyway). This is Debian sid wpasupplicant_0.6.9-3.
   The error is from wpasupplicant-0.6.9/src/drivers/driver_nl80211.c
   where is sends the NL80211_CMD_SET_INTERFACE msg.

2. The first ifup after boot or ath5k module reload
   (modprobe ath5k -r; modprobe ath5k) is much faster
   than the second and subsequent ifup.  The first time
   it takes around 7 secs until "wpa_cli status" reports
   wpa_state=COMPLETED, the second time it takes around 25 secs.
 

Thanks
Johannes