kernel crashes, 2.6.30, rt2x00, ath5k, ieee80211_get_*_rate, automatic rate control

kernel crashes, 2.6.30, rt2x00, ath5k, ieee80211_get_*_rate, automatic rate control

[Richard Zidlicky]

Hi,

I am experiencing kernel crashes with a combination of ath5k and rt73usb 
wireless cards run as an adhoc network. While not entirely new in 2.6.30 these 
were rare enough in 2.6.29.* or earlier kernels that I was unable to look at 
it in detail earlier.

Submitting everything in one email because for me it is hard to tell appart
what the actual culprit is - appears like all the issues are very closely
related.

Crashes occur on 2 computers, with ath5k-pci and rt73usb cards respectively.
ath5k phy0: Atheros AR2425 chip found (MAC: 0xe2, PHY: 0x70)
02:00.0 Ethernet controller: Atheros Communications Inc. AR242x 802.11abg Wireless PCI Express Adapter (rev 01)
Bus 005 Device 002: ID 148f:2573 Ralink Technology, Corp. RT2501USB Wireless Adapter

The good news - setting a fixed rate appears to prevent all crashes. This is perhaps
the reason why wireless developers never see this crashes?
Unfortunately the unsuspecting user not setting the bitrate manually will experience 
many mysterious freezes and crashes.

Depending on distance 11-24M fixed bitrates worked very well for me. Otoh a quick 
look at data transfer rates (4m direct view distance), with "auto" rate setting 
confirms that something is seriously hosed with automatic rate setting:

  transfer from rt73usb->ath5k go with approximately 50-100Kb/s
  transfer from ath5k->rt73usb go with approximately 500-800Kb/s.

Ping times did preiodically climb from severeal ms to apporximately 23seconds (!!)
at which point something occured (hw reset ?) and the whole repeated.

Debugging is a bit difficult, only one of the affected computers has a serial 
connection and so far all crashes appeard when I was not running with serial 
console connected. So I was able to partialy decode only 2 exemplary crashes, 
1 for each driver although I am convinced that several more variants occured.

Here is a partially decoded crash with the ath5k driver, I have only a photo 
of kernel panic screen so I am not sure if it is reliable. 
I have pinpointed the suspected crash point according to the "Code" line
appearing bellow the kernel panic.
I can transcribe part of the backtrace or email the picture for more info,
register values not available though.

EIP: f825cad1 SS:SSP 68:c0681d

4a 08 8b... ath5k/base.c : 0x2c24

static inline struct ieee80211_rate *
ieee80211_get_tx_rate(const struct ieee80211_hw *hw,
                      const struct ieee80211_tx_info *c)
{
        if (WARN_ON(c->control.rates[0].idx < 0))
    2c0e:       8b 54 24 44             mov    0x44(%esp),%edx
    2c12:       8b 9b 70 0f 00 00       mov    0xf70(%ebx),%ebx
    2c18:       89 5c 24 58             mov    %ebx,0x58(%esp)
    2c1c:       0f b6 40 09             movzbl 0x9(%eax),%eax
    2c20:       88 44 24 57             mov    %al,0x57(%esp)
    2c24:       0f b6 4a 08             movzbl 0x8(%edx),%ecx   ************************
    2c28:       8b 85 18 01 00 00       mov    0x118(%ebp),%eax
    2c2e:       84 c9                   test   %cl,%cl
    2c30:       0f 88 2a 02 00 00       js     2e60 <ath5k_tx+0x3e0>
                return NULL;
        return &hw->wiphy->bands[c->band]->bitrates[c->control.rates[0].idx];


Partially decoded crash on the rt2x00 side, again have a photo of that. Crash in
rt2x00_get_rate, ebx was zero.


/home/rz/rpmbuild/kernels/linux-2.6.30/drivers/net/wireless/rt2x00/rt2x00queue.c
:323
            !test_bit(ENTRY_TXD_RTS_FRAME, &txdesc->flags)) {
                __set_bit(ENTRY_TXD_FIRST_FRAGMENT, &txdesc->flags);
                txdesc->ifs = IFS_BACKOFF;
        } else
                txdesc->ifs = IFS_SIFS;
    1e18:       66 c7 46 16 01 00       movw   $0x1,0x16(%esi)
rt2x00_get_rate():
/home/rz/rpmbuild/kernels/linux-2.6.30/drivers/net/wireless/rt2x00/rt2x00lib.h:5
7
    1e1e:       0f b6 5b 06             movzbl 0x6(%ebx),%ebx   *********************
rt2x00queue_create_tx_descriptor():
/home/rz/rpmbuild/kernels/linux-2.6.30/drivers/net/wireless/rt2x00/rt2x00queue.c
:330
        /*
         * Determine rate modulation.
         */

        hwrate = rt2x00_get_rate(rate->hw_value);
        txdesc->rate_mode = RATE_MODE_CCK;
    1e22:       66 c7 46 10 00 00       movw   $0x0,0x10(%esi)
rt2x00_get_rate():
/home/rz/rpmbuild/kernels/linux-2.6.30/drivers/net/wireless/rt2x00/rt2x00lib.h:5
7
    1e28:       89 5d d4                mov    %ebx,-0x2c(%ebp)


Both ieee80211_get_tx_rate() and ieee80211_get_rts_cts_rate() can return NULL instead of
a valid pointer and that is what appears to happen here.


On the ath5k side I also got a bunch  of these WARNINGs:

