ath5k: invalid hw_rix with 64 stations.

DISCUSSION Ben Greear 2 participants 6 messages Dec 2, 2010

Share & tools

Ben Greear

author

2010-12-02 00:49 UTC #0 lore raw

We were testing with 64 virtual stations running WPA, with a single instance of supplicant controlling all interfaces and the scan-sharing enabled. It was running clean w/out encryption (and w/out supplicant).

We see a large number of these types of warnings. We had a proprietary module loaded, but it was not in active use. We're going to reproduce without it, but in the meantime, here is a representative trace:

Dec  1 16:35:23 localhost kernel: ------------[ cut here ]------------
Dec  1 16:35:23 localhost kernel: WARNING: at /home/greearb/git/linux.wireless-testing-ct/drivers/net/wireless/ath/ath5k/base.c:620 ath5k_hw_to_driver_rix+0x5b/0x5f [ath5k]()
Dec  1 16:35:23 localhost kernel: Hardware name:
Dec  1 16:35:23 localhost kernel: invalid hw_rix: 1b
Dec  1 16:35:23 localhost kernel: Modules linked in: 8021q garp stp llc fuse michael_mic macvlan wanlink(P) pktgen w83627hf hwmon_vid hwmon nfs lockd fscache nfs_acl auth_rpcgss sunrpc ipv6 dm_multipath uinput arc4 ecb ath5k ath mac80211 cfg80211 e1000e i2c_i801 e100 output iTCO_wdt iTCO_vendor_support mii i2c_core serio_raw pcspkr ata_generic pata_acpi [last unloaded: ipt_addrtype]
Dec  1 16:35:23 localhost kernel: Pid: 2298, comm: clock-applet Tainted: P            2.6.37-rc4-wl+ #9
Dec  1 16:35:23 localhost kernel: Call Trace:
Dec  1 16:35:23 localhost kernel: [<8043144d>] warn_slowpath_common+0x77/0x8c
Dec  1 16:35:23 localhost kernel: [<f8663994>] ? ath5k_hw_to_driver_rix+0x5b/0x5f [ath5k]
Dec  1 16:35:23 localhost kernel: [<f8663994>] ? ath5k_hw_to_driver_rix+0x5b/0x5f [ath5k]
Dec  1 16:35:23 localhost kernel: [<804314de>] warn_slowpath_fmt+0x2e/0x30
Dec  1 16:35:23 localhost kernel: [<f8663994>] ath5k_hw_to_driver_rix+0x5b/0x5f [ath5k]
Dec  1 16:35:23 localhost kernel: [<f8663ba5>] ath5k_tasklet_tx+0x1ab/0x2f0 [ath5k]
Dec  1 16:35:23 localhost kernel: [<80435948>] tasklet_action+0x78/0xc1
Dec  1 16:35:23 localhost kernel: [<80436034>] __do_softirq+0x75/0x121
Dec  1 16:35:23 localhost kernel: [<80435fbf>] ? __do_softirq+0x0/0x121
Dec  1 16:35:23 localhost kernel: <IRQ>  [<80435f0c>] ? irq_exit+0x29/0x5d
Dec  1 16:35:23 localhost kernel: [<804042c9>] ? do_IRQ+0x8e/0xa2
Dec  1 16:35:23 localhost kernel: [<80403729>] ? common_interrupt+0x29/0x30
Dec  1 16:35:23 localhost kernel: ---[ end trace 5cdceca81890f6e3 ]---

Thanks,
Ben

Signature · 2 lines

Ben Greear <[email protected]>
Candela Technologies Inc  http://www.candelatech.com

Ben Greear

author

2010-12-02 00:54 UTC #1 lore raw

Quoted 8 lines · Ben Greear

We were testing with 64 virtual stations running WPA, with a single instance of supplicant controlling all interfaces and the scan-sharing enabled. It was running clean w/out encryption (and w/out supplicant).
We see a large number of these types of warnings. We had a proprietary module loaded, but it was not in active use. We're going to reproduce without it, but in the meantime, here is a representative trace:

