Ticket #8301 (closed defect: fixed)

Opened 5 years ago

Last modified 5 years ago

Fast suspend/resume cycle causes a libertas crash

Reported by: cjb Owned by: dsaxena
Priority: blocker Milestone: 8.2.0 (was Update.2)
Component: kernel Version: not specified
Keywords: blocks-:8.2.0 cjbfor8.2 relnote Cc:
Action Needed: finalize Verified: no
Deployments affected: Blocked By:
Blocking:

Description

dmesg attached, with loglevel=9 and libertas_debug=0x4000. To reproduce, on joyride-2386:

  • suspend (and turn off wireless) by closing lid
  • resume by opening lid
  • while driver resume is still happening, close lid again

I think the hang happens because we power down the device while it was being brought up, and khubd refuses to freeze (because it's still trying to send URBs?). Marking as blocks?:8.2.0, and we have some options:

  1. back out turning off the wifi power on suspend
  2. make that code quiesce the wifi somehow (how?) before powering it off
  3. make that code delay performing a suspend that is less than a few seconds after a resume

Maybe there are other options here. What do you think, wireless/kernel people?

Attachments

newlibertas.cap (217.5 kB) - added by cjb 5 years ago.
newlibertas4.cap (267.2 kB) - added by cjb 5 years ago.
newlibertas5.cap (0.8 MB) - added by cjb 5 years ago.
libertas-command-queue-fix-backport.patch (1.7 kB) - added by dsaxena 5 years ago.
Backport from patch posted to linux-wireless

Change History

Changed 5 years ago by cjb

  Changed 5 years ago by dilinger

How did you come up w/ that? I see no indication from the logs that this has anything to do with URB transmission (which we can certainly control during suspend/resume)...

  Changed 5 years ago by cjb

Sorry, just a wild guess as to why khubd would go crazy when faced with the unexpected loss of a USB device.

  Changed 5 years ago by dilinger

I think at this point, the firmware (or something) is already confused/broken: 

935	[  233.000236] devpath 1 ep3in 3strikes
936	[  233.003973] usb 1-1: USB disconnect, address 3

Doing anything with the device after that fails; it's getting to that point that I'm concerned w/.

  Changed 5 years ago by cjb

The kernel log is quite similar to #4431.

  Changed 5 years ago by cjb

I think at this point, the firmware (or something) is already confused/broken:

The firmware isn't running. On the way down in userspace, we *cut power* to the 8388 via the EC and /sys/power/wlan-enabled. (This is a new feature in 8.2, #7879.)

The 3strikes is coincident with that: 

[  232.994419] olpc-ec:  running cmd 0x35
[  233.000236] devpath 1 ep3in 3strikes
[  233.003973] usb 1-1: USB disconnect, address 3

EC command 0x35 is "put the 8388 into reset".

  Changed 5 years ago by dilinger

Something's screwy with command_timer here. I can physically remove the harware (libertas usb dongle) or remove the usb8xxx module, and rather than lbs functionality immediately stopping... I can watch ping hang for a few seconds, or get "usbcore: deregistering interface driver usb8xxx" followed by (a few seconds later) "libertas: Command 6 timed out". That should _not_ be happening...

lbs_add_card (called from if_usb_probe) inits command_timer; lbs_remove_card should be deleting the timer (synchronously!). Instead, it appears to call kthread_stop on lbs_thread, which then deletes command_timer before exiting. Problems include: 1) it deletes the timer asynchronously. we should be calling del_timer_sync. 2) kthread_stop doesn't immediately stop the thread, so we're hanging for a few seconds somewhere before checking kthread_should_stop.

I also don't see URB errors (which the host controller should be setting, if the libertas driver is in the middle of an URB submission), so.. my theory is that we're not currently waiting on an URB submission, but elsewhere in lbs_thread.

  Changed 5 years ago by gregorio

  • keywords blocks:8.2.0 added; blocks?:8.2.0 removed

  Changed 5 years ago by gregorio

  • keywords blocks-:8.2.0 relnote added; blocks:8.2.0 removed

  Changed 5 years ago by cjb

  • cc dcbw added

I think trying one of the obvious workarounds (rmmod before power off, for example) should block the release. Finding the ultimate fix doesn't have to, though.

follow-up: ↓ 11   Changed 5 years ago by cjb

Wow. I think it hangs even with rmmod before power off; rmmod becomes the hung task instead of khubd. This is really bad.

in reply to: ↑ 10   Changed 5 years ago by dsaxena

Replying to cjb:

Wow. I think it hangs even with rmmod before power off; rmmod becomes the hung task instead of khubd. This is really bad.

Do you see anything new in the logs?

  Changed 5 years ago by cjb

  • cc gregorio added

Do you see anything new in the logs?

No, much the same, with a "command 50 timed out" in the logs. rmmod continues to be hung after that timeout. I guess a similar thing happens as with the suspend case -- the rmmod hang is due to us continuing to wait for the command response after the device goes away.

Greg, heads up that #7879 is jeopardized here, and might end up waiting for 8.2.1.

  Changed 5 years ago by cjb

Here's an easy way to reproduce this without involving suspend/resume: 

bash-3.2# while true; do sleep 4; rmmod usb8xxx; rmmod libertas; echo 0 > /sys/power/wlan-enabled; sleep 1; echo 1 > /sys/power/wlan-enabled; done
[  275.930321] usbcore: deregistering interface driver usb8xxx
[  276.208964] olpc-ec:  running cmd 0x35
[  276.216321] usb 2-1: USB disconnect, address 3
[  277.237338] olpc-ec:  running cmd 0x25
[  277.546581] hub_port_wait_reset: portstatus=503 portchange=10
[  277.616270] usb 2-1: new high speed USB device using ehci_hcd and address 4
[  277.686501] hub_port_wait_reset: portstatus=503 portchange=10
[  277.790819] usb 2-1: configuration #1 chosen from 1 choice
[  280.488535] usb8xxx: Firmware ready event received
[  280.507147] libertas: 00:17:c4:10:c4:da, fw 5.110.22p18, cap 0x000003a3
[  280.550840] libertas: eth0: Marvell WLAN 802.11 adapter
[  280.579188] libertas: PREP_CMD: command 0x0074 failed: 2
[  280.596130] usb8xxx: Firmware does not seem to support PS mode
[  280.602723] usbcore: registered new interface driver usb8xxx
[  281.053829] usbcore: deregistering interface driver usb8xxx
[  281.506851] libertas: SCAN_CMD failed
[  282.253929] olpc-ec:  running cmd 0x35
[  282.261554] usb 2-1: USB disconnect, address 4
[  283.296720] olpc-ec:  running cmd 0x25
[  283.622701] hub_port_wait_reset: portstatus=503 portchange=10
[  283.682504] usb 2-1: new high speed USB device using ehci_hcd and address 5
[  283.754276] hub_port_wait_reset: portstatus=503 portchange=10
[  283.856891] usb 2-1: configuration #1 chosen from 1 choice
[  284.646520] usb8xxx: Firmware ready event received
[  284.680471] libertas: 00:17:c4:10:c4:da, fw 5.110.22p18, cap 0x000003a3
[  284.725557] libertas: eth0: Marvell WLAN 802.11 adapter
[  284.753176] libertas: PREP_CMD: command 0x0074 failed: 2
[  284.779040] usb8xxx: Firmware does not seem to support PS mode
[  284.792873] usbcore: registered new interface driver usb8xxx
[  285.312541] ADDRCONF(NETDEV_UP): eth0: link is not ready
[  286.881135] usbcore: deregistering interface driver usb8xxx
[  297.055069] libertas: Command 6 timed out
<perpetual hang inside rmmod>

  Changed 5 years ago by cjb

I tried the one-liner of: 

-	del_timer(&priv->command_timer);
+	del_timer_sync(&priv->command_timer);
 	wake_up_all(&priv->cmd_pending);

but it gets exactly the same dmesg as in the previous comment, perpetual hang after: 

[  328.785923] usbcore: deregistering interface driver usb8xxx
[  338.527283] libertas: Command 6 timed out

  Changed 5 years ago by gregorio

  • cc gnu added

Hi Chris,

Thanks for the heads up. I don't think this one is that bad since it requires a close then quick open (or a short press of power key then another short press within 1 sec, right?) and it only affects users connected to APs.

That said, it will come up in the field, including in Uruguay and Peru. Also, I don't think you can avoid this one by not turning on power save in the SCP (right?).

We should take another stab at documenting where we are in terms of power save mode in SCP and power save via quick press of power key/lid close.

I still don't think we have explained the difference between those two very well either. Can you read through the open bugs listed at: http://wiki.laptop.org/go/Release_notes/8.2.0#Notable_Open_Bugs_In_This_Release

Let me know if you are aware of any other open bugs in power save that should be on that list. Let's collect all the power save relevant ones in to a single section. Then write up some release notes explanation of what will work and what wont in the various power save/suspend/idles modes?

I can look for someone to work with you on this if that helps, but I think you have all the main info. This will help us see where we are and therefore help decide what (if any) bugs we should try to address in 8.2 and what to focus on in 8.2.1.

Thanks,

Greg S

follow-up: ↓ 23   Changed 5 years ago by cjb

Javier/libertas people, do you know if there's a way for me to quiesce the radio and command queue such that it becomes safe to rmmod? rmmod isn't that way, as above, but maybe one of the libertas commands for turning off the radio might be..?

  Changed 5 years ago by cjb

Hi Greg,

I don't think this one is that bad since it requires a close then quick open (or a short press of power key then another short press within 1 sec, right?)

I think it's looking worse than that now, several seconds instead of just one. I might try making a suspend be delayed until at least five seconds after a resume and see if that helps..

  Changed 5 years ago by dcbw