Jun 11 19:44:48 richard kernel: [ 3759.874096] ------------[ cut here ]------------
Jun 11 19:44:48 richard kernel: [ 3759.874113] WARNING: at /home/rz/rpmbuild/kernels/linux-2.6.29.4/net/mac80211/tx.c:567 invoke_tx_handlers+0xcf5/0xd70 [mac80211]()
Jun 11 19:44:48 richard kernel: [ 3759.874127] Hardware name: NB81005
Jun 11 19:44:48 richard kernel: [ 3759.874134] Modules linked in: i915 i2c_algo_bit rfcomm l2cap bluetooth ppdev parport_pc lp parport autofs4 acpi_cpufreq cpufreq_userspace cpufreq_conservative cpufreq_powersave cpufreq_stats pci_slot drm snd_hda_codec_realtek snd_hda_intel snd_hda_codec snd_pcm_oss snd_mixer_oss arc4 snd_pcm ecb uvcvideo videodev v4l1_compat snd_seq_dummy rtc_cmos rtc_core rtc_lib ath5k r8169 mac80211 led_class cfg80211 serio_raw snd_seq_oss snd_seq_midi snd_rawmidi snd_seq_midi_event snd_seq snd_timer snd_seq_device psmouse snd iTCO_wdt iTCO_vendor_support intel_agp shpchp pci_hotplug agpgart soundcore snd_page_alloc xt_multiport nf_conntrack_ipv4 nf_defrag_ipv4 xt_state nf_conntrack xt_tcpudp ipt_LOG xt_limit iptable_filter ip_tables x_tables fuse ahci squashfs ehci_hcd isofs zlib_inflate
Jun 11 19:44:48 richard kernel: [ 3759.874402] Pid: 0, comm: swapper Not tainted 2.6.29.4nb-fc2 #2
Jun 11 19:44:48 richard kernel: [ 3759.874411] Call Trace:
Jun 11 19:44:48 richard kernel: [ 3759.874433]  [<c012cc67>] warn_slowpath+0x87/0xe0
Jun 11 19:44:48 richard kernel: [ 3759.874451]  [<c02b5f25>] _raw_spin_lock+0x45/0x120
Jun 11 19:44:48 richard kernel: [ 3759.874518]  [<f823f386>] rate_control_get_rate+0xb6/0xc0 [mac80211]
Jun 11 19:44:48 richard kernel: [ 3759.874586]  [<f8246665>] invoke_tx_handlers+0xcf5/0xd70 [mac80211]
Jun 11 19:44:48 richard kernel: [ 3759.874621]  [<c0152ace>] trace_hardirqs_on_caller+0x5e/0x1b0
Jun 11 19:44:48 richard kernel: [ 3759.874675]  [<f824540a>] __ieee80211_tx_prepare+0x16a/0x2e0 [mac80211]
Jun 11 19:44:48 richard kernel: [ 3759.874732]  [<f8247cf0>] ieee80211_master_start_xmit+0x210/0x5a0 [mac80211]
Jun 11 19:44:48 richard kernel: [ 3759.874789]  [<f8247c92>] ieee80211_master_start_xmit+0x1b2/0x5a0 [mac80211]
Jun 11 19:44:48 richard kernel: [ 3759.874807]  [<c01328f3>] local_bh_enable_ip+0x93/0x110
Jun 11 19:44:48 richard kernel: [ 3759.874824]  [<c03f3bc3>] dev_hard_start_xmit+0x2a3/0x330
Jun 11 19:44:48 richard kernel: [ 3759.874838]  [<c02b5f25>] _raw_spin_lock+0x45/0x120
Jun 11 19:44:48 richard kernel: [ 3759.874853]  [<c0404a07>] __qdisc_run+0x1c7/0x230
Jun 11 19:44:48 richard kernel: [ 3759.874867]  [<c0404a1d>] __qdisc_run+0x1dd/0x230
Jun 11 19:44:48 richard kernel: [ 3759.874880]  [<c02b5f25>] _raw_spin_lock+0x45/0x120
Jun 11 19:44:48 richard kernel: [ 3759.874894]  [<c03f3e27>] dev_queue_xmit+0xc7/0x600
Jun 11 19:44:48 richard kernel: [ 3759.874908]  [<c03f40d7>] dev_queue_xmit+0x377/0x600
Jun 11 19:44:48 richard kernel: [ 3759.874921]  [<c03f3d97>] dev_queue_xmit+0x37/0x600
Jun 11 19:44:48 richard kernel: [ 3759.874978]  [<f8247686>] ieee80211_subif_start_xmit+0x466/0x8c0 [mac80211]
Jun 11 19:44:48 richard kernel: [ 3759.875060]  [<f8247726>] ieee80211_subif_start_xmit+0x506/0x8c0 [mac80211]
Jun 11 19:44:48 richard kernel: [ 3759.875078]  [<c0132a05>] local_bh_enable+0x95/0x110
Jun 11 19:44:48 richard kernel: [ 3759.875093]  [<c03f3bc3>] dev_hard_start_xmit+0x2a3/0x330
Jun 11 19:44:48 richard kernel: [ 3759.875106]  [<c02b5f25>] _raw_spin_lock+0x45/0x120
Jun 11 19:44:48 richard kernel: [ 3759.875121]  [<c0404a07>] __qdisc_run+0x1c7/0x230
Jun 11 19:44:48 richard kernel: [ 3759.875135]  [<c0404a1d>] __qdisc_run+0x1dd/0x230
Jun 11 19:44:48 richard kernel: [ 3759.875148]  [<c02b5f25>] _raw_spin_lock+0x45/0x120
Jun 11 19:44:48 richard kernel: [ 3759.875161]  [<c03f3e27>] dev_queue_xmit+0xc7/0x600
Jun 11 19:44:48 richard kernel: [ 3759.875175]  [<c03f40d7>] dev_queue_xmit+0x377/0x600
Jun 11 19:44:48 richard kernel: [ 3759.875188]  [<c03f3d97>] dev_queue_xmit+0x37/0x600
Jun 11 19:44:48 richard kernel: [ 3759.875204]  [<c041b6bd>] ip_finish_output+0x1fd/0x2b0
Jun 11 19:44:48 richard kernel: [ 3759.875219]  [<c041a755>] ip_local_out+0x15/0x20
Jun 11 19:44:48 richard kernel: [ 3759.875233]  [<c041af20>] ip_queue_xmit+0x1a0/0x380
Jun 11 19:44:48 richard kernel: [ 3759.875251]  [<c01a6d49>] add_partial+0x19/0x60
Jun 11 19:44:48 richard kernel: [ 3759.875264]  [<c02b5f25>] _raw_spin_lock+0x45/0x120
Jun 11 19:44:48 richard kernel: [ 3759.875278]  [<c0432754>] tcp_v4_send_check+0x44/0xf0
Jun 11 19:44:48 richard kernel: [ 3759.875293]  [<c042e404>] tcp_transmit_skb+0x494/0x6e0
Jun 11 19:44:48 richard kernel: [ 3759.875307]  [<c0152ace>] trace_hardirqs_on_caller+0x5e/0x1b0
Jun 11 19:44:48 richard kernel: [ 3759.875323]  [<c04306ca>] tcp_write_xmit+0x21a/0xa20
Jun 11 19:44:48 richard kernel: [ 3759.875337]  [<c0152981>] mark_held_locks+0x41/0x80
Jun 11 19:44:48 richard kernel: [ 3759.875351]  [<c0152981>] mark_held_locks+0x41/0x80
Jun 11 19:44:48 richard kernel: [ 3759.875365]  [<c042d60a>] tcp_established_options+0x2a/0xa0
Jun 11 19:44:48 richard kernel: [ 3759.875381]  [<c0430f4d>] __tcp_push_pending_frames+0x3d/0x110
Jun 11 19:44:48 richard kernel: [ 3759.875396]  [<c042c12b>] tcp_rcv_established+0x3fb/0xa20
Jun 11 19:44:48 richard kernel: [ 3759.875411]  [<c0434415>] tcp_v4_do_rcv+0x225/0x380
Jun 11 19:44:48 richard kernel: [ 3759.875426]  [<c0152ace>] trace_hardirqs_on_caller+0x5e/0x1b0
Jun 11 19:44:48 richard kernel: [ 3759.875441]  [<c0434b26>] tcp_v4_rcv+0x5b6/0x760
Jun 11 19:44:48 richard kernel: [ 3759.875457]  [<c04b323f>] _spin_lock_nested+0x2f/0x40
Jun 11 19:44:48 richard kernel: [ 3759.875471]  [<c0434b40>] tcp_v4_rcv+0x5d0/0x760
Jun 11 19:44:48 richard kernel: [ 3759.875486]  [<c041675f>] ip_local_deliver_finish+0xcf/0x230
Jun 11 19:44:48 richard kernel: [ 3759.875501]  [<c04166c0>] ip_local_deliver_finish+0x30/0x230
Jun 11 19:44:48 richard kernel: [ 3759.875516]  [<c041619e>] ip_rcv_finish+0xfe/0x370
Jun 11 19:44:48 richard kernel: [ 3759.875530]  [<c04160a0>] ip_rcv_finish+0x0/0x370
Jun 11 19:44:48 richard kernel: [ 3759.875544]  [<c03f2c69>] netif_receive_skb+0x2b9/0x560
Jun 11 19:44:48 richard kernel: [ 3759.875558]  [<c03f2aa8>] netif_receive_skb+0xf8/0x560
Jun 11 19:44:48 richard kernel: [ 3759.875572]  [<c03f2f88>] process_backlog+0x78/0xd0
Jun 11 19:44:48 richard kernel: [ 3759.875586]  [<c03f12f3>] net_rx_action+0x163/0x230
Jun 11 19:44:48 richard kernel: [ 3759.875599]  [<c03f1276>] net_rx_action+0xe6/0x230
Jun 11 19:44:48 richard kernel: [ 3759.875613]  [<c0132547>] __do_softirq+0xa7/0x160
Jun 11 19:44:48 richard kernel: [ 3759.875628]  [<c0172f1a>] handle_fasteoi_irq+0x7a/0xe0
Jun 11 19:44:48 richard kernel: [ 3759.875643]  [<c01162b3>] ack_apic_level+0x73/0x270
Jun 11 19:44:48 richard kernel: [ 3759.875657]  [<c0132685>] do_softirq+0x85/0x90
Jun 11 19:44:48 richard kernel: [ 3759.875670]  [<c013283d>] irq_exit+0x6d/0x90
Jun 11 19:44:48 richard kernel: [ 3759.875685]  [<c0105b8d>] do_IRQ+0x5d/0xc0
Jun 11 19:44:48 richard kernel: [ 3759.875699]  [<c010452c>] common_interrupt+0x2c/0x40
Jun 11 19:44:48 richard kernel: [ 3759.875713]  [<c015007b>] lockdep_reset_lock+0x1cb/0x2b0
Jun 11 19:44:48 richard kernel: [ 3759.875729]  [<c02fd72b>] acpi_idle_enter_bm+0x287/0x310
Jun 11 19:44:48 richard kernel: [ 3759.875746]  [<c03c488f>] cpuidle_idle_call+0x6f/0xc0
Jun 11 19:44:48 richard kernel: [ 3759.875760]  [<c0102d0b>] cpu_idle+0x6b/0xa0
Jun 11 19:44:48 richard kernel: [ 3759.875770] ---[ end trace 5d9979cba48023b9 ]---