Here's another one from a non-tainted kernel. Seems this is trivial to reproduce.

------------[ cut here ]------------
WARNING: at /home/greearb/git/linux.wireless-testing-ct/drivers/net/wireless/ath/ath5k/base.c:620 ath5k_hw_to_driver_rix+0x5b/0x5f [ath5k]()
Hardware name:
invalid hw_rix: 1b
Modules linked in: 8021q garp stp llc fuse michael_mic macvlan pktgen w83627hf hwmon_vid hwmon nfs lockd fscache nfs_acl auth_rpcgss sunrpc ipv6 dm_multipath uinput arc4 ecb ath5k ath mac80211 cfg80211 e1000e i2c_i801 e100 i2c_core output serio_raw pcspkr mii iTCO_wdt iTCO_vendor_support ata_generic pata_acpi [last unloaded: ipt_addrtype]
Pid: 1225, comm: rsyslogd Tainted: G        W   2.6.37-rc4-wl+ #9
Call Trace:
 [<8043144d>] warn_slowpath_common+0x77/0x8c
 [<f8663994>] ? ath5k_hw_to_driver_rix+0x5b/0x5f [ath5k]
 [<f8663994>] ? ath5k_hw_to_driver_rix+0x5b/0x5f [ath5k]
 [<804314de>] warn_slowpath_fmt+0x2e/0x30
 [<f8663994>] ath5k_hw_to_driver_rix+0x5b/0x5f [ath5k]
 [<f8663ba5>] ath5k_tasklet_tx+0x1ab/0x2f0 [ath5k]
 [<80435948>] tasklet_action+0x78/0xc1
 [<80436034>] __do_softirq+0x75/0x121
 [<80435fbf>] ? __do_softirq+0x0/0x121
 <IRQ>  [<80435f0c>] ? irq_exit+0x29/0x5d
 [<804042c9>] ? do_IRQ+0x8e/0xa2
 [<80403729>] ? common_interrupt+0x29/0x30
 [<8044007b>] ? __queue_work+0x138/0x1af
 [<804b8e53>] ? mntput+0x0/0x15
 [<804b8fb1>] ? path_put+0x15/0x18
 [<8046b551>] ? audit_free_names+0x40/0x59
 [<8046b6fe>] ? audit_syscall_exit+0x91/0x10f
 [<804031d0>] ? sysexit_audit+0x24/0x44
---[ end trace e87e98eb2549568d ]---

Thanks,
Ben

Signature · 2 lines

Ben Greear <[email protected]>
Candela Technologies Inc  http://www.candelatech.com

Nick Kossifidis

2010-12-02 04:19 UTC #2 lore raw

2010/12/2 Ben Greear <[email protected]>:

Quoted 47 lines · Ben Greear

