2009-08-07 21:51:44

by Johannes Stezenbach

[permalink] [raw]
Subject: 2.6.31-rc5 regression: ath5k broken after suspend-to-ram

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


2009-08-10 12:52:41

by Johannes Stezenbach

[permalink] [raw]
Subject: Re: 2.6.31-rc5 regression: ath5k broken after suspend-to-ram

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

2009-08-09 09:34:35

by Johannes Stezenbach

[permalink] [raw]
Subject: Re: 2.6.31-rc5 regression: ath5k broken after suspend-to-ram

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

2009-08-09 16:06:03

by Bob Copeland

[permalink] [raw]
Subject: Re: 2.6.31-rc5 regression: ath5k broken after suspend-to-ram

On Fri, Aug 7, 2009 at 5:51 PM, Johannes Stezenbach<[email protected]> 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 %% http://www.bobcopeland.com

2009-08-09 17:04:02

by Johannes Stezenbach

[permalink] [raw]
Subject: Re: 2.6.31-rc5 regression: ath5k broken after suspend-to-ram

On Sun, Aug 09, 2009 at 12:06:03PM -0400, Bob Copeland wrote:
> On Fri, Aug 7, 2009 at 5:51 PM, Johannes Stezenbach<[email protected]> 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