Jun 11 20:25:16 richard kernel: [  147.867299] ------------[ cut here ]------------
Jun 11 20:25:16 richard kernel: [  147.867316] WARNING: at /home/rz/rpmbuild/kernels/linux-2.6.29.4/net/mac80211/tx.c:567 invoke_tx_handlers+0xcf5/0xd70 [mac80211]()
Jun 11 20:25:16 richard kernel: [  147.867330] Hardware name: NB81005
Jun 11 20:25:16 richard kernel: [  147.867337] Modules linked in: i915 i2c_algo_bit rfcomm l2cap bluetooth ppdev parport_pc lp parport autofs4 acpi_cpufreq cpufreq_userspace cpufreq_conservative cpufreq_powersave cpufreq_stats pci_slot drm snd_hda_codec_realtek snd_hda_intel snd_hda_codec snd_pcm_oss snd_mixer_oss arc4 snd_pcm uvcvideo videodev ecb v4l1_compat snd_seq_dummy rtc_cmos rtc_core rtc_lib ath5k mac80211 led_class serio_raw cfg80211 r8169 snd_seq_oss snd_seq_midi snd_rawmidi snd_seq_midi_event psmouse snd_seq snd_timer snd_seq_device intel_agp iTCO_wdt iTCO_vendor_support shpchp agpgart snd pci_hotplug soundcore snd_page_alloc xt_multiport nf_conntrack_ipv4 nf_defrag_ipv4 xt_state nf_conntrack xt_tcpudp ipt_LOG xt_limit iptable_filter ip_tables x_tables fuse ahci squashfs ehci_hcd isofs zlib_inflate
Jun 11 20:25:16 richard kernel: [  147.867604] Pid: 0, comm: swapper Not tainted 2.6.29.4nb-fc2 #2
Jun 11 20:25:16 richard kernel: [  147.867613] Call Trace:
Jun 11 20:25:16 richard kernel: [  147.867635]  [<c012cc67>] warn_slowpath+0x87/0xe0
Jun 11 20:25:16 richard kernel: [  147.867704]  [<f8226386>] rate_control_get_rate+0xb6/0xc0 [mac80211]
Jun 11 20:25:16 richard kernel: [  147.867772]  [<f822d665>] invoke_tx_handlers+0xcf5/0xd70 [mac80211]
Jun 11 20:25:16 richard kernel: [  147.867808]  [<c0152ace>] trace_hardirqs_on_caller+0x5e/0x1b0
Jun 11 20:25:16 richard kernel: [  147.867861]  [<f822c40a>] __ieee80211_tx_prepare+0x16a/0x2e0 [mac80211]
Jun 11 20:25:16 richard kernel: [  147.867919]  [<f822ecf0>] ieee80211_master_start_xmit+0x210/0x5a0 [mac80211]
Jun 11 20:25:16 richard kernel: [  147.867976]  [<f822ec92>] ieee80211_master_start_xmit+0x1b2/0x5a0 [mac80211]
Jun 11 20:25:16 richard kernel: [  147.867995]  [<c03f3bc3>] dev_hard_start_xmit+0x2a3/0x330
Jun 11 20:25:16 richard kernel: [  147.868011]  [<c02b5f25>] _raw_spin_lock+0x45/0x120
Jun 11 20:25:16 richard kernel: [  147.868026]  [<c0404a07>] __qdisc_run+0x1c7/0x230
Jun 11 20:25:16 richard kernel: [  147.868040]  [<c0404a1d>] __qdisc_run+0x1dd/0x230
Jun 11 20:25:16 richard kernel: [  147.868053]  [<c02b5f25>] _raw_spin_lock+0x45/0x120
Jun 11 20:25:16 richard kernel: [  147.868067]  [<c03f3e27>] dev_queue_xmit+0xc7/0x600
Jun 11 20:25:16 richard kernel: [  147.868081]  [<c03f40d7>] dev_queue_xmit+0x377/0x600
Jun 11 20:25:16 richard kernel: [  147.868095]  [<c03f3d97>] dev_queue_xmit+0x37/0x600
Jun 11 20:25:16 richard kernel: [  147.868151]  [<f822e686>] ieee80211_subif_start_xmit+0x466/0x8c0 [mac80211]
Jun 11 20:25:16 richard kernel: [  147.868207]  [<f822e726>] ieee80211_subif_start_xmit+0x506/0x8c0 [mac80211]
Jun 11 20:25:16 richard kernel: [  147.868263]  [<f827315a>] nf_conntrack_in+0x45a/0x8f0 [nf_conntrack]
Jun 11 20:25:16 richard kernel: [  147.868281]  [<c0132a05>] local_bh_enable+0x95/0x110
Jun 11 20:25:16 richard kernel: [  147.868295]  [<c03f3bc3>] dev_hard_start_xmit+0x2a3/0x330
Jun 11 20:25:16 richard kernel: [  147.868309]  [<c02b5f25>] _raw_spin_lock+0x45/0x120
Jun 11 20:25:16 richard kernel: [  147.868323]  [<c0404a07>] __qdisc_run+0x1c7/0x230
Jun 11 20:25:16 richard kernel: [  147.868337]  [<c0404a1d>] __qdisc_run+0x1dd/0x230
Jun 11 20:25:16 richard kernel: [  147.868350]  [<c02b5f25>] _raw_spin_lock+0x45/0x120
Jun 11 20:25:16 richard kernel: [  147.868364]  [<c03f3e27>] dev_queue_xmit+0xc7/0x600
Jun 11 20:25:16 richard kernel: [  147.868378]  [<c03f40d7>] dev_queue_xmit+0x377/0x600
Jun 11 20:25:16 richard kernel: [  147.868391]  [<c03f3d97>] dev_queue_xmit+0x37/0x600
Jun 11 20:25:16 richard kernel: [  147.868407]  [<c041b6bd>] ip_finish_output+0x1fd/0x2b0
Jun 11 20:25:16 richard kernel: [  147.868422]  [<c041a755>] ip_local_out+0x15/0x20
Jun 11 20:25:16 richard kernel: [  147.868437]  [<c041a9e2>] ip_push_pending_frames+0x282/0x3a0
Jun 11 20:25:16 richard kernel: [  147.868452]  [<c043e307>] icmp_reply+0x137/0x1e0
Jun 11 20:25:16 richard kernel: [  147.868466]  [<c043e4e9>] icmp_echo+0x49/0x50
Jun 11 20:25:16 richard kernel: [  147.868497]  [<c043eac4>] icmp_rcv+0x254/0x2a0
Jun 11 20:25:16 richard kernel: [  147.868512]  [<c041675f>] ip_local_deliver_finish+0xcf/0x230
Jun 11 20:25:16 richard kernel: [  147.868527]  [<c04166c0>] ip_local_deliver_finish+0x30/0x230
Jun 11 20:25:16 richard kernel: [  147.868542]  [<c041619e>] ip_rcv_finish+0xfe/0x370
Jun 11 20:25:16 richard kernel: [  147.868556]  [<c04160a0>] ip_rcv_finish+0x0/0x370
Jun 11 20:25:16 richard kernel: [  147.868570]  [<c03f2c69>] netif_receive_skb+0x2b9/0x560
Jun 11 20:25:16 richard kernel: [  147.868584]  [<c03f2aa8>] netif_receive_skb+0xf8/0x560
Jun 11 20:25:16 richard kernel: [  147.868599]  [<c03f2f88>] process_backlog+0x78/0xd0
Jun 11 20:25:16 richard kernel: [  147.868613]  [<c03f12f3>] net_rx_action+0x163/0x230
Jun 11 20:25:16 richard kernel: [  147.868626]  [<c03f1276>] net_rx_action+0xe6/0x230
Jun 11 20:25:16 richard kernel: [  147.868640]  [<c0132547>] __do_softirq+0xa7/0x160
Jun 11 20:25:16 richard kernel: [  147.868655]  [<c0172f1a>] handle_fasteoi_irq+0x7a/0xe0
Jun 11 20:25:16 richard kernel: [  147.868671]  [<c01162b3>] ack_apic_level+0x73/0x270
Jun 11 20:25:16 richard kernel: [  147.868684]  [<c0132685>] do_softirq+0x85/0x90
Jun 11 20:25:16 richard kernel: [  147.868697]  [<c013283d>] irq_exit+0x6d/0x90
Jun 11 20:25:16 richard kernel: [  147.868712]  [<c0105b8d>] do_IRQ+0x5d/0xc0
Jun 11 20:25:16 richard kernel: [  147.868726]  [<c010452c>] common_interrupt+0x2c/0x40
Jun 11 20:25:16 richard kernel: [  147.868741]  [<c015007b>] lockdep_reset_lock+0x1cb/0x2b0
Jun 11 20:25:16 richard kernel: [  147.868756]  [<c02fd72b>] acpi_idle_enter_bm+0x287/0x310
Jun 11 20:25:16 richard kernel: [  147.868773]  [<c03c488f>] cpuidle_idle_call+0x6f/0xc0
Jun 11 20:25:16 richard kernel: [  147.868787]  [<c0102d0b>] cpu_idle+0x6b/0xa0
Jun 11 20:25:16 richard kernel: [  147.868797] ---[ end trace 04f25978ef36fa0b ]---