Quoted 9 lines
We were testing with 64 virtual stations running WPA, with a single instance of supplicant controlling all interfaces and the scan-sharing enabled. It was running clean w/out encryption (and w/out supplicant).
We see a large number of these types of warnings. We had a proprietary module loaded, but it was not in active use. We're going to reproduce without it, but in the meantime, here is a representative trace:
Here's another one from a non-tainted kernel. Seems this is trivial to reproduce.
------------[ cut here ]------------
WARNING: at
/home/greearb/git/linux.wireless-testing-ct/drivers/net/wireless/ath/ath5k/base.c:620 ath5k_hw_to_driver_rix+0x5b/0x5f [ath5k]()
Hardware name:
invalid hw_rix: 1b
Modules linked in: 8021q garp stp llc fuse michael_mic macvlan pktgen
w83627hf hwmon_vid hwmon nfs lockd fscache nfs_acl auth_rpcgss sunrpc ipv6 dm_multipath uinput arc4 ecb ath5k ath mac80211 cfg80211 e1000e i2c_i801 e100 i2c_core output serio_raw pcspkr mii iTCO_wdt iTCO_vendor_support ata_generic pata_acpi [last unloaded: ipt_addrtype]
Pid: 1225, comm: rsyslogd Tainted: G W 2.6.37-rc4-wl+ #9
Call Trace:
 [<8043144d>] warn_slowpath_common+0x77/0x8c
 [<f8663994>] ? ath5k_hw_to_driver_rix+0x5b/0x5f [ath5k]
 [<f8663994>] ? ath5k_hw_to_driver_rix+0x5b/0x5f [ath5k]
 [<804314de>] warn_slowpath_fmt+0x2e/0x30
 [<f8663994>] ath5k_hw_to_driver_rix+0x5b/0x5f [ath5k]
 [<f8663ba5>] ath5k_tasklet_tx+0x1ab/0x2f0 [ath5k]
 [<80435948>] tasklet_action+0x78/0xc1
 [<80436034>] __do_softirq+0x75/0x121
 [<80435fbf>] ? __do_softirq+0x0/0x121
 <IRQ>  [<80435f0c>] ? irq_exit+0x29/0x5d
 [<804042c9>] ? do_IRQ+0x8e/0xa2
 [<80403729>] ? common_interrupt+0x29/0x30
 [<8044007b>] ? __queue_work+0x138/0x1af
 [<804b8e53>] ? mntput+0x0/0x15
 [<804b8fb1>] ? path_put+0x15/0x18
 [<8046b551>] ? audit_free_names+0x40/0x59
 [<8046b6fe>] ? audit_syscall_exit+0x91/0x10f
 [<804031d0>] ? sysexit_audit+0x24/0x44
---[ end trace e87e98eb2549568d ]---

Quoted 7 lines

Thanks,
Ben
--
Ben Greear <[email protected]>
Candela Technologies Inc http://www.candelatech.com

That's a weird one, I've seen it again sometimes but couldn't reproduce it easily to debug it...

#define ATH5K_RATE_CODE_1M 0x1B
is not an invalid rate code and if driver couldn't handle 0x1b I guess we would have a problem receiving beacons or other management frames sent @ 1Mbit.

Maybe there is a case when switching bands (eg. when we scan), when we switch from b/g to a in sw but hw has still a frame from b/g with a b rate code on its descriptor (eg. a beacon). Since b rates are not available on a band ath5k_hw_to_driver_rix will not be able to handle it since during ath5k_setup_rate_idx we set up rate_idx per band and ath5k_hw_to_driver_rix blindly uses sc->curband->band.

I think since we know on ath5k_receive_frame the frequency, we should check it and not blindly set rxs->band to sc->curband->band, we should then pass the correct band to ath5k_hw_to_driver_rix.

Also on tx we can have the same problem when we send a frame while on b/g band, switch bands on sw and frame is sent afterwards so again when we try to process tx status descriptor through ath5k_tx_frame_completed we 'll hit the same error on ath5k_hw_to_driver_rix. Unfortunately tx status descriptor doesn't provide us with frequency so I guess we should use 0 in case we get this error or find another workaround.

It's weird because when we switch channels through ath5k_hw_reset we wait for tx/rx dma to stop (also on synth-only channel change) and if they don't we reset pcu/dma unit so there shouldn't be any pending frames and even if there are they should get dropped (well there is nothing on documentation for that i think, they might just stay on some buffer, we just assume they get dropped). Maybe when a tx queue is stuck (and the beacon queue is known to get stuck sometimes -and beacons are @1Mbit-) it gets unstuck after reset and frame gets out (on the new channel of course).

Just out of curiosity can you check for malformed tx packets, packets that are received on a 2.4Ghz channel and on the header they say they are on a 5GHz channel or the opposite ? Try sniffing on channel 1, the first 5GHz channel available and your AP's channel. Also i introduced a debug level for DMA start/stop in one of my patches, in case you use them, can you please enable it so that we can see what goes on ? If you don't can you at least enable ATH5K_DEBUG_XMIT ?

Also can you try using a b/g only card or skip a band on ath5k_setup_bands ?

I know it doesn't make much sense why it gets triggered when you use encryption (hw or sw encryption btw ?), maybe sw acts more slowly or something, or wpa_supplicant does some extra scans...