Can somebody add 0x100000 to lbs_debug and reproduce the issue? we need to see what the main thread is doing at the time that it's told to quit, that might expose the source of the hang in lbs_thread() and allow us to figure out how to fix it.

  Changed 5 years ago by cjb

Thanks, Dan, will do this immediately.

  Changed 5 years ago by cjb

Cool, here we go. Happened immediately on turning on loglevel 9 and closing the lid. EC cmd 0x35 is the 8388 power down. 

[  245.345392] libertas thread: main-thread sleeping... Conn=1 IntC=0 PS_mode=0 PS_State=0
[  245.469350] libertas thread (INT): lbs_interrupt: intcounter=0
[  245.479405] libertas thread: main-thread 222 (waking up): intcounter=1 currenttxskb=00000000 dnld_sent=0
[  245.480099] libertas thread: main-thread 333: intcounter=1 currenttxskb=00000000 dnld_sent=0
[  245.490401] libertas thread: main-thread 444: intcounter=0 currenttxskb=00000000 dnld_sent=0
[  245.498863] libertas thread: main-thread: cmd response ready
[  245.501529] libertas thread: main-thread 111: intcounter=0 currenttxskb=00000000 dnld_sent=0
[  245.509955] libertas thread: main-thread sleeping... Conn=1 IntC=0 PS_mode=0 PS_State=0
[  246.259117] libertas thread: main-thread 222 (waking up): intcounter=0 currenttxskb=00000000 dnld_sent=0
[  246.262126] libertas thread: main-thread 333: intcounter=0 currenttxskb=00000000 dnld_sent=0
[  246.272131] libertas thread: main-thread 444: intcounter=0 currenttxskb=00000000 dnld_sent=0
[  246.282475] libertas thread: main-thread 111: intcounter=0 currenttxskb=00000000 dnld_sent=2
[  246.291878] libertas thread (INT): lbs_interrupt: intcounter=0
[  246.298089] libertas thread: main-thread 222 (waking up): intcounter=1 currenttxskb=00000000 dnld_sent=0
[  246.302052] libertas thread: main-thread 333: intcounter=1 currenttxskb=00000000 dnld_sent=0
[  246.312038] libertas thread: main-thread 444: intcounter=0 currenttxskb=00000000 dnld_sent=0
[  246.320497] libertas thread: main-thread: cmd response ready
[  246.323247] libertas thread: main-thread 111: intcounter=0 currenttxskb=00000000 dnld_sent=2
[  246.331863] libertas thread (INT): lbs_interrupt: intcounter=0
[  246.338063] libertas thread: main-thread 222 (waking up): intcounter=1 currenttxskb=00000000 dnld_sent=0
[  246.342044] libertas thread: main-thread 333: intcounter=1 currenttxskb=00000000 dnld_sent=0
[  246.352038] libertas thread: main-thread 444: intcounter=0 currenttxskb=00000000 dnld_sent=0
[  246.360495] libertas thread: main-thread: cmd response ready
[  246.362988] libertas thread: main-thread 111: intcounter=0 currenttxskb=00000000 dnld_sent=0
[  246.372767] libertas thread: main-thread sleeping... Conn=1 IntC=0 PS_mode=0 PS_State=0
[  246.435664] olpc-ec:  running cmd 0x26
[  246.440454] olpc-ec:  sending cmd arg 0x0
[  246.571521] libertas thread: main-thread 222 (waking up): intcounter=0 currenttxskb=00000000 dnld_sent=0
[  246.592848] libertas thread: main-thread 333: intcounter=0 currenttxskb=00000000 dnld_sent=0
[  246.620279] libertas thread: main-thread 444: intcounter=0 currenttxskb=00000000 dnld_sent=0
[  246.621995] libertas thread: main-thread 111: intcounter=0 currenttxskb=00000000 dnld_sent=2
[  246.651104] libertas thread: main-thread sleeping... Conn=1 IntC=0 PS_mode=0 PS_State=0
[  246.676459] olpc-ec:  running cmd 0x35
[  246.681388] devpath 1 ep3in 3strikes
[  246.685092] usb 2-1: USB disconnect, address 2
[  246.707142] olpc-ec:  running cmd 0x1c
[  246.711293] olpc-ec:  received 0xff
[  246.711395] olpc-ec:  running cmd 0x1b
[  246.718171] olpc-ec:  sending cmd arg 0xdf
[  246.825085] olpc-ec:  running cmd 0x1c
[  246.831293] olpc-ec:  received 0xdf
[  246.831355] olpc-ec:  running cmd 0x1b
[  246.836123] olpc-ec:  sending cmd arg 0xde
[  246.972093] olpc-ec:  running cmd 0x1c
[  246.978893] olpc-ec:  received 0xde
[  246.981387] olpc-ec:  running cmd 0x1b
[  246.986157] olpc-ec:  sending cmd arg 0x9e
[  247.078694] olpc-ec:  running cmd 0x1c
[  247.081293] olpc-ec:  received 0x9e
[  247.081393] olpc-ec:  running cmd 0x1b
[  247.086165] olpc-ec:  sending cmd arg 0x96
[  247.151888] olpc-ec:  running cmd 0x1c
[  247.158688] olpc-ec:  received 0x96
[  247.161377] olpc-ec:  running cmd 0x1b
[  247.166151] olpc-ec:  sending cmd arg 0x92
[  247.258654] olpc-ec:  running cmd 0x1c
[  247.261293] olpc-ec:  received 0x92
[  247.261373] olpc-ec:  running cmd 0x1b
[  247.266144] olpc-ec:  sending cmd arg 0x90
[  247.321846] PM: Syncing filesystems ... done.
[  247.361452] PM: Preparing system for mem sleep
[  247.388221] Freezing user space processes ... (elapsed 0.01 seconds) done.
[  247.417623] Freezing remaining freezable tasks ... <6>libertas: Command 6 timed out
[  256.614535] libertas thread: main-thread 222 (waking up): intcounter=0 currenttxskb=00000000 dnld_sent=0
[  256.621524] libertas thread: main-thread 333: intcounter=0 currenttxskb=00000000 dnld_sent=0
[  256.631522] libertas thread: adapter removed; waiting to die...
[  256.637459] libertas thread: main-thread 111: intcounter=0 currenttxskb=00000000 dnld_sent=0
[  256.641532] libertas thread: main-thread sleeping... Conn=1 IntC=0 PS_mode=0 PS_State=0
[  267.431686] 
[  267.433196] Freezing of tasks failed after 20.00 seconds (1 tasks refusing to freeze):
[  267.441206]   task                PC stack   pid father
[  267.441601] init          D cdd47b80  2388     1      0
[  267.444354]        ce81f470 00000082 ce81f6d0 cdd47b80 9ada4511 00000039 00c21078 ce817efb 
[  267.455704]        00000000 00000000 ce817fb8 ce817f10 c04324a5 00000000 c041e0f2 ce817fb8 
[  267.467333]        ce817f90 ce81fa44 00000000 00000000 ce817fb8 ce817000 c0402eaf 00000000 
[  267.471601] Call Trace:
[  267.471697]  [<c04324a5>] refrigerator+0xaa/0xb5
[  267.476368]  [<c041e0f2>] get_signal_to_deliver+0x31/0x2d8
[  267.484682]  [<c0402eaf>] do_notify_resume+0x7e/0x692
[  267.491702]  [<c05eda4c>] _spin_lock_irqsave+0x18/0x1d
[  267.496895]  [<c0424140>] remove_wait_queue+0x16/0x22
[  267.504234]  [<c05edba2>] _spin_unlock_irqrestore+0x14/0x29
[  267.511681]  [<c0417cd1>] do_wait+0x86a/0x8ff
[  267.516108]  [<c04dc0be>] copy_to_user+0x2f/0x45
[  267.520864]  [<c0462372>] sys_select+0x156/0x17c
[  267.521601]  [<c040387c>] work_notifysig+0x9/0x11
[  267.523881]  =======================

  Changed 5 years ago by dcbw

can I get another log with 0x124007? LBS_DEB_MAIN would also be useful here. What I'm getting at is that I'd like to see if the USB code gets the disconnect event. The EC is clearly cutting the power and the 8388 drops off the bus, but that should trigger if_usb.c::if_usb_disconnect() which should clean stuff up. 0x124007 should show that. If thats too much output, just use 0x104007 instead which should show the enter/leave for if_usb_disconnect().

  Changed 5 years ago by cjb

Sure, here it is with 0x124007: 

