2007-08-08 22:55:11

by Adam Baker

[permalink] [raw]
Subject: Kernel BUG when using ad-hoc mode in rt2x00

I've been seeing crashes when attempting to run an RT73 based device in ad-hoc
mode (I'm using the rt2x00 git tree). I recently managed to capture the
console output when it crashes and it all seems to point more to mac80211
than the rt2x00 driver so I thought I'd ask here.

a) If anyone can see anything obvious wrong in the trace
b) If anyone has recently tested ad-hoc mode with another driver and can
confirm it works.

The sequence of events that leads to the crash is
iwconfig wlan1 mode ad-hoc
ifconfig wlan1 192.168.0.230
iwconfig wlan1 channel 11
iwconfig wlan1 essid test

then attempt a scan from another device.

My guess is that the lockdep warning is caused by trying to lock something in
which the actual lock object has become corrupted hence it shortly afterwards
deadlocks.

[ 7053.830623] INFO: trying to register non-static key.
[ 7053.835989] the code is fine but needs lockdep annotation.
[ 7053.841919] turning off the locking correctness validator.
[ 7053.847832] [<c01470f3>] __lock_acquire+0x573/0x1020
[ 7053.853332] [<c01465f7>] trace_hardirqs_on+0xb7/0x160
[ 7053.858920] [<c01473a5>] __lock_acquire+0x825/0x1020
[ 7053.864420] [<c0147c00>] lock_acquire+0x60/0x80
[ 7053.869450] [<c02c882c>] skb_queue_tail+0x1c/0x50
[ 7053.874664] [<c03432c8>] _spin_lock_irqsave+0x38/0x50
[ 7053.880226] [<c02c882c>] skb_queue_tail+0x1c/0x50
[ 7053.885379] [<c02c882c>] skb_queue_tail+0x1c/0x50
[ 7053.890543] [<e0ac536f>] ieee80211_tx_h_ps_buf+0xaf/0x270 [mac80211]
[ 7053.897543] [<e0ad15c5>] sta_info_get+0x55/0x60 [mac80211]
[ 7053.903601] [<e0ad15c5>] sta_info_get+0x55/0x60 [mac80211]
[ 7053.909662] [<e0ac8325>] ieee80211_master_start_xmit+0x2b5/0x600
[mac80211]
[ 7053.917346] [<c02ced0b>] dev_hard_start_xmit+0x1fb/0x2d0
[ 7053.923189] [<c02dfba3>] __qdisc_run+0x53/0x1c0
[ 7053.928221] [<c02dfbcd>] __qdisc_run+0x7d/0x1c0
[ 7053.933226] [<c02d0f62>] dev_queue_xmit+0x2e2/0x330
[ 7053.938595] [<e0ad8101>] ieee80211_sta_scan_work+0x201/0x240 [mac80211]
[ 7053.945878] [<e0ad7f00>] ieee80211_sta_scan_work+0x0/0x240 [mac80211]
[ 7053.952962] [<c01465f7>] trace_hardirqs_on+0xb7/0x160
[ 7053.958521] [<c0138b6e>] run_workqueue+0xe/0x150
[ 7053.963620] [<e0ad7f00>] ieee80211_sta_scan_work+0x0/0x240 [mac80211]
[ 7053.970711] [<c0138c1f>] run_workqueue+0xbf/0x150
[ 7053.975904] [<c0139610>] worker_thread+0x0/0x100
[ 7053.981018] [<c01396b0>] worker_thread+0xa0/0x100
[ 7053.986174] [<c013c600>] autoremove_wake_function+0x0/0x50
[ 7053.992212] [<c0139610>] worker_thread+0x0/0x100
[ 7053.997298] [<c013c382>] kthread+0x42/0x70
[ 7054.001799] [<c013c340>] kthread+0x0/0x70
[ 7054.006235] [<c0105537>] kernel_thread_helper+0x7/0x10
[ 7054.011925] =======================
[ 7059.169014] BUG: NMI Watchdog detected LOCKUP on CPU0, eip c022ba50,
registers:
[ 7059.176941] Modules linked in: rfcomm l2cap binfmt_misc cpufreq_powersave
cpufreq_stats cpufreq_userspace cpufreq_ondemand cpufreq_conservative
freq_table video output battery container sbs fan button thermal processor
dock ac bluetooth sg ipv6 nfs lockd sd_mod sunrpc asb100 hwmon_vid af_packet
lp rt2500usb arc4 ecb blkcipher rc80211_simple usb_storage rt73usb scsi_mod
rt2x00usb rt2x00lib input_polldev crc_itu_t libusual mac80211 snd_ens1371
gameport snd_rawmidi snd_seq_device snd_ac97_codec ac97_bus snd_pcm_oss
snd_mixer_oss snd_pcm snd_timer tsdev i2c_viapro snd 8139too i2c_core
ehci_hcd uhci_hcd via_agp serio_raw via_ircc soundcore snd_page_alloc shpchp
8139cp irda agpgart mii usbcore crc_ccitt parport_pc parport pci_hotplug
evdev psmouse floppy pcspkr
[ 7059.250390] CPU: 0
[ 7059.250391] EIP: 0060:[<c022ba50>] Not tainted VLI
[ 7059.250392] EFLAGS: 00000046 (2.6.23-rc1 #6)
[ 7059.263355] EIP is at __delay+0x0/0x10
[ 7059.267415] eax: 00000001 ebx: dbb0591c ecx: 17e8625e edx: 65e66186
[ 7059.274755] esi: 0e6cdab6 edi: 00000000 ebp: 6b8abb30 esp: dba03d94
[ 7059.282066] ds: 007b es: 007b fs: 00d8 gs: 0000 ss: 0068
[ 7059.288351] Process rt73usb (pid: 2160, ti=dba02000 task=dfde2630
task.ti=dba02000)
[ 7059.296435] Stack: c022e478 dfde2c1c 00000046 dbb0592c dbb0591c cc617c28
00000001 6b8abb30
[ 7059.305694] 00000000 dbb0591c 00000296 dbb0591c cc617c28 c03432cf
00000000 00000002
[ 7059.314912] c02c882c dbb05910 d2503b40 c02c882c 00000000 dba03e5c
00000001 e0ac536f
[ 7059.324030] Call Trace:
[ 7059.326872] [<c022e478>] _raw_spin_lock+0xb8/0x150
[ 7059.332164] [<c03432cf>] _spin_lock_irqsave+0x3f/0x50
[ 7059.337747] [<c02c882c>] skb_queue_tail+0x1c/0x50
[ 7059.342898] [<c02c882c>] skb_queue_tail+0x1c/0x50
[ 7059.348062] [<e0ac536f>] ieee80211_tx_h_ps_buf+0xaf/0x270 [mac80211]
[ 7059.355059] [<e0ad15c5>] sta_info_get+0x55/0x60 [mac80211]
[ 7059.361120] [<e0ad15c5>] sta_info_get+0x55/0x60 [mac80211]
[ 7059.367182] [<e0ac8325>] ieee80211_master_start_xmit+0x2b5/0x600
[mac80211]
[ 7059.374865] [<c02ced0b>] dev_hard_start_xmit+0x1fb/0x2d0
[ 7059.380674] [<c02dfba3>] __qdisc_run+0x53/0x1c0
[ 7059.385651] [<c02dfbcd>] __qdisc_run+0x7d/0x1c0
[ 7059.390651] [<c02d0f62>] dev_queue_xmit+0x2e2/0x330
[ 7059.396052] [<e0ad8101>] ieee80211_sta_scan_work+0x201/0x240 [mac80211]
[ 7059.403333] [<e0ad7f00>] ieee80211_sta_scan_work+0x0/0x240 [mac80211]
[ 7059.410431] [<c01465f7>] trace_hardirqs_on+0xb7/0x160
[ 7059.415985] [<c0138b6e>] run_workqueue+0xe/0x150
[ 7059.421090] [<e0ad7f00>] ieee80211_sta_scan_work+0x0/0x240 [mac80211]
[ 7059.428169] [<c0138c1f>] run_workqueue+0xbf/0x150
[ 7059.433389] [<c0139610>] worker_thread+0x0/0x100
[ 7059.438511] [<c01396b0>] worker_thread+0xa0/0x100
[ 7059.443727] [<c013c600>] autoremove_wake_function+0x0/0x50
[ 7059.449758] [<c0139610>] worker_thread+0x0/0x100
[ 7059.454882] [<c013c382>] kthread+0x42/0x70
[ 7059.459412] [<c013c340>] kthread+0x0/0x70
[ 7059.463850] [<c0105537>] kernel_thread_helper+0x7/0x10
[ 7059.469544] =======================
[ 7059.473412] Code: c0 80 ba 22 c0 c3 90 8d 74 26 00 81 3d e4 8e 42 c0 80 ba
22 c0 89 c1 b8 ff ff ff ff 74 02 f3 c3 0f 31 89 01 31 c0 c3 8d 74 26 00 <ff>
15 e4 8e 42 c0 f3 c3 90 8d b4 26 00 00 00 00 64 8b 15 08 40


2007-08-16 13:45:25

by Johannes Berg

[permalink] [raw]
Subject: Re: Kernel BUG when using ad-hoc mode in rt2x00

On Wed, 2007-08-15 at 22:49 +0100, Adam Baker wrote:

> Aug 15 22:28:20 gromit kernel: [ 286.592323] wlan1: Creating new IBSS network, BSSID 2a:3f:11:b4:62:c9
> Aug 15 22:28:20 gromit kernel: [ 286.593514] HW CONFIG: channel=11 freq=2462 phymode=3
> Aug 15 22:28:20 gromit kernel: [ 286.607980] wlan1: Configured IBSS beacon template based on scan results
> Aug 15 22:28:40 gromit kernel: [ 306.008510] wmaster0: Adding new IBSS station 00:19:4f:9e:b8:ba (dev=wlan1)
> Aug 15 22:28:40 gromit kernel: [ 306.008693] wmaster0: Added STA 00:19:4f:9e:b8:ba
> Aug 15 22:28:40 gromit kernel: [ 306.008742] wlan1: STA 00:19:4f:9e:b8:ba aid 0 enters power save mode
> Aug 15 22:28:42 gromit kernel: [ 308.022518] wlan1: STA 00:19:4f:9e:b8:ba aid 0 exits power save mode
> Aug 15 22:28:44 gromit kernel: [ 309.966798] wlan1: STA 00:19:4f:9e:b8:ba aid 0 enters power save mode

So that MAC address, which device is that? Is that some other device or
somehow your own?

johannes


Attachments:
signature.asc (190.00 B)
This is a digitally signed message part

2007-08-20 20:21:42

by Adam Baker

[permalink] [raw]
Subject: Re: Kernel BUG when using ad-hoc mode in rt2x00

On Friday 17 August 2007 11:13, Johannes Berg wrote:
>
> Hm. Maybe you could disable verbose debugging in the ralink drivers to
> get a lower printk rate; however, this is weird, I think I'll have to
> try to reproduce it.
>
I've instead obtained a faster terminal, taken out the printk on ieee80211_master_start_xmit
as that wasn't telling us much and added a couple more printk's

One is in ieee80211_if_set_type at the only point where I can see u.ap.ps_bc_buf could get
initialised and as I suspected that doesn't get called.
case IEEE80211_IF_TYPE_AP:
sdata->u.ap.dtim_period = 2;
sdata->u.ap.force_unicast_rateidx = -1;
sdata->u.ap.max_ratectrl_rateidx = -1;
skb_queue_head_init(&sdata->u.ap.ps_bc_buf);
printk( KERN_DEBUG "Initiatilsing ps_bc_buf at %p\n",&sdata->u.ap.ps_bc_buf);
sdata->bss = &sdata->u.ap;
break;

The other is in ieee80211_tx_h_multicast_ps_buf just before tx->sdata->bss->ps_bc_buf gets
used. I haven't quite followed what ap structure bss should be pointing to at that time but I'm
presuming whatever it is doesn't contain an initialised ps_bc_buf hence the lock failure.

printk( KERN_INFO "About to queue skb %p to buffer %p\n",tx->skb, &tx->sdata->bss->ps_bc_buf);
skb_queue_tail(&tx->sdata->bss->ps_bc_buf, tx->skb);



[ 1358.490901] phy4 -> rt2x00lib_request_firmware: Info - Loading firmware file 'rt73.bin'.
[ 1358.509476] phy4 -> rt2x00lib_request_firmware: Info - Firmware detected - version: 1.7.
[ 1358.565453] phy4 -> rt73usb_init_bbp: Debug - Start initialization from EEPROM...
[ 1358.573378] phy4 -> rt73usb_init_bbp: Debug - ...End initialization from EEPROM.
[ 1358.586965] HW CONFIG: channel=1 freq=2412 phymode=3
[ 1358.619446] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1358.627387] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1358.634066] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1358.648203] HW CONFIG: channel=11 freq=2462 phymode=3
[ 1358.682333] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1358.699790] phy4 -> rt2x00mac_conf_tx: Info - Configured TX ring 0 - CWmin: 4, CWmax: 10, Aifs: 2.
[ 1358.709530] phy4 -> rt2x00mac_conf_tx: Info - Configured TX ring 1 - CWmin: 4, CWmax: 10, Aifs: 2.
[ 1358.719248] phy4 -> rt2x00mac_conf_tx: Info - Configured TX ring 2 - CWmin: 4, CWmax: 10, Aifs: 2.
[ 1358.728958] phy4 -> rt2x00mac_conf_tx: Info - Configured TX ring 3 - CWmin: 4, CWmax: 10, Aifs: 2.
[ 1358.738673] phy4 -> rt2x00mac_conf_tx: Info - Configured TX ring 4 - CWmin: 4, CWmax: 10, Aifs: 2.
[ 1358.748367] phy4 -> rt2x00mac_conf_tx: Info - Configured TX ring 7 - CWmin: 5, CWmax: 10, Aifs: 2.
[ 1358.758042] wlan1: Trigger new scan to find an IBSS to join
[ 1358.784674] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1358.793919] HW CONFIG: channel=1 freq=2412 phymode=3
[ 1358.855430] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1358.863375] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1358.870162] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1358.899358] HW CONFIG: channel=2 freq=2417 phymode=3
[ 1358.959295] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1358.967225] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1358.973893] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1359.003330] HW CONFIG: channel=3 freq=2422 phymode=3
[ 1359.063266] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1359.071184] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1359.077874] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1359.108220] HW CONFIG: channel=4 freq=2427 phymode=3
[ 1359.168078] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1359.175982] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1359.182725] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1359.211205] HW CONFIG: channel=5 freq=2432 phymode=3
[ 1359.271307] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1359.279236] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1359.285962] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1359.315170] HW CONFIG: channel=6 freq=2437 phymode=3
[ 1359.375181] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1359.383120] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1359.389943] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1359.419206] HW CONFIG: channel=7 freq=2442 phymode=3
[ 1359.479142] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1359.487076] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1359.493800] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1359.523180] HW CONFIG: channel=8 freq=2447 phymode=3
[ 1359.583111] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1359.591058] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1359.597781] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1359.628117] HW CONFIG: channel=9 freq=2452 phymode=3
[ 1359.688023] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1359.695949] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1359.702763] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1359.731052] HW CONFIG: channel=10 freq=2457 phymode=3
[ 1359.791063] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1359.798986] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1359.805742] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1359.835016] HW CONFIG: channel=11 freq=2462 phymode=3
[ 1359.895016] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1359.902930] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1359.909723] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1359.916100] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1359.943001] HW CONFIG: channel=11 freq=2462 phymode=3
[ 1359.963638] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1359.971435] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1359.978005] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1360.013076] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1360.115434] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1360.217788] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1360.320146] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1360.326786] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1360.334677] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1360.341392] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1360.422630] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1360.524985] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1360.627341] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1360.729697] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1360.832054] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1360.934408] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1361.036766] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1361.139125] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1361.211736] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1361.218304] wmaster0: Adding new IBSS station 00:19:4f:9e:b8:ba (dev=wlan1)
[ 1361.225846] wmaster0: Added STA 00:19:4f:9e:b8:ba
[ 1361.241481] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1361.343960] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1361.446316] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1361.548676] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1361.651027] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1361.753388] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1361.855746] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1361.958098] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1362.051290] wlan1: Trigger new scan to find an IBSS to join
[ 1362.060453] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1362.086345] HW CONFIG: channel=1 freq=2412 phymode=3
[ 1362.146344] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1362.154277] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1362.161066] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1362.191366] HW CONFIG: channel=2 freq=2417 phymode=3
[ 1362.251197] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1362.259136] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1362.265923] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1362.294292] HW CONFIG: channel=3 freq=2422 phymode=3
[ 1362.354333] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1362.362276] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1362.369026] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1362.398294] HW CONFIG: channel=4 freq=2427 phymode=3
[ 1362.458345] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1362.466288] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1362.472913] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1362.479633] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1362.506218] HW CONFIG: channel=5 freq=2432 phymode=3
[ 1362.566263] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1362.574205] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1362.580754] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1362.587488] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1362.615234] HW CONFIG: channel=6 freq=2437 phymode=3
[ 1362.675134] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1362.683061] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1362.689847] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1362.718583] HW CONFIG: channel=7 freq=2442 phymode=3
[ 1362.778161] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1362.786115] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1362.792825] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1362.822124] HW CONFIG: channel=8 freq=2447 phymode=3
[ 1362.882126] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1362.890060] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1362.896811] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1362.926261] HW CONFIG: channel=9 freq=2452 phymode=3
[ 1362.986100] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1362.994041] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1363.000788] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1363.030137] HW CONFIG: channel=10 freq=2457 phymode=3
[ 1363.084146] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1363.094061] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1363.101980] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1363.108771] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1363.139114] HW CONFIG: channel=11 freq=2462 phymode=3
[ 1363.186503] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1363.199095] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1363.207034] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1363.213755] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1363.242022] HW CONFIG: channel=11 freq=2462 phymode=3
[ 1363.288983] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1363.391343] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1363.493699] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1363.596054] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1363.698411] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1363.800766] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1363.903128] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1364.005481] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1364.107839] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1364.210196] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1364.312675] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1364.415034] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1364.517387] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1364.525666] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1364.533607] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1364.540390] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1364.619749] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1364.722103] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1364.824461] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1364.926817] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1365.029173] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1365.131654] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1365.234011] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1365.319769] wlan1: Trigger new scan to find an IBSS to join
[ 1365.336363] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1365.358235] HW CONFIG: channel=1 freq=2412 phymode=3
[ 1365.418412] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1365.426358] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1365.433100] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1365.461343] HW CONFIG: channel=2 freq=2417 phymode=3
[ 1365.521352] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1365.529292] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1365.536086] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1365.565303] HW CONFIG: channel=3 freq=2422 phymode=3
[ 1365.625307] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1365.633251] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1365.640067] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1365.669343] HW CONFIG: channel=4 freq=2427 phymode=3
[ 1365.729279] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1365.737197] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1365.743919] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1365.773309] HW CONFIG: channel=5 freq=2432 phymode=3
[ 1365.833244] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1365.841178] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1365.847900] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1365.854304] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1365.882301] HW CONFIG: channel=6 freq=2437 phymode=3
[ 1365.941254] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1365.949194] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1365.956009] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1365.986234] HW CONFIG: channel=7 freq=2442 phymode=3
[ 1366.046132] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1366.054054] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1366.060867] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1366.089151] HW CONFIG: channel=8 freq=2447 phymode=3
[ 1366.149157] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1366.157101] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1366.163843] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1366.193184] HW CONFIG: channel=9 freq=2452 phymode=3
[ 1366.253120] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1366.261036] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1366.267829] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1366.301950] HW CONFIG: channel=10 freq=2457 phymode=3
[ 1366.360060] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1366.373276] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1366.381212] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1366.387934] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1366.417060] HW CONFIG: channel=11 freq=2462 phymode=3
[ 1366.462415] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1366.477056] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1366.484996] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1366.491792] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1366.521180] HW CONFIG: channel=11 freq=2462 phymode=3
[ 1366.540954] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1366.548765] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1366.555400] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1366.564770] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1366.667126] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1366.769486] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1366.871842] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1366.974200] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1367.076679] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1367.179035] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1367.281396] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1367.383746] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1367.486103] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1367.588461] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1367.690815] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1367.793177] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1367.895530] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1367.997886] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1368.100371] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1368.202725] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1368.305081] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1368.407439] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1368.509794] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1368.604400] wlan1: Trigger new scan to find an IBSS to join
[ 1368.612152] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1368.640387] HW CONFIG: channel=1 freq=2412 phymode=3
[ 1368.700481] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1368.708413] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1368.715140] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1368.745500] HW CONFIG: channel=2 freq=2417 phymode=3
[ 1368.805364] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1368.813309] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1368.820122] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1368.848329] HW CONFIG: channel=3 freq=2422 phymode=3
[ 1368.908331] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1368.916254] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1368.922974] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1368.952323] HW CONFIG: channel=4 freq=2427 phymode=3
[ 1369.012294] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1369.020236] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1369.026958] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1369.056328] HW CONFIG: channel=5 freq=2432 phymode=3
[ 1369.116367] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1369.124314] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1369.131064] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1369.160298] HW CONFIG: channel=6 freq=2437 phymode=3
[ 1369.220234] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1369.228155] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1369.234919] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1369.265141] HW CONFIG: channel=7 freq=2442 phymode=3
[ 1369.325188] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1369.333121] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1369.339904] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1369.368173] HW CONFIG: channel=8 freq=2447 phymode=3
[ 1369.428180] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1369.436091] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1369.442883] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1369.472233] HW CONFIG: channel=9 freq=2452 phymode=3
[ 1369.532145] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1369.540071] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1369.546863] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1369.576178] HW CONFIG: channel=10 freq=2457 phymode=3
[ 1369.636107] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1369.644030] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1369.650721] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1369.680149] HW CONFIG: channel=11 freq=2462 phymode=3
[ 1369.738197] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1369.745442] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1369.753379] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1369.760197] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1369.789113] HW CONFIG: channel=11 freq=2462 phymode=3
[ 1369.804027] wlan1: no IPv6 routers present
[ 1369.814985] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1369.822806] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1369.829372] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1369.840558] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1369.942913] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1370.045394] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1370.147752] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1370.250106] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1370.352461] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1370.358977] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 384
[ 1370.365430] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 384
[ 1370.371925] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 448
[ 1370.378426] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 384
[ 1370.384922] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 448
[ 1370.391428] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 384
[ 1370.397925] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 448
[ 1370.404421] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 448
[ 1370.410930] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 448
[ 1370.417422] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 448
[ 1370.454822] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1370.557181] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1370.659535] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1370.762014] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1370.864371] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1370.966726] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1371.069088] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1371.171442] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1371.273799] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1371.376152] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1371.478514] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1371.580869] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1371.683349] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1371.785710] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1371.888061] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1371.947429] wlan1: Trigger new scan to find an IBSS to join
[ 1371.979459] HW CONFIG: channel=1 freq=2412 phymode=3
[ 1372.039397] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1372.047350] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1372.054038] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1372.083359] HW CONFIG: channel=2 freq=2417 phymode=3
[ 1372.151356] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1372.159291] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1372.166012] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1372.196260] HW CONFIG: channel=3 freq=2422 phymode=3
[ 1372.256213] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1372.264152] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1372.270875] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1372.299370] HW CONFIG: channel=4 freq=2427 phymode=3
[ 1372.359340] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1372.367288] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1372.374104] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1372.403305] HW CONFIG: channel=5 freq=2432 phymode=3
[ 1372.463332] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1372.471272] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1372.478087] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1372.502204] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1372.511359] HW CONFIG: channel=6 freq=2437 phymode=3
[ 1372.571230] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1372.579147] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1372.585941] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1372.616165] HW CONFIG: channel=7 freq=2442 phymode=3
[ 1372.650935] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1372.679206] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1372.687130] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1372.693921] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1372.723167] HW CONFIG: channel=8 freq=2447 phymode=3
[ 1372.783266] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1372.791197] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1372.797801] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1372.804525] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1372.831167] HW CONFIG: channel=9 freq=2452 phymode=3
[ 1372.891142] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1372.899065] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1372.905885] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1372.936081] HW CONFIG: channel=10 freq=2457 phymode=3
[ 1372.941601] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1373.003102] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1373.011049] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1373.017740] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1373.047140] HW CONFIG: channel=11 freq=2462 phymode=3
[ 1373.107073] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1373.115005] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1373.121623] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1373.128342] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1373.155117] HW CONFIG: channel=11 freq=2462 phymode=3
[ 1373.218825] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1373.232195] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1373.321183] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1373.423535] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1373.525893] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1373.628374] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1373.730728] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1373.833086] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1373.935442] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1374.037802] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1374.140157] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1374.242513] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1374.344870] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1374.447355] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1374.549706] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1374.652066] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1374.754419] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1374.856779] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1374.959133] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1375.061493] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1375.163849] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1375.200966] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1375.236983] wlan1: Trigger new scan to find an IBSS to join
[ 1375.266204] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1375.274417] HW CONFIG: channel=1 freq=2412 phymode=3
[ 1375.335340] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1375.343287] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1375.350070] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1375.378378] HW CONFIG: channel=2 freq=2417 phymode=3
[ 1375.438424] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1375.446361] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1375.453176] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1375.482649] HW CONFIG: channel=3 freq=2422 phymode=3
[ 1375.542343] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1375.550278] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1375.557027] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1375.586376] HW CONFIG: channel=4 freq=2427 phymode=3
[ 1375.646323] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1375.654222] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1375.661014] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1375.690455] HW CONFIG: channel=5 freq=2432 phymode=3
[ 1375.750283] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1375.758204] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1375.764994] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1375.795285] HW CONFIG: channel=6 freq=2437 phymode=3
[ 1375.855104] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1375.863041] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1375.869854] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1375.898293] HW CONFIG: channel=7 freq=2442 phymode=3
[ 1375.958227] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1375.966166] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1375.972957] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1376.002187] HW CONFIG: channel=8 freq=2447 phymode=3
[ 1376.062252] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1376.070185] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1376.076934] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1376.106225] HW CONFIG: channel=9 freq=2452 phymode=3
[ 1376.166155] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1376.174107] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1376.180795] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1376.210222] HW CONFIG: channel=10 freq=2457 phymode=3
[ 1376.270128] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1376.278054] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1376.284771] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1376.315107] HW CONFIG: channel=11 freq=2462 phymode=3
[ 1376.375077] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1376.383010] Leaving ieee80211_tx_h_multicast_ps_buf TXRX_CONTINUE
[ 1376.389752] phy4 -> rt2x00usb_interrupt_txdone: Debug - status 0
[ 1376.396133] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1376.426080] HW CONFIG: channel=11 freq=2462 phymode=3
[ 1376.494732] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1376.597092] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1376.699444] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1376.801806] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1376.904158] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1377.006520] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1377.108874] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1377.151117] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1377.157679] wlan1: STA 00:19:4f:9e:b8:ba aid 0 enters power save mode
[ 1377.211229] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1377.313714] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1377.416067] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1377.518421] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1377.620778] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1377.723134] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1377.825494] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1377.927852] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1378.030207] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1378.132564] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1378.234919] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1378.337401] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1378.439757] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1378.506770] wlan1: Trigger new scan to find an IBSS to join
[ 1378.537434] HW CONFIG: channel=1 freq=2412 phymode=3
[ 1378.542830] phy4 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[ 1378.605435] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[ 1378.613385] About to queue skb cd3cc3c0 to buffer c6eee910
[ 1378.619351] INFO: trying to register non-static key.
[ 1378.624717] the code is fine but needs lockdep annotation.
[ 1378.630651] turning off the locking correctness validator.
[ 1378.636560] [<c01464f3>] __lock_acquire+0x573/0x1020
[ 1378.642062] [<c01288b8>] vprintk+0x298/0x360
[ 1378.646815] [<c0147000>] lock_acquire+0x60/0x80
[ 1378.651839] [<c02c816c>] skb_queue_tail+0x1c/0x50
[ 1378.657055] [<c0342e78>] _spin_lock_irqsave+0x38/0x50
[ 1378.662644] [<c02c816c>] skb_queue_tail+0x1c/0x50
[ 1378.667805] [<c02c816c>] skb_queue_tail+0x1c/0x50
[ 1378.672994] [<e0ad9517>] ieee80211_tx_h_ps_buf+0xf7/0x3c0 [mac80211]
[ 1378.679991] [<e0ae5b85>] sta_info_get+0x55/0x60 [mac80211]
[ 1378.686050] [<e0adc5f5>] ieee80211_master_start_xmit+0x2b5/0x620 [mac80211]
[ 1378.693732] [<c02ce64b>] dev_hard_start_xmit+0x1fb/0x2d0
[ 1378.699577] [<c02df5c3>] __qdisc_run+0x53/0x1c0
[ 1378.704578] [<c02df5ed>] __qdisc_run+0x7d/0x1c0
[ 1378.709609] [<c02d09b2>] dev_queue_xmit+0x2e2/0x330
[ 1378.714984] [<e0aec701>] ieee80211_sta_scan_work+0x201/0x240 [mac80211]
[ 1378.722229] [<e0aec500>] ieee80211_sta_scan_work+0x0/0x240 [mac80211]
[ 1378.729288] [<c01459f7>] trace_hardirqs_on+0xb7/0x160
[ 1378.734850] [<c0137f7e>] run_workqueue+0xe/0x150
[ 1378.739946] [<e0aec500>] ieee80211_sta_scan_work+0x0/0x240 [mac80211]
[ 1378.747036] [<c013802f>] run_workqueue+0xbf/0x150
[ 1378.752229] [<c0138a20>] worker_thread+0x0/0x100
[ 1378.757319] [<c0138ac0>] worker_thread+0xa0/0x100
[ 1378.762502] [<c013ba10>] autoremove_wake_function+0x0/0x50
[ 1378.768538] [<c0138a20>] worker_thread+0x0/0x100
[ 1378.773623] [<c013b762>] kthread+0x42/0x70
[ 1378.778125] [<c013b720>] kthread+0x0/0x70
[ 1378.782539] [<c0105537>] kernel_thread_helper+0x7/0x10
[ 1378.788220] =======================
[ 1384.142553] BUG: NMI Watchdog detected LOCKUP on CPU0, eip c022d7fc, registers:
[ 1384.150444] Modules linked in: nls_cp437 isofs udf rfcomm l2cap bluetooth binfmt_misc cpufreq_powersave cpufreq_stats cpufreq_userspace cpufreq_ondemand cpufreq_conservative freq_table video output battery container sbs fan thermal dock ac ipv6 nfs lockd sunrpc asb100 hwmon_vid lp rt2500usb arc4 ecb blkcipher rc80211_simple af_packet rt73usb rt2x00usb rt2x00lib input_polldev crc_itu_t mac80211 snd_ens1371 gameport snd_rawmidi snd_seq_device snd_ac97_codec ac97_bus snd_pcm_oss snd_mixer_oss tsdev snd_pcm snd_timer 8139too serio_raw parport_pc evdev parport snd i2c_viapro i2c_core ehci_hcd psmouse floppy uhci_hcd via_ircc pcspkr soundcore snd_page_alloc 8139cp irda crc_ccitt mii shpchp usbcore pci_hotplug via_agp agpgart processor button
[ 1384.221432] CPU: 0
[ 1384.221433] EIP: 0060:[<c022d7fc>] Not tainted VLI
[ 1384.221435] EFLAGS: 00000046 (2.6.23-rc3 #11)
[ 1384.234489] EIP is at _raw_spin_lock+0xac/0x150
[ 1384.239396] eax: 00000000 ebx: c6eee91c ecx: fec8738b edx: 6490a1cc
[ 1384.246734] esi: 0f1a13aa edi: 00000000 ebp: 6b8ab266 esp: d8629d98
[ 1384.254036] ds: 007b es: 007b fs: 00d8 gs: 0000 ss: 0068
[ 1384.260333] Process rt73usb (pid: 4428, ti=d8628000 task=c7c1caa0 task.ti=d8628000)
[ 1384.268426] Stack: 00000041 00000046 c6eee92c c6eee91c ca60e028 00000001 6b8ab266 00000000
[ 1384.277544] c6eee91c 00000296 c6eee91c ca60e028 c0342e7f 00000000 00000002 c02c816c
[ 1384.286797] c6eee910 cd3cc3c0 c02c816c 00000000 d8629e5c 00000001 e0ad9517 e0afcf38
[ 1384.295915] Call Trace:
[ 1384.298765] [<c0342e7f>] _spin_lock_irqsave+0x3f/0x50
[ 1384.304319] [<c02c816c>] skb_queue_tail+0x1c/0x50
[ 1384.309534] [<c02c816c>] skb_queue_tail+0x1c/0x50
[ 1384.314753] [<e0ad9517>] ieee80211_tx_h_ps_buf+0xf7/0x3c0 [mac80211]
[ 1384.321727] [<e0ae5b85>] sta_info_get+0x55/0x60 [mac80211]
[ 1384.327788] [<e0adc5f5>] ieee80211_master_start_xmit+0x2b5/0x620 [mac80211]
[ 1384.335471] [<c02ce64b>] dev_hard_start_xmit+0x1fb/0x2d0
[ 1384.341315] [<c02df5c3>] __qdisc_run+0x53/0x1c0
[ 1384.346317] [<c02df5ed>] __qdisc_run+0x7d/0x1c0
[ 1384.351317] [<c02d09b2>] dev_queue_xmit+0x2e2/0x330
[ 1384.356686] [<e0aec701>] ieee80211_sta_scan_work+0x201/0x240 [mac80211]
[ 1384.363930] [<e0aec500>] ieee80211_sta_scan_work+0x0/0x240 [mac80211]
[ 1384.370993] [<c01459f7>] trace_hardirqs_on+0xb7/0x160
[ 1384.376552] [<c0137f7e>] run_workqueue+0xe/0x150
[ 1384.381625] [<e0aec500>] ieee80211_sta_scan_work+0x0/0x240 [mac80211]
[ 1384.388707] [<c013802f>] run_workqueue+0xbf/0x150
[ 1384.393873] [<c0138a20>] worker_thread+0x0/0x100
[ 1384.398962] [<c0138ac0>] worker_thread+0xa0/0x100
[ 1384.404178] [<c013ba10>] autoremove_wake_function+0x0/0x50
[ 1384.410208] [<c0138a20>] worker_thread+0x0/0x100
[ 1384.415298] [<c013b762>] kthread+0x42/0x70
[ 1384.419795] [<c013b720>] kthread+0x0/0x70
[ 1384.424205] [<c0105537>] kernel_thread_helper+0x7/0x10
[ 1384.429857] =======================
[ 1384.433699] Code: 44 24 1c 00 00 00 00 c7 44 24 14 01 00 00 00 89 6c 24 18 85 ed 74 36 31 c0 86 03 84 c0 7f a4 31 f6 31 ff eb 08 31 c0 86 03 84 c0 <7f> 96 b8 01 00 00 00 e8 d8 d5 ff ff 83 c6 01 83 d7 00 8b 54 24


2007-08-21 10:34:34

by Johannes Berg

[permalink] [raw]
Subject: Re: Kernel BUG when using ad-hoc mode in rt2x00


> One is in ieee80211_if_set_type at the only point where I can see u.ap.ps_bc_buf could get
> initialised and as I suspected that doesn't get called.
> case IEEE80211_IF_TYPE_AP:
> sdata->u.ap.dtim_period = 2;
> sdata->u.ap.force_unicast_rateidx = -1;
> sdata->u.ap.max_ratectrl_rateidx = -1;
> skb_queue_head_init(&sdata->u.ap.ps_bc_buf);
> printk( KERN_DEBUG "Initiatilsing ps_bc_buf at %p\n",&sdata->u.ap.ps_bc_buf);
> sdata->bss = &sdata->u.ap;
> break;

> The other is in ieee80211_tx_h_multicast_ps_buf just before tx->sdata->bss->ps_bc_buf gets
> used. I haven't quite followed what ap structure bss should be pointing to at that time but I'm
> presuming whatever it is doesn't contain an initialised ps_bc_buf hence the lock failure.
>
> printk( KERN_INFO "About to queue skb %p to buffer %p\n",tx->skb, &tx->sdata->bss->ps_bc_buf);
> skb_queue_tail(&tx->sdata->bss->ps_bc_buf, tx->skb);

At that point, sdata->bss should point to the master device, which
apparently hasn't been initialised yet. The device initialisation code
is pretty black magic to me, Jiri/Michael?

johannes


Attachments:
signature.asc (190.00 B)
This is a digitally signed message part

2007-08-15 10:46:23

by Johannes Berg

[permalink] [raw]
Subject: Re: Kernel BUG when using ad-hoc mode in rt2x00

On Wed, 2007-08-08 at 23:24 +0100, Adam Baker wrote:

> a) If anyone can see anything obvious wrong in the trace
> b) If anyone has recently tested ad-hoc mode with another driver and can
> confirm it works.