Signature · 3 lines

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

Ben Greear

author

2010-12-02 06:25 UTC #3 lore raw

Quoted 51 lines · Nick Kossifidis

2010/12/2 Ben Greear<[email protected]>:
Quoted 50 lines · Ben Greear
Quoted 9 lines
We were testing with 64 virtual stations running WPA, with a single instance of supplicant controlling all interfaces and the scan-sharing enabled. It was running clean w/out encryption (and w/out supplicant).
We see a large number of these types of warnings. We had a proprietary module loaded, but it was not in active use. We're going to reproduce without it, but in the meantime, here is a representative trace:
Here's another one from a non-tainted kernel. Seems this is trivial to reproduce.
------------[ cut here ]------------
WARNING: at
/home/greearb/git/linux.wireless-testing-ct/drivers/net/wireless/ath/ath5k/base.c:620 ath5k_hw_to_driver_rix+0x5b/0x5f [ath5k]()
Hardware name:
invalid hw_rix: 1b
Modules linked in: 8021q garp stp llc fuse michael_mic macvlan pktgen
w83627hf hwmon_vid hwmon nfs lockd fscache nfs_acl auth_rpcgss sunrpc ipv6 dm_multipath uinput arc4 ecb ath5k ath mac80211 cfg80211 e1000e i2c_i801 e100 i2c_core output serio_raw pcspkr mii iTCO_wdt iTCO_vendor_support ata_generic pata_acpi [last unloaded: ipt_addrtype]
Pid: 1225, comm: rsyslogd Tainted: G W 2.6.37-rc4-wl+ #9
Call Trace:
  [<8043144d>] warn_slowpath_common+0x77/0x8c
  [<f8663994>] ? ath5k_hw_to_driver_rix+0x5b/0x5f [ath5k]
  [<f8663994>] ? ath5k_hw_to_driver_rix+0x5b/0x5f [ath5k]
  [<804314de>] warn_slowpath_fmt+0x2e/0x30
  [<f8663994>] ath5k_hw_to_driver_rix+0x5b/0x5f [ath5k]
  [<f8663ba5>] ath5k_tasklet_tx+0x1ab/0x2f0 [ath5k]
  [<80435948>] tasklet_action+0x78/0xc1
  [<80436034>] __do_softirq+0x75/0x121
  [<80435fbf>] ? __do_softirq+0x0/0x121
  <IRQ>    [<80435f0c>] ? irq_exit+0x29/0x5d
  [<804042c9>] ? do_IRQ+0x8e/0xa2
  [<80403729>] ? common_interrupt+0x29/0x30
  [<8044007b>] ? __queue_work+0x138/0x1af
  [<804b8e53>] ? mntput+0x0/0x15
  [<804b8fb1>] ? path_put+0x15/0x18
  [<8046b551>] ? audit_free_names+0x40/0x59
  [<8046b6fe>] ? audit_syscall_exit+0x91/0x10f
  [<804031d0>] ? sysexit_audit+0x24/0x44
---[ end trace e87e98eb2549568d ]---
Thanks,
Ben

Quoted 7 lines

Quoted 4 lines
--
Ben Greear<[email protected]>
Candela Technologies Inc http://www.candelatech.com
That's a weird one, I've seen it again sometimes but couldn't reproduce it easily to debug it...

This script is likely to reproduce it for you..it's a simplistic version of the test that caused this:

http://www.spinics.net/lists/linux-wireless/msg60126.html

Also, we can currently reproduce this easily in our setup, and we're more than happy to test patches.

Quoted 4 lines

#define ATH5K_RATE_CODE_1M 0x1B
is not an invalid rate code and if driver couldn't handle 0x1b I guess we would have a problem receiving beacons or other management frames sent @ 1Mbit.

In case it matters, most of the warnings are 0x1B, but a few are 0x18 and one was 0x19.

Quoted 37 lines