[ 1033.278168] usb8xxx usbd (INT): 2-1:Wake up main thread to handle cmd response
[ 1033.278168] usb8xxx leave (INT): if_usb_receive():772
[ 1033.426201] olpc-ec:  running cmd 0x35
[ 1033.428267] devpath 1 ep3in 3strikes
[ 1033.431868] usb8xxx enter (INT): if_usb_receive():712
[ 1033.436937] usb8xxx leave (INT): if_usb_receive():772
[ 1033.438382] usb 2-1: USB disconnect, address 2
[ 1033.443537] usb8xxx enter: if_usb_disconnect():340
[ 1033.452897] libertas enter: lbs_stop_card():1316
[ 1033.462926] olpc-ec:  running cmd 0x1c
[ 1033.468168] olpc-ec:  received 0xff
[ 1033.468325] olpc-ec:  running cmd 0x1b
[ 1033.473102] olpc-ec:  sending cmd arg 0xdf
[ 1033.481724] olpc-ec:  running cmd 0x1c
[ 1033.488168] olpc-ec:  received 0xdf
[ 1033.488257] olpc-ec:  running cmd 0x1b
[ 1033.493029] olpc-ec:  sending cmd arg 0xde
[ 1033.498389] libertas enter: lbs_cmd_async():2146
[ 1033.503045] libertas leave: lbs_cmd_async():2149
[ 1033.531497] olpc-ec:  running cmd 0x1c
[ 1033.538168] olpc-ec:  received 0xde
[ 1033.538246] olpc-ec:  running cmd 0x1b
[ 1033.543019] olpc-ec:  sending cmd arg 0x9e
[ 1033.588347] libertas leave: lbs_stop_card():1338, ret -1
[ 1033.593691] libertas enter: lbs_remove_card():1205
[ 1033.618275] libertas thread: main-thread 111: intcounter=1 currenttxskb=00000000 dnld_sent=0
[ 1033.638264] libertas thread: main-thread sleeping... Conn=1 IntC=1 PS_mode=0 PS_State=0
[ 1033.658446] libertas enter: lbs_set_mac_control():1356
[ 1033.664320] libertas enter: lbs_cmd_async():2146
[ 1033.669432] libertas leave: lbs_cmd_async():2149
[ 1033.674253] libertas leave: lbs_set_mac_control():1364
[ 1033.684294] olpc-ec:  running cmd 0x1c
[ 1033.688168] olpc-ec:  received 0x9e
[ 1033.688268] olpc-ec:  running cmd 0x1b
[ 1033.696046] olpc-ec:  sending cmd arg 0x96
[ 1033.738314] libertas enter: lbs_remove_rtap():1568
[ 1033.828758] olpc-ec:  running cmd 0x1c
[ 1033.836564] olpc-ec:  received 0x96
[ 1033.838251] olpc-ec:  running cmd 0x1b
[ 1033.843020] olpc-ec:  sending cmd arg 0x92
[ 1034.012201] olpc-ec:  running cmd 0x1c
[ 1034.018168] olpc-ec:  received 0x92
[ 1034.018243] olpc-ec:  running cmd 0x1b
[ 1034.023011] olpc-ec:  sending cmd arg 0x90
[ 1034.166441] PM: Syncing filesystems ... done.
[ 1034.188339] PM: Preparing system for mem sleep
[ 1034.218336] Freezing user space processes ... (elapsed 0.01 seconds) done.
[ 1034.261447] Freezing remaining freezable tasks ... <7>libertas enter (INT): command_timer_fn():1016
[ 1038.192684] libertas: Command 1d timed out
[ 1038.198297] libertas leave (INT): command_timer_fn():1030
[ 1038.203730] libertas thread: main-thread 222 (waking up): intcounter=1 currenttxskb=00000000 dnld_sent=0
[ 1038.208306] libertas thread: main-thread 333: intcounter=1 currenttxskb=00000000 dnld_sent=0
[ 1038.218312] libertas thread: adapter removed; waiting to die...
[ 1038.224252] libertas thread: main-thread 111: intcounter=1 currenttxskb=00000000 dnld_sent=0
[ 1038.228321] libertas thread: main-thread sleeping... Conn=1 IntC=1 PS_mode=0 PS_State=0
[ 1054.278563] 
[ 1054.280079] Freezing of tasks failed after 20.00 seconds (1 tasks refusing to
 freeze):
[ 1054.288106]   task                PC stack   pid father

in reply to: ↑ 16 ; follow-up: ↓ 24   Changed 5 years ago by dsaxena

Replying to cjb:

Javier/libertas people, do you know if there's a way for me to quiesce the radio and command queue such that it becomes safe to rmmod? rmmod isn't that way, as above, but maybe one of the libertas commands for turning off the radio might be..?

Would a simple "ifconfig eth0 down" do the trick? If the driver is properly behaved, it should quiesce the queue and wait for all outstanding commands to timeout or cancel them.

in reply to: ↑ 23   Changed 5 years ago by cjb

Replying to dsaxena:

Would a simple "ifconfig eth0 down" do the trick? If the driver is properly behaved, it should quiesce the queue and wait for all outstanding commands to timeout or cancel them.

Maybe -- what if we're in the middle of association? That seems to be what most of the timed out commands are, and it's iwconfig/layer 2 rather than ifconfig/layer 3.

  Changed 5 years ago by dcbw

Awesome.

So the lbs_cmd_async() in lbs_stop_card() is probably coming from lbs_set_mcast_worker(), which is scheduled from lbs_eth_stop() which is called via netif_carrier_off(). Not a problem, but shouldn't be happening. We should be checking priv->surprise_removed before sending any new commands to the card from stop/remove paths.

The return value of lbs_stop_card() can be ignored because nothing actually touches it, and in fact it now returns void on 2.6.27.

I think the lbs_set_mac_control() and lbs_cmd_async() bits during lbs_remove_card() are the same thing since that code also does netif_carrier_off().

We can ignore the lack of a 'leave' for lbs_remove_rtap(), which is also fixed in 2.6.27.

The core problem looks like kthread_should_stop() isn't returning true in lbs_thread(), otherwise it would break out before the priv->surpriseremoved check in lbs_thread(), or it would set shouldsleep to 0 after and break out in the next iteration.

Can you put something like this in, rebuild and reproduce? We need to see if it's getting block in one of the timer/queue cancellation calls in lbs_remove_card() before it's able to hit the kthread_stop() near the bottom. 

	lbs_remove_mesh(priv);
+lbs_deb_main("%s: 1\n", __func__);
	lbs_remove_rtap(priv);

	dev = priv->dev;

+lbs_deb_main("%s: 2\n", __func__);
	cancel_delayed_work_sync(&priv->scan_work);
+lbs_deb_main("%s: 3\n", __func__);
	cancel_delayed_work_sync(&priv->assoc_work);
+lbs_deb_main("%s: 4\n", __func__);
	cancel_work_sync(&priv->mcast_work);
+lbs_deb_main("%s: 5\n", __func__);
	destroy_workqueue(priv->work_thread);
+lbs_deb_main("%s: 6\n", __func__);

	if (priv->psmode == LBS802_11POWERMODEMAX_PSP) {
		priv->psmode = LBS802_11POWERMODECAM;
+lbs_deb_main("%s: 7\n", __func__);
		lbs_ps_wakeup(priv, CMD_OPTION_WAITFORRSP);
	}

+lbs_deb_main("%s: 8\n", __func__);
	memset(wrqu.ap_addr.sa_data, 0xaa, ETH_ALEN);
	wrqu.ap_addr.sa_family = ARPHRD_ETHER;
	wireless_send_event(priv->dev, SIOCGIWAP, &wrqu, NULL);

	/* Stop the thread servicing the interrupts */
+lbs_deb_main("%s: 9\n", __func__);
	priv->surpriseremoved = 1;
	kthread_stop(priv->main_thread);
+lbs_deb_main("%s: 10\n", __func__);

	lbs_free_adapter(priv);

follow-up: ↓ 29   Changed 5 years ago by dsaxena

The command we are seeing timeout is 1d, which is an RF_CHANNEL, and in the previous logs it was 6, which is a SCAN. Are we also possibly still accepting commands from network manager once we get the USB disonnect? Or are those leftovers from the insmod/resume path that did not get processed before we shutdown power?

  Changed 5 years ago by cjb

Hi, Dan, thanks for all the help: 

[ 1261.331658] olpc-ec:  running cmd 0x35
[ 1261.334485] devpath 1 ep3in 3strikes
[ 1261.338085] usb8xxx enter (INT): if_usb_receive():712
[ 1261.343161] usb8xxx leave (INT): if_usb_receive():772
[ 1261.344546] usb 2-1: USB disconnect, address 4
[ 1261.349715] usb8xxx enter: if_usb_disconnect():340
[ 1261.358647] libertas enter: lbs_stop_card():1326
[ 1261.369416] olpc-ec:  running cmd 0x1c
[ 1261.374397] olpc-ec:  received 0xff
[ 1261.374475] olpc-ec:  running cmd 0x1b
[ 1261.379245] olpc-ec:  sending cmd arg 0xdf
[ 1261.397359] olpc-ec:  running cmd 0x1c
[ 1261.404155] olpc-ec:  received 0xdf
[ 1261.404512] olpc-ec:  running cmd 0x1b
[ 1261.409282] olpc-ec:  sending cmd arg 0xde
[ 1261.424503] libertas thread: main-thread sleeping... Conn=0 IntC=0 PS_mode=0 PS_State=0
[ 1261.525084] olpc-ec:  running cmd 0x1c
[ 1261.531882] olpc-ec:  received 0xde
[ 1261.534474] olpc-ec:  running cmd 0x1b
[ 1261.539244] olpc-ec:  sending cmd arg 0x9e
[ 1261.594922] olpc-ec:  running cmd 0x1c
[ 1261.601723] olpc-ec:  received 0x9e
[ 1261.604490] olpc-ec:  running cmd 0x1b
[ 1261.609259] olpc-ec:  sending cmd arg 0x96
[ 1261.664992] olpc-ec:  running cmd 0x1c
[ 1261.671793] olpc-ec:  received 0x96
[ 1261.674470] olpc-ec:  running cmd 0x1b
[ 1261.679241] olpc-ec:  sending cmd arg 0x92
[ 1261.724669] libertas leave: lbs_stop_card():1348, ret -1
[ 1261.744677] libertas enter: lbs_cmd_async():2146
[ 1261.749758] libertas leave: lbs_cmd_async():2149
[ 1261.771816] libertas enter: lbs_remove_card():1205
[ 1261.804574] libertas enter: lbs_cmd_async():2146
[ 1261.810000] libertas leave: lbs_cmd_async():2149
[ 1261.860449] olpc-ec:  running cmd 0x1c
[ 1261.864397] olpc-ec:  received 0x92
[ 1261.864487] olpc-ec:  running cmd 0x1b
[ 1261.870262] olpc-ec:  sending cmd arg 0x90
[ 1261.974953] PM: Syncing filesystems ... done.
[ 1262.003956] PM: Preparing system for mem sleep
[ 1262.004397] Freezing user space processes ... <7>libertas main: lbs_remove_card: 1
[ 1262.467882] libertas enter: lbs_remove_rtap():1578
[ 1262.474490] libertas main: lbs_remove_card: 2
[ 1262.478861] libertas main: lbs_remove_card: 3
[ 1262.485025] libertas main: lbs_remove_card: 4
[ 1262.489400] libertas main: lbs_remove_card: 5
[ 1262.494674] libertas main: lbs_remove_card: 6
[ 1262.499044] libertas main: lbs_remove_card: 8
[ 1262.504513] libertas main: lbs_remove_card: 9
[ 1262.508969] libertas thread: main-thread 222 (waking up): intcounter=0 currenttxskb=00000000 dnld_sent=0
[ 1262.514503] libertas thread: main-thread 333: intcounter=0 currenttxskb=00000000 dnld_sent=0
[ 1262.524483] libertas thread: main-thread: break from main thread
[ 1262.530511] libertas leave: lbs_thread():907
[ 1262.534535] libertas main: lbs_remove_card: 10
[ 1262.538998] libertas enter: lbs_free_adapter():1104
[ 1262.544513] libertas leave: lbs_free_adapter():1111
[ 1262.549412] libertas leave: lbs_remove_card():1245
[ 1262.554939] (elapsed 0.54 seconds) done.
[ 1262.558902] Freezing remaining freezable tasks ... <7>usb8xxx enter: if_usb_free():147
[ 1262.567729] usb8xxx leave: if_usb_free():162
[ 1262.574484] usb8xxx leave: if_usb_disconnect():359
[ 1262.734558] (elapsed 0.15 seconds) done.
[ 1262.738555] PM: Entering mem sleep
[ 1262.744483] Suspending console(s)

  Changed 5 years ago by cjb

