linux-kernel - Re: Hang while loading firmware when going into suspend

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-Id: <201204292346.43473.rjw@sisk.pl>
Date:	Sun, 29 Apr 2012 23:46:43 +0200
From:	"Rafael J. Wysocki" <rjw@...k.pl>
To:	Daniel Drake <dsd@...top.org>
Cc:	Linux PM list <linux-pm@...r.kernel.org>,
	linux-kernel@...r.kernel.org
Subject: Re: Hang while loading firmware when going into suspend

On Thursday, April 26, 2012, Daniel Drake wrote:
> Hi,
> 
> I can easily reproduce a hang related to loading firmware
> (asynchronously) while going into suspend.
> 
> This is running on kernel 3.3.3.
> 
> I run:
> 
> echo mem > /sys/power/state; echo mem > /sys/power/state
> 
> i.e. I tell the system to suspend, and when I wake it up it will go
> very quickly into suspend again.
> 
> After waking up, it will start to re-detect the libertas SDIO wifi
> card which was completely powered down during suspend.
> This triggers a firmware loading sequence.
> However, the system then immediately goes into suspend, and at this
> point the system becomes unhappy.

Is this a new bug or did we do that before too?

> Here are the logs from the first wakeup into the second suspend,
> including DEBUG enabled in firmware_class.c
> 
> [   49.389773] Restarting tasks ...
> [   49.404539] olpc-dcon: The CPU has control
> [   49.419371] done.
> [   49.440444] PM: Syncing filesystems ...
> [   49.505994] sdhci-pci 0000:00:0c.0: setting latency timer to 64
> [   49.540921] done.
> [   49.542865] PM: Preparing system for mem sleep
> [   49.577882] sdhci-pci 0000:00:0c.0: setting latency timer to 64
> [   49.654932] sdhci-pci 0000:00:0c.0: setting latency timer to 64
> [   49.753343] sdhci-pci 0000:00:0c.0: setting latency timer to 64
> [   49.890879] mmc1: new SDIO card at address 0001
> [   49.914515] libertas_sdio: get async now
> [   49.918506] Requesting libertas/sd8686_v9_helper.bin
> [   49.940231] libertas_sdio mmc1:0001:1: firmware: requesting
> libertas/sd8686_v9_helper.bin
> [   49.961299] helper_firmware_cb   (null)
> [   49.965200] Requesting libertas/sd8686_v8_helper.bin
> [   49.970283] Freezing user space processes ... (elapsed 0.11 seconds) done.
> [   50.092922] Freezing remaining freezable tasks ... (elapsed 0.01
> seconds) done.
> [   50.112828] PM: Entering mem sleep
> [   50.116749] dcon_source_switch to DCON
> [   50.142874] olpc-dcon: The DCON has control
> [   50.147634] i8042 kbd 00:04: wake-up capability enabled by ACPI
> [   50.153871] i8042 aux 00:03: wake-up capability disabled by ACPI
> [   50.160268] sdhci-pci 0000:00:0c.0: setting latency timer to 64
> [   50.167265] libertas_sdio mmc1:0001:1: mmc1:0001:1: suspend: PM flags = 0x3
> [   50.174370] viafb_suspend!
> [  109.980122] libertas_sdio mmc1:0001:1: firmware:
> libertas/sd8686_v8_helper.bin loading timed out
> [  109.989070] helper_firmware_cb   (null)
> [  109.992952] Requesting sd8686_helper.bin
> [  169.990109] libertas_sdio mmc1:0001:1: firmware: sd8686_helper.bin
> loading timed out
> [  169.997960] helper_firmware_cb   (null)
> [  170.001859] libertas_sdio: sdio got firmware -2   (null)   (null)
> [  170.008047] libertas_sdio: failed to find firmware (-2)
> [  170.013351] libertas: INIT FAILED
> [  170.016719] libertas: ret new state 2
> [  170.020781] mmc1: card 0001 removed
> [  170.024397] sdhci-pci 0000:00:0c.0: setting latency timer to 64
> [  170.031423] sdhci-pci 0000:00:0c.0: setting latency timer to 64
> [  170.038496] sdhci-pci 0000:00:0c.0: setting latency timer to 64
> [  170.060137] PM: suspend of devices complete after 119943.496 msecs
> 
> Some weird things here:
> 
> Early during the routine, we request a firmware that cannot be found:
> 
> [   49.918506] Requesting libertas/sd8686_v9_helper.bin
> [   49.940231] libertas_sdio mmc1:0001:1: firmware: requesting
> libertas/sd8686_v9_helper.bin
> [   49.961299] helper_firmware_cb   (null)
> 
> (The first and last lines are debug output from my driver, line 2
> comes from firmware_class)
> 
> Then when we try to find a different firmware file, we don't get the
> firmware_class debug line that we saw above, only my driver debug:
> [   49.965200] Requesting libertas/sd8686_v8_helper.bin
> [   49.970283] Freezing user space processes ... (elapsed 0.11 seconds) done.
> 
> Eventually we get a timeout, then we request another firmware, which
> also times out, and finally we fall into suspend after a long delay.

OK, so the system suspends eventually?

> Sidenote:
> There is a driver race in the current libertas code - in the above
> situation it will attempt to call the driver suspend routine even if
> probe hasn't finished (i.e. async firmware loading still underway). I
> have that solved locally in the tests above - the suspend routine will
> detect that probing/firmware loading is still ongoing and wait for
> that to complete before asking the hardware to suspend. However, in
> testing this change, I am facing the above issue with the firmware
> loader behaving badly when going into suspend.

That looks like a bug in the driver, to be honest.  I'll have a look at it
in the next few days.

Thanks,
Rafael
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/