Neither.

> The sequence of events that leads to the crash is
> iwconfig wlan1 mode ad-hoc
> ifconfig wlan1 192.168.0.230
> iwconfig wlan1 channel 11
> iwconfig wlan1 essid test
>
> then attempt a scan from another device.

Very weird. Can you please enable verbose debugging and also add a few
printks to various lines of the code in ieee80211_tx_h_multicast_ps_buf
and ieee80211_tx_h_unicast_ps_buf? Both ought to be fine as far as I can
tell and the STA scanning shouldn't be in powersave mode either so this
is a bit strange.

johannes


Attachments:
signature.asc (190.00 B)
This is a digitally signed message part

2007-08-14 09:52:54

by Ivo Van Doorn

[permalink] [raw]
Subject: Re: Kernel BUG when using ad-hoc mode in rt2x00

On Thursday 09 August 2007, Adam Baker wrote:
> I've been seeing crashes when attempting to run an RT73 based device in ad-hoc
> mode (I'm using the rt2x00 git tree). I recently managed to capture the
> console output when it crashes and it all seems to point more to mac80211
> than the rt2x00 driver so I thought I'd ask here.
>
> a) If anyone can see anything obvious wrong in the trace
> b) If anyone has recently tested ad-hoc mode with another driver and can
> confirm it works.
>
> The sequence of events that leads to the crash is
> iwconfig wlan1 mode ad-hoc
> ifconfig wlan1 192.168.0.230
> iwconfig wlan1 channel 11
> iwconfig wlan1 essid test
>
> then attempt a scan from another device.
>
> My guess is that the lockdep warning is caused by trying to lock something in
> which the actual lock object has become corrupted hence it shortly afterwards
> deadlocks.