Regards
Richard

Re: kernel crashes, 2.6.30, rt2x00, ath5k, ieee80211_get_*_rate, automatic rate control

[Bob Copeland]

On Sun, Jun 21, 2009 at 03:49:54PM +0200, Richard Zidlicky wrote:
> 
> The good news - setting a fixed rate appears to prevent all crashes. This is
> perhaps the reason why wireless developers never see this crashes?

Sounds like the rate controller.  Does this patch help?

http://lkml.org/lkml/2009/6/5/269

-- 
Bob Copeland %% www.bobcopeland.com

Re: kernel crashes, 2.6.30, rt2x00, ath5k, ieee80211_get_*_rate, automatic rate control

[Richard Zidlicky]

On Sun, Jun 21, 2009 at 02:04:47PM -0400, Bob Copeland wrote:
> On Sun, Jun 21, 2009 at 03:49:54PM +0200, Richard Zidlicky wrote:
> > 
> > The good news - setting a fixed rate appears to prevent all crashes. This is
> > perhaps the reason why wireless developers never see this crashes?
> 
> Sounds like the rate controller.  Does this patch help?
> 
> http://lkml.org/lkml/2009/6/5/269

will try ASAP, should have results on Monday

Richard

Re: kernel crashes, 2.6.30, rt2x00, ath5k, ieee80211_get_*_rate, automatic rate control