Oops, the above isn't a crash, it's a successful suspend.

in reply to: ↑ 26 ; follow-up: ↓ 30   Changed 5 years ago by dcbw

Replying to dsaxena:

The command we are seeing timeout is 1d, which is an RF_CHANNEL, and in the previous logs it was 6, which is a SCAN. Are we also possibly still accepting commands from network manager once we get the USB disonnect? Or are those leftovers from the insmod/resume path that did not get processed before we shutdown power?

SCAN commands are definitely left around from before; the driver isn't clearing the command queue correctly. There's work to be done with command handling; priv->cur_cmd_retcode and cmdnode->result are all muddled together and used interchangably in some places. I'll try to fix that up.

RF_CHANNEL (set) only ever gets called from the association worker code as a result of WEXT calls. RF_CHANNEL (get) only gets called from WEXT code, or from the mesh autostart code when the firmware sends MACREG_INT_CODE_MESH_AUTO_STARTED, to ensure the driver and firmware agree on a channel.

I think that (besides the async MAC_CONTROL commands) all the commands we're seeing here are in-flight commands that aren't properly canceled while tearing down the driver.

cjb: any chance you can reproduce the failed suspend with the ~20s hang?

in reply to: ↑ 29   Changed 5 years ago by cjb

Hi,

Replying to dcbw:

cjb: any chance you can reproduce the failed suspend with the ~20s hang?

I'm sure I can, but I'm not in the office -- I'll try and drop by tomorrow, else Monday.

  Changed 5 years ago by cjb

I've got a log now: 

[  204.423003] olpc-ec:  running cmd 0x35
[  204.428827] devpath 1 ep3in 3strikes
[  204.432429] usb8xxx enter (INT): if_usb_receive():712
[  204.432692] usb8xxx leave (INT): if_usb_receive():772
[  204.432835] usb 2-1: USB disconnect, address 4
[  204.437966] usb8xxx enter: if_usb_disconnect():340
[  204.442816] libertas enter: lbs_stop_card():1326
[  204.458664] olpc-ec:  running cmd 0x1c
[  204.462692] olpc-ec:  received 0xff
[  204.462756] olpc-ec:  running cmd 0x1b
[  204.467527] olpc-ec:  sending cmd arg 0xdf
[  204.472692] olpc-ec:  running cmd 0x1c
[  204.472692] olpc-ec:  received 0xdf
[  204.472818] olpc-ec:  running cmd 0x1b
[  204.477589] olpc-ec:  sending cmd arg 0xde
[  204.482997] libertas enter: lbs_cmd_async():2146
[  204.487635] libertas leave: lbs_cmd_async():2149
[  204.501134] olpc-ec:  running cmd 0x1c
[  204.502692] olpc-ec:  received 0xde
[  204.502821] olpc-ec:  running cmd 0x1b
[  204.508599] olpc-ec:  sending cmd arg 0x9e
[  204.582842] libertas leave: lbs_stop_card():1348, ret -1
[  204.588189] libertas enter: lbs_remove_card():1205
[  204.622836] libertas enter: lbs_cmd_async():2146
[  204.627484] libertas leave: lbs_cmd_async():2149
[  204.702875] libertas main: lbs_remove_card: 1
[  204.707270] libertas enter: lbs_remove_rtap():1578
[  204.712498] libertas main: lbs_remove_card: 2
[  204.712692] libertas main: lbs_remove_card: 3
[  204.712949] libertas main: lbs_remove_card: 4
[  204.717508] libertas main: lbs_remove_card: 5
[  204.741084] olpc-ec:  running cmd 0x1c
[  204.742692] olpc-ec:  received 0x9e
[  204.742776] olpc-ec:  running cmd 0x1b
[  204.747551] olpc-ec:  sending cmd arg 0x96
[  204.800403] olpc-ec:  running cmd 0x1c
[  204.802692] olpc-ec:  received 0x96
[  204.802767] olpc-ec:  running cmd 0x1b
[  204.807537] olpc-ec:  sending cmd arg 0x92
[  204.903286] olpc-ec:  running cmd 0x1c
[  204.911090] olpc-ec:  received 0x92
[  204.912757] olpc-ec:  running cmd 0x1b
[  204.917527] olpc-ec:  sending cmd arg 0x90
[  205.093240] PM: Syncing filesystems ... done.
[  205.142860] PM: Preparing system for mem sleep
[  205.152392] Freezing user space processes ... (elapsed 0.00 seconds) done.
[  205.160775] Freezing remaining freezable tasks ... <7>libertas enter (INT): command_timer_fn():1016
[  214.097284] libertas: Command 6 timed out
[  214.102893] libertas leave (INT): command_timer_fn():1030
[  214.108328] libertas thread: main-thread 222 (waking up): intcounter=0 currenttxskb=00000000 dnld_sent=0
[  214.112897] libertas thread: main-thread 333: intcounter=0 currenttxskb=00000000 dnld_sent=0
[  214.121444] libertas thread: adapter removed; waiting to die...   
[  214.122823] libertas thread: main-thread 111: intcounter=0 currenttxskb=00000000 dnld_sent=0
[  214.122915] libertas thread: main-thread sleeping... Conn=1 IntC=0 PS_mode=0 PS_State=0
[  225.153070]
[  225.154584] Freezing of tasks failed after 20.00 seconds (1 tasks refusing to freeze):
[  225.163056]   task                PC stack   pid father
[  225.168296] init          D cdd47d60  2436     1      0

  Changed 5 years ago by cjb

Neat, the log helps: 

    lbs_deb_main("%s: 5\n", __func__);
    destroy_workqueue(priv->work_thread);
    lbs_deb_main("%s: 6\n", __func__);

It looks from a glance that destroy_workqueue() is supposed to block waiting for work to finish before destroying the workqeue.

  Changed 5 years ago by cjb

I tried adding a flush_workqueue() before the destroy_workqueue(), with the result that we hung in the flush_workqueue() instead -- then I noticed that destroy_ calls the same internal function as flush_. So, I think it's safe to say that we're hanging in flush_cpu_workqueue(), and the reason is that we're successfully clearing scheduled tasks from the runqueue, but we're not successfully clearing the active thread, and we're instead blocking on it to return, which it never does.

I don't know enough about the workqueue API yet to know what the right way for a kernel thread to know when to tear itself down immediately is.

  Changed 5 years ago by dcbw

lbs_stop_card() should be clearing out any in-flight commands, and the driver should also be failing command prep if priv->surpriseremoved == 1, which is done in lbs_cmd_async() for direct commands and lbs_prepare_and_send_command() for old-style commands. So there definitely shouldn't be any commands getting through after if_usb_disconnect().

But the command 6 (SCAN) surely is coming from earlier since nothing in the disconnect path will call scan, since there isn't any indication of a WEXT scan request coming in, and since there isn't any indication of an association request (which triggers a scan) coming in either.

scan.c::lbs_do_scan() calls cmd.c::lbs_cmd(CMD_802_11_SCAN), which then blocks on cmdnode->cmd_waitq. When lbs_stop_card() cycles through all the commands in the queue and stops them,

Argh. I forgot about LBS_DEB_HOST, which is what most of the command code uses when queuing commands. I hate to ask, but could you get another log with 0x126007 (which adds LBS_DEB_HOST) and also see if you can retrieve about 15 - 20 seconds of earlier logging before the stuff that you've attached so far? That should be enough to show us where the actual command that's in-flight at the time of disconnect is getting queued, and if it's successfully blocking on its cmdnode waitq. Thanks!

  Changed 5 years ago by cjb

Attached (newlibertas4.cap) is one example, this time it's cmd "b". Will reproduce again with cmd 6 in case that's important.

Changed 5 years ago by cjb

  Changed 5 years ago by cjb

Here (newlibertas5.cap) is a long trace with a CMD6 hang.

Changed 5 years ago by cjb

  Changed 5 years ago by dcbw

So here's the problem... priv->work_queue is a generic worker thread that executes commands, including SCAN. In newlibertas5.cap, the worker thread is blocked in lbs_do_scan() waiting for the queued scan command to finish. When lbs_remove_card() is called, it calls destroy_workqueue() which blocks on the worker finishing, but priv->work_queue is blocked waiting for the command to finish, so there's the hang.