Well not a lot of responses so far. ;)

Adam, could you try below patch to see if that helps?
rt73usb_reset_tsf should be allowed to sleep, but perhaps this is not
really the case after all. :S
If the below patch does not work, then the bug really is inside mac80211
since all other callbacks are either not linked to adhoc or are not being scheduled
by rt2x00.

Ivo

---

diff --git a/drivers/net/wireless/rt73usb.c b/drivers/net/wireless/rt73usb.c
index 98d3acc..589d16f 100644
--- a/drivers/net/wireless/rt73usb.c
+++ b/drivers/net/wireless/rt73usb.c
@@ -1831,7 +1831,6 @@ static u64 rt73usb_get_tsf(struct ieee80211_hw *hw)

return tsf;
}
-#endif

static void rt73usb_reset_tsf(struct ieee80211_hw *hw)
{
@@ -1840,6 +1839,7 @@ static void rt73usb_reset_tsf(struct ieee80211_hw *hw)
rt73usb_register_write(rt2x00dev, TXRX_CSR12, 0);
rt73usb_register_write(rt2x00dev, TXRX_CSR13, 0);
}
+#endif

static const struct ieee80211_ops rt73usb_mac80211_ops = {
.tx = rt2x00mac_tx,
@@ -1858,8 +1858,8 @@ static const struct ieee80211_ops rt73usb_mac80211_ops = {
* See comment at the rt73usb_get_tsf function.
*/
.get_tsf = rt73usb_get_tsf,
-#endif
.reset_tsf = rt73usb_reset_tsf,
+#endif
.beacon_update = rt2x00usb_beacon_update,
};





2007-08-16 15:32:26

by Johannes Berg

[permalink] [raw]
Subject: Re: Kernel BUG when using ad-hoc mode in rt2x00

On Thu, 2007-08-16 at 16:25 +0100, Adam Baker wrote:

> I'm starting to think that scanning from the remote device always causes a crash
> if done just after the iwconfig essid and never does if left for a while first
> (~ 1 minute). Scanning on the local machine I've usually done when the scan and
> subsequent connect from the remote machine has succeeded. I'm not yet sure if
> that is a necessary condition for the crash.

To be fair, I managed to reproduce it once with b43 but not again. Maybe
this weird timing behaviour was the cause of that.

> I've added some printk's as you suggested, the log is attached. I
> haven't yet
> managed to capture this on the serial port so I can't yet guarantee
> that there
> aren't any calls that didn't get logged just as it crashed - I'll keep
> trying.

Ok. I'll look through.

> Aug 16 15:53:34 gromit kernel: [ 633.972956] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
> Aug 16 15:53:34 gromit kernel: [ 633.972960] Leaving ieee80211_tx_h_multicast_ps_buf

Hm. I thought it crashed in there. Could you put printk's into the two
functions called from this, and then switch to a console and tell me
which one shows up last? Elevate the printk priority to something like
KERN_ERR or change your console to show all messages.

johannes


Attachments:
signature.asc (190.00 B)
This is a digitally signed message part

2007-08-15 21:49:13

by Adam Baker

[permalink] [raw]
Subject: Re: Kernel BUG when using ad-hoc mode in rt2x00

On Wednesday 15 August 2007 10:50, Johannes Berg wrote:
> On Wed, 2007-08-08 at 23:24 +0100, Adam Baker wrote:
> > a) If anyone can see anything obvious wrong in the trace
> > b) If anyone has recently tested ad-hoc mode with another driver and can
> > confirm it works.
>
> Neither.
>
> > The sequence of events that leads to the crash is
> > iwconfig wlan1 mode ad-hoc
> > ifconfig wlan1 192.168.0.230
> > iwconfig wlan1 channel 11
> > iwconfig wlan1 essid test
> >
> > then attempt a scan from another device.
>
> Very weird. Can you please enable verbose debugging and also add a few
> printks to various lines of the code in ieee80211_tx_h_multicast_ps_buf
> and ieee80211_tx_h_unicast_ps_buf? Both ought to be fine as far as I can
> tell and the STA scanning shouldn't be in powersave mode either so this
> is a bit strange.
>