Maybe there is a case when switching bands (eg. when we scan), when we switch from b/g to a in sw but hw has still a frame from b/g with a b rate code on its descriptor (eg. a beacon). Since b rates are not available on a band ath5k_hw_to_driver_rix will not be able to handle it since during ath5k_setup_rate_idx we set up rate_idx per band and ath5k_hw_to_driver_rix blindly uses sc->curband->band.
I think since we know on ath5k_receive_frame the frequency, we should check it and not blindly set rxs->band to sc->curband->band, we should then pass the correct band to ath5k_hw_to_driver_rix.
Also on tx we can have the same problem when we send a frame while on b/g band, switch bands on sw and frame is sent afterwards so again when we try to process tx status descriptor through ath5k_tx_frame_completed we 'll hit the same error on ath5k_hw_to_driver_rix. Unfortunately tx status descriptor doesn't provide us with frequency so I guess we should use 0 in case we get this error or find another workaround.
It's weird because when we switch channels through ath5k_hw_reset we wait for tx/rx dma to stop (also on synth-only channel change) and if they don't we reset pcu/dma unit so there shouldn't be any pending frames and even if there are they should get dropped (well there is nothing on documentation for that i think, they might just stay on some buffer, we just assume they get dropped). Maybe when a tx queue is stuck (and the beacon queue is known to get stuck sometimes -and beacons are @1Mbit-) it gets unstuck after reset and frame gets out (on the new channel of course).
Just out of curiosity can you check for malformed tx packets, packets that are received on a 2.4Ghz channel and on the header they say they are on a 5GHz channel or the opposite ? Try sniffing on channel 1, the first 5GHz channel available and your AP's channel. Also i introduced a debug level for DMA start/stop in one of my patches, in case you use them, can you please enable it so that we can see what goes on ? If you don't can you at least enable ATH5K_DEBUG_XMIT ?

Quoted 5 lines

Also can you try using a b/g only card or skip a band on ath5k_setup_bands ?
I know it doesn't make much sense why it gets triggered when you use encryption (hw or sw encryption btw ?), maybe sw acts more slowly or something, or wpa_supplicant does some extra scans...

WPA is definitely doing lots of scans, even with the scan-sharing logic enabled.

I'm using latest wireless-testing, and will look for some debug to enable.

I'm not sure we'll have time to set up a sniffer in the near term.

Also, I have a patch in the kernel that allows it to keep from scanning channels other than the current channel as long as one interface is associated. This still tends to cause the off-channel/on-channel logic to happen, as the scan core logic isn't smart enough to figure out it isn't really leaving channels to scan..but at least it shouldn't be walking to different bands. Of course, maybe no VIFs are associated when this happened, or something managed to request a full scan.

Thanks,
Ben

Signature · 2 lines

Ben Greear <[email protected]>
Candela Technologies Inc  http://www.candelatech.com

Nick Kossifidis

2010-12-02 16:18 UTC #4 lore raw

2010/12/2 Ben Greear <[email protected]>:

Quoted 72 lines · Nick Kossifidis