What's not clear yet is why the bits in lbs_stop_card() aren't clearing the command and waking up the priv->work_queue and making the lbs_prepare_and_send_command() in lbs_do_scan() return with an error so that the scan work completes.

My current theory is that killing the current in-flight command is mishandled.

  Changed 5 years ago by dcbw

The current command actually gets removed from the pending command queue when it's in-flight, and thus the code in lbs_stop_card() doesn't look like it could possibly kill that command too. Can you try the following patch (completely untested, against stable)? 

diff --git a/drivers/net/wireless/libertas/cmd.c b/drivers/net/wireless/libertas/cmd.c
index fcf3826..3ea3136 100644
--- a/drivers/net/wireless/libertas/cmd.c
+++ b/drivers/net/wireless/libertas/cmd.c
@@ -1674,6 +1674,7 @@ int lbs_prepare_and_send_command(struct lbs_private *priv,
 		might_sleep();
 		wait_event_interruptible(cmdnode->cmdwait_q,
 					 cmdnode->cmdwaitqwoken);
+lbs_deb_host("PREP_CMD: done waiting for command 0x%X\n", cmd_no);
 	}
 
 	spin_lock_irqsave(&priv->driver_lock, flags);
diff --git a/drivers/net/wireless/libertas/main.c b/drivers/net/wireless/libertas/main.c
index 20af097..b4cdb4b 100644
--- a/drivers/net/wireless/libertas/main.c
+++ b/drivers/net/wireless/libertas/main.c
@@ -1300,11 +1300,24 @@ int lbs_stop_card(struct lbs_private *priv)
 
 	/* Flush pending command nodes */
 	spin_lock_irqsave(&priv->driver_lock, flags);
+lbs_deb_main("%s: clearing pending commands\n", __func__);
 	list_for_each_entry(cmdnode, &priv->cmdpendingq, list) {
 		cmdnode->result = -ENOENT;
 		cmdnode->cmdwaitqwoken = 1;
 		wake_up_interruptible(&cmdnode->cmdwait_q);
 	}
+
+	if (priv->cur_cmd) {
+		struct cmd_header *cmd;
+
+		cmd = priv->cur_cmd->cmdbuf;
+		lbs_deb_main("%s: clearing in-flight command 0x%X\n", __func__, le16_to_cpu(cmd->command));
+
+		priv->cur_cmd->result = -ENOENT;
+		priv->cur_cmd->cmdwaitqwoken = 1;
+		wake_up_interruptible(&priv->cur_cmd->cmdwait_q);
+	}
+lbs_deb_main("%s: done clearing commands\n", __func__);
 	spin_unlock_irqrestore(&priv->driver_lock, flags);
 
 	unregister_netdev(dev);

  Changed 5 years ago by cjb

Here's post-patch output. We suspend successfully after an aborted command! 

[  190.871389] libertas host: PREP_CMD: command 0x0006
[  190.873754] libertas enter: lbs_queue_cmd():1182
[  190.874847] libertas host: QUEUE_CMD: inserted command 0x0006 into cmdpending q
[  190.885446] libertas leave: lbs_queue_cmd():1217
[  190.890368] libertas host: PREP_CMD: wait for response
[  190.894134] libertas leave: lbs_process_rx_command():700, ret 0
[  190.900361] libertas enter: lbs_execute_next_command():1812
[  190.904135] libertas host: EXEC_NEXT_CMD: sending command 0x000b
[  190.916759] libertas enter: lbs_submit_command():1230
[  190.930002] libertas cmd: DNLD_CMD: command 0x000b, seq 222, size 60, jiffies 4294956921
[  190.934099] usb8xxx usbd: 2-1:*** type = 1
[  190.938972] usb8xxx usbd: 2-1:size after = 60
[  190.949161] libertas leave: lbs_submit_command():1263
[  190.953852] libertas enter (INT): lbs_host_to_card_done():510
[  190.959619] libertas leave (INT): lbs_host_to_card_done():521
[  190.963754] usb8xxx enter (INT): if_usb_receive():712
[  190.963754] usb8xxx usbd (INT): 2-1:Recv length = 0x42, Recv type = 0xF00DFACE
[  190.963754] libertas enter (INT): lbs_interrupt():1530
[  190.963754] libertas thread (INT): lbs_interrupt: intcounter=0
[  190.963754] libertas leave (INT): lbs_interrupt():1538
[  190.963754] usb8xxx usbd (INT): 2-1:Wake up main thread to handle cmd response
[  190.963754] usb8xxx leave (INT): if_usb_receive():772
[  190.982877] libertas leave: lbs_execute_next_command():1947
[  190.984270] libertas thread: main-thread 111: intcounter=1 currenttxskb=00000000 dnld_sent=0
[  191.008163] libertas thread: main-thread 222 (waking up): intcounter=1 currenttxskb=00000000 dnld_sent=0
[  191.018842] libertas thread: main-thread 333: intcounter=1 currenttxskb=00000000 dnld_sent=0
[  191.028960] usb8xxx usbd: 2-1:Int cause is 0x8
[  191.033436] libertas thread: main-thread 444: intcounter=0 currenttxskb=00000000 dnld_sent=0
[  191.033754] libertas thread: main-thread: cmd response ready
[  191.040964] libertas enter: lbs_process_rx_command():550
[  191.045458] libertas cmd: CMD_RESP: response 0x800b, seq 222, size 62, jiffies 4294956940[  191.065003] libertas enter: handle_cmd_response():401
[  191.070334] libertas enter: lbs_ret_get_log():366
[  191.074423] libertas leave: lbs_ret_get_log():371
[  191.086556] libertas leave: handle_cmd_response():538
[  191.101925] olpc-ec:  running cmd 0x35
[  191.103840] devpath 1 ep3in 3strikes
[  191.107439] usb8xxx enter (INT): if_usb_receive():712
[  191.112515] usb8xxx leave (INT): if_usb_receive():772
[  191.113963] usb 2-1: USB disconnect, address 2
[  191.123537] usb8xxx enter: if_usb_disconnect():340
[  191.123864] libertas enter: lbs_stop_card():1328
[  191.128733] libertas main: lbs_stop_card: clearing pending commands
[  191.133754] libertas main: lbs_stop_card: clearing in-flight command 0xB
[  191.133754] libertas main: lbs_stop_card: done clearing commands
[  191.138621] libertas host: PREP_CMD: done waiting for command 0x6
[  191.143847] libertas leave: lbs_prepare_and_send_command():1640, ret 0
[  191.150398] libertas enter: lbs_prepare_and_send_command():1388
[  191.154542] libertas host: PREP_CMD: card removed
[  191.159265] libertas leave: lbs_prepare_and_send_command():1640, ret -1
[  191.164762] olpc-ec:  running cmd 0x1c
[  191.172549] olpc-ec:  received 0xff
[  191.173851] olpc-ec:  running cmd 0x1b
[  191.178621] olpc-ec:  sending cmd arg 0xdf
[  191.184092] libertas enter: lbs_cmd_async():2147
[  191.188732] libertas enter: __lbs_cmd_async():2102
[  191.193857] libertas host: PREP_CMD: card removed
[  191.198576] libertas leave: __lbs_cmd_async():2140, ret fffffffe
[  191.203845] libertas leave: lbs_cmd_async():2150
[  191.209910] libertas: SCAN_CMD failed
[  191.216839] olpc-ec:  running cmd 0x1c
[  191.223637] olpc-ec:  received 0xdf
[  191.223847] olpc-ec:  running cmd 0x1b
[  191.228621] olpc-ec:  sending cmd arg 0xde
[  191.296583] libertas enter: __lbs_cleanup_and_insert_cmd():1273
[  191.302541] libertas leave: __lbs_cleanup_and_insert_cmd():1285
[  191.313890] libertas enter: lbs_prepare_and_send_command():1388
[  191.320088] libertas host: PREP_CMD: card removed
[  191.324363] libertas leave: lbs_prepare_and_send_command():1640, ret -1
[  191.331199] libertas: SCAN_CMD failed
[  191.334177] libertas leave: lbs_process_rx_command():700, ret 0
[  191.353855] libertas enter: lbs_execute_next_command():1812
[  191.359658] libertas host: EXEC_NEXT_CMD: sending command 0x0006
[  191.364859] libertas enter: lbs_submit_command():1230
[  191.370576] olpc-ec:  running cmd 0x1c
[  191.373754] olpc-ec:  received 0xde
[  191.373831] olpc-ec:  running cmd 0x1b
[  191.378606] olpc-ec:  sending cmd arg 0x9e
[  191.383232] libertas cmd: DNLD_CMD: command 0x0006, seq 224, size 63, jiffies 4294956977
[  191.384032] usb8xxx usbd: 2-1:*** type = 1
[  191.388319] usb8xxx usbd: 2-1:size after = 63
[  191.403848] usb8xxx usbd: 2-1:Device removed
[  191.408335] libertas: DNLD_CMD: hw_host_to_card failed: -1
[  191.414877] libertas leave: lbs_submit_command():1263
[  191.420134] libertas leave: lbs_execute_next_command():1947
[  191.433854] libertas thread: main-thread 111: intcounter=0 currenttxskb=00000000 dnld_sent=2
[  191.445364] olpc-ec:  running cmd 0x1c
[  191.452156] olpc-ec:  received 0x9e
[  191.453819] olpc-ec:  running cmd 0x1b
[  191.458596] olpc-ec:  sending cmd arg 0x96
[  191.465355] libertas thread: main-thread sleeping... Conn=0 IntC=0 PS_mode=0 PS_State=0
[  191.514357] olpc-ec:  running cmd 0x1c
[  191.521159] olpc-ec:  received 0x96
[  191.523840] olpc-ec:  running cmd 0x1b
[  191.528614] olpc-ec:  sending cmd arg 0x92
[  191.556649] olpc-ec:  running cmd 0x1c
[  191.563446] olpc-ec:  received 0x92
[  191.563843] olpc-ec:  running cmd 0x1b
[  191.568617] olpc-ec:  sending cmd arg 0x90
[  191.604470] PM: Syncing filesystems ... <6>ADDRCONF(NETDEV_CHANGE): msh0: link becomes ready
[  191.753912] libertas thread: main-thread 222 (waking up): intcounter=0 currenttxskb=00000000 dnld_sent=2
[  191.765812] libertas thread: main-thread 333: intcounter=0 currenttxskb=00000000 dnld_sent=2
[  191.775750] libertas thread: adapter removed; waiting to die...
[  191.781979] libertas thread: main-thread 111: intcounter=0 currenttxskb=00000000 dnld_sent=2
[  191.784035] libertas leave: lbs_stop_card():1364, ret -1
[  191.789367] libertas enter: lbs_remove_card():1205
[  191.794582] libertas enter: lbs_cmd_async():2147
[  191.799217] libertas enter: __lbs_cmd_async():2102
[  191.803927] libertas host: PREP_CMD: card removed
[  191.808646] libertas leave: __lbs_cmd_async():2140, ret fffffffe
[  191.813847] libertas leave: lbs_cmd_async():2150
[  191.818779] libertas enter: lbs_prepare_and_send_command():1388
[  191.823845] libertas host: PREP_CMD: card removed
[  191.828567] libertas leave: lbs_prepare_and_send_command():1640, ret -1
[  191.833835] libertas enter: lbs_prepare_and_send_command():1388
[  191.839771] libertas host: PREP_CMD: card removed
[  191.843832] libertas leave: lbs_prepare_and_send_command():1640, ret -1
[  191.860251] libertas thread: main-thread sleeping... Conn=0 IntC=0 PS_mode=0 PS_State=0
[  191.894055] libertas enter: lbs_set_mac_control():1356
[  191.899224] libertas enter: lbs_cmd_async():2147
[  191.906072] libertas enter: __lbs_cmd_async():2102
[  191.911157] libertas host: PREP_CMD: card removed
[  191.914127] libertas leave: __lbs_cmd_async():2140, ret fffffffe
[  191.920444] libertas leave: lbs_cmd_async():2150
[  191.924124] libertas leave: lbs_set_mac_control():1364
[  192.403830] libertas enter (INT): command_timer_fn():1016
[  192.409261] libertas: Command 6 timed out
[  192.413846] libertas leave (INT): command_timer_fn():1030
[  192.419307] libertas thread: main-thread 222 (waking up): intcounter=0 currenttxskb=00000000 dnld_sent=2
[  192.423844] libertas thread: main-thread 333: intcounter=0 currenttxskb=00000000 dnld_sent=2
[  192.433846] libertas thread: adapter removed; waiting to die...
[  192.439778] libertas thread: main-thread 111: intcounter=0 currenttxskb=00000000 dnld_sent=2
[  192.443917] libertas thread: main-thread sleeping... Conn=0 IntC=0 PS_mode=0 PS_State=0
[  192.743875] libertas main: lbs_remove_card: 1
[  192.748271] libertas enter: lbs_remove_rtap():1594
[  192.753842] libertas main: lbs_remove_card: 2
[  192.758213] libertas main: lbs_remove_card: 3
[  192.763844] libertas main: lbs_remove_card: 4
[  192.768214] libertas main: lbs_remove_card: 5
[  192.773963] libertas main: lbs_remove_card: 6
[  192.778333] libertas main: lbs_remove_card: 8
[  192.783873] libertas main: lbs_remove_card: 9
[  192.823934] libertas thread: main-thread 222 (waking up): intcounter=0 currenttxskb=00000000 dnld_sent=2
[  192.833929] libertas thread: main-thread 333: intcounter=0 currenttxskb=00000000 dnld_sent=2
[  192.842479] libertas thread: main-thread: break from main thread
[  192.843754] libertas leave: lbs_thread():907
[  192.844021] libertas main: lbs_remove_card: 10
[  192.848482] libertas enter: lbs_free_adapter():1104
[  192.853469] libertas enter: lbs_free_cmd_buffer():1701
[  192.853754] libertas leave: lbs_free_cmd_buffer():1726
[  192.853836] libertas leave: lbs_free_adapter():1111
[  192.858738] libertas leave: lbs_remove_card():1247
[  192.863822] usb8xxx enter: if_usb_free():147
[  192.868122] usb8xxx leave: if_usb_free():162
[  192.872495] usb8xxx leave: if_usb_disconnect():359
[  199.466577] done.
[  199.468892] PM: Preparing system for mem sleep
[  199.483912] Freezing user space processes ... (elapsed 0.02 seconds) done.
[  199.521128] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
[  199.544480] PM: Entering mem sleep
[  199.547892] Suspending console(s)

  Changed 5 years ago by cjb