Today the most reliable way to crash it seems to be to start a scan locally,
i.e. iwlist wlan1 scan rather than from a different machine. I've appied Ivo's
patch and enabled
CONFIG_MAC80211_VERBOSE_DEBUG=y
CONFIG_MAC80211_VERBOSE_PS_DEBUG=y
and I then see in syslog shortly before the crash

I guess this is indicating something is attempting to power save when it shouldn't
so that gives me a clue where to try adding printk's

Aug 15 22:28:20 gromit kernel: [ 286.592323] wlan1: Creating new IBSS network, BSSID 2a:3f:11:b4:62:c9
Aug 15 22:28:20 gromit kernel: [ 286.593514] HW CONFIG: channel=11 freq=2462 phymode=3
Aug 15 22:28:20 gromit kernel: [ 286.607980] wlan1: Configured IBSS beacon template based on scan results
Aug 15 22:28:40 gromit kernel: [ 306.008510] wmaster0: Adding new IBSS station 00:19:4f:9e:b8:ba (dev=wlan1)
Aug 15 22:28:40 gromit kernel: [ 306.008693] wmaster0: Added STA 00:19:4f:9e:b8:ba
Aug 15 22:28:40 gromit kernel: [ 306.008742] wlan1: STA 00:19:4f:9e:b8:ba aid 0 enters power save mode
Aug 15 22:28:42 gromit kernel: [ 308.022518] wlan1: STA 00:19:4f:9e:b8:ba aid 0 exits power save mode
Aug 15 22:28:44 gromit kernel: [ 309.966798] wlan1: STA 00:19:4f:9e:b8:ba aid 0 enters power save mode