Quoted 55 lines
2010/12/2 Ben Greear<[email protected]>:
Quoted 53 lines · Ben Greear
Quoted 9 lines
We were testing with 64 virtual stations running WPA, with a single instance of supplicant controlling all interfaces and the scan-sharing enabled. It was running clean w/out encryption (and w/out supplicant).
We see a large number of these types of warnings. We had a proprietary module loaded, but it was not in active use. We're going to reproduce without it, but in the meantime, here is a representative trace:
Here's another one from a non-tainted kernel. Seems this is trivial to reproduce.
------------[ cut here ]------------
WARNING: at
/home/greearb/git/linux.wireless-testing-ct/drivers/net/wireless/ath/ath5k/base.c:620 ath5k_hw_to_driver_rix+0x5b/0x5f [ath5k]()
Hardware name:
invalid hw_rix: 1b
Modules linked in: 8021q garp stp llc fuse michael_mic macvlan pktgen
w83627hf hwmon_vid hwmon nfs lockd fscache nfs_acl auth_rpcgss sunrpc ipv6
dm_multipath uinput arc4 ecb ath5k ath mac80211 cfg80211 e1000e i2c_i801 e100 i2c_core output serio_raw pcspkr mii iTCO_wdt iTCO_vendor_support ata_generic pata_acpi [last unloaded: ipt_addrtype]
Pid: 1225, comm: rsyslogd Tainted: G W 2.6.37-rc4-wl+ #9
Call Trace:
 [<8043144d>] warn_slowpath_common+0x77/0x8c
 [<f8663994>] ? ath5k_hw_to_driver_rix+0x5b/0x5f [ath5k]
 [<f8663994>] ? ath5k_hw_to_driver_rix+0x5b/0x5f [ath5k]
 [<804314de>] warn_slowpath_fmt+0x2e/0x30
 [<f8663994>] ath5k_hw_to_driver_rix+0x5b/0x5f [ath5k]
 [<f8663ba5>] ath5k_tasklet_tx+0x1ab/0x2f0 [ath5k]
 [<80435948>] tasklet_action+0x78/0xc1
 [<80436034>] __do_softirq+0x75/0x121
 [<80435fbf>] ? __do_softirq+0x0/0x121
 <IRQ>    [<80435f0c>] ? irq_exit+0x29/0x5d
 [<804042c9>] ? do_IRQ+0x8e/0xa2
 [<80403729>] ? common_interrupt+0x29/0x30
 [<8044007b>] ? __queue_work+0x138/0x1af
 [<804b8e53>] ? mntput+0x0/0x15
 [<804b8fb1>] ? path_put+0x15/0x18
 [<8046b551>] ? audit_free_names+0x40/0x59
 [<8046b6fe>] ? audit_syscall_exit+0x91/0x10f
 [<804031d0>] ? sysexit_audit+0x24/0x44
---[ end trace e87e98eb2549568d ]---
Thanks,
Ben
Quoted 7 lines
Quoted 4 lines
--
Ben Greear<[email protected]>
Candela Technologies Inc http://www.candelatech.com
That's a weird one, I've seen it again sometimes but couldn't reproduce it easily to debug it...
This script is likely to reproduce it for you..it's a simplistic version of the test that caused this:
http://www.spinics.net/lists/linux-wireless/msg60126.html
Also, we can currently reproduce this easily in our setup, and we're more than happy to test patches.

Quoted 8 lines

Quoted 4 lines
#define ATH5K_RATE_CODE_1M 0x1B
is not an invalid rate code and if driver couldn't handle 0x1b I guess we would have a problem receiving beacons or other management frames sent @ 1Mbit.
In case it matters, most of the warnings are 0x1B, but a few are 0x18 and one was 0x19.

Also valid rates for b/g ;-)
#define ATH5K_RATE_CODE_5_5M 0x19
#define ATH5K_RATE_CODE_11M 0x18

Quoted 18 lines

WPA is definitely doing lots of scans, even with the scan-sharing logic enabled.
I'm using latest wireless-testing, and will look for some debug to enable.
I'm not sure we'll have time to set up a sniffer in the near term.
Also, I have a patch in the kernel that allows it to keep from scanning channels other than the current channel as long as one interface is associated. This still tends to cause the off-channel/on-channel logic to happen, as the scan core logic isn't smart enough to figure out it isn't really leaving channels to scan..but at least it shouldn't be walking to different bands. Of course, maybe no VIFs are associated when this happened, or something managed to request a full scan.

Quoted 3 lines

Thanks,
Ben

At least try skipping 11a on ath5k_setup_bands, just comment out the 11a part...

Signature · 3 lines

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

Ben Greear

author

2010-12-02 18:16 UTC #5 lore raw

Quoted 4 lines · Nick Kossifidis

2010/12/2 Ben Greear<[email protected]>:
At least try skipping 11a on ath5k_setup_bands, just comment out the 11a part...

I did this, and it took a bit longer than last time to see the errors, but they still do happen. The 'longer' might just be random luck, and the kernel was compiled with more debugging enabled...

Thanks,
Ben

Signature · 2 lines

Ben Greear <[email protected]>
Candela Technologies Inc  http://www.candelatech.com