[Richard Zidlicky]

On Sun, Jun 21, 2009 at 02:04:47PM -0400, Bob Copeland wrote:
> On Sun, Jun 21, 2009 at 03:49:54PM +0200, Richard Zidlicky wrote:
> > 
> > The good news - setting a fixed rate appears to prevent all crashes. This is
> > perhaps the reason why wireless developers never see this crashes?
> 
> Sounds like the rate controller.  Does this patch help?
> 
> http://lkml.org/lkml/2009/6/5/269


did not crash for a day which does not prove much yet. I have now added a printk
that would alert me that the bugfix actually did anything and so far waiting to 
see it.

Something is still going very wrong with the automatic rate selection on the rt73usb
device - it is receiving fine with 11-24M but TX rate is not even 1M (50-100Kb/s). 
TX is fine with fixed rates 11-24M.

Richard

Re: kernel crashes, 2.6.30, rt2x00, ath5k, ieee80211_get_*_rate, automatic rate control

[Richard Zidlicky]

Got the confirmation that the patch for minstrel indeed does something good to me,
both on the ath5k and rt73usb side. The code path seems to be trigered only in 
special circumstances in my configuration but the printk did fire on both ends
after a while.

Richard

Re: kernel crashes, 2.6.30, rt2x00, ath5k, ieee80211_get_*_rate, automatic rate control

[Bob Copeland]

On Tue, Jun 23, 2009 at 07:46:16PM +0200, Richard Zidlicky wrote:
> Got the confirmation that the patch for minstrel indeed does something good
> to me, both on the ath5k and rt73usb side. The code path seems to be trigered
> only in special circumstances in my configuration but the printk did fire on
> both ends after a while.

Good news, thanks for testing.  Yeah it generally only occurs if you
have a nearby peer with a single (or none) available rates which is
why some people hit it a lot and others not so much.

The patch should already be on the way to stable, but I'll check on it.

-- 
Bob Copeland %% www.bobcopeland.com

Re: kernel crashes, 2.6.30, rt2x00, ath5k, ieee80211_get_*_rate, automatic rate control

[Richard Zidlicky]

On Tue, Jun 23, 2009 at 04:25:41PM -0400, Bob Copeland wrote:

> 
> The patch should already be on the way to stable, but I'll check on it.

thanks, you certainly have my vote that it should get into 2.6.30.*

On an unrelated note, the ath5k device is in a netbook with an wifi LED and
Fn-F2 hotkey to toggle wlan.

The hotkey works, the LED not. What do I need to make the LED working on the 
device?

Also, while the hotkey works how do query the current on/off status of it 
in Linux?

Richard

Re: kernel crashes, 2.6.30, rt2x00, ath5k, ieee80211_get_*_rate, automatic rate control

[Bob Copeland]

On Thu, Jun 25, 2009 at 10:36:36AM +0200, Richard Zidlicky wrote:
> > The patch should already be on the way to stable, but I'll check on it.
> 
> thanks, you certainly have my vote that it should get into 2.6.30.*

Ok, it has been released in 2.6.30.1.

> On an unrelated note, the ath5k device is in a netbook with an wifi LED and
> Fn-F2 hotkey to toggle wlan.
> 
> The hotkey works, the LED not. What do I need to make the LED working on the 
> device?