2007-08-16 15:50:33

by Adam Baker

[permalink] [raw]
Subject: Re: Kernel BUG when using ad-hoc mode in rt2x00

On Thursday 16 August 2007 14:48, Johannes Berg wrote:
> On Wed, 2007-08-15 at 22:49 +0100, Adam Baker wrote:
> > Aug 15 22:28:20 gromit kernel: [ 286.592323] wlan1: Creating new IBSS
> > network, BSSID 2a:3f:11:b4:62:c9 Aug 15 22:28:20 gromit kernel: [
> > 286.593514] HW CONFIG: channel=11 freq=2462 phymode=3 Aug 15 22:28:20
> > gromit kernel: [ 286.607980] wlan1: Configured IBSS beacon template
> > based on scan results Aug 15 22:28:40 gromit kernel: [ 306.008510]
> > wmaster0: Adding new IBSS station 00:19:4f:9e:b8:ba (dev=wlan1) Aug 15
> > 22:28:40 gromit kernel: [ 306.008693] wmaster0: Added STA
> > 00:19:4f:9e:b8:ba Aug 15 22:28:40 gromit kernel: [ 306.008742] wlan1:
> > STA 00:19:4f:9e:b8:ba aid 0 enters power save mode Aug 15 22:28:42 gromit
> > kernel: [ 308.022518] wlan1: STA 00:19:4f:9e:b8:ba aid 0 exits power
> > save mode Aug 15 22:28:44 gromit kernel: [ 309.966798] wlan1: STA
> > 00:19:4f:9e:b8:ba aid 0 enters power save mode
>
> So that MAC address, which device is that? Is that some other device or
> somehow your own?
>

The address 00:19:4F:9E:B8:BA is the remote device I was scanning / connecting
from. The RT73 device is 00:0E:2E:C5:BE:70

I'm starting to think that scanning from the remote device always causes a crash
if done just after the iwconfig essid and never does if left for a while first
(~ 1 minute). Scanning on the local machine I've usually done when the scan and
subsequent connect from the remote machine has succeeded. I'm not yet sure if
that is a necessary condition for the crash.

I've added some printk's as you suggested, the log is attached. I haven't yet
managed to capture this on the serial port so I can't yet guarantee that there
aren't any calls that didn't get logged just as it crashed - I'll keep trying.

