Backtraces and 'please file's with latest git and rt61pci

Live forum: http://rt2x00.serialmonkey.com/viewtopic.php?t=4788

Thikasabrik

12-05-2008 08:52:26

Testing the latest git to see if it holds the link longer than the current in-kernel version. It does, a bit, but it also has issues....
[code3iz86uq2]May 11 20:48:15 wlan0: Initial auth_alg=0
May 11 20:48:15 wlan0: authenticate with AP <mac>
May 11 20:48:15 wlan0: RX authentication from <mac> (alg=0 transaction=2 status=0)
May 11 20:48:15 wlan0: authenticated
May 11 20:48:15 wlan0: associate with AP <mac>
May 11 20:48:15 wlan0: RX AssocResp from <mac> (capab=0x411 status=0 aid=1)
May 11 20:48:15 wlan0: associated
May 11 20:48:15 phy0 -> rt2x00mac_conf_tx: Info - Configured TX queue 2 - CWmin: 4, CWmax: 10, Aifs: 3.
May 11 20:48:15 phy0 -> rt2x00mac_conf_tx: Info - Configured TX queue 3 - CWmin: 4, CWmax: 10, Aifs: 7.
May 11 20:48:15 phy0 -> rt2x00mac_conf_tx: Info - Configured TX queue 1 - CWmin: 3, CWmax: 4, Aifs: 2.
May 11 20:48:15 phy0 -> rt2x00mac_conf_tx: Info - Configured TX queue 0 - CWmin: 2, CWmax: 3, Aifs: 2.
May 11 20:48:15 wlan0: CTS protection enabled (BSSID=<mac>)
May 11 20:48:15 ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
May 11 20:48:15 NetworkManager: <info> Supplicant state changed: 1
////////Time passes..//////////
May 11 21:14:08 wlan0: No ProbeResp from current AP <mac> - assume out of range
May 11 21:14:08 ------------[ cut here ]------------
May 11 21:14:08 WARNING: at kernel/softirq.c:141 local_bh_enable+0x1f/0x64()
May 11 21:14:08 Modules linked in: aes_i586 aes_generic af_packet ipv6 radeon drm xt_tcpudp nf_conntrack_ipv4 xt_state nf
May 11 21:14:08 Pid: 2279, comm: rt61pci Not tainted 2.6.26-beyondash #2
May 11 21:14:08 [<c011704c>] warn_on_slowpath+0x40/0x79
May 11 21:14:08 [<c0128ea0>] ktime_get+0xd/0x2b
May 11 21:14:08 [<c0112dad>] check_preempt_wakeup+0xe2/0x13e
May 11 21:14:08 [<c01261dd>] autoremove_wake_function+0xd/0x2d
May 11 21:14:08 [<c011288d>] __wake_up_common+0x2d/0x52
May 11 21:14:08 [<c0114d47>] __wake_up+0x1d/0x3d
May 11 21:14:08 NetworkManager: <info> Supplicant state changed: 0
May 11 21:14:09 [<c012377e>] insert_work+0x4f/0x52
May 11 21:14:09 [<c0123916>] queue_work+0x2c/0x4f
May 11 21:14:09 [<c011b04b>] local_bh_enable+0x1f/0x64
May 11 21:14:09 [<e19077af>] __sta_info_unlink+0xb7/0x142 [mac80211]
May 11 21:14:09 [<e1907901>] sta_info_unlink+0x14/0x2e [mac80211]
May 11 21:14:09 [<e190d0e7>] ieee80211_associated+0xac/0x15c [mac80211]
May 11 21:14:09 [<e190d81a>] ieee80211_sta_work+0x0/0x1488 [mac80211]
May 11 21:14:09 [<e190eaad>] ieee80211_sta_work+0x1293/0x1488 [mac80211]
May 11 21:14:09 [<e1914d9e>] ___ieee80211_tx+0x6a/0x75 [mac80211]
May 11 21:14:09 [<e19151de>] ieee80211_master_start_xmit+0x435/0x4b7 [mac80211]
May 11 21:14:09 [<e18db75f>] rt61pci_config+0x3f/0x4cd [rt61pci]
May 11 21:14:09 [<c012a70d>] getnstimeofday+0x32/0xb0
May 11 21:14:09 [<c012a70d>] getnstimeofday+0x32/0xb0
May 11 21:14:09 [<c01b006f>] rb_insert_color+0x93/0xb5
May 11 21:14:09 [<c011232a>] update_curr+0x3d/0x5d
May 11 21:14:09 [<c01129ff>] __dequeue_entity+0x1f/0x71
May 11 21:14:09 [<c01239dd>] worker_thread+0x0/0xb8
May 11 21:14:09 [<c0113192>] pick_next_task_fair+0xfc/0x10f
May 11 21:14:09 [<c021fa10>] cpuidle_idle_call+0x0/0x7d
May 11 21:14:09 [<c0280a2c>] schedule+0x28b/0x2bf
May 11 21:14:09 [<e190d81a>] ieee80211_sta_work+0x0/0x1488 [mac80211]
May 11 21:14:09 [<c0123697>] run_workqueue+0x83/0x11b
May 11 21:14:09 [<c01239dd>] worker_thread+0x0/0xb8
May 11 21:14:09 [<c0123a8a>] worker_thread+0xad/0xb8
May 11 21:14:09 [<c01261d0>] autoremove_wake_function+0x0/0x2d
May 11 21:14:09 [<c01239dd>] worker_thread+0x0/0xb8
May 11 21:14:09 [<c0125e3c>] kthread+0x36/0x5a
May 11 21:14:09 [<c0125e06>] kthread+0x0/0x5a
May 11 21:14:09 [<c010369b>] kernel_thread_helper+0x7/0x10
May 11 21:14:09 =======================
May 11 21:14:09 ---[ end trace 438b607766bafa55 ]---
May 11 21:14:09 wlan0: Initial auth_alg=0
May 11 21:14:09 wlan0: authenticate with AP <mac>
May 11 21:14:09 wlan0: Initial auth_alg=0
May 11 21:14:09 wlan0: authenticate with AP <mac>
May 11 21:14:09 wlan0: RX authentication from <mac> (alg=0 transaction=2 status=0)
May 11 21:14:09 wlan0: authenticated
May 11 21:14:09 wlan0: associate with AP <mac>
May 11 21:14:09 wlan0: authentication frame received from <mac>, but not in authenticate state - ignored
May 11 21:14:09 wlan0: authentication frame received from <mac>, but not in authenticate state - ignored
May 11 21:14:09 wlan0: RX ReassocResp from <mac> (capab=0x411 status=0 aid=1)
May 11 21:14:09 wlan0: associated
May 11 21:14:09 phy0 -> rt2x00mac_conf_tx: Info - Configured TX queue 2 - CWmin: 4, CWmax: 10, Aifs: 3.
May 11 21:14:09 phy0 -> rt2x00mac_conf_tx: Info - Configured TX queue 3 - CWmin: 4, CWmax: 10, Aifs: 7.
May 11 21:14:09 phy0 -> rt2x00mac_conf_tx: Info - Configured TX queue 1 - CWmin: 3, CWmax: 4, Aifs: 2.
May 11 21:14:09 phy0 -> rt2x00mac_conf_tx: Info - Configured TX queue 0 - CWmin: 2, CWmax: 3, Aifs: 2.
May 11 21:14:09 wlan0: CTS protection enabled (BSSID=<mac>)
May 11 21:14:09 wlan0: association frame received from <mac>, but not in associate state - ignored
May 11 21:14:09 NetworkManager: <info> Supplicant state changed: 1
May 11 21:15:33 wlan0: No ProbeResp from current AP <mac> - assume out of range
May 11 21:15:33 NetworkManager: <info> Supplicant state changed: 0
May 11 21:15:34 wlan0: Initial auth_alg=0
May 11 21:15:34 wlan0: authenticate with AP <mac>
May 11 21:15:34 wlan0: Initial auth_alg=0
May 11 21:15:34 wlan0: authenticate with AP <mac>
May 11 21:15:34 wlan0: RX authentication from <mac> (alg=0 transaction=2 status=0)
May 11 21:15:34 wlan0: authenticated
May 11 21:15:34 wlan0: associate with AP <mac>
May 11 21:15:34 wlan0: associate with AP <mac>
May 11 21:15:34 wlan0: RX ReassocResp from <mac> (capab=0x411 status=0 aid=1)
May 11 21:15:34 wlan0: associated
May 11 21:15:34 phy0 -> rt2x00mac_conf_tx: Info - Configured TX queue 2 - CWmin: 4, CWmax: 10, Aifs: 3.
May 11 21:15:34 phy0 -> rt2x00mac_conf_tx: Info - Configured TX queue 3 - CWmin: 4, CWmax: 10, Aifs: 7.
May 11 21:15:34 phy0 -> rt2x00mac_conf_tx: Info - Configured TX queue 1 - CWmin: 3, CWmax: 4, Aifs: 2.
May 11 21:15:34 phy0 -> rt2x00mac_conf_tx: Info - Configured TX queue 0 - CWmin: 2, CWmax: 3, Aifs: 2.
May 11 21:15:34 wlan0: CTS protection enabled (BSSID=<mac>)
May 11 21:15:34 wlan0: association frame received from <mac>, but not in associate state - ignored
May 11 21:15:35 NetworkManager: <info> Supplicant state changed: 1
May 11 21:21:52 wlan0: No ProbeResp from current AP <mac> - assume out of range
May 11 21:21:52 NetworkManager: <info> Supplicant state changed: 0
May 11 21:21:53 wlan0: Initial auth_alg=0
May 11 21:21:53 wlan0: authenticate with AP <mac>
May 11 21:21:53 wlan0: Initial auth_alg=0
May 11 21:21:53 wlan0: authenticate with AP <mac>
May 11 21:21:53 wlan0: RX authentication from <mac> (alg=0 transaction=2 status=0)
May 11 21:21:53 wlan0: authenticated
May 11 21:21:53 wlan0: associate with AP <mac>
May 11 21:21:53 wlan0: authentication frame received from <mac>, but not in authenticate state - ignored
May 11 21:21:53 wlan0: RX ReassocResp from <mac> (capab=0x411 status=0 aid=1)
May 11 21:21:53 wlan0: associated
May 11 21:21:53 phy0 -> rt2x00mac_conf_tx: Info - Configured TX queue 2 - CWmin: 4, CWmax: 10, Aifs: 3.
May 11 21:21:53 phy0 -> rt2x00mac_conf_tx: Info - Configured TX queue 3 - CWmin: 4, CWmax: 10, Aifs: 7.
May 11 21:21:53 phy0 -> rt2x00mac_conf_tx: Info - Configured TX queue 1 - CWmin: 3, CWmax: 4, Aifs: 2.
May 11 21:21:53 phy0 -> rt2x00mac_conf_tx: Info - Configured TX queue 0 - CWmin: 2, CWmax: 3, Aifs: 2.
May 11 21:21:53 wlan0: CTS protection enabled (BSSID=<mac>)
May 11 21:21:54 NetworkManager: <info> Supplicant state changed: 1
///////Time passes again...//////
May 11 23:34:50 wlan0: No ProbeResp from current AP <mac> - assume out of range
May 11 23:34:51 wlan0: Initial auth_alg=0
May 11 23:34:51 wlan0: authenticate with AP <mac>
May 11 23:34:51 wlan0: Initial auth_alg=0
May 11 23:34:51 wlan0: authenticate with AP <mac>
May 11 23:34:51 wlan0: RX authentication from <mac> (alg=0 transaction=2 status=0)
May 11 23:34:51 wlan0: authenticated
May 11 23:34:51 wlan0: associate with AP <mac>
May 11 23:34:51 wlan0: authentication frame received from <mac>, but not in authenticate state - ignored
May 11 23:34:51 wlan0: authentication frame received from <mac>, but not in authenticate state - ignored
May 11 23:34:52 wlan0: associate with AP <mac>
May 11 23:34:52 wlan0: associate with AP <mac>
May 11 23:34:52 wlan0: association with AP <mac> timed out
May 11 23:34:55 wlan0: RX deauthentication from <mac> (reason=1)
May 11 23:34:55 wlan0: deauthenticated
May 11 23:35:04 wlan0: Initial auth_alg=0
May 11 23:35:04 wlan0: authenticate with AP <mac>
May 11 23:35:04 NetworkManager: <info> SUP: response was 'OK'
May 11 23:35:04 NetworkManager: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
May 11 23:35:04 wlan0: authenticate with AP <mac>
May 11 23:35:04 wlan0: authenticate with AP <mac>
May 11 23:35:04 wlan0: authentication with AP <mac> timed out
May 11 23:35:19 NetworkManager: <info> Old device 'wlan0' activating, won't change.
May 11 23:35:24 NetworkManager: <info> Activation (wlan0/wireless): association took too long (>20s), failing activation
May 11 23:35:24 NetworkManager: <info> Activation (wlan0) failed for access point (<ssid>)
May 11 23:35:24 NetworkManager: <info> Activation (wlan0) failed.
May 11 23:35:24 NetworkManager: <info> Deactivating device wlan0.
May 11 23:35:24 NetworkManager: <info> Activation (wlan0) failure scheduled...
May 11 23:35:24 NetworkManager: <WARN> nm_signal_handler(): Caught signal 11. Generating backtrace...
//////NM Backtrace skipped/////
//////Manually restarted NM/////
May 11 23:38:32 NetworkManager: <info> starting...
May 11 23:38:35 ADDRCONF(NETDEV_UP): wlan0: link is not ready
May 11 23:38:35 NetworkManager: <info> wlan0: Device is fully-supported using driver '(null)'.
May 11 23:38:35 NetworkManager: <info> wlan0: driver supports SSID scans (scan_capa 0x01).
May 11 23:38:35 NetworkManager: <info> nm_device_init(): waiting for device's worker thread to start
May 11 23:38:35 NetworkManager: <info> nm_device_init(): device's worker thread started, continuing.
May 11 23:38:35 NetworkManager: <info> Now managing wireless (802.11) device 'wlan0'.
May 11 23:38:35 NetworkManager: <info> Deactivating device wlan0.
May 11 23:38:36 phy0 -> rt2x00queue_write_tx_frame: Error - Arrived at non-free entry in the non-full queue 0.
May 11 23:38:36 Please file bug report to http://rt2x00.serialmonkey.com.
May 11 23:38:36 ------------[ cut here ]------------
May 11 23:38:36 WARNING: at net/mac80211/tx.c:1094 ___ieee80211_tx+0x43/0x75 [mac80211]()
May 11 23:38:36 Modules linked in: aes_i586 aes_generic af_packet ipv6 radeon drm xt_tcpudp nf_conntrack_ipv4 xt_state nf
_conntrack iptable_filter ip_tables x_tables snd_seq_oss snd_seq_midi_event snd_seq snd_seq_device joydev parport_pc arc4 snd_pc
m_oss ecb crypto_blkcipher snd_mixer_oss ppdev serio_raw snd_intel8x0 cryptomgr crypto_algapi snd_intel8x0m snd_ac97_codec pcmci
a ac97_bus snd_pcm lp parport snd_timer snd psmouse pcspkr soundcore snd_page_alloc sg i2c_i801 yenta_socket rsrc_nonstatic pcmc
ia_core 8139too mii uhci_hcd intel_agp agpgart video output evdev battery ac floppy rt61pci crc_itu_t rt2x00pci rt2x00lib firmwa
re_class rfkill led_class input_polldev mac80211 cfg80211 eeprom_93cx6 loop fuse rtc_cmos rtc_core rtc_lib usbcore sr_mod cdrom
sd_mod ata_piix libata scsi_mod dock ext3 jbd
May 11 23:38:36 Pid: 2279, comm: rt61pci Tainted: G W 2.6.26-beyondash #2
May 11 23:38:36 [<c011704c>] warn_on_slowpath+0x40/0x79
May 11 23:38:36 [<c012a70d>] getnstimeofday+0x32/0xb0
May 11 23:38:36 [<e18e31ba>] rt2x00queue_write_tx_frame+0x56/0xa8 [rt2x00lib]
May 11 23:38:36 [<c011afcc>] irq_exit+0x58/0x63
May 11 23:38:36 [<c0104de6>] do_IRQ+0x9a/0xb0
May 11 23:38:36 [<e18e254b>] rt2x00mac_tx+0x239/0x26e [rt2x00lib]
May 11 23:38:36 [<e1914d77>] ___ieee80211_tx+0x43/0x75 [mac80211]
May 11 23:38:36 [<e191515e>] ieee80211_master_start_xmit+0x3b5/0x4b7 [mac80211]
May 11 23:38:36 [<c02293f8>] __alloc_skb+0x45/0xf2
May 11 23:38:36 [<c022d4ca>] dev_hard_start_xmit+0x173/0x1df
May 11 23:38:36 [<c02390db>] __qdisc_run+0xbd/0x18e
May 11 23:38:36 [<c022d734>] dev_queue_xmit+0x120/0x264
May 11 23:38:36 [<e190c1a1>] ieee80211_sta_scan_work+0x147/0x171 [mac80211]
May 11 23:38:36 [<e190c05a>] ieee80211_sta_scan_work+0x0/0x171 [mac80211]
May 11 23:38:36 [<c0123697>] run_workqueue+0x83/0x11b
May 11 23:38:36 [<c01239dd>] worker_thread+0x0/0xb8
May 11 23:38:36 [<c0123a8a>] worker_thread+0xad/0xb8
May 11 23:38:36 [<c01261d0>] autoremove_wake_function+0x0/0x2d
May 11 23:38:36 [<c01239dd>] worker_thread+0x0/0xb8
May 11 23:38:36 [<c0125e3c>] kthread+0x36/0x5a
May 11 23:38:36 [<c0125e06>] kthread+0x0/0x5a
May 11 23:38:36 [<c010369b>] kernel_thread_helper+0x7/0x10
May 11 23:38:36 =======================
May 11 23:38:36 ---[ end trace 438b607766bafa55 ]---
May 11 23:38:36 BUG wmaster0 code -16 qlen 0
May 11 23:39:07 phy0 -> rt2x00queue_write_tx_frame: Error - Arrived at non-free entry in the non-full queue 0.
May 11 23:39:07 Please file bug report to http://rt2x00.serialmonkey.com.
May 11 23:39:07 BUG wmaster0 code -16 qlen 0
[/code3iz86uq2]
So, although in between all this I had extended periods of trouble-free use, NM eventually died, and the driver with it, apparently.
Then it was stuck. I had to reload the driver (I also ejected and replaced the wlan card) to get it to associate again.
Looks like there's some nice helpful BUGs in there though. If you need more, just ask.

IvD

12-05-2008 09:21:14

Thanks for the traces, I'll look into them.