Try latest wireless-testing or 2.6.31-rc1; there may already be a fix
for your hardware thanks to recently added rfkill support.

> Also, while the hotkey works how do query the current on/off status of it 
> in Linux?

There's the /dev/rfkill device (see http://git.sipsolutions.net/rfkill.git)
and I believe there are files under /sys/ as well which show the state but
I don't have the details handy (/sys/class/rfkill/xxx/state?).

Also I don't have any hardware with a kill switch/LED so YMMV :)

-- 
Bob Copeland %% www.bobcopeland.com

ath5k, wifi enable hotkeys

[Richard Zidlicky]

On Sun, Jul 05, 2009 at 08:31:05AM -0400, Bob Copeland wrote:

Hi,


> Try latest wireless-testing or 2.6.31-rc1; there may already be a fix
> for your hardware thanks to recently added rfkill support.

got around to give 2.6.30* more testing. LED now works nicely but that is about the
only thing that works.

Tried computers linked in Ad-Hoc mode with WEP. 2.6.30 and 2.6.31.1 work nicely
on the other end.

On the ath5k end it seems like 2.6.31 choked after resume from suspend or when interface 
was reconfigured. 

2.6.31.1 does not work at all on this netbook. LED indicates activity but network does
not get associated. "iwlist scan" does display available networks.

After having tried 2.6.31.1 I have to cold-boot 2.6.30.x to get the ath5k working again,
simple reboot does not do it.

> 
> > Also, while the hotkey works how do query the current on/off status of it 
> > in Linux?
> 
> There's the /dev/rfkill device (see http://git.sipsolutions.net/rfkill.git)
> and I believe there are files under /sys/ as well which show the state but
> I don't have the details handy (/sys/class/rfkill/xxx/state?).

has that been merged into 2.6.31* ? 

The /sys/.../rfkill files are there but could not figure out anything that changes 
when hitting the hotkey.

Besides, I would think the LED will indicate rfkill status?

Richard

2.6.31.[12] ath5k regression

[Richard Zidlicky]

Hi,

ath5k no longer works for me in 2.6.31.[1-2]. 

2.6.31 worked good enough even though in patched 2.6.30.3 the connection and association 
is seemingly more stable.

All tests done in ad-hoc mode with 2 computers, the other end is a rt73usb which
is not quite trouble free either.

I have now confirmed that going back to 2.6.31 the wlan works at least most of the
time and completely stops working after applying this patch on top of 2.6.31

diff --git a/drivers/net/wireless/ath/ath5k/base.c b/drivers/net/wireless/ath/ath5k/base.c
index 029c1bc..ba6d225 100644
--- a/drivers/net/wireless/ath/ath5k/base.c
+++ b/drivers/net/wireless/ath/ath5k/base.c
@@ -2676,7 +2676,7 @@ ath5k_reset(struct ath5k_softc *sc, struct ieee80211_channel *chan)
                sc->curchan = chan;
                sc->curband = &sc->sbands[chan->band];
        }