Aug 16 15:52:41 gromit kernel: [ 581.431014] usb 2-4: new high speed USB device using ehci_hcd and address 4
Aug 16 15:52:42 gromit kernel: [ 581.703888] usb 2-4: configuration #1 chosen from 1 choice
Aug 16 15:52:42 gromit kernel: [ 582.349463] phy0 -> rt73usb_validate_eeprom: EEPROM recovery - NIC: 0xffef
Aug 16 15:52:42 gromit kernel: [ 582.349473] phy0 -> rt73usb_validate_eeprom: EEPROM recovery - Led: 0xe000
Aug 16 15:52:42 gromit kernel: [ 582.349476] phy0 -> rt73usb_validate_eeprom: EEPROM recovery - RSSI OFFSET BG: 0x0000
Aug 16 15:52:42 gromit kernel: [ 582.352058] phy0 -> rt2x00_set_chip: Info - Chipset detected - rt: 1300, rf: 0002, rev: 0002573a.
Aug 16 15:52:42 gromit kernel: [ 582.422603] wmaster0: Selected rate control algorithm 'simple'
Aug 16 15:52:43 gromit kernel: [ 582.554797] usbcore: registered new interface driver rt73usb
Aug 16 15:52:43 gromit kernel: [ 582.600998] usbcore: registered new interface driver rt2500usb
Aug 16 15:53:27 gromit kernel: [ 626.903878] phy0 -> rt2x00lib_request_firmware: Info - Loading firmware file 'rt73.bin'.
Aug 16 15:53:27 gromit kernel: [ 626.940512] phy0 -> rt2x00lib_request_firmware: Info - Firmware detected - version: 1.7.
Aug 16 15:53:27 gromit kernel: [ 626.988778] phy0 -> rt73usb_init_bbp: Debug - Start initialization from EEPROM...
Aug 16 15:53:27 gromit kernel: [ 626.988790] phy0 -> rt73usb_init_bbp: Debug - ...End initialization from EEPROM.
Aug 16 15:53:27 gromit kernel: [ 626.995372] HW CONFIG: channel=1 freq=2412 phymode=3
Aug 16 15:53:27 gromit kernel: [ 627.023029] Entering ieee80211_master_start_xmit()
Aug 16 15:53:27 gromit kernel: [ 627.023267] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:27 gromit kernel: [ 627.023270] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:27 gromit kernel: [ 627.026840] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:27 gromit kernel: [ 627.027895] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:27 gromit kernel: [ 627.029396] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:27 gromit kernel: [ 627.037980] HW CONFIG: channel=11 freq=2462 phymode=3
Aug 16 15:53:27 gromit kernel: [ 627.076827] phy0 -> rt2x00mac_conf_tx: Info - Configured TX ring 0 - CWmin: 4, CWmax: 10, Aifs: 2.
Aug 16 15:53:27 gromit kernel: [ 627.076844] phy0 -> rt2x00mac_conf_tx: Info - Configured TX ring 1 - CWmin: 4, CWmax: 10, Aifs: 2.
Aug 16 15:53:27 gromit kernel: [ 627.076848] phy0 -> rt2x00mac_conf_tx: Info - Configured TX ring 2 - CWmin: 4, CWmax: 10, Aifs: 2.
Aug 16 15:53:27 gromit kernel: [ 627.076852] phy0 -> rt2x00mac_conf_tx: Info - Configured TX ring 3 - CWmin: 4, CWmax: 10, Aifs: 2.
Aug 16 15:53:27 gromit kernel: [ 627.076856] phy0 -> rt2x00mac_conf_tx: Info - Configured TX ring 4 - CWmin: 4, CWmax: 10, Aifs: 2.
Aug 16 15:53:27 gromit kernel: [ 627.076859] phy0 -> rt2x00mac_conf_tx: Info - Configured TX ring 7 - CWmin: 5, CWmax: 10, Aifs: 2.
Aug 16 15:53:27 gromit kernel: [ 627.077484] wlan1: Trigger new scan to find an IBSS to join
Aug 16 15:53:27 gromit kernel: [ 627.105311] HW CONFIG: channel=1 freq=2412 phymode=3
Aug 16 15:53:27 gromit kernel: [ 627.161311] Entering ieee80211_master_start_xmit()
Aug 16 15:53:27 gromit kernel: [ 627.161331] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:27 gromit kernel: [ 627.161335] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:27 gromit kernel: [ 627.161366] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:27 gromit kernel: [ 627.161506] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:27 gromit kernel: [ 627.189279] HW CONFIG: channel=2 freq=2417 phymode=3
Aug 16 15:53:27 gromit kernel: [ 627.245279] Entering ieee80211_master_start_xmit()
Aug 16 15:53:27 gromit kernel: [ 627.245298] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:27 gromit kernel: [ 627.245302] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:27 gromit kernel: [ 627.245330] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:27 gromit kernel: [ 627.245495] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:27 gromit kernel: [ 627.273380] HW CONFIG: channel=3 freq=2422 phymode=3
Aug 16 15:53:27 gromit kernel: [ 627.329247] Entering ieee80211_master_start_xmit()
Aug 16 15:53:27 gromit kernel: [ 627.329266] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:27 gromit kernel: [ 627.329269] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:27 gromit kernel: [ 627.329291] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:27 gromit kernel: [ 627.329477] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:27 gromit kernel: [ 627.357272] HW CONFIG: channel=4 freq=2427 phymode=3
Aug 16 15:53:27 gromit kernel: [ 627.413290] Entering ieee80211_master_start_xmit()
Aug 16 15:53:27 gromit kernel: [ 627.413309] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:27 gromit kernel: [ 627.413313] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:27 gromit kernel: [ 627.413344] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:27 gromit kernel: [ 627.413463] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:27 gromit kernel: [ 627.441237] HW CONFIG: channel=5 freq=2432 phymode=3
Aug 16 15:53:28 gromit kernel: [ 627.497205] Entering ieee80211_master_start_xmit()
Aug 16 15:53:28 gromit kernel: [ 627.497225] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:28 gromit kernel: [ 627.497228] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:28 gromit kernel: [ 627.497260] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:28 gromit kernel: [ 627.497453] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:28 gromit kernel: [ 627.525220] HW CONFIG: channel=6 freq=2437 phymode=3
Aug 16 15:53:28 gromit kernel: [ 627.581347] Entering ieee80211_master_start_xmit()
Aug 16 15:53:28 gromit kernel: [ 627.581367] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:28 gromit kernel: [ 627.581371] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:28 gromit kernel: [ 627.581402] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:28 gromit kernel: [ 627.581559] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:28 gromit kernel: [ 627.609191] HW CONFIG: channel=7 freq=2442 phymode=3
Aug 16 15:53:28 gromit kernel: [ 627.665148] Entering ieee80211_master_start_xmit()
Aug 16 15:53:28 gromit kernel: [ 627.665168] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:28 gromit kernel: [ 627.665171] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:28 gromit kernel: [ 627.665201] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:28 gromit kernel: [ 627.665288] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:28 gromit kernel: [ 627.693180] HW CONFIG: channel=8 freq=2447 phymode=3
Aug 16 15:53:28 gromit kernel: [ 627.749882] Entering ieee80211_master_start_xmit()
Aug 16 15:53:28 gromit kernel: [ 627.749901] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:28 gromit kernel: [ 627.749904] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:28 gromit kernel: [ 627.749935] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:28 gromit kernel: [ 627.750030] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:28 gromit kernel: [ 627.777137] HW CONFIG: channel=9 freq=2452 phymode=3
Aug 16 15:53:28 gromit kernel: [ 627.833177] Entering ieee80211_master_start_xmit()
Aug 16 15:53:28 gromit kernel: [ 627.833196] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:28 gromit kernel: [ 627.833200] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:28 gromit kernel: [ 627.833225] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:28 gromit kernel: [ 627.833388] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:28 gromit kernel: [ 627.862875] HW CONFIG: channel=10 freq=2457 phymode=3
Aug 16 15:53:28 gromit kernel: [ 627.917068] Entering ieee80211_master_start_xmit()
Aug 16 15:53:28 gromit kernel: [ 627.917087] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:28 gromit kernel: [ 627.917090] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:28 gromit kernel: [ 627.917110] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:28 gromit kernel: [ 627.917245] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:28 gromit kernel: [ 627.945063] HW CONFIG: channel=11 freq=2462 phymode=3
Aug 16 15:53:28 gromit kernel: [ 628.001044] Entering ieee80211_master_start_xmit()
Aug 16 15:53:28 gromit kernel: [ 628.001062] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:28 gromit kernel: [ 628.001066] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:28 gromit kernel: [ 628.001089] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:28 gromit kernel: [ 628.001231] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:28 gromit kernel: [ 628.029049] HW CONFIG: channel=11 freq=2462 phymode=3
Aug 16 15:53:28 gromit kernel: [ 628.045759] Entering ieee80211_master_start_xmit()
Aug 16 15:53:28 gromit kernel: [ 628.045777] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:28 gromit kernel: [ 628.045781] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:28 gromit kernel: [ 628.045802] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:28 gromit kernel: [ 628.045965] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:28 gromit kernel: [ 628.052109] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:28 gromit kernel: [ 628.154451] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:28 gromit kernel: [ 628.256806] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:28 gromit kernel: [ 628.359160] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:29 gromit kernel: [ 628.461518] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:29 gromit kernel: [ 628.563875] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:29 gromit kernel: [ 628.608934] Entering ieee80211_master_start_xmit()
Aug 16 15:53:29 gromit kernel: [ 628.608953] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:29 gromit kernel: [ 628.608957] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:29 gromit kernel: [ 628.608990] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:29 gromit kernel: [ 628.609124] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:29 gromit kernel: [ 628.666236] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:29 gromit kernel: [ 628.768591] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:29 gromit kernel: [ 628.870955] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:29 gromit kernel: [ 628.973308] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:29 gromit kernel: [ 629.075787] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:29 gromit kernel: [ 629.178144] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:29 gromit kernel: [ 629.280498] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:29 gromit kernel: [ 629.382857] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:30 gromit kernel: [ 629.485211] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:30 gromit kernel: [ 629.587568] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:30 gromit kernel: [ 629.689927] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:30 gromit kernel: [ 629.792284] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:30 gromit kernel: [ 629.894780] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:30 gromit kernel: [ 629.997120] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:30 gromit kernel: [ 630.045969] wlan1: Trigger new scan to find an IBSS to join
Aug 16 15:53:30 gromit kernel: [ 630.072511] HW CONFIG: channel=1 freq=2412 phymode=3
Aug 16 15:53:30 gromit kernel: [ 630.128416] Entering ieee80211_master_start_xmit()
Aug 16 15:53:30 gromit kernel: [ 630.128436] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:30 gromit kernel: [ 630.128440] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:30 gromit kernel: [ 630.128468] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:30 gromit kernel: [ 630.128599] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:30 gromit kernel: [ 630.156393] HW CONFIG: channel=2 freq=2417 phymode=3
Aug 16 15:53:30 gromit kernel: [ 630.212387] Entering ieee80211_master_start_xmit()
Aug 16 15:53:30 gromit kernel: [ 630.212406] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:30 gromit kernel: [ 630.212409] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:30 gromit kernel: [ 630.212435] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:30 gromit kernel: [ 630.212585] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:30 gromit kernel: [ 630.240427] HW CONFIG: channel=3 freq=2422 phymode=3
Aug 16 15:53:30 gromit kernel: [ 630.296364] Entering ieee80211_master_start_xmit()
Aug 16 15:53:30 gromit kernel: [ 630.296384] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:30 gromit kernel: [ 630.296387] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:30 gromit kernel: [ 630.296420] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:30 gromit kernel: [ 630.296700] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:30 gromit kernel: [ 630.324343] HW CONFIG: channel=4 freq=2427 phymode=3
Aug 16 15:53:30 gromit kernel: [ 630.380435] Entering ieee80211_master_start_xmit()
Aug 16 15:53:30 gromit kernel: [ 630.380456] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:30 gromit kernel: [ 630.380459] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:30 gromit kernel: [ 630.380491] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:30 gromit kernel: [ 630.380681] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:30 gromit kernel: [ 630.408318] HW CONFIG: channel=5 freq=2432 phymode=3
Aug 16 15:53:31 gromit kernel: [ 630.464331] Entering ieee80211_master_start_xmit()
Aug 16 15:53:31 gromit kernel: [ 630.464352] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:31 gromit kernel: [ 630.464355] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:31 gromit kernel: [ 630.464389] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:31 gromit kernel: [ 630.464544] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:31 gromit kernel: [ 630.492312] HW CONFIG: channel=6 freq=2437 phymode=3
Aug 16 15:53:31 gromit kernel: [ 630.549911] Entering ieee80211_master_start_xmit()
Aug 16 15:53:31 gromit kernel: [ 630.549933] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:31 gromit kernel: [ 630.549936] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:31 gromit kernel: [ 630.549968] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:31 gromit kernel: [ 630.550151] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:31 gromit kernel: [ 630.576299] HW CONFIG: channel=7 freq=2442 phymode=3
Aug 16 15:53:31 gromit kernel: [ 630.611254] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:31 gromit kernel: [ 630.634793] Entering ieee80211_master_start_xmit()
Aug 16 15:53:31 gromit kernel: [ 630.634814] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:31 gromit kernel: [ 630.634818] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:31 gromit kernel: [ 630.634850] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:31 gromit kernel: [ 630.635016] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:31 gromit kernel: [ 630.660245] HW CONFIG: channel=8 freq=2447 phymode=3
Aug 16 15:53:31 gromit kernel: [ 630.716236] Entering ieee80211_master_start_xmit()
Aug 16 15:53:31 gromit kernel: [ 630.716255] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:31 gromit kernel: [ 630.716259] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:31 gromit kernel: [ 630.716280] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:31 gromit kernel: [ 630.716364] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:31 gromit kernel: [ 630.744224] HW CONFIG: channel=9 freq=2452 phymode=3
Aug 16 15:53:31 gromit kernel: [ 630.800210] Entering ieee80211_master_start_xmit()
Aug 16 15:53:31 gromit kernel: [ 630.800229] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:31 gromit kernel: [ 630.800233] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:31 gromit kernel: [ 630.800256] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:31 gromit kernel: [ 630.800348] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:31 gromit kernel: [ 630.828208] HW CONFIG: channel=10 freq=2457 phymode=3
Aug 16 15:53:31 gromit kernel: [ 630.884188] Entering ieee80211_master_start_xmit()
Aug 16 15:53:31 gromit kernel: [ 630.884207] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:31 gromit kernel: [ 630.884211] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:31 gromit kernel: [ 630.884234] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:31 gromit kernel: [ 630.884337] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:31 gromit kernel: [ 630.912481] HW CONFIG: channel=11 freq=2462 phymode=3
Aug 16 15:53:31 gromit kernel: [ 630.968163] Entering ieee80211_master_start_xmit()
Aug 16 15:53:31 gromit kernel: [ 630.968181] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:31 gromit kernel: [ 630.968185] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:31 gromit kernel: [ 630.968210] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:31 gromit kernel: [ 630.968327] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:31 gromit kernel: [ 630.996158] HW CONFIG: channel=11 freq=2462 phymode=3
Aug 16 15:53:31 gromit kernel: [ 631.020812] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:31 gromit kernel: [ 631.123167] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:31 gromit kernel: [ 631.225524] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:31 gromit kernel: [ 631.327881] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:31 gromit kernel: [ 631.430238] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:32 gromit kernel: [ 631.532598] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:32 gromit kernel: [ 631.634950] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:32 gromit kernel: [ 631.737308] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:32 gromit kernel: [ 631.839666] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:32 gromit kernel: [ 631.942147] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:32 gromit kernel: [ 632.044528] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:32 gromit kernel: [ 632.146860] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:32 gromit kernel: [ 632.249216] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:32 gromit kernel: [ 632.351573] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:33 gromit kernel: [ 632.453932] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:33 gromit kernel: [ 632.556288] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:33 gromit kernel: [ 632.607696] Entering ieee80211_master_start_xmit()
Aug 16 15:53:33 gromit kernel: [ 632.607715] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:33 gromit kernel: [ 632.607719] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:33 gromit kernel: [ 632.607753] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:33 gromit kernel: [ 632.607908] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:33 gromit kernel: [ 632.658643] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:33 gromit kernel: [ 632.760999] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:33 gromit kernel: [ 632.863483] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:33 gromit kernel: [ 632.965859] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:33 gromit kernel: [ 633.008852] wlan1: Trigger new scan to find an IBSS to join
Aug 16 15:53:33 gromit kernel: [ 633.035535] HW CONFIG: channel=1 freq=2412 phymode=3
Aug 16 15:53:33 gromit kernel: [ 633.091529] Entering ieee80211_master_start_xmit()
Aug 16 15:53:33 gromit kernel: [ 633.091549] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:33 gromit kernel: [ 633.091552] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:33 gromit kernel: [ 633.091582] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:33 gromit kernel: [ 633.091689] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:33 gromit kernel: [ 633.119507] HW CONFIG: channel=2 freq=2417 phymode=3
Aug 16 15:53:33 gromit kernel: [ 633.175537] Entering ieee80211_master_start_xmit()
Aug 16 15:53:33 gromit kernel: [ 633.175558] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:33 gromit kernel: [ 633.175561] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:33 gromit kernel: [ 633.175592] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:33 gromit kernel: [ 633.175674] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:33 gromit kernel: [ 633.203484] HW CONFIG: channel=3 freq=2422 phymode=3
Aug 16 15:53:33 gromit kernel: [ 633.259483] Entering ieee80211_master_start_xmit()
Aug 16 15:53:33 gromit kernel: [ 633.259502] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:33 gromit kernel: [ 633.259506] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:33 gromit kernel: [ 633.259537] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:33 gromit kernel: [ 633.259667] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:33 gromit kernel: [ 633.287461] HW CONFIG: channel=4 freq=2427 phymode=3
Aug 16 15:53:33 gromit kernel: [ 633.343467] Entering ieee80211_master_start_xmit()
Aug 16 15:53:33 gromit kernel: [ 633.343488] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:33 gromit kernel: [ 633.343491] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:33 gromit kernel: [ 633.343523] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:33 gromit kernel: [ 633.343649] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:33 gromit kernel: [ 633.371433] HW CONFIG: channel=5 freq=2432 phymode=3
Aug 16 15:53:33 gromit kernel: [ 633.428937] Entering ieee80211_master_start_xmit()
Aug 16 15:53:33 gromit kernel: [ 633.428958] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:33 gromit kernel: [ 633.428961] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:33 gromit kernel: [ 633.428995] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:33 gromit kernel: [ 633.429137] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:34 gromit kernel: [ 633.455408] HW CONFIG: channel=6 freq=2437 phymode=3
Aug 16 15:53:34 gromit kernel: [ 633.513686] Entering ieee80211_master_start_xmit()
Aug 16 15:53:34 gromit kernel: [ 633.513707] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:34 gromit kernel: [ 633.513711] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:34 gromit kernel: [ 633.513744] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:34 gromit kernel: [ 633.513868] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:34 gromit kernel: [ 633.539746] HW CONFIG: channel=7 freq=2442 phymode=3
Aug 16 15:53:34 gromit kernel: [ 633.595377] Entering ieee80211_master_start_xmit()
Aug 16 15:53:34 gromit kernel: [ 633.595396] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:34 gromit kernel: [ 633.595399] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:34 gromit kernel: [ 633.595426] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:34 gromit kernel: [ 633.595599] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:34 gromit kernel: [ 633.623363] HW CONFIG: channel=8 freq=2447 phymode=3
Aug 16 15:53:34 gromit kernel: [ 633.679686] Entering ieee80211_master_start_xmit()
Aug 16 15:53:34 gromit kernel: [ 633.679706] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:34 gromit kernel: [ 633.679709] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:34 gromit kernel: [ 633.679738] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:34 gromit kernel: [ 633.679838] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:34 gromit kernel: [ 633.707347] HW CONFIG: channel=9 freq=2452 phymode=3
Aug 16 15:53:34 gromit kernel: [ 633.763329] Entering ieee80211_master_start_xmit()
Aug 16 15:53:34 gromit kernel: [ 633.763346] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:34 gromit kernel: [ 633.763350] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:34 gromit kernel: [ 633.763380] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:34 gromit kernel: [ 633.763573] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:34 gromit kernel: [ 633.791325] HW CONFIG: channel=10 freq=2457 phymode=3
Aug 16 15:53:34 gromit kernel: [ 633.847301] Entering ieee80211_master_start_xmit()
Aug 16 15:53:34 gromit kernel: [ 633.847320] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:34 gromit kernel: [ 633.847323] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:34 gromit kernel: [ 633.847349] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:34 gromit kernel: [ 633.847429] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:34 gromit kernel: [ 633.875313] HW CONFIG: channel=11 freq=2462 phymode=3
Aug 16 15:53:34 gromit kernel: [ 633.931370] Entering ieee80211_master_start_xmit()
Aug 16 15:53:34 gromit kernel: [ 633.931390] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:34 gromit kernel: [ 633.931393] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:34 gromit kernel: [ 633.931421] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:34 gromit kernel: [ 633.931545] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:34 gromit kernel: [ 633.959384] HW CONFIG: channel=11 freq=2462 phymode=3
Aug 16 15:53:34 gromit kernel: [ 633.972942] Entering ieee80211_master_start_xmit()
Aug 16 15:53:34 gromit kernel: [ 633.972956] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
Aug 16 15:53:34 gromit kernel: [ 633.972960] Leaving ieee80211_tx_h_multicast_ps_buf
Aug 16 15:53:34 gromit kernel: [ 633.972980] Leaving ieee80211_master_start_xmit() ret=0
Aug 16 15:53:34 gromit kernel: [ 633.973155] phy0 -> rt2x00usb_interrupt_txdone: Debug - status 0
Aug 16 15:53:34 gromit kernel: [ 633.989533] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:34 gromit kernel: [ 634.091886] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
Aug 16 15:53:34 gromit kernel: [ 634.194244] phy0 -> rt2x00usb_interrupt_rxdone: Debug - Size 128