And here's one with 0x6 in-flight: 

[  470.505596] libertas host: QUEUE_CMD: inserted command 0x001e into cmdpending q
[  470.527453] libertas leave: lbs_queue_cmd():1217
[  470.530521] libertas thread: main-thread 222 (waking up): intcounter=0 currenttxskb=00000000 dnld_sent=0
[  470.530606] libertas thread: main-thread 333: intcounter=0 currenttxskb=00000000 dnld_sent=0
[  470.544146] libertas thread: main-thread 444: intcounter=0 currenttxskb=00000000 dnld_sent=0
[  470.552538] libertas thread: main-thread 111: intcounter=0 currenttxskb=00000000 dnld_sent=0
[  470.562543] libertas thread: main-thread sleeping... Conn=1 IntC=0 PS_mode=0 PS_State=0
[  470.572782] libertas host: PREP_CMD: wait for response
[  470.827009] olpm-pm:  PM_PWRBTN event received
[  470.913102] usb8xxx enter (INT): if_usb_receive():712
[  470.918193] usb8xxx usbd (INT): 2-1:Recv length = 0x442, Recv type = 0xF00DFACE
[  470.919999] libertas enter (INT): lbs_interrupt():1530
[  470.919999] libertas thread (INT): lbs_interrupt: intcounter=0
[  470.919999] libertas leave (INT): lbs_interrupt():1538
[  470.919999] usb8xxx usbd (INT): 2-1:Wake up main thread to handle cmd response
[  470.919999] usb8xxx leave (INT): if_usb_receive():772
[  470.920116] libertas thread: main-thread 222 (waking up): intcounter=1 currenttxskb=00000000 dnld_sent=0
[  470.930150] libertas thread: main-thread 333: intcounter=1 currenttxskb=00000000 dnld_sent=0
[  470.938711] usb8xxx usbd: 2-1:Int cause is 0x8
[  470.939999] libertas thread: main-thread 444: intcounter=0 currenttxskb=00000000 dnld_sent=0
[  470.939999] libertas thread: main-thread: cmd response ready
[  470.940095] libertas enter: lbs_process_rx_command():550
[  470.945437] libertas cmd: CMD_RESP: response 0x8006, seq 14, size 1086, jiffies 23836
[  470.950080] libertas enter: handle_cmd_response():401
[  470.955195] libertas leave: handle_cmd_response():538
[  470.960086] libertas enter: __lbs_cleanup_and_insert_cmd():1273
[  470.966021] libertas leave: __lbs_cleanup_and_insert_cmd():1285
[  470.970083] libertas host: PREP_CMD: done waiting for command 0x6
[  470.976191] libertas leave: lbs_prepare_and_send_command():1640, ret 0
[  470.980145] libertas enter: lbs_prepare_and_send_command():1388
[  470.986080] libertas enter: lbs_get_cmd_ctrl_node():1742
[  470.990079] libertas leave: lbs_get_cmd_ctrl_node():1760
[  470.995403] libertas enter: lbs_set_cmd_ctrl_node():1783
[  471.000075] libertas leave: lbs_set_cmd_ctrl_node():1791
[  471.005402] libertas host: PREP_CMD: command 0x0006
[  471.010089] libertas enter: lbs_queue_cmd():1182
[  471.014723] libertas host: QUEUE_CMD: inserted command 0x0006 into cmdpending q
[  471.020159] libertas leave: lbs_queue_cmd():1217
[  471.024796] libertas host: PREP_CMD: wait for response
[  471.030173] libertas leave: lbs_process_rx_command():700, ret 0
[  471.036106] libertas enter: lbs_execute_next_command():1812
[  471.040283] libertas host: EXEC_NEXT_CMD: sending command 0x0010
[  471.046310] libertas enter: lbs_submit_command():1230
[  471.050087] libertas cmd: DNLD_CMD: command 0x0010, seq 15, size 24, jiffies 23849
[  471.073229] usb8xxx usbd: 2-1:*** type = 1
[  471.077352] usb8xxx usbd: 2-1:size after = 24
[  471.080080] libertas leave: lbs_submit_command():1263
[  471.085170] libertas enter (INT): lbs_host_to_card_done():510
[  471.090000] libertas leave (INT): lbs_host_to_card_done():521
[  471.090000] usb8xxx enter (INT): if_usb_receive():712
[  471.090000] usb8xxx usbd (INT): 2-1:Recv length = 0x1c, Recv type = 0xF00DFACE
[  471.090000] libertas enter (INT): lbs_interrupt():1530
[  471.090000] libertas thread (INT): lbs_interrupt: intcounter=0
[  471.090000] libertas leave (INT): lbs_interrupt():1538
[  471.090000] usb8xxx usbd (INT): 2-1:Wake up main thread to handle cmd response
[  471.090000] usb8xxx leave (INT): if_usb_receive():772
[  471.090108] libertas leave: lbs_execute_next_command():1947
[  471.095709] usb8xxx usbd: 2-1:*** type = 0
[  471.099817] usb8xxx usbd: 2-1:size after = 105
[  471.100096] libertas enter (INT): lbs_host_to_card_done():510
[  471.105855] libertas leave (INT): lbs_host_to_card_done():521
[  471.110116] libertas thread: main-thread 111: intcounter=1 currenttxskb=00000000 dnld_sent=0
[  471.120104] libertas thread: main-thread 222 (waking up): intcounter=1 currenttxskb=00000000 dnld_sent=0
[  471.130103] libertas thread: main-thread 333: intcounter=1 currenttxskb=00000000 dnld_sent=0
[  471.140075] usb8xxx usbd: 2-1:Int cause is 0x8
[  471.144541] libertas thread: main-thread 444: intcounter=0 currenttxskb=00000000 dnld_sent=0
[  471.150000] libertas thread: main-thread: cmd response ready
[  471.150078] libertas enter: lbs_process_rx_command():550
[  471.155414] libertas cmd: CMD_RESP: response 0x8010, seq 15, size 24, jiffies 23865
[  471.161524] libertas enter: __lbs_cleanup_and_insert_cmd():1273
[  471.167467] libertas leave: __lbs_cleanup_and_insert_cmd():1285
[  471.170074] libertas leave: lbs_process_rx_command():700, ret 0
[  471.176009] libertas enter: lbs_execute_next_command():1812
[  471.189837] libertas host: EXEC_NEXT_CMD: sending command 0x0010
[  471.190371] libertas enter: lbs_submit_command():1230
[  471.195734] libertas cmd: DNLD_CMD: command 0x0010, seq 16, size 30, jiffies 23870
[  471.201994] usb8xxx usbd: 2-1:*** type = 1
[  471.206392] usb8xxx usbd: 2-1:size after = 30
[  471.211926] libertas leave: lbs_submit_command():1263
[  471.217021] libertas enter (INT): lbs_host_to_card_done():510
[  471.220000] libertas leave (INT): lbs_host_to_card_done():521
[  471.220000] usb8xxx enter (INT): if_usb_receive():712
[  471.220000] usb8xxx usbd (INT): 2-1:Recv length = 0x22, Recv type = 0xF00DFACE
[  471.220000] libertas enter (INT): lbs_interrupt():1530
[  471.220000] libertas thread (INT): lbs_interrupt: intcounter=0
[  471.220000] libertas leave (INT): lbs_interrupt():1538
[  471.220000] usb8xxx usbd (INT): 2-1:Wake up main thread to handle cmd response
[  471.220000] usb8xxx leave (INT): if_usb_receive():772
[  471.226739] libertas leave: lbs_execute_next_command():1947
[  471.231920] libertas thread: main-thread 111: intcounter=1 currenttxskb=00000000 dnld_sent=0
[  471.241769] libertas thread: main-thread 222 (waking up): intcounter=1 currenttxskb=00000000 dnld_sent=0
[  471.260097] libertas thread: main-thread 333: intcounter=1 currenttxskb=00000000 dnld_sent=0
[  471.272057] usb8xxx usbd: 2-1:Int cause is 0x8
[  471.276530] libertas thread: main-thread 444: intcounter=0 currenttxskb=00000000 dnld_sent=0
[  471.280000] libertas thread: main-thread: cmd response ready
[  471.281393] libertas enter: lbs_process_rx_command():550
[  471.296947] libertas cmd: CMD_RESP: response 0x8010, seq 16, size 30, jiffies 23887
[  471.301272] libertas enter: __lbs_cleanup_and_insert_cmd():1273
[  471.307220] libertas leave: __lbs_cleanup_and_insert_cmd():1285
[  471.310629] libertas leave: lbs_process_rx_command():700, ret 0
[  471.316756] libertas enter: lbs_execute_next_command():1812
[  471.320994] libertas host: EXEC_NEXT_CMD: sending command 0x0010
[  471.327206] libertas enter: lbs_submit_command():1230
[  471.340095] libertas cmd: DNLD_CMD: command 0x0010, seq 17, size 30, jiffies 23893
[  471.348056] usb8xxx usbd: 2-1:*** type = 1
[  471.351914] usb8xxx usbd: 2-1:size after = 30
[  471.356493] libertas leave: lbs_submit_command():1263
[  471.360093] libertas enter (INT): lbs_host_to_card_done():510
[  471.365854] libertas leave (INT): lbs_host_to_card_done():521
[  471.370000] usb8xxx enter (INT): if_usb_receive():712
[  471.370000] usb8xxx usbd (INT): 2-1:Recv length = 0x22, Recv type = 0xF00DFACE
[  471.370000] libertas enter (INT): lbs_interrupt():1530
[  471.370000] libertas thread (INT): lbs_interrupt: intcounter=0
[  471.370000] libertas leave (INT): lbs_interrupt():1538
[  471.370000] usb8xxx usbd (INT): 2-1:Wake up main thread to handle cmd response
[  471.370000] usb8xxx leave (INT): if_usb_receive():772
[  471.380096] libertas leave: lbs_execute_next_command():1947
[  471.386047] libertas thread: main-thread 111: intcounter=1 currenttxskb=00000000 dnld_sent=0
[  471.390408] libertas thread: main-thread 222 (waking up): intcounter=1 currenttxskb=00000000 dnld_sent=0
[  471.400313] libertas thread: main-thread 333: intcounter=1 currenttxskb=00000000 dnld_sent=0
[  471.420095] usb8xxx usbd: 2-1:Int cause is 0x8
[  471.424576] libertas thread: main-thread 444: intcounter=0 currenttxskb=00000000 dnld_sent=0
[  471.430000] libertas thread: main-thread: cmd response ready
[  471.431986] libertas enter: lbs_process_rx_command():550
[  471.437512] libertas cmd: CMD_RESP: response 0x8010, seq 17, size 30, jiffies 23907
[  471.440273] libertas enter: __lbs_cleanup_and_insert_cmd():1273
[  471.446216] libertas leave: __lbs_cleanup_and_insert_cmd():1285
[  471.458192] libertas leave: lbs_process_rx_command():700, ret 0
[  471.460000] libertas enter: lbs_execute_next_command():1812
[  471.462198] libertas host: EXEC_NEXT_CMD: sending command 0x001e
[  471.468416] libertas enter: lbs_submit_command():1230
[  471.470995] libertas cmd: DNLD_CMD: command 0x001e, seq 18, size 12, jiffies 23913
[  471.490091] usb8xxx usbd: 2-1:*** type = 1
[  471.495990] usb8xxx usbd: 2-1:size after = 12
[  471.500000] libertas leave: lbs_submit_command():1263
[  471.500105] libertas enter (INT): lbs_host_to_card_done():510
[  471.505864] libertas leave (INT): lbs_host_to_card_done():521
[  471.510000] usb8xxx enter (INT): if_usb_receive():712
[  471.510000] usb8xxx usbd (INT): 2-1:Recv length = 0x10, Recv type = 0xF00DFACE
[  471.510000] libertas enter (INT): lbs_interrupt():1530
[  471.510000] libertas thread (INT): lbs_interrupt: intcounter=0
[  471.510000] libertas leave (INT): lbs_interrupt():1538
[  471.510000] usb8xxx usbd (INT): 2-1:Wake up main thread to handle cmd response
[  471.510000] usb8xxx leave (INT): if_usb_receive():772
[  471.511052] libertas leave: lbs_execute_next_command():1947
[  471.516839] libertas thread: main-thread 111: intcounter=1 currenttxskb=00000000 dnld_sent=0
[  471.521014] libertas thread: main-thread 222 (waking up): intcounter=1 currenttxskb=00000000 dnld_sent=0
[  471.540101] libertas thread: main-thread 333: intcounter=1 currenttxskb=00000000 dnld_sent=0
[  471.551132] usb8xxx usbd: 2-1:Int cause is 0x8
[  471.555602] libertas thread: main-thread 444: intcounter=0 currenttxskb=00000000 dnld_sent=0
[  471.560000] libertas thread: main-thread: cmd response ready
[  471.568369] libertas enter: lbs_process_rx_command():550
[  471.570000] libertas cmd: CMD_RESP: response 0x801e, seq 18, size 12, jiffies 23928
[  471.570000] libertas host: CMD_RESP: error 0x0001 in command reply 0x801e
[  471.570000] libertas enter: __lbs_cleanup_and_insert_cmd():1273
[  471.570000] libertas leave: __lbs_cleanup_and_insert_cmd():1285
[  471.570154] libertas host: PREP_CMD: done waiting for command 0x1E
[  471.576349] libertas host: PREP_CMD: command failed with return code 1
[  471.580154] libertas leave: lbs_prepare_and_send_command():1640, ret -1
[  471.606061] libertas leave: lbs_process_rx_command():700, ret -1
[  471.610000] libertas enter: lbs_execute_next_command():1812
[  471.610996] libertas host: EXEC_NEXT_CMD: sending command 0x0006
[  471.617212] libertas enter: lbs_submit_command():1230
[  471.623201] libertas cmd: DNLD_CMD: command 0x0006, seq 19, size 63, jiffies 23938
[  471.640095] usb8xxx usbd: 2-1:*** type = 1
[  471.646723] usb8xxx usbd: 2-1:size after = 63
[  471.657067] libertas leave: lbs_submit_command():1263
[  471.660083] libertas enter (INT): lbs_host_to_card_done():510
[  471.665848] libertas leave (INT): lbs_host_to_card_done():521
[  471.680099] libertas leave: lbs_execute_next_command():1947
[  471.696940] usb8xxx usbd: 2-1:*** type = 0
[  471.700000] usb8xxx usbd: 2-1:size after = 97
[  471.700100] libertas enter (INT): lbs_host_to_card_done():510
[  471.705868] libertas leave (INT): lbs_host_to_card_done():521
[  471.710816] libertas thread: main-thread 111: intcounter=0 currenttxskb=00000000 dnld_sent=0
[  471.721456] libertas enter: lbs_cmd_async():2147
[  471.726102] libertas enter: __lbs_cmd_async():2102
[  471.730100] libertas enter: lbs_get_cmd_ctrl_node():1742
[  471.735425] libertas leave: lbs_get_cmd_ctrl_node():1760
[  471.740138] libertas host: PREP_CMD: command 0x0010
[  471.745032] libertas enter: lbs_queue_cmd():1182
[  471.750096] libertas host: QUEUE_CMD: inserted command 0x0010 into cmdpending q
[  471.760100] libertas leave: lbs_queue_cmd():1217
[  471.764736] libertas leave: __lbs_cmd_async():2140, ret ce1b91d4
[  471.770101] libertas leave: lbs_cmd_async():2150
[  471.776310] libertas thread: main-thread sleeping... Conn=1 IntC=0 PS_mode=0 PS_State=0
[  471.781335] libertas enter: lbs_cmd_async():2147
[  471.786175] libertas enter: __lbs_cmd_async():2102
[  471.790000] libertas enter: lbs_get_cmd_ctrl_node():1742
[  471.790251] libertas leave: lbs_get_cmd_ctrl_node():1760
[  471.795771] libertas host: PREP_CMD: command 0x0010
[  471.800276] libertas enter: lbs_queue_cmd():1182
[  471.805097] libertas host: QUEUE_CMD: inserted command 0x0010 into cmdpending q
[  471.811185] libertas leave: lbs_queue_cmd():1217
[  471.816592] libertas leave: __lbs_cmd_async():2140, ret ce1b9000
[  471.820000] libertas leave: lbs_cmd_async():2150
[  471.830280] libertas thread: main-thread 222 (waking up): intcounter=0 currenttxskb=00000000 dnld_sent=0
[  471.856953] libertas thread: main-thread 333: intcounter=0 currenttxskb=00000000 dnld_sent=0
[  471.860361] libertas thread: main-thread 444: intcounter=0 currenttxskb=00000000 dnld_sent=0
[  471.870307] libertas thread: main-thread 111: intcounter=0 currenttxskb=00000000 dnld_sent=0
[  471.892243] libertas thread: main-thread sleeping... Conn=1 IntC=0 PS_mode=0 PS_State=0
[  471.977910] olpc-ec:  running cmd 0x35
[  471.980068] devpath 1 ep3in 3strikes
[  471.983667] usb8xxx enter (INT): if_usb_receive():712
[  471.988734] usb8xxx leave (INT): if_usb_receive():772
[  471.990172] usb 2-1: USB disconnect, address 8
[  471.995281] usb8xxx enter: if_usb_disconnect():340
[  472.004738] libertas enter: lbs_stop_card():1328
[  472.009629] libertas main: lbs_stop_card: clearing pending commands
[  472.010000] libertas main: lbs_stop_card: clearing in-flight command 0x6
[  472.010000] libertas main: lbs_stop_card: done clearing commands
[  472.010156] libertas host: PREP_CMD: done waiting for command 0x6
[  472.016267] libertas leave: lbs_prepare_and_send_command():1640, ret 0
[  472.020101] libertas enter: lbs_prepare_and_send_command():1388
[  472.026033] libertas host: PREP_CMD: card removed
[  472.030115] libertas leave: lbs_prepare_and_send_command():1640, ret -1
[  472.036828] libertas: SCAN_CMD failed
[  472.044631] olpc-ec:  running cmd 0x26
[  472.049420] olpc-ec:  sending cmd arg 0x0
[  472.059558] olpc-ec:  running cmd 0x1c
[  472.060000] olpc-ec:  received 0xff
[  472.060109] olpc-ec:  running cmd 0x1b
[  472.064885] olpc-ec:  sending cmd arg 0xdf
[  472.073765] olpc-ec:  running cmd 0x1c
[  472.080000] olpc-ec:  received 0xdf
[  472.080092] olpc-ec:  running cmd 0x1b
[  472.084865] olpc-ec:  sending cmd arg 0xde
[  472.150160] libertas leave: lbs_stop_card():1364, ret -1
[  472.156195] ADDRCONF(NETDEV_CHANGE): msh0: link becomes ready
[  472.161958] libertas enter: lbs_cmd_async():2147
[  472.166809] libertas enter: lbs_remove_card():1205
[  472.171389] libertas enter: __lbs_cmd_async():2102
[  472.176594] libertas host: PREP_CMD: card removed
[  472.180415] libertas leave: __lbs_cmd_async():2140, ret fffffffe
[  472.186729] libertas leave: lbs_cmd_async():2150
[  472.190804] olpc-ec:  running cmd 0x1c
[  472.197596] olpc-ec:  received 0xde
[  472.200086] olpc-ec:  running cmd 0x1b
[  472.204855] olpc-ec:  sending cmd arg 0x9e
[  472.210000] libertas enter: lbs_set_mac_control():1356
[  472.210000] libertas enter: lbs_cmd_async():2147
[  472.211991] libertas enter: __lbs_cmd_async():2102
[  472.217078] libertas host: PREP_CMD: card removed
[  472.222015] libertas leave: __lbs_cmd_async():2140, ret fffffffe
[  472.228324] libertas leave: lbs_cmd_async():2150
[  472.231592] libertas leave: lbs_set_mac_control():1364
[  472.327374] olpc-ec:  running cmd 0x1c
[  472.330000] olpc-ec:  received 0x9e
[  472.330080] olpc-ec:  running cmd 0x1b
[  472.334851] olpc-ec:  sending cmd arg 0x96
[  472.410530] olpc-ec:  running cmd 0x1c
[  472.417329] olpc-ec:  received 0x96
[  472.420094] olpc-ec:  running cmd 0x1b
[  472.424865] olpc-ec:  sending cmd arg 0x92
[  472.500592] olpc-ec:  running cmd 0x1c
[  472.507393] olpc-ec:  received 0x92
[  472.510074] olpc-ec:  running cmd 0x1b
[  472.514850] olpc-ec:  sending cmd arg 0x90
[  472.530123] libertas main: lbs_remove_card: 1
[  472.534518] libertas enter: lbs_remove_rtap():1594
[  472.541203] libertas main: lbs_remove_card: 2
[  472.545761] libertas main: lbs_remove_card: 3
[  472.551086] libertas main: lbs_remove_card: 4
[  472.555649] libertas main: lbs_remove_card: 5
[  472.561184] libertas main: lbs_remove_card: 6
[  472.565745] libertas main: lbs_remove_card: 8
[  472.571124] libertas main: lbs_remove_card: 9
[  472.577292] libertas thread: main-thread 222 (waking up): intcounter=0 currenttxskb=00000000 dnld_sent=0
[  472.580105] libertas thread: main-thread 333: intcounter=0 currenttxskb=00000000 dnld_sent=0
[  472.590443] libertas thread: main-thread: break from main thread
[  472.596657] libertas leave: lbs_thread():907
[  472.600336] libertas main: lbs_remove_card: 10
[  472.604979] libertas enter: lbs_free_adapter():1104
[  472.610263] libertas enter: lbs_free_cmd_buffer():1701
[  472.615610] libertas leave: lbs_free_cmd_buffer():1726
[  472.620277] libertas leave: lbs_free_adapter():1111
[  472.650169] libertas leave: lbs_remove_card():1247
[  472.655932] usb8xxx enter: if_usb_free():147
[  472.660000] usb8xxx leave: if_usb_free():162
[  472.661087] usb8xxx leave: if_usb_disconnect():359
[  472.747317] PM: Syncing filesystems ... done.
[  472.820000] PM: Preparing system for mem sleep
[  472.820253] Freezing user space processes ... (elapsed 0.00 seconds) done.
[  472.854144] Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done.
[  472.863905] PM: Entering mem sleep
[  472.867318] Suspending console(s)

  Changed 5 years ago by cjb

  • cc jcardona, ashish, mbletsas, carrano, dwmw2, dilinger, dcbw, gregorio, gnu removed