-       ret = ath5k_hw_reset(ah, sc->opmode, sc->curchan, true);
+       ret = ath5k_hw_reset(ah, sc->opmode, sc->curchan, chan != NULL);
        if (ret) {
                ATH5K_ERR(sc, "can't reset hardware (%d)\n", ret);
                goto err;

One more odd observation - since 2.6.31 "iwlist wlan0 scan" will list my own ad-hoc
network twice although there are really only 2 machines.

messages:
Oct  8 10:44:09 richard kernel: [ 5818.459845] ath5k 0000:02:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17
Oct  8 10:44:09 richard kernel: [ 5818.460301] ath5k 0000:02:00.0: registered as 'phy0'
Oct  8 10:44:09 richard kernel: [ 5818.564470] ath5k phy0: Atheros AR2425 chip found (MAC: 0xe2, PHY: 0x70)

lspci:
02:00.0 Ethernet controller: Atheros Communications Inc. AR242x 802.11abg Wireless PCI Express Adapter (rev 01)

Some messages I caught on the other end of the connection:
- after cold booting the ath5k device:
[26996.271773] wlan0: RX ProbeReq SA=00:22:43:2c:76:0f DA=ff:ff:ff:ff:ff:ff BSSI
D=ff:ff:ff:ff:ff:ff (tx_last_beacon=1)
[27302.312129] wlan0: sta_find_ibss (active_ibss=0)
[27302.312134]    sta_find_ibss: selected da:d2:d4:53:53:03 current da:d2:d4:53:
53:03
[27302.312136]    did not try to join ibss


- after warm reboot from working 2.6.30.3

[26763.469116] wlan0: dropped frame to 00:22:43:2c:76:0f (unauthorized port)
[26763.931242] wlan0: RX ProbeReq SA=00:22:43:2c:76:0f DA=ff:ff:ff:ff:ff:ff BSSI
D=ff:ff:ff:ff:ff:ff (tx_last_beacon=1)
[26763.931248] wlan0: Sending ProbeResp to 00:22:43:2c:76:0f
[26764.469021] wlan0: dropped frame to 00:22:43:2c:76:0f (unauthorized port)
[26764.469115] wlan0: dropped frame to 00:22:43:2c:76:0f (unauthorized port)
[26766.151827] wlan0: RX ProbeReq SA=00:22:43:2c:76:0f DA=ff:ff:ff:ff:ff:ff BSSI
D=ff:ff:ff:ff:ff:ff (tx_last_beacon=1)
[26766.151833] wlan0: Sending ProbeResp to 00:22:43:2c:76:0f


Richard

Re: 2.6.31.[12] ath5k regression

[Bob Copeland]

On Fri, Oct 09, 2009 at 04:39:22PM +0200, Richard Zidlicky wrote:
> -       ret = ath5k_hw_reset(ah, sc->opmode, sc->curchan, true);
> +       ret = ath5k_hw_reset(ah, sc->opmode, sc->curchan, chan != NULL);
>         if (ret) {
>                 ATH5K_ERR(sc, "can't reset hardware (%d)\n", ret);
>                 goto err;

So, this change effectively just ensures we now program the pcu registers
at startup (every other time chan should not be null).  So my guess is
programming the pcu actually causes some problem.  Can you try this patch
instead?

Also, since you're using adhoc there may be a path that's somewhat
different from infrastructure mode, please check dmesg after applying the
patch and be sure that you only see "ath5k: reset with change_channel=true"
once per driver load.


diff --git a/drivers/net/wireless/ath/ath5k/initvals.c b/drivers/net/wireless/ath/ath5k/initvals.c
index 8fa4393..c099fa2 100644
--- a/drivers/net/wireless/ath/ath5k/initvals.c
+++ b/drivers/net/wireless/ath/ath5k/initvals.c
@@ -1376,9 +1376,8 @@ static void ath5k_hw_ini_registers(struct ath5k_hw *ah, unsigned int size,
 	for (i = 0; i < size; i++) {
 		/* On channel change there is
 		 * no need to mess with PCU */
-		if (change_channel &&
-				ini_regs[i].ini_register >= AR5K_PCU_MIN &&
-				ini_regs[i].ini_register <= AR5K_PCU_MAX)
+		if (ini_regs[i].ini_register >= AR5K_PCU_MIN &&
+		    ini_regs[i].ini_register <= AR5K_PCU_MAX)
 			continue;
 
 		switch (ini_regs[i].ini_mode) {
diff --git a/drivers/net/wireless/ath/ath5k/reset.c b/drivers/net/wireless/ath/ath5k/reset.c
index 3dab3d8..4b8ccbe 100644
--- a/drivers/net/wireless/ath/ath5k/reset.c
+++ b/drivers/net/wireless/ath/ath5k/reset.c
@@ -880,6 +880,9 @@ int ath5k_hw_reset(struct ath5k_hw *ah, enum nl80211_iftype op_mode,
 
 	ATH5K_TRACE(ah->ah_sc);
 
+	if (!change_channel)
+		printk(KERN_DEBUG "ath5k: reset with change_channel=true\n");
+
 	s_ant = 0;
 	ee_mode = 0;
 	staid1_flags = 0;

-- 
Bob Copeland %% www.bobcopeland.com

Re: 2.6.31.[12] ath5k regression

[Bob Copeland]

On Sat, Oct 10, 2009 at 8:58 AM, Bob Copeland <me@bobcopeland.com> wrote:
>        ATH5K_TRACE(ah->ah_sc);
>
> +       if (!change_channel)
> +               printk(KERN_DEBUG "ath5k: reset with change_channel=true\n");
> +

Of course I meant change_channel=false in the format string but what's
important is how often it is printed :)

-- 
Bob Copeland %% www.bobcopeland.com

Re: 2.6.31.[12] ath5k regression

[Richard Zidlicky]

On Sat, Oct 10, 2009 at 08:58:24AM -0400, Bob Copeland wrote:
> On Fri, Oct 09, 2009 at 04:39:22PM +0200, Richard Zidlicky wrote:
> > -       ret = ath5k_hw_reset(ah, sc->opmode, sc->curchan, true);
> > +       ret = ath5k_hw_reset(ah, sc->opmode, sc->curchan, chan != NULL);
> >         if (ret) {
> >                 ATH5K_ERR(sc, "can't reset hardware (%d)\n", ret);
> >                 goto err;
> 
> So, this change effectively just ensures we now program the pcu registers
> at startup (every other time chan should not be null).  So my guess is
> programming the pcu actually causes some problem.  Can you try this patch
> instead?

thanks, compiling it right now. Not quite sure - which version of this
> > -       ret = ath5k_hw_reset(ah, sc->opmode, sc->curchan, true);
> > +       ret = ath5k_hw_reset(ah, sc->opmode, sc->curchan, chan != NULL);

is it supposed to be tested with?

Richard

Re: 2.6.31.[12] ath5k regression

[Bob Copeland]

On Sun, Oct 11, 2009 at 02:26:16PM +0200, Richard Zidlicky wrote:
> thanks, compiling it right now. Not quite sure - which version of this
> > > -       ret = ath5k_hw_reset(ah, sc->opmode, sc->curchan, true);
> > > +       ret = ath5k_hw_reset(ah, sc->opmode, sc->curchan, chan != NULL);
> 
> is it supposed to be tested with?

The "chan != NULL" case.  The patch should apply against latest
wireless-testing (but will probably work with linus-2.6).

-- 
Bob Copeland %% www.bobcopeland.com

Re: 2.6.31.[12] ath5k regression

[Richard Zidlicky]

On Sun, Oct 11, 2009 at 09:30:10AM -0400, Bob Copeland wrote:
> On Sun, Oct 11, 2009 at 02:26:16PM +0200, Richard Zidlicky wrote:
> > thanks, compiling it right now. Not quite sure - which version of this
> > > > -       ret = ath5k_hw_reset(ah, sc->opmode, sc->curchan, true);
> > > > +       ret = ath5k_hw_reset(ah, sc->opmode, sc->curchan, chan != NULL);
> > 
> > is it supposed to be tested with?
> 
> The "chan != NULL" case.  The patch should apply against latest
> wireless-testing (but will probably work with linus-2.6).

so the results are same like before. The printk message came once only,
I will try to gather more debug info tomorrow.

It is striking that after running the not working driver the machine requires
a power-off reboot to have working ath5k again.

Richard

Re: 2.6.31.[12] ath5k regression

[Bob Copeland]

On Mon, 12 Oct 2009 00:00:02 +0200, Richard Zidlicky wrote:
> so the results are same like before. The printk message came once only,
> I will try to gather more debug info tomorrow.

Meaning it works the same as with your change (replacing "chan != null"
with "true") or it works the same as mainline, i.e. it fails?

-- 
Bob Copeland %% www.bobcopeland.com

Re: 2.6.31.[12] ath5k regression

[Richard Zidlicky]

On Sun, Oct 11, 2009 at 06:23:56PM -0400, Bob Copeland wrote:
> On Mon, 12 Oct 2009 00:00:02 +0200, Richard Zidlicky wrote:
> > so the results are same like before. The printk message came once only,
> > I will try to gather more debug info tomorrow.
> 
> Meaning it works the same as with your change (replacing "chan != null"
> with "true") or it works the same as mainline, i.e. it fails?

it works like in mainline and fails.

Richard

Re: 2.6.31.[12] ath5k regression

[Bob Copeland]

On Mon, Oct 12, 2009 at 10:23:16PM +0200, Richard Zidlicky wrote:
> it works like in mainline and fails.

Huh, well it should be equivalent to your patch, so I'm stumped
as to why.

-- 
Bob Copeland %% www.bobcopeland.com

Re: 2.6.31.[12] ath5k regression

[Richard Zidlicky]

On Mon, Oct 12, 2009 at 07:54:38PM -0400, Bob Copeland wrote:
> On Mon, Oct 12, 2009 at 10:23:16PM +0200, Richard Zidlicky wrote:
> > it works like in mainline and fails.
> 
> Huh, well it should be equivalent to your patch, so I'm stumped
> as to why.

mee too. I am trying to verify all variants because I do remember that adding the 
change_chan patch on top of clean 2.6.31 broke that while I do vaguely remember that
reverting this patch form 2.6.31.[23] did not make a working wlan.
However testing is time consuming - the machine requires allways a complete shutdown, 
power off reboot.

Strange things were happening even in 2.6.31 - for example my ad-hoc network was listed 
twice by iwlist scan - strangely one of the entries has 0db signal strength. Similar
listing on both ends.

Here is what the other end is reporting if that is of any help..

### ath5k end shut down here ###
[52262.000044] wlan0: expiring inactive STA 00:22:43:2c:76:0f
[52262.000050] phy6: Removed STA 00:22:43:2c:76:0f
[52262.003025] phy6: Destroyed STA 00:22:43:2c:76:0f
[52343.404540] wlan0: RX ProbeReq SA=00:60:b3:06:f4:17 DA=ff:ff:ff:ff:ff:ff BSSID=ff:ff:ff:ff:ff:ff (tx_last_beacon=1)
[52345.711165] wlan0: RX ProbeReq SA=00:60:b3:06:f4:17 DA=ff:ff:ff:ff:ff:ff BSSID=ff:ff:ff:ff:ff:ff (tx_last_beacon=1)
...
...
...
...
[52350.930907] wlan0: RX ProbeReq SA=00:60:b3:06:f4:17 DA=ff:ff:ff:ff:ff:ff BSSID=ff:ff:ff:ff:ff:ff (tx_last_beacon=1)
[52881.645705] wlan0: RX ProbeReq SA=00:22:43:2c:76:0f DA=ff:ff:ff:ff:ff:ff BSSID=ff:ff:ff:ff:ff:ff (tx_last_beacon=1)
[52881.645711] wlan0: Sending ProbeResp to 00:22:43:2c:76:0f
[52883.886696] wlan0: RX ProbeReq SA=00:22:43:2c:76:0f DA=ff:ff:ff:ff:ff:ff BSSID=ff:ff:ff:ff:ff:ff (tx_last_beacon=1)
[52883.886702] wlan0: Sending ProbeResp to 00:22:43:2c:76:0f
[52915.330070] wlan0: RX ProbeReq SA=00:22:43:2c:76:0f DA=ff:ff:ff:ff:ff:ff BSSID=ff:ff:ff:ff:ff:ff (tx_last_beacon=1)
[52947.327315] wlan0: RX ProbeReq SA=00:22:43:2c:76:0f DA=ff:ff:ff:ff:ff:ff BSSID=ff:ff:ff:ff:ff:ff (tx_last_beacon=1)
[53011.323892] wlan0: RX ProbeReq SA=00:22:43:2c:76:0f DA=ff:ff:ff:ff:ff:ff BSSID=ff:ff:ff:ff:ff:ff (tx_last_beacon=1)
[53106.964036] wlan0: RX ProbeReq SA=00:22:43:2c:76:0f DA=ff:ff:ff:ff:ff:ff BSSID=ff:ff:ff:ff:ff:ff (tx_last_beacon=1)
[53138.613029] wlan0: RX ProbeReq SA=00:22:43:2c:76:0f DA=ff:ff:ff:ff:ff:ff BSSID=ff:ff:ff:ff:ff:ff (tx_last_beacon=1)
[53266.603257] wlan0: RX ProbeReq SA=00:22:43:2c:76:0f DA=ff:ff:ff:ff:ff:ff BSSID=ff:ff:ff:ff:ff:ff (tx_last_beacon=1)
[53298.604621] wlan0: RX ProbeReq SA=00:22:43:2c:76:0f DA=ff:ff:ff:ff:ff:ff BSSID=ff:ff:ff:ff:ff:ff (tx_last_beacon=1)
[53330.599864] wlan0: RX ProbeReq SA=00:22:43:2c:76:0f DA=ff:ff:ff:ff:ff:ff BSSID=ff:ff:ff:ff:ff:ff (tx_last_beacon=1)
[53362.598110] wlan0: RX ProbeReq SA=00:22:43:2c:76:0f DA=ff:ff:ff:ff:ff:ff BSSID=ff:ff:ff:ff:ff:ff (tx_last_beacon=1)
[53382.140098] wlan0: RX ProbeReq SA=00:22:43:2c:76:0f DA=ff:ff:ff:ff:ff:ff BSSID=ff:ff:ff:ff:ff:ff (tx_last_beacon=1)
[53382.140104] wlan0: Sending ProbeResp to 00:22:43:2c:76:0f
[53413.898474] wlan0: RX ProbeReq SA=00:22:43:2c:76:0f DA=ff:ff:ff:ff:ff:ff BSSID=ff:ff:ff:ff:ff:ff (tx_last_beacon=1)

Richard

Re: 2.6.31.[12] ath5k regression

[Richard Zidlicky]

Hi,

small update, it appears to work very nicely in 2.6.32. No idea what really
caused it, or what fixed it in the end.

Richard

On Mon, Oct 12, 2009 at 07:54:38PM -0400, Bob Copeland wrote:
> On Mon, Oct 12, 2009 at 10:23:16PM +0200, Richard Zidlicky wrote:
> > it works like in mainline and fails.
> 
> Huh, well it should be equivalent to your patch, so I'm stumped
> as to why.
> 
> -- 
> Bob Copeland %% www.bobcopeland.com
>