2007-08-17 10:13:28

by Johannes Berg

[permalink] [raw]
Subject: Re: Kernel BUG when using ad-hoc mode in rt2x00

On Thu, 2007-08-16 at 22:43 +0100, Adam Baker wrote:

> Having now managed to capture a small relevant area it looks like
> there were a couple of seconds missing from the end of that log file.

> [16697.856499] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
> [16697.864492] INFO: trying to register non-stat

Hm. Maybe you could disable verbose debugging in the ralink drivers to
get a lower printk rate; however, this is weird, I think I'll have to
try to reproduce it.

johannes


Attachments:
signature.asc (190.00 B)
This is a digitally signed message part

2007-08-16 21:43:09

by Adam Baker

[permalink] [raw]
Subject: Re: Kernel BUG when using ad-hoc mode in rt2x00


> > I've added some printk's as you suggested, the log is attached. I
> > haven't yet
> > managed to capture this on the serial port so I can't yet guarantee
> > that there
> > aren't any calls that didn't get logged just as it crashed - I'll keep
> > trying.
>
> Ok. I'll look through.

Having now managed to capture a small relevant area it looks like there were a couple of seconds missing from the end of that log file.

>
> > Aug 16 15:53:34 gromit kernel: [ 633.972956] wmaster0: Entering
> > ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746 Aug 16 15:53:34 gromit
> > kernel: [ 633.972960] Leaving ieee80211_tx_h_multicast_ps_buf
>
> Hm. I thought it crashed in there. Could you put printk's into the two
> functions called from this, and then switch to a console and tell me
> which one shows up last? Elevate the printk priority to something like
> KERN_ERR or change your console to show all messages.
>
My problem is that I'm using a console that can't keep up with logging at
the necessary data rate so I get gaps in the log. I'll try to get the necessary
cables to try a different solution. I think I got the bit we want this time though.

