Keyboard/trackpad not responsive on resume for Macbook 8,1 (12" 2015)

[rquast]

The keyboard and trackpad don't resume after suspend for me. I am using Ubuntu 17.04 and have tried this with both the 4.10 kernel and the mainline 4.14 rc5 kernel that both have the same issue. The issue appears to have affected other models in the past: https://github.com/cb22/macbook12-spi-driver/pull/30

[roadrunner2]

Were there any related errors in dmesg? I presume the relevant driver messages show up? (spi-device suspend done and spi-device resume done)

[rquast]

No error messages, both of those messages you mentioned appeared. Here's the output:

https://gist.github.com/rquast/519ade5d36e2eac73b20fbdf29a4fbe8

[rquast]

Have tested to see if this worked after fixing https://github.com/cb22/macbook12-spi-driver/issues/50 but still doesn't resume.

[roadrunner2]

Since there are no error messages, let's see what's going on with the initialization command. Just before suspending (assuming a working keyboard at this point), can you set the debug param to enable logging of some of the SPI packets:

echo 0x0501 | sudo tee /sys/module/applespi/parameters/debug

After resume you can turn off that logging by setting the debug param to 0 again. This should generate a moderate amount of output (a hexdump of each 256 byte packet, one packet for each key event plus a few others). Then provide the dmesg output for that, please.

[rquast]

There's no debug output by the look. Is there something wrong there?

root@rquast-MacBook:/var/log# cat /sys/module/applespi/parameters/debug 1281

https://gist.github.com/rquast/8dac9b6bc946ee82f8e4b27d13f4aab1

[roadrunner2]

That's very odd! Did you type anything on the (internal) keyboard after enabling the debug logs? At the very least before the suspend any such key events should've gotten logged.

[rquast]

Yes, there's output when typing a few keys and so on before suspend, but nothing in the suspend itself.

https://gist.github.com/rquast/8559a388330ddecfd259f37160219e01

[rquast]

Don't know if it helps, but the keyboard doesn't light up again after resume either. Also, no packets captured after resume.

[roadrunner2]

Thanks for the info. Ok, I suspect we're running into a race here where a command is sent during shutdown but it's response is not received, and hence the write-outstanding flag is still set when we resume.

Can you do the following:

• change the debug flags to 0x507 (this will show any backlight and caps-lock-led commands sent too)
• Apply the following patch:

--- a/applespi.c
+++ b/applespi.c
@@ -1459,6 +1459,10 @@ static int applespi_resume(struct device *dev)
        struct applespi_data *applespi = spi_get_drvdata(spi);
        acpi_status status;
 
+       applespi->cmd_msg_queued = false;
+       applespi->write_active = false;
+       applespi->read_active = false;
+
        status = acpi_enable_gpe(NULL, applespi->gpe);
        if (ACPI_FAILURE(status)) {
                pr_err("Failed to re-enable GPE handler for GPE %d: %s\n",

Again, please show me the dmesg output (whether this patch helps or not).

[rquast]

Applied the patch, but had to manually do that because it's different from master (wrong line number). Unfortunately, no change. https://gist.github.com/rquast/d5e970fb4891714fabdaf4c8839de279

[rquast]

My apologies.. I didn't notice the change in the debug flag. Will re-run and paste the output.

[rquast]

I don't think it gave any more information with the 0x507 flag: https://gist.github.com/rquast/b9dfbe14643729933fc0ba7852a9a663

[roadrunner2]

Thanks. Sorry about the wrong line numbers - have some changes sitting in my tree and I figured patch would handle it.

So we're getting closer to the culprit. Can you apply this patch instead (the line numbers should be accurate now):

--- a/applespi.c
+++ b/applespi.c
@@ -674,6 +674,10 @@ applespi_send_cmd_msg(struct applespi_data *applespi)
        u16 crc;
        int sts;
 
+       pr_info("drain=%d cmd_msg_queued=%d init_cmd_idx=%d\n",
+               applespi->drain, applespi->cmd_msg_queued,
+               applespi->init_cmd_idx);
+
        /* check if draining */
        if (applespi->drain)
                return 0;
@@ -749,6 +753,7 @@ applespi_send_cmd_msg(struct applespi_data *applespi)
 
        sts = applespi_async(applespi, &applespi->wr_m,
                             applespi_async_write_complete);
+       pr_info("applespi_async: sts=%d\n", sts);
 
        if (sts != 0) {
                pr_warn("Error queueing async write to device: %d\n", sts);

And again show the dmesg output.

Right now it's looking like spi_async may actually be swallowing up the init request, indicating some issue with the keyboard/trackpad itself.

One reason for this could be an issue with the SIST ACPI call - try adding this patch too:

--- a/applespi.c
+++ b/applespi.c
@@ -617,9 +617,11 @@ static int applespi_enable_spi(struct applespi_data *applespi)
        long long unsigned int spi_status;
 
        /* Check if SPI is already enabled, so we can skip the delay below */
+       /*
        result = acpi_evaluate_integer(applespi->sist, NULL, NULL, &spi_status);
        if (ACPI_SUCCESS(result) && spi_status)
                return 0;
+       */
 
        /* SIEN(1) will enable SPI communication */
        result = acpi_execute_simple_method(applespi->sien, NULL, 1);

[rquast]

No luck, but here's the output from the new info you are logging: https://gist.github.com/rquast/7b9cfe53cfe1a94bd926ac7722e18dc3

[rquast]

Note: I don't have the earlier patch applied to this one. Worked from a fresh applespi.c with the new patches you provided.

[roadrunner2]

Thanks - this basically confirms that the issue appears to be with the spi device or driver, rather than a logic issue in this applespi driver: we're queueing an init message, but never get a completion. So the spi device or driver is not processing the messages. I'm sorry, but this is going to take some more back and forth to figure out.

Here's another patch (I'll attach this one - I'm guessing that's easier to grab than copy pasting): resume-dbg-1.patch.txt This one will print out a bunch of flags (state) of the spi controller before and after queueing the init message on resume - trying to see if that gives us any clues as to why it's not sending the messages. Also, at this point setting the debug flag isn't necessary anymore.

[rquast]

No this is great! Thanks for helping like this. I am more than happy to take the time to keep working at it.

Here is the output: https://gist.github.com/rquast/b8a579ce053776784cef76512c2a5eac

[roadrunner2]

@rquast Sorry for the delay - things were busy. Thank you for the output. That's helpful - the controller state looks fine, as far as what was printed. Here's an expanded version of the patch which will print some more details, especially from the low-level driver: resume-dbg-2.patch.txt - same steps as for the last one.

Oh, forgot: this latest patch requires that you have the spi-pxa2xx.h header file for your kernel (either download just that, or get the full sources for the kernel) - and then adjust the first #include in the patch to point to right location of that file.

[shrijitsingh99]

Has this issue been fixed? If not is there anyway i can help in debugging?

[roadrunner2]

@shrijitsingh99 No, this issue is still open AFAIK. And yes, you could help by doing the following:

• grab and apply the resume-dbg-2.patch.txt above to the applespi driver - if you can do this on the latest driver code from my repo (that has several more patches which are currently sitting in pull request #56) that would be great
• build and load the new applespi module
• turn on debugging: echo 0x507 | sudo tee /sys/module/applespi/parameters/debug
• suspend and resume
• post the applespi dmesg output from resume

So far the issue is looking to be in the existing kernel code, rather than this driver, so the next steps will most likely involve patching the kernel proper to get more debug info from there.

[shrijitsingh99]

Trying to build the patched applespi module give me this make error https://gist.github.com/shrijitsingh99/b26e76aef3528c24ef6e073b6e4d379a

I made some small changes to the file to fix the build error and then built and loaded the module. This is the applespi dmesg output i am getting https://gist.github.com/shrijitsingh99/96e04ba52de206092f196617e9ce65c1

[roadrunner2]

Apologies, should've tested the patch against the latest code. Here is an updated patch: resume-dbg-3.patch.txt

Rather than building via dkms it might be easier to just build the module via make and load it via sudo rmmod applespi ; sudo insmod applespi.ko - but whatever works for you.

[shrijitsingh99]

Thanks for the info will use make now onwards. This is the output i am getting get https://gist.github.com/shrijitsingh99/640cf2a6dd54f0fc06792244cfe7b56c

[roadrunner2]

@shrijitsingh99 Thanks for running this and getting the output. It confirms what I stated earlier: the spi message is being queued in the spi core, but for some reason the actual device-specific driver is not sending the message (we never get a completion callback). So it looks to me like the SPI controller device, or its driver, are not being woken up correctly.

@andy-shev I see you've done work on the spi-pxa2xx driver - do you have any suggestions or ideas here? FYI, the pci device is

00:15.4 Serial bus controller [0c80]: Intel Corporation Wildcat Point-LP Serial IO GSPI Controller #1 [8086:9ce6] (rev 03)

Also: the resume appears to work fine on other MacBook(Pro)'s (though it's not been widely tested, so there may be issues on some others too, but it does work fine on MBP13,3 with a 8086:a12a SPI device), and the main difference between the MB8,1 and the others is that this one uses the spi_pxa2xx_pci driver whereas the others use the intel_lpss_pci driver.

[andy-shev]

On Broadwell a different PCI driver is used, indeed. Though, the SPI host controller driver is still the same. We did a lot of self-test against SPI in PIO/DMA modes, so, I doubt is anything wrong there. The symptoms looks like you didn't get an interrupt on receiver side which might mean that SPI is working on MAC in half-duplex mode. I dunno if it's supported by SPI PXA2xx driver.

[roadrunner2]

@TheChatty (or anybody else interested): I was just wondering if for some reason the keyboard's SPI interface needs to be forcefully re-enabled after resume on the MB8,1 (from my reading of the DSDT it should already be re-enabling the SPI interface on resume, but...). Can you try this quick patch:

--- a/applespi.c
+++ b/applespi.c
@@ -813,9 +813,11 @@ static int applespi_enable_spi(struct applespi_data *applespi)
        unsigned long long spi_status;
 
        /* check if SPI is already enabled, so we can skip the delay below */
+       /*
        result = acpi_evaluate_integer(applespi->sist, NULL, NULL, &spi_status);
        if (ACPI_SUCCESS(result) && spi_status)
                return 0;
+       */
 
        /* SIEN(1) will enable SPI communication */
        result = acpi_execute_simple_method(applespi->sien, NULL, 1);

If that doesn't work, then maybe this:

--- a/applespi.c
+++ b/applespi.c
@@ -813,11 +813,16 @@ static int applespi_enable_spi(struct applespi_data *applespi)
        unsigned long long spi_status;
 
        /* check if SPI is already enabled, so we can skip the delay below */
+       /*
        result = acpi_evaluate_integer(applespi->sist, NULL, NULL, &spi_status);
        if (ACPI_SUCCESS(result) && spi_status)
                return 0;
+       */
 
        /* SIEN(1) will enable SPI communication */
+       result = acpi_execute_simple_method(applespi->sien, NULL, 0);
+       if (ACPI_FAILURE(result))
+               pr_err("SIEN(0) failed: %s\n", acpi_format_exception(result));
        result = acpi_execute_simple_method(applespi->sien, NULL, 1);
        if (ACPI_FAILURE(result)) {
                pr_err("SIEN failed: %s\n", acpi_format_exception(result));

[TheChatty]

@roadrunner2: I tested your first and second patch and later even added info output that SIEN(0|1) get called even but to no avail. After resume the SPI transfers still time out. rmmod and modprobe of applespi doesn't help either.

[denisix]

the same issue for me, Ubuntu 19.04, kernel 4.16.0-041600-generic, after resume - keyboard & touch doesnt work, tried the patches, alse the patch with SIEN(0|1), tried even multiple times calling applespi_enable_spi() and added some timeouts before SIEN(1), but still no luck:

applied debug using echo 0x0507 | sudo tee /sys/module/applespi/parameters/debug and gathered the logs - dmesg, lspci -vvv, lsmod before (ok) and after(fail): https://gist.github.com/denisix/dcd12689bcc01a6022427d3b848933f6

please let me know if you need any other information! thanks!

[roadrunner2]

@denisix Looking at the dmesg.fail log, it looks like you are unloading applespi and some of the pxa2xx modules before suspend and loading them again after resume? Can you tell me exactly which modules are being unloaded/loaded? Also, I'm a bit confused by the following: according to your dmesg.fail at least the applespi, spi_pxa2xx_platform, and spi_pxa2xx_pci modules are failing to load after resume, however your lsmod.fail shows them loaded - any idea what's going on?

[denisix]

@roadrunner2 I experimented in many different ways and it was configured in /etc/hibernate/common.conf:

UnloadAllModules no
UnloadBlacklistedModules no
LoadModules auto
LoadModulesFromFile /etc/modules

now I commented all these options, tried with the provided modifications of applespi.c but still no result (i'm suspending my system with hibernate-ram, and pm-suspend if that makes sense).

The other strange situation detected after system resume, when I tried to unload the module with rmmod applespi - command just freeze, from lsmod i see the following:

applespi               28672  -1

attached logs: dmesg.rmmod.txt lspci.fail.txt lsmod.fail.txt dmesg.fail.txt lspci.ok.txt lsmod.ok.txt dmesg.ok.txt

thank you!