Deepak, can you pull this patch please?

Changed 5 years ago by dsaxena

Backport from patch posted to linux-wireless

follow-up: ↓ 43   Changed 5 years ago by cscott

  • next_action changed from diagnose to communicate

Has this been packaged yet? Can we get it into joyride?

in reply to: ↑ 42   Changed 5 years ago by dsaxena

Replying to cscott:

Has this been packaged yet? Can we get it into joyride?

Packaged at http://dev.laptop.org/~dilinger/testing/kernel-devel-2.6.25-20080909.2.olpc.2dfd32b70c58803.i586.rpm

  Changed 5 years ago by cjb

  • next_action changed from communicate to test in build

They both made joyride today, Scott.

  Changed 5 years ago by cjb

  • next_action changed from test in build to add to release

Tested in joyride-2414, please pull to 8.2.

  Changed 5 years ago by cscott

Both? Please name the ohm version, k thx.

  Changed 5 years ago by cjb

(No, just kernel 2.6.25-20080909.2.olpc.2dfd32b70c58803.i586.rpm)

  Changed 5 years ago by cscott

  • next_action changed from add to release to test in release

kernel-2.6.25-20080909.3.olpc.850b087f7daf1b0 added to stable repo: http://mock.laptop.org/gitweb/gitweb.cgi?p=repos;a=commitdiff;h=10fbd74d6603239e05f057028d7b77e0974c1128

Should be in 8.2 build 760 and later. Please test.

  Changed 5 years ago by cjb

  • next_action changed from test in release to finalize

We haven't seen one of these crashes since pre-760.

  Changed 5 years ago by gregorio

  • status changed from new to closed
  • resolution set to fixed

Closed. Will write something in 8.2 release notes about encrypted APs don't always work. GS

  Changed 5 years ago by gregorio

Sorry, wrong not above. Closed no doc needed on this one.

Note: See TracTickets for help on using tickets.