Trying to make sense of this I just noticed that I missed the exit printk on the
TXRX_QUEUED exit from ieee80211_tx_h_multicast_ps_buf but I think I get
a hint of what might be going wrong. The remote device is being added as a
new IBSS station even though it hasn't associated, only probed. Could
something be assuming there is more info recorded for that device than there
really is?

It may be relevant at this point to mention that the remote device is a Nokia
n800 so likely to have fairly aggressive power save settings.

MISSING DATA
[16694.835829] phy7 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[16694.938310] phy7 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[16695.040666] phy7 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[16695.143039] phy7 -> rt2x00usb_interrupt_rxdone
MISSING DATA
[16695.843860] Entering ieee80211_master_start_xmit()
[16695.849097] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[16695.857083] Leaving ieee80211_tx_h_multicast_ps_buf
[16695.862383] Leaving ieee80211_master_start_xmit() ret=0
MISSING DATA
[16696.883214] phy7 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[16696.952071] phy7 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[16696.958640] wmaster0: Adding new IBSS station 00:19:4f:9e:b8:ba (dev=wlan1)
[16696.966386] wmaster0: Added STA 00:
MISSING DATA
[16697.804543] phy7 -> rt2x00usb_interrupt_rxdone: Debug - Size 128
[16697.851272] Entering ieee80211_master_start_xmit()
[16697.856499] wmaster0: Entering ieee80211_tx_h_multicast_ps_buf(), hw.flags 1746
[16697.864492] INFO: trying to register non-stat
MISSING DATA
16703.045044] BUG: NMI Watchdog detected LOCKUP on CPU0, eip c022d7fa, registers:
[16703.052642] Modules linked in: nls_cp437 isofs udf rfcomm l2cap bluetooth binfmt_misc cpufreq_powersave cpufreq_stats cpufreq_userspace cpufre
q_ondemand cpufreq_conservative freq_table video output battery container sbs fan dock ac ipv6 nfs lockd sunrpc asb100 hwmon_vid lp pl2303 rt2500
usb arc4 ecb blkcipher rc80211_simple usbserial rt73usb rt2x00usb rt2x00lib input_polldev crc_itu_t mac80211 af_packet tsdev snd_ens1371 gameport
snd_rawmidi snd_seq_device snd_ac97_codec ac97_bus snd_pcm_oss snd_mixer_oss snd_pcm serio_raw snd_timer parport_pc evdev parport psmouse i2c_vi
apro 8139too i2c_core snd ehci_hcd pcspkr floppy via_ircc uhci_hcd irda 8139cp soundcore snd_page_alloc mii crc_ccitt usbcore shpchp via_agp pci_
hotplug agpgart thermal button processor
[16703.123282] CPU: 0
[16703.123283] EIP: 0060:[<c022d7fa>] Not tainted VLI
[16703.123285] EFLAGS: 00000046 (2.6.23-rc3 #11)
[16703.135782] EIP is at _raw_spin_lock+0xaa/0x150
[16703.140450] eax: 00000000 ebx: c4f5791c ecx: 1ec4817c edx: 665fa417
[16703.147506] esi: 0dd5135f edi: 00000000 ebp: 6b8ab748 esp: c0453ad8
[16703.154598] ds: 007b es: 007b fs: 00d8 gs: 0000 ss: 0068
[16703.160664] Process swapper (pid: 0, ti=c0452000 task=c041a3c0 task.ti=c0452000)


2007-09-25 21:19:26

by Johannes Berg

[permalink] [raw]
Subject: Re: Kernel BUG when using ad-hoc mode in rt2x00

On Tue, 2007-09-25 at 23:09 +0200, Johannes Berg wrote:
> On Tue, 2007-08-21 at 12:34 +0200, Johannes Berg wrote:
>
> > At that point, sdata->bss should point to the master device, which
> > apparently hasn't been initialised yet. The device initialisation code
> > is pretty black magic to me, Jiri/Michael?
>
> No reply. Can you try this patch?

Ah, no, there's a bug in this. Try this:
http://johannes.sipsolutions.net/patches/kernel/all/2007-09-25-21%3a19/005-mac80211-fix-register-netdevice-error-return-oops.patch

johannes


Attachments:
signature.asc (190.00 B)
This is a digitally signed message part

2007-09-27 22:39:22

by Adam Baker

[permalink] [raw]
Subject: Re: Kernel BUG when using ad-hoc mode in rt2x00

On Tuesday 25 September 2007 22:20, Johannes Berg wrote:
> On Tue, 2007-09-25 at 23:09 +0200, Johannes Berg wrote:
> > On Tue, 2007-08-21 at 12:34 +0200, Johannes Berg wrote:
> > > At that point, sdata->bss should point to the master device, which
> > > apparently hasn't been initialised yet. The device initialisation code
> > > is pretty black magic to me, Jiri/Michael?
> >
> > No reply. Can you try this patch?
>
> Ah, no, there's a bug in this. Try this:
> http://johannes.sipsolutions.net/patches/kernel/all/2007-09-25-21%3a19/005-
>mac80211-fix-register-netdevice-error-return-oops.patch
>

I can't currently test it the way I was testing before because rt2x00
currently Oopses on unplug (I'll investigate that tomorrow) but it did
occasionally crash on scanning even if the interface had been up for a long
time before and with this patch it has survived quite a few scans.

I'll keep testing but it looks promising.

Adam Baker

2007-09-25 21:08:16

by Johannes Berg

[permalink] [raw]
Subject: Re: Kernel BUG when using ad-hoc mode in rt2x00

On Tue, 2007-08-21 at 12:34 +0200, Johannes Berg wrote:

> At that point, sdata->bss should point to the master device, which
> apparently hasn't been initialised yet. The device initialisation code
> is pretty black magic to me, Jiri/Michael?

No reply. Can you try this patch?

---
net/mac80211/ieee80211.c | 3 +--
net/mac80211/ieee80211_iface.c | 12 ++++++++++++
2 files changed, 13 insertions(+), 2 deletions(-)

--- wireless-dev.orig/net/mac80211/ieee80211.c 2007-09-25 22:26:31.341579155 +0200
+++ wireless-dev/net/mac80211/ieee80211.c 2007-09-25 22:43:38.681568738 +0200
@@ -266,7 +266,6 @@ void ieee80211_if_mgmt_setup(struct net_
dev->stop = ieee80211_mgmt_stop;
dev->type = ARPHRD_IEEE80211_PRISM;
dev->hard_header_parse = header_parse_80211;
- dev->uninit = ieee80211_if_reinit;
dev->destructor = ieee80211_if_free;
}

@@ -543,7 +542,6 @@ void ieee80211_if_setup(struct net_devic
dev->change_mtu = ieee80211_change_mtu;
dev->open = ieee80211_open;
dev->stop = ieee80211_stop;
- dev->uninit = ieee80211_if_reinit;
dev->destructor = ieee80211_if_free;
}

@@ -1234,6 +1232,7 @@ int ieee80211_register_hw(struct ieee802
goto fail_dev;

ieee80211_debugfs_add_netdev(IEEE80211_DEV_TO_SUB_IF(local->mdev));
+ ieee80211_if_set_type(local->mdev, IEEE80211_IF_TYPE_AP);

result = ieee80211_init_rate_ctrl_alg(local, NULL);
if (result < 0) {
--- wireless-dev.orig/net/mac80211/ieee80211_iface.c 2007-09-25 22:26:40.111572537 +0200
+++ wireless-dev/net/mac80211/ieee80211_iface.c 2007-09-25 22:41:52.251569443 +0200
@@ -127,6 +127,12 @@ int ieee80211_if_add_mgmt(struct ieee802
if (ret)
goto fail;

+ /*
+ * Called even when register_netdevice fails, it would
+ * oops if assigned before initialising the rest.
+ */
+ ndev->uninit = ieee80211_if_reinit;
+
ieee80211_debugfs_add_netdev(nsdata);

if (local->open_count > 0)
@@ -157,6 +163,12 @@ void ieee80211_if_set_type(struct net_de

dev->hard_start_xmit = ieee80211_subif_start_xmit;

+ /*
+ * Called even when register_netdevice fails, it would
+ * oops if assigned before initialising the rest.
+ */
+ dev->uninit = ieee80211_if_reinit;
+
sdata->type = type;
switch (type) {
case IEEE80211_IF_TYPE_WDS: