MacBook8,1 (Early 2015) and Fedora

[TheChatty]

Recent Fedora (28, 29 & 30) running kernel 4.18 or newer fail to load applespi. Here's the output from 4.20.0-1.fc30.x86_64 after compiling and loading the module:

# dmesg
[  604.776896] applespi: loading out-of-tree module taints kernel.
[  604.776940] applespi: module verification failed: signature and/or required key missing - tainting kernel
[  604.829319] input: Apple SPI Keyboard as /devices/pci0000:00/0000:00:15.4/pxa2xx-spi.0/spi_master/spi0/spi-APP000D:00/input/input14
[  604.829879] input: Apple SPI Touchpad as /devices/pci0000:00/0000:00:15.4/pxa2xx-spi.0/spi_master/spi0/spi-APP000D:00/input/input15
[  604.830130] applespi: spi-device probe done: spi-APP000D:00
[  605.039209] applespi spi-APP000D:00: SPI transfer timed out
[  605.039351] applespi: Error writing to device: -110
[  605.247211] applespi spi-APP000D:00: SPI transfer timed out
[  605.247346] applespi: Error reading from device: -110
[  605.455247] applespi spi-APP000D:00: SPI transfer timed out
[  605.455388] applespi: Error reading from device: -110
[  605.627374] irq 21: nobody cared (try booting with the "irqpoll" option)
[  605.627379] CPU: 3 PID: 4721 Comm: dracut Tainted: G           OE     4.20.0-1.fc30.x86_64 #1
[  605.627380] Hardware name: Apple Inc. MacBook8,1/Mac-BE0E8AC46FE800CC, BIOS 177.0.0.0.0 09/17/2018
[  605.627381] Call Trace:
[  605.627384]  <IRQ>
[  605.627393]  dump_stack+0x5c/0x80
[  605.627397]  __report_bad_irq+0x37/0xae
[  605.627401]  note_interrupt.cold.9+0xa/0x69
[  605.627403]  handle_irq_event_percpu+0x6a/0x80
[  605.627406]  handle_irq_event+0x27/0x44
[  605.627409]  handle_fasteoi_irq+0x7f/0x120
[  605.627413]  handle_irq+0xbf/0x100
[  605.627417]  do_IRQ+0x49/0xd0
[  605.627421]  common_interrupt+0xf/0xf
[  605.627422]  </IRQ>
[  605.627427] RIP: 0010:copy_page_range+0x774/0xec0
[  605.627429] Code: 48 8d 94 24 f4 00 00 00 48 0f 45 c1 48 8b 00 a9 00 00 08 00 48 8d 84 24 e8 00 00 00 48 0f 44 d0 83 02 01 48 8b 3c 24 4c 89 e6 <48> 89 ea 48 89 d9 e8 c1 65 e2 ff 66 90 41 83 c5 08 45 31 c0 e9 ca
[  605.627431] RSP: 0018:ffffae8202dd7c90 EFLAGS: 00000206 ORIG_RAX: ffffffffffffffdb
[  605.627433] RAX: ffffdaa4870328c0 RBX: 80000001c0ca3845 RCX: ffffdaa4870328c0
[  605.627435] RDX: ffffae8202dd7d7c RSI: 00005616a9a10000 RDI: ffff91d87004ea40
[  605.627436] RBP: ffff91d81e241080 R08: 8000000000000845 R09: ffff91d7e1fc3320
[  605.627437] R10: 000000000000010c R11: 0000000000027340 R12: 00005616a9a10000
[  605.627439] R13: 0000000000000008 R14: ffff91d7e1fc3320 R15: ffff91d81e241058
[  605.627445]  ? anon_vma_chain_link+0x39/0x70
[  605.627449]  copy_process.part.35+0x17b4/0x1eb0
[  605.627454]  _do_fork+0xe2/0x390
[  605.627457]  ? __set_current_blocked+0x3d/0x60
[  605.627460]  ? sigprocmask+0x72/0xa0
[  605.627464]  do_syscall_64+0x5b/0x160
[  605.627467]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[  605.627469] RIP: 0033:0x7fb83af47942
[  605.627471] Code: db 0f 85 01 01 00 00 64 4c 8b 0c 25 10 00 00 00 45 31 c0 4d 8d 91 d0 02 00 00 31 d2 31 f6 bf 11 00 20 01 b8 38 00 00 00 0f 05 <48> 3d 00 f0 ff ff 0f 87 a2 00 00 00 41 89 c4 85 c0 0f 85 af 00 00
[  605.627473] RSP: 002b:00007ffdc726e100 EFLAGS: 00000246 ORIG_RAX: 0000000000000038
[  605.627475] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007fb83af47942
[  605.627476] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000001200011
[  605.627477] RBP: 0000000000000001 R08: 0000000000000000 R09: 00007fb83ae7c740
[  605.627479] R10: 00007fb83ae7ca10 R11: 0000000000000246 R12: 00007ffdc726e140
[  605.627480] R13: 00007ffdc726e1c0 R14: 00005616a99d5918 R15: 0000000000000000
[  605.627482] handlers:
[  605.627487] [<000000004f62a4ba>] ssp_int [spi_pxa2xx_platform]
[  605.627489] Disabling IRQ #21
[  644.007948] applespi spi-APP000D:00: SPI transfer timed out
[  644.008093] applespi: Error reading from device: -110
[  644.319955] applespi spi-APP000D:00: SPI transfer timed out
[  644.320100] applespi: Error reading from device: -110
[  644.631962] applespi spi-APP000D:00: SPI transfer timed out
[  644.632107] applespi: Error reading from device: -110

# lspci -nnk | grep -i spi
00:15.4 Serial bus controller [0c80]: Intel Corporation Wildcat Point-LP Serial IO GSPI Controller #1 [8086:9ce6] (rev 03)
        Subsystem: Intel Corporation Wildcat Point-LP Serial IO GSPI Controller #1 [8086:9ce6]
        Kernel driver in use: pxa2xx_spi_pci
        Kernel modules: spi_pxa2xx_pci

Btw, I had it working once.
And when booting with irqpoll mouse and keyboard are working.

[roadrunner2]

This sounds like the known issue with the interrupt (21 on your system) on MB8,1 and needing irqpoll. Can you search for other mentions of interrupt 21 in your dmesg (these would occur during boot) - e.g. on my system (a MBP13,3, so somewhat different) I see a couple messages like

[...] dw-apb-uart.1: ttyS4 at MMIO 0x8272a000 (irq = 21, base_baud = 115200) is a 16550A

And what does the following show?

grep 21: /proc/interrupts

Lastly, we noted in the README, have you tried booting with all three needed drivers (applespi, spi_pxa2xx_platform, and spi_pxa2xx_pci) loaded as part of initramfs? For Fedora, use something like this:

cat <<EOF | sudo tee /etc/dracut.conf.d/keyboard.conf
# load all drivers needed for the keyboard
add_drivers+="applespi spi_pxa2xx_pci spi_pxa2xx_platform"
EOF

and rerun dracut and reboot.

[TheChatty]

Booting with irqpoll I get (keyboard and mouse working):

# dmesg|grep "= 21"
[    2.853188] 0000:00:15.5: ttyS4 at MMIO 0xc1819000 (irq = 21, base_baud = 2764800) is a 16550A
# grep 21: /proc/interrupts
 21:          0          0          0        586  IR-IO-APIC  21-fasteoi   pxa2xx-spi.0

Booting without irqpoll but with modules as part of initramfs (keyboard and mouse not working):

[    2.730828] applespi: loading out-of-tree module taints kernel.
[    2.730897] applespi: module verification failed: signature and/or required key missing - tainting kernel
[    2.740017] audit: type=1130 audit(1546088138.151:9): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=plymouth-start comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    2.749036] 0000:00:15.5: ttyS4 at MMIO 0xc1819000 (irq = 21, base_baud = 2764800) is a 16550A
[    2.749702] serial serial0-0: controller busy
[    2.749704] serial serial0-0: failure adding ACPI serdev device. status -16
[    2.749707] serial serial0: tty port ttyS4 registered

Every key down and up event triggers:

[ 1995.596692] applespi spi-APP000D:00: SPI transfer timed out
[ 1995.596835] applespi: Error reading from device: -110

[roadrunner2]

Btw., does using irqfixup instead of irqpoll also "fix" the issue? That would appear to be a lighter weight hack.

As to what exactly the problem is with the (not) registering of the interrupt handler, maybe @andy-shev has some ideas?

[TheChatty]

irqfixup does indeed already circumvent the issue. In any case (e.g. keyboard working) the keyboard is not lit up - is that expected?

[roadrunner2]

In any case (e.g. keyboard working) the keyboard is not lit up - is that expected?

No, it isn't, though I'm not 100% sure if anybody else has tested it on MB8,1. Does manually setting the brightness also not work?

echo 150 | sudo tee /sys/class/leds/spi::kbd_backlight/brightness

But I guess the caps-lock led works?

[TheChatty]

That manual brightness is working! And caps-lock as well (led is lit up, keyboard produces upper case letter and vice versa).

But when going to standby (e.g. systemctl suspend) keyboard and mouse are not working anymore. I grabbed the following dmesg:

[  146.831440] PM: suspend entry (deep)
[  146.831443] PM: Syncing filesystems ... done.
[  147.089468] Freezing user space processes ... (elapsed 0.003 seconds) done.
[  147.093108] OOM killer disabled.
[  147.093112] Freezing remaining freezable tasks ... (elapsed 0.000 seconds) done.
[  147.094086] printk: Suspending console(s) (use no_console_suspend to debug)
[  147.094705] applespi: spi-device suspend done.
[  147.096596] ------------[ cut here ]------------
[  147.096599] reqid not found
[  147.096687] WARNING: CPU: 3 PID: 46 at drivers/net/wireless/broadcom/brcm80211/brcmfmac/pno.c:77 brcmf_pno_remove_request+0xac/0xd0 [brcmfmac]
[  147.096689] Modules linked in: fuse bnep nf_conntrack_netbios_ns nf_conntrack_broadcast xt_CT ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 xt_conntrack ebtable_nat ip6table_nat nf_nat_ipv6 ip6table_mangle ip6table_raw devlink ip6table_security iptable_nat nf_nat_ipv4 nf_nat iptable_mangle iptable_raw iptable_security nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 ip_set nfnetlink ebtable_filter ebtables ip6table_filter ip6_tables sunrpc vfat fat brcmfmac intel_rapl x86_pkg_temp_thermal brcmutil intel_powerclamp coretemp kvm_intel cfg80211 joydev snd_hda_codec_cirrus snd_hda_codec_generic snd_hda_codec_hdmi hci_uart snd_hda_intel mmc_core btqca crct10dif_pclmul btrtl crc32_pclmul btbcm snd_hda_codec iTCO_wdt iTCO_vendor_support btintel snd_hda_core snd_hwdep ghash_clmulni_intel intel_cstate snd_seq bluetooth intel_uncore snd_seq_device applesmc snd_pcm input_polldev intel_rapl_perf sbs snd_timer ecdh_generic acpi_als rfkill kfifo_buf sbshc industrialio mei_me snd soundcore mei i2c_i801
[  147.096799]  spi_pxa2xx_pci intel_pch_thermal apple_bl lpc_ich pcc_cpufreq binfmt_misc btrfs libcrc32c xor zstd_decompress zstd_compress xxhash raid6_pq i915 kvmgt mdev vfio kvm uas usb_storage r8152 mii irqbypass i2c_algo_bit drm_kms_helper nvme crc32c_intel drm nvme_core 8250_lpss applespi(OE) video spi_pxa2xx_platform
[  147.096853] CPU: 3 PID: 46 Comm: kworker/u8:1 Tainted: G           OE     4.20.0-1.fc30.x86_64 #1
[  147.096856] Hardware name: Apple Inc. MacBook8,1/Mac-BE0E8AC46FE800CC, BIOS 177.0.0.0.0 09/17/2018
[  147.096868] Workqueue: events_unbound async_run_entry_fn
[  147.096895] RIP: 0010:brcmf_pno_remove_request+0xac/0xd0 [brcmfmac]
[  147.096900] Code: 08 48 89 74 d3 08 48 63 d0 39 ca 7e e9 31 db 4c 89 e7 e8 37 70 e8 d9 89 d8 5b 5d 41 5c c3 48 c7 c7 06 3a ad c0 e8 ce b4 5f d9 <0f> 0b bb fe ff ff ff 4c 89 e7 e8 15 70 e8 d9 89 d8 5b 5d 41 5c c3
[  147.096904] RSP: 0018:ffffab4140e0fd18 EFLAGS: 00010286
[  147.096909] RAX: 0000000000000000 RBX: ffff88bb201c5900 RCX: 0000000000000006
[  147.096913] RDX: 0000000000000007 RSI: 0000000000000096 RDI: ffff88bb26b968c0
[  147.096916] RBP: 0000000000000000 R08: 0000000000000004 R09: 00000000000207c0
[  147.096920] R10: 0000003867fd0840 R11: 000000000002d13c R12: ffff88bb201c5988
[  147.096923] R13: ffff88bb0d678300 R14: ffff88bb253a6000 R15: ffffffff9b143407
[  147.096929] FS:  0000000000000000(0000) GS:ffff88bb26b80000(0000) knlGS:0000000000000000
[  147.096933] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  147.096936] CR2: 000056498b0c5078 CR3: 000000025020a004 CR4: 00000000003606e0
[  147.096940] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  147.096943] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  147.096945] Call Trace:
[  147.096977]  brcmf_pno_stop_sched_scan+0x22/0x50 [brcmfmac]
[  147.097000]  brcmf_cfg80211_sched_scan_stop+0x28/0x60 [brcmfmac]
[  147.097022]  brcmf_cfg80211_suspend+0x303/0x340 [brcmfmac]
[  147.097081]  wiphy_suspend+0x8f/0x270 [cfg80211]
[  147.097129]  ? addresses_show+0xa0/0xa0 [cfg80211]
[  147.097137]  dpm_run_callback+0x59/0x150
[  147.097144]  __device_suspend+0x108/0x470
[  147.097151]  ? __switch_to+0x8c/0x4a0
[  147.097156]  async_suspend+0x1a/0x90
[  147.097163]  async_run_entry_fn+0x39/0x160
[  147.097171]  process_one_work+0x1a1/0x3a0
[  147.097177]  worker_thread+0x30/0x380
[  147.097183]  ? pwq_unbound_release_workfn+0xd0/0xd0
[  147.097189]  kthread+0x112/0x130
[  147.097196]  ? kthread_create_on_node+0x60/0x60
[  147.097204]  ret_from_fork+0x35/0x40
[  147.097211] ---[ end trace 9cb107899b67ba06 ]---
[  148.103789] brcmfmac: brcmf_fil_cmd_data: bus is down. we have nothing to do.
[  148.103793] brcmfmac: brcmf_cfg80211_reg_notifier: Country code iovar returned err = -5
[  148.104497] PM: suspend devices took 1.010 seconds
[  148.117969] ACPI: EC: interrupt blocked
[  148.163902] ACPI: Preparing to enter system sleep state S3
[  148.319145] ACPI: EC: event blocked
[  148.319146] ACPI: EC: EC stopped
[  148.319148] PM: Saving platform NVS memory
[  148.319156] Disabling non-boot CPUs ...
[  148.326880] smpboot: CPU 1 is now offline
[  148.342506] smpboot: CPU 2 is now offline
[  148.351436] smpboot: CPU 3 is now offline
[  148.359582] ACPI: Low-level resume complete
[  148.359682] ACPI: EC: EC started
[  148.359684] PM: Restoring platform NVS memory
[  148.360198] Enabling non-boot CPUs ...
[  148.360300] x86: Booting SMP configuration:
[  148.360304] smpboot: Booting Node 0 Processor 1 APIC 0x2
[  148.415077] hrtimer: interrupt took 3172719 ns
[  148.897931]  cache: parent cpu1 should not be sleeping
[  149.443442] CPU1 is up
[  149.443492] smpboot: Booting Node 0 Processor 2 APIC 0x1
[  149.444128]  cache: parent cpu2 should not be sleeping
[  149.449284] CPU2 is up
[  149.449307] smpboot: Booting Node 0 Processor 3 APIC 0x3
[  149.667090]  cache: parent cpu3 should not be sleeping
[  150.260302] CPU3 is up
[  150.266531] ACPI: Waking up from system sleep state S3
[  150.267699] ACPI: EC: interrupt unblocked
[  150.297532] ACPI: EC: event unblocked
[  150.298666] nvme nvme0: detected Apple NVMe controller, set queue depth=2 to work around controller resets
[  150.303468] nvme nvme0: IO queues not created
[  150.306885] ACPI: button: The lid device is not compliant to SW_LID.
[  150.307171] applespi: spi-device resume done.
[  150.446359] PM: resume devices took 0.149 seconds
[  150.446571] OOM killer enabled.
[  150.446575] Restarting tasks ... done.
[  150.511844] video LNXVIDEO:00: Restoring backlight state
[  150.512115] PM: suspend exit
[  150.514809] applespi spi-APP000D:00: SPI transfer timed out
[  150.514823] applespi: Error reading from device: -110
[  150.722800] applespi spi-APP000D:00: SPI transfer timed out
[  150.722813] applespi: Error writing to device: -110
[  150.930953] applespi spi-APP000D:00: SPI transfer timed out
[  150.930971] applespi: Error reading from device: -110
[  151.073474] IPv6: ADDRCONF(NETDEV_UP): enp0s20u1u1: link is not ready
[  151.080305] IPv6: ADDRCONF(NETDEV_UP): enp0s20u1u1: link is not ready
[  151.081797] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[  151.082183] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[  151.138792] applespi spi-APP000D:00: SPI transfer timed out
[  151.138805] applespi: Error writing to device: -110
[  151.346811] applespi spi-APP000D:00: SPI transfer timed out
[  151.346822] applespi: Error reading from device: -110
[  151.554846] applespi spi-APP000D:00: SPI transfer timed out
[  151.554869] applespi: Error reading from device: -110
[  151.607767] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[  151.647958] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[  151.763814] applespi spi-APP000D:00: SPI transfer timed out
[  151.763835] applespi: Error reading from device: -110
[  151.970822] applespi spi-APP000D:00: SPI transfer timed out
[  151.970842] applespi: Error reading from device: -110
[  152.178836] applespi spi-APP000D:00: SPI transfer timed out
[  152.178855] applespi: Error reading from device: -110
[  152.386831] applespi spi-APP000D:00: SPI transfer timed out
[  152.386840] applespi: Error reading from device: -110
[  152.594968] applespi spi-APP000D:00: SPI transfer timed out
[  152.594989] applespi: Error reading from device: -110
[  152.802827] applespi spi-APP000D:00: SPI transfer timed out
[  152.802848] applespi: Error reading from device: -110
[  153.011908] applespi spi-APP000D:00: SPI transfer timed out
[  153.011930] applespi: Error reading from device: -110
[  153.218975] applespi spi-APP000D:00: SPI transfer timed out
[  153.218997] applespi: Error reading from device: -110
[  153.426995] applespi spi-APP000D:00: SPI transfer timed out
[  153.427019] applespi: Error reading from device: -110
[  153.634981] applespi spi-APP000D:00: SPI transfer timed out
[  153.635004] applespi: Error reading from device: -110
[  153.842978] applespi spi-APP000D:00: SPI transfer timed out
[  153.843001] applespi: Error reading from device: -110
[  154.050900] applespi spi-APP000D:00: SPI transfer timed out
[  154.050917] applespi: Error reading from device: -110
[  154.258967] applespi spi-APP000D:00: SPI transfer timed out
[  154.258985] applespi: Error reading from device: -110
[  154.466967] applespi spi-APP000D:00: SPI transfer timed out
[  154.466984] applespi: Error reading from device: -110
[  154.674993] applespi spi-APP000D:00: SPI transfer timed out
[  154.675016] applespi: Error reading from device: -110
[  154.882995] applespi spi-APP000D:00: SPI transfer timed out
[  154.883018] applespi: Error reading from device: -110
[  155.090918] applespi spi-APP000D:00: SPI transfer timed out
[  155.090934] applespi: Error reading from device: -110
[  155.298995] applespi spi-APP000D:00: SPI transfer timed out
[  155.299012] applespi: Error reading from device: -110
[  155.507013] applespi spi-APP000D:00: SPI transfer timed out
[  155.507036] applespi: Error reading from device: -110
[  155.574329] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[  155.715005] applespi spi-APP000D:00: SPI transfer timed out
[  155.715022] applespi: Error reading from device: -110
[  155.923015] applespi spi-APP000D:00: SPI transfer timed out
[  155.923038] applespi: Error reading from device: -110
[  156.130952] applespi spi-APP000D:00: SPI transfer timed out
[  156.130972] applespi: Error reading from device: -110
[  156.339043] applespi spi-APP000D:00: SPI transfer timed out
[  156.339067] applespi: Error reading from device: -110
[  156.546926] applespi spi-APP000D:00: SPI transfer timed out
[  156.546948] applespi: Error reading from device: -110
[  156.754977] applespi spi-APP000D:00: SPI transfer timed out
[  156.755000] applespi: Error reading from device: -110
[  156.962989] applespi spi-APP000D:00: SPI transfer timed out
[  156.963012] applespi: Error reading from device: -110
[  157.170919] applespi spi-APP000D:00: SPI transfer timed out
[  157.170946] applespi: Error reading from device: -110
[  157.379007] applespi spi-APP000D:00: SPI transfer timed out
[  157.379031] applespi: Error reading from device: -110
[  157.587034] applespi spi-APP000D:00: SPI transfer timed out
[  157.587058] applespi: Error reading from device: -110
[  157.795041] applespi spi-APP000D:00: SPI transfer timed out
[  157.795064] applespi: Error reading from device: -110
[  158.003043] applespi spi-APP000D:00: SPI transfer timed out
[  158.003066] applespi: Error reading from device: -110
[  158.211045] applespi spi-APP000D:00: SPI transfer timed out
[  158.211068] applespi: Error reading from device: -110
[  158.419046] applespi spi-APP000D:00: SPI transfer timed out
[  158.419068] applespi: Error reading from device: -110
[  158.627007] applespi spi-APP000D:00: SPI transfer timed out
[  158.627029] applespi: Error reading from device: -110
[  158.835052] applespi spi-APP000D:00: SPI transfer timed out
[  158.835076] applespi: Error reading from device: -110
[  159.043051] applespi spi-APP000D:00: SPI transfer timed out
[  159.043071] applespi: Error reading from device: -110
[  159.251066] applespi spi-APP000D:00: SPI transfer timed out
[  159.251088] applespi: Error reading from device: -110
[  159.458990] applespi spi-APP000D:00: SPI transfer timed out
[  159.459013] applespi: Error reading from device: -110
[  159.667066] applespi spi-APP000D:00: SPI transfer timed out
[  159.667088] applespi: Error reading from device: -110
[  159.875067] applespi spi-APP000D:00: SPI transfer timed out
[  159.875089] applespi: Error reading from device: -110
[  160.083073] applespi spi-APP000D:00: SPI transfer timed out
[  160.083095] applespi: Error reading from device: -110
[  160.291075] applespi spi-APP000D:00: SPI transfer timed out
[  160.291098] applespi: Error reading from device: -110
[  160.499078] applespi spi-APP000D:00: SPI transfer timed out
[  160.499100] applespi: Error reading from device: -110
[  160.707020] applespi spi-APP000D:00: SPI transfer timed out
[  160.707042] applespi: Error reading from device: -110
[  160.915084] applespi spi-APP000D:00: SPI transfer timed out
[  160.915107] applespi: Error reading from device: -110
[  161.123066] applespi spi-APP000D:00: SPI transfer timed out
[  161.123084] applespi: Error reading from device: -110
[  161.331094] applespi spi-APP000D:00: SPI transfer timed out
[  161.331117] applespi: Error reading from device: -110
[  161.539097] applespi spi-APP000D:00: SPI transfer timed out
[  161.539119] applespi: Error reading from device: -110
[  161.747045] applespi spi-APP000D:00: SPI transfer timed out
[  161.747067] applespi: Error reading from device: -110
[  161.955098] applespi spi-APP000D:00: SPI transfer timed out
[  161.955121] applespi: Error reading from device: -110
[  162.163110] applespi spi-APP000D:00: SPI transfer timed out
[  162.163133] applespi: Error reading from device: -110
[  162.371113] applespi spi-APP000D:00: SPI transfer timed out
[  162.371136] applespi: Error reading from device: -110
[  162.578994] applespi spi-APP000D:00: SPI transfer timed out
[  162.579021] applespi: Error reading from device: -110
[  162.751572] IPv6: ADDRCONF(NETDEV_CHANGE): wlp1s0: link becomes ready
[  162.786981] applespi spi-APP000D:00: SPI transfer timed out
[  162.786994] applespi: Error reading from device: -110
[  162.995022] applespi spi-APP000D:00: SPI transfer timed out
[  162.995045] applespi: Error reading from device: -110
[  163.203091] applespi spi-APP000D:00: SPI transfer timed out
[  163.203113] applespi: Error reading from device: -110
[  163.411028] applespi spi-APP000D:00: SPI transfer timed out
[  163.411050] applespi: Error reading from device: -110
[  163.619127] applespi spi-APP000D:00: SPI transfer timed out
[  163.619150] applespi: Error reading from device: -110
[  163.827129] applespi spi-APP000D:00: SPI transfer timed out
[  163.827152] applespi: Error reading from device: -110
[  164.035132] applespi spi-APP000D:00: SPI transfer timed out
[  164.035154] applespi: Error reading from device: -110
[  164.243138] applespi spi-APP000D:00: SPI transfer timed out
[  164.243158] applespi: Error reading from device: -110
[  164.451150] applespi spi-APP000D:00: SPI transfer timed out
[  164.451173] applespi: Error reading from device: -110
[  164.659145] applespi spi-APP000D:00: SPI transfer timed out
[  164.659168] applespi: Error reading from device: -110
[  164.867143] applespi spi-APP000D:00: SPI transfer timed out
[  164.867166] applespi: Error reading from device: -110
[  165.075151] applespi spi-APP000D:00: SPI transfer timed out
[  165.075174] applespi: Error reading from device: -110
[  165.283172] applespi spi-APP000D:00: SPI transfer timed out
[  165.283196] applespi: Error reading from device: -110
[  165.491159] applespi spi-APP000D:00: SPI transfer timed out
[  165.491183] applespi: Error reading from device: -110
[  165.699158] applespi spi-APP000D:00: SPI transfer timed out
[  165.699181] applespi: Error reading from device: -110
[  165.907164] applespi spi-APP000D:00: SPI transfer timed out
[  165.907187] applespi: Error reading from device: -110
[  166.115157] applespi spi-APP000D:00: SPI transfer timed out
[  166.115174] applespi: Error reading from device: -110
[  166.323169] applespi spi-APP000D:00: SPI transfer timed out
[  166.323192] applespi: Error reading from device: -110
[  166.531170] applespi spi-APP000D:00: SPI transfer timed out
[  166.531193] applespi: Error reading from device: -110
[  166.739172] applespi spi-APP000D:00: SPI transfer timed out
[  166.739195] applespi: Error reading from device: -110
[  166.947173] applespi spi-APP000D:00: SPI transfer timed out
[  166.947195] applespi: Error reading from device: -110
[  167.155179] applespi spi-APP000D:00: SPI transfer timed out
[  167.155201] applespi: Error reading from device: -110
[  167.363194] applespi spi-APP000D:00: SPI transfer timed out
[  167.363217] applespi: Error reading from device: -110
[  167.571185] applespi spi-APP000D:00: SPI transfer timed out
[  167.571208] applespi: Error reading from device: -110
[  167.779187] applespi spi-APP000D:00: SPI transfer timed out
[  167.779210] applespi: Error reading from device: -110
[  167.986221] applespi spi-APP000D:00: SPI transfer timed out
[  167.986244] applespi: Error reading from device: -110
[  168.179910] applespi spi-APP000D:00: SPI transfer timed out
[  168.179932] applespi: Error reading from device: -110
[  168.378851] applespi spi-APP000D:00: SPI transfer timed out
[  168.378874] applespi: Error reading from device: -110
[  168.566834] applespi spi-APP000D:00: SPI transfer timed out
[  168.566863] applespi: Error reading from device: -110
[  168.761236] applespi spi-APP000D:00: SPI transfer timed out
[  168.761256] applespi: Error reading from device: -110
[  168.952173] applespi spi-APP000D:00: SPI transfer timed out
[  168.952196] applespi: Error reading from device: -110
[  169.143600] applespi spi-APP000D:00: SPI transfer timed out
[  169.143631] applespi: Error reading from device: -110
[  169.343849] applespi spi-APP000D:00: SPI transfer timed out
[  169.343872] applespi: Error reading from device: -110
[  169.545986] applespi spi-APP000D:00: SPI transfer timed out
[  169.546008] applespi: Error reading from device: -110
[  169.734487] applespi spi-APP000D:00: SPI transfer timed out
[  169.734509] applespi: Error reading from device: -110
[  169.928690] applespi spi-APP000D:00: SPI transfer timed out
[  169.928719] applespi: Error reading from device: -110
[  170.122616] applespi spi-APP000D:00: SPI transfer timed out
[  170.122638] applespi: Error reading from device: -110
[  170.320991] applespi spi-APP000D:00: SPI transfer timed out
[  170.321013] applespi: Error reading from device: -110
[  170.511767] applespi spi-APP000D:00: SPI transfer timed out
[  170.511792] applespi: Error reading from device: -110
[  170.705378] applespi spi-APP000D:00: SPI transfer timed out
[  170.705401] applespi: Error reading from device: -110
[  170.893873] applespi spi-APP000D:00: SPI transfer timed out
[  170.893886] applespi: Error reading from device: -110
[  171.085198] applespi spi-APP000D:00: SPI transfer timed out
[  171.085215] applespi: Error reading from device: -110
[  171.286265] applespi spi-APP000D:00: SPI transfer timed out
[  171.286288] applespi: Error reading from device: -110
[  171.479319] applespi spi-APP000D:00: SPI transfer timed out
[  171.479342] applespi: Error reading from device: -110
[  171.668425] applespi spi-APP000D:00: SPI transfer timed out
[  171.668447] applespi: Error reading from device: -110
[  171.872354] applespi spi-APP000D:00: SPI transfer timed out
[  171.872376] applespi: Error reading from device: -110
[  172.071435] applespi spi-APP000D:00: SPI transfer timed out
[  172.071457] applespi: Error reading from device: -110
[  172.264889] applespi spi-APP000D:00: SPI transfer timed out
[  172.264912] applespi: Error reading from device: -110
[  172.462482] applespi spi-APP000D:00: SPI transfer timed out
[  172.462505] applespi: Error reading from device: -110
[  172.650614] applespi spi-APP000D:00: SPI transfer timed out
[  172.650636] applespi: Error reading from device: -110
[  172.853596] applespi spi-APP000D:00: SPI transfer timed out
[  172.853618] applespi: Error reading from device: -110
[  173.046016] applespi spi-APP000D:00: SPI transfer timed out
[  173.046042] applespi: Error reading from device: -110
[  173.243010] applespi spi-APP000D:00: SPI transfer timed out
[  173.243033] applespi: Error reading from device: -110
[  173.434436] applespi spi-APP000D:00: SPI transfer timed out
[  173.434459] applespi: Error reading from device: -110
[  173.628576] applespi spi-APP000D:00: SPI transfer timed out
[  173.628598] applespi: Error reading from device: -110
[  173.820176] applespi spi-APP000D:00: SPI transfer timed out
[  173.820198] applespi: Error reading from device: -110
[  174.020965] applespi spi-APP000D:00: SPI transfer timed out
[  174.020988] applespi: Error reading from device: -110
[  174.220401] applespi spi-APP000D:00: SPI transfer timed out
[  174.220423] applespi: Error reading from device: -110
[  174.417188] applespi spi-APP000D:00: SPI transfer timed out
[  174.417214] applespi: Error reading from device: -110
[  174.610430] applespi spi-APP000D:00: SPI transfer timed out
[  174.610452] applespi: Error reading from device: -110
[  174.811265] applespi spi-APP000D:00: SPI transfer timed out
[  174.811287] applespi: Error reading from device: -110
[  175.000382] applespi spi-APP000D:00: SPI transfer timed out
[  175.000405] applespi: Error reading from device: -110
[  175.194395] applespi spi-APP000D:00: SPI transfer timed out
[  175.194422] applespi: Error reading from device: -110
[  175.385533] applespi spi-APP000D:00: SPI transfer timed out
[  175.385574] applespi: Error reading from device: -110
[  175.580126] applespi spi-APP000D:00: SPI transfer timed out
[  175.580153] applespi: Error reading from device: -110
[  175.769662] applespi spi-APP000D:00: SPI transfer timed out
[  175.769685] applespi: Error reading from device: -110
[  175.961363] applespi spi-APP000D:00: SPI transfer timed out
[  175.961387] applespi: Error reading from device: -110
[  176.154571] applespi spi-APP000D:00: SPI transfer timed out
[  176.154595] applespi: Error reading from device: -110
[  176.343344] applespi spi-APP000D:00: SPI transfer timed out
[  176.343356] applespi: Error reading from device: -110
[  176.543536] applespi spi-APP000D:00: SPI transfer timed out
[  176.543558] applespi: Error reading from device: -110
[  176.746614] applespi spi-APP000D:00: SPI transfer timed out
[  176.746637] applespi: Error reading from device: -110
[  176.954532] applespi spi-APP000D:00: SPI transfer timed out
[  176.954554] applespi: Error reading from device: -110
[  177.162531] applespi spi-APP000D:00: SPI transfer timed out
[  177.162552] applespi: Error reading from device: -110
[  177.370538] applespi spi-APP000D:00: SPI transfer timed out
[  177.370559] applespi: Error reading from device: -110
[  177.578650] applespi spi-APP000D:00: SPI transfer timed out
[  177.578676] applespi: Error reading from device: -110
[  177.787515] applespi spi-APP000D:00: SPI transfer timed out
[  177.787528] applespi: Error reading from device: -110
[  177.994633] applespi spi-APP000D:00: SPI transfer timed out
[  177.994651] applespi: Error reading from device: -110
[  178.202647] applespi spi-APP000D:00: SPI transfer timed out
[  178.202667] applespi: Error reading from device: -110
[  178.410677] applespi spi-APP000D:00: SPI transfer timed out
[  178.410704] applespi: Error reading from device: -110
[  178.618671] applespi spi-APP000D:00: SPI transfer timed out
[  178.618694] applespi: Error reading from device: -110
[  178.826681] applespi spi-APP000D:00: SPI transfer timed out
[  178.826704] applespi: Error reading from device: -110
[  179.034686] applespi spi-APP000D:00: SPI transfer timed out
[  179.034709] applespi: Error reading from device: -110
[  179.242689] applespi spi-APP000D:00: SPI transfer timed out
[  179.242711] applespi: Error reading from device: -110
[  179.450697] applespi spi-APP000D:00: SPI transfer timed out
[  179.450720] applespi: Error reading from device: -110
[  179.658703] applespi spi-APP000D:00: SPI transfer timed out
[  179.658726] applespi: Error reading from device: -110
[  179.866716] applespi spi-APP000D:00: SPI transfer timed out
[  179.866739] applespi: Error reading from device: -110

And when I try to wake the system the first time by the power key, the screen lights up. On a second time it crashes.

[roadrunner2]

Regarding the keyboard brightness working manually: if you unload and reload the applespi module, or just load it later, then the keyboard brightness keys will stop working (in Gnome, at least), due to a bug in upowerd (see https://bugs.freedesktop.org/show_bug.cgi?id=101244). One way to work around this is to restart upowerd after (re)loading the module:

systemctl restart upower

Regarding the keyboard and touchpad unresponsive after resume, see #49.

[TheChatty]

After suspend I am unable to remove the module. rmmod applespi just hangs. As is the case with any other new module loading etc. The system is right before a crash.

[TheChatty]

I applied roadrunner2's patch and enabled debugging and got the following output while suspending:

[ 2426.487735] PM: suspend entry (deep)
[ 2426.487858] PM: Syncing filesystems ... done.
[ 2426.872552] Freezing user space processes ... (elapsed 0.005 seconds) done.
[ 2426.877826] OOM killer disabled.
[ 2426.877832] Freezing remaining freezable tasks ... (elapsed 0.002 seconds) done.
[ 2426.880793] printk: Suspending console(s) (use no_console_suspend to debug)
[ 2426.885840] applespi: spi-device suspend done.
[ 2426.888873] ------------[ cut here ]------------
[ 2426.889065] reqid not found
[ 2426.889106] WARNING: CPU: 0 PID: 5657 at drivers/net/wireless/broadcom/brcm80211/brcmfmac/pno.c:77 brcmf_pno_remove_request+0xae/0xd0 [brcmfmac]
[ 2426.889108] Modules linked in: applespi(OE) fuse bnep nf_conntrack_netbios_ns nf_conntrack_broadcast xt_CT ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 xt_conntrack ebtable_nat ip6table_nat nf_nat_ipv6 ip6table_mangle ip6table_raw ip6table_security iptable_nat nf_nat_ipv4 nf_nat iptable_mangle iptable_raw iptable_security devlink nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 ip_set nfnetlink ebtable_filter ebtables ip6table_filter ip6_tables sunrpc vfat fat brcmfmac intel_rapl x86_pkg_temp_thermal intel_powerclamp coretemp brcmutil kvm_intel joydev iTCO_wdt hci_uart iTCO_vendor_support btqca cfg80211 btrtl btbcm btintel snd_hda_codec_cirrus snd_hda_codec_generic bluetooth ledtrig_audio snd_hda_codec_hdmi crct10dif_pclmul snd_hda_intel crc32_pclmul ghash_clmulni_intel applesmc input_polldev intel_cstate snd_hda_codec intel_uncore mmc_core intel_rapl_perf sbs snd_hda_core ecdh_generic sbshc snd_hwdep rfkill acpi_als kfifo_buf snd_seq industrialio snd_seq_device snd_pcm spi_pxa2xx_platform snd_timer
[ 2426.889166]  mei_me snd spi_pxa2xx_pci intel_pch_thermal pcc_cpufreq soundcore mei i2c_i801 lpc_ich apple_bl binfmt_misc btrfs libcrc32c xor zstd_decompress zstd_compress xxhash raid6_pq i915 kvmgt mdev vfio kvm crc32c_intel nvme nvme_core irqbypass i2c_algo_bit drm_kms_helper drm 8250_lpss video uas usb_storage r8152 mii [last unloaded: applespi]
[ 2426.889201] CPU: 0 PID: 5657 Comm: kworker/u8:0 Tainted: G           OE     4.21.0-0.rc0.git1.1.fc30.x86_64 #1
[ 2426.889203] Hardware name: Apple Inc. MacBook8,1/Mac-BE0E8AC46FE800CC, BIOS 177.0.0.0.0 09/17/2018
[ 2426.889209] Workqueue: events_unbound async_run_entry_fn
[ 2426.889220] RIP: 0010:brcmf_pno_remove_request+0xae/0xd0 [brcmfmac]
[ 2426.889223] Code: 08 48 89 74 d3 08 48 63 d0 39 ca 7e e9 31 db 4c 89 e7 e8 a5 3b e7 da 89 d8 5b 5d 41 5c c3 48 c7 c7 01 4e c1 c0 e8 e6 51 4c da <0f> 0b bb fe ff ff ff 4c 89 e7 e8 83 3b e7 da 89 d8 5b 5d 41 5c c3
[ 2426.889226] RSP: 0018:ffffaa8508d97cd0 EFLAGS: 00010286
[ 2426.889230] RAX: 0000000000000000 RBX: ffff9a24217fec00 RCX: 0000000000000006
[ 2426.889232] RDX: 0000000000000007 RSI: ffff9a241e238dd0 RDI: ffff9a24265d6c20
[ 2426.889235] RBP: 0000000000000000 R08: 0000000000000002 R09: 0000000000000000
[ 2426.889237] R10: 0000000000000000 R11: 0000000000000000 R12: ffff9a24217fec88
[ 2426.889240] R13: ffff9a240d240640 R14: ffff9a240e53f000 R15: ffffffff9c38a5d7
[ 2426.889244] FS:  0000000000000000(0000) GS:ffff9a2426400000(0000) knlGS:0000000000000000
[ 2426.889246] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2426.889249] CR2: 00005653676dc106 CR3: 0000000184612003 CR4: 00000000003606f0
[ 2426.889252] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 2426.889255] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 2426.889257] Call Trace:
[ 2426.889271]  brcmf_pno_stop_sched_scan+0x22/0x50 [brcmfmac]
[ 2426.889282]  brcmf_cfg80211_sched_scan_stop+0x28/0x60 [brcmfmac]
[ 2426.889291]  brcmf_cfg80211_suspend+0x303/0x340 [brcmfmac]
[ 2426.889318]  wiphy_suspend+0xb0/0x460 [cfg80211]
[ 2426.889337]  ? wiphy_resume+0x220/0x220 [cfg80211]
[ 2426.889344]  dpm_run_callback+0x70/0x240
[ 2426.889352]  __device_suspend+0x10a/0x570
[ 2426.889361]  async_suspend+0x1a/0x90
[ 2426.889367]  async_run_entry_fn+0x39/0x160
[ 2426.889374]  process_one_work+0x27d/0x600
[ 2426.889389]  worker_thread+0x3c/0x390
[ 2426.889397]  ? process_one_work+0x600/0x600
[ 2426.889401]  kthread+0x120/0x140
[ 2426.889406]  ? kthread_create_on_node+0x60/0x60
[ 2426.889414]  ret_from_fork+0x3a/0x50
[ 2426.889432] irq event stamp: 38642
[ 2426.889438] hardirqs last  enabled at (38641): [<ffffffff9b13e377>] vprintk_emit+0x307/0x320
[ 2426.889442] hardirqs last disabled at (38642): [<ffffffff9b0037e8>] trace_hardirqs_off_thunk+0x1a/0x1c
[ 2426.889446] softirqs last  enabled at (38614): [<ffffffff9be00365>] __do_softirq+0x365/0x47c
[ 2426.889450] softirqs last disabled at (38601): [<ffffffff9b0c60e9>] irq_exit+0x119/0x120
[ 2426.889453] ---[ end trace ac626f1b7c1e216d ]---
[ 2427.898811] PM: suspend devices took 1.018 seconds
[ 2427.900914] brcmfmac: brcmf_fil_cmd_data: bus is down. we have nothing to do.
[ 2427.901005] brcmfmac: brcmf_cfg80211_reg_notifier: Country code iovar returned err = -5
[ 2427.923082] ACPI: EC: interrupt blocked
[ 2427.967170] ACPI: Preparing to enter system sleep state S3
[ 2428.121170] ACPI: EC: event blocked
[ 2428.121197] ACPI: EC: EC stopped
[ 2428.121202] PM: Saving platform NVS memory
[ 2428.121416] Disabling non-boot CPUs ...
[ 2428.141558] NOHZ: local_softirq_pending 02
[ 2428.141589] NOHZ: local_softirq_pending 02
[ 2428.144210] smpboot: CPU 1 is now offline
[ 2428.167940] smpboot: CPU 2 is now offline
[ 2428.186382] smpboot: CPU 3 is now offline
[ 2428.232317] ACPI: Low-level resume complete
[ 2428.232480] ACPI: EC: EC started
[ 2428.232488] PM: Restoring platform NVS memory
[ 2428.236425] Enabling non-boot CPUs ...
[ 2428.239298] x86: Booting SMP configuration:
[ 2428.239405] smpboot: Booting Node 0 Processor 1 APIC 0x2
[ 2428.272289] hrtimer: interrupt took 12289685 ns
[ 2430.288827]  cache: parent cpu1 should not be sleeping
[ 2432.776635] CPU1 is up
[ 2432.777957] smpboot: Booting Node 0 Processor 2 APIC 0x1
[ 2432.779201]  cache: parent cpu2 should not be sleeping
[ 2432.802112] CPU2 is up
[ 2432.802184] smpboot: Booting Node 0 Processor 3 APIC 0x3
[ 2433.460317]  cache: parent cpu3 should not be sleeping
[ 2435.091636] CPU3 is up
[ 2435.123359] ACPI: Waking up from system sleep state S3
[ 2435.126141] ACPI: EC: interrupt unblocked
[ 2435.162836] ACPI: EC: event unblocked
[ 2435.170501] nvme nvme0: detected Apple NVMe controller, set queue depth=2 to work around controller resets
[ 2435.173131] ACPI: button: The lid device is not compliant to SW_LID.
[ 2435.176145] nvme nvme0: IO queues not created
[ 2435.323247] applespi: spi-device resume done.
[ 2435.352192] PM: resume devices took 0.192 seconds
[ 2435.352820] OOM killer enabled.
[ 2435.352828] Restarting tasks ... done.
[ 2435.409816] video LNXVIDEO:00: Restoring backlight state
[ 2435.410860] PM: suspend exit
[ 2435.523761] applespi spi-APP000D:00: SPI transfer timed out
[ 2435.523796] applespi: Error reading from device: -110
[ 2435.523932] spi_master spi0: failed to transfer one message from queue
[ 2435.732714] applespi spi-APP000D:00: SPI transfer timed out
[ 2435.732764] applespi: --- Touchpad Initialization ------------------------
[ 2435.732769] applespi: write  40 02 00 00 00 00 0c 00 52 02 00 01 02 00 02 00 02 01 6b d1 00 00 00 00 00 00 00 00 00 00 00 00
[ 2435.732772] applespi: write  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 2435.732776] applespi: write  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 2435.732779] applespi: write  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 2435.732783] applespi: write  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 2435.732786] applespi: write  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 2435.732789] applespi: write  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 2435.732793] applespi: write  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 23 ab
[ 2435.732796] applespi: status 00 00 00 00
[ 2435.732799] applespi: Error writing to device: -110
[ 2435.732808] spi_master spi0: failed to transfer one message from queue
[ 2435.939937] applespi spi-APP000D:00: SPI transfer timed out
[ 2435.939988] applespi: Error reading from device: -110
[ 2435.940158] spi_master spi0: failed to transfer one message from queue
[ 2436.052552] IPv6: ADDRCONF(NETDEV_UP): enp0s20u1u1: link is not ready
[ 2436.060449] IPv6: ADDRCONF(NETDEV_UP): enp0s20u1u1: link is not ready
[ 2436.064011] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[ 2436.083485] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[ 2436.148744] applespi spi-APP000D:00: SPI transfer timed out
[ 2436.148783] applespi: Error reading from device: -110
[ 2436.148909] spi_master spi0: failed to transfer one message from queue
[ 2436.355902] applespi spi-APP000D:00: SPI transfer timed out
[ 2436.355951] applespi: Error reading from device: -110
[ 2436.356113] spi_master spi0: failed to transfer one message from queue
[ 2436.563904] applespi spi-APP000D:00: SPI transfer timed out
[ 2436.563961] applespi: Error reading from device: -110
[ 2436.564144] spi_master spi0: failed to transfer one message from queue
[ 2436.604655] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[ 2436.684240] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[ 2436.771754] applespi spi-APP000D:00: SPI transfer timed out
[ 2436.771790] applespi: Error reading from device: -110
[ 2436.771920] spi_master spi0: failed to transfer one message from queue
[ 2436.979759] applespi spi-APP000D:00: SPI transfer timed out
[ 2436.979797] applespi: Error reading from device: -110
[ 2436.979943] spi_master spi0: failed to transfer one message from queue
[ 2437.187718] applespi spi-APP000D:00: SPI transfer timed out
[ 2437.187745] applespi: Error reading from device: -110
[ 2437.187759] spi_master spi0: failed to transfer one message from queue
[ 2437.395758] applespi spi-APP000D:00: SPI transfer timed out
[ 2437.395893] applespi: Error reading from device: -110
[ 2437.396163] spi_master spi0: failed to transfer one message from queue
[ 2437.603860] applespi spi-APP000D:00: SPI transfer timed out

[roadrunner2]

After suspend I am unable to remove the module. rmmod applespi just hangs.

I think I see the problem (missed clearing some flags on a read error) and pushed a fix for it. Not sure exactly what code you're running, but grab the latest from #70 and it should fix the module remove hang.

Btw, I presume you're running into the #49 issue despite having booted with irqfixup (or irqoll)?

[TheChatty]

Now I am running exactly this code.

Without irqpoll/irqfixup modprobe applespi I never get up to the point where the corrupted packet (see below) is received (after keyboard is set up as device). Instead the modprobe is done early:

[    5.733388] applespi: loading out-of-tree module taints kernel.
[    5.738059] applespi: module verification failed: signature and/or required key missing - tainting kernel
[   12.929544] pxa2xx-spi pxa2xx-spi.0: Looking for DMA channel "tx" at index 0...
[   12.929808] pxa2xx-spi pxa2xx-spi.0: Looking for DMA channel "rx" at index 1...
[   12.994736] input: Apple SPI Keyboard as /devices/pci0000:00/0000:00:15.4/pxa2xx-spi.0/spi_master/spi0/spi-APP000D:00/input/input6
[   13.015081] applespi: spi-device probe done: spi-APP000D:00
[   13.205965] applespi spi-APP000D:00: SPI transfer timed out
[   13.206595] applespi: Error writing to device: -110
[   13.206627] spi_master spi0: failed to transfer one message from queue
[   13.414008] applespi spi-APP000D:00: SPI transfer timed out
[   13.414211] applespi: Error reading from device: -110
[   13.414249] spi_master spi0: failed to transfer one message from queue
[   13.622027] applespi spi-APP000D:00: SPI transfer timed out
[   13.622249] applespi: Error writing to device: -110
[   13.622271] spi_master spi0: failed to transfer one message from queue
[   13.722367] [<000000001ca0335e>] ssp_int [spi_pxa2xx_platform]
[   13.903206] audit: type=1130 audit(1546238246.151:65): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-backlight@leds:spi::kbd_backlight comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'

With either of irqpoll/irqfixup modprobe succeeds (no better than when integrated into initramfs except for 7 seconds earlier loading with still seting up inputs 7 seconds later). Still keyboard is not lit up automatically.

[    5.743182] applespi: loading out-of-tree module taints kernel.
[    5.753454] applespi: module verification failed: signature and/or required key missing - tainting kernel
[   12.734667] pxa2xx-spi pxa2xx-spi.0: Looking for DMA channel "tx" at index 0...
[   12.734945] pxa2xx-spi pxa2xx-spi.0: Looking for DMA channel "rx" at index 1...
[   12.796193] input: Apple SPI Keyboard as /devices/pci0000:00/0000:00:15.4/pxa2xx-spi.0/spi_master/spi0/spi-APP000D:00/input/input6
[   12.814562] applespi spi-APP000D:00: Received corrupted packet (crc mismatch)
[   12.817702] input: Apple SPI Touchpad as /devices/pci0000:00/0000:00:15.4/pxa2xx-spi.0/spi_master/spi0/spi-APP000D:00/input/input7
[   12.822974] applespi: modeswitch done.
[   12.837590] applespi: spi-device probe done: spi-APP000D:00
[   13.781225] audit: type=1130 audit(1546238664.046:66): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-backlight@leds:spi::kbd_backlight comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'

Does the corrupted packet tell you something?

With a working keyboard going systemctl suspend and resume by pressing power key I get a non-working keboard and:

[  669.080432] PM: suspend entry (deep)
[  669.081255] PM: Syncing filesystems ... done.
[  669.531027] Freezing user space processes ... (elapsed 0.002 seconds) done.
[  669.533499] OOM killer disabled.
[  669.533526] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[  669.535920] printk: Suspending console(s) (use no_console_suspend to debug)
[  669.539178] applespi: spi-device suspend done.
[  669.542893] ------------[ cut here ]------------
[  669.542987] reqid not found
[  669.543028] WARNING: CPU: 1 PID: 2326 at drivers/net/wireless/broadcom/brcm80211/brcmfmac/pno.c:77 brcmf_pno_remove_request+0xae/0xd0 [brcmfmac]
[  669.543030] Modules linked in: joydev applespi(OE) bnep nf_conntrack_netbios_ns nf_conntrack_broadcast xt_CT ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 xt_conntrack ebtable_nat ip6table_nat nf_nat_ipv6 ip6table_mangle ip6table_raw ip6table_security iptable_nat nf_nat_ipv4 nf_nat iptable_mangle iptable_raw iptable_security nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 devlink ip_set nfnetlink ebtable_filter ebtables ip6table_filter ip6_tables sunrpc vfat fat intel_rapl x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel hci_uart iTCO_wdt iTCO_vendor_support btqca btrtl btbcm btintel crct10dif_pclmul bluetooth crc32_pclmul applesmc brcmfmac input_polldev snd_hda_codec_cirrus snd_hda_codec_generic ledtrig_audio ghash_clmulni_intel snd_hda_codec_hdmi intel_cstate snd_hda_intel intel_uncore intel_rapl_perf snd_hda_codec ecdh_generic brcmutil sbs acpi_als cfg80211 kfifo_buf snd_hda_core snd_hwdep sbshc snd_seq spi_pxa2xx_platform snd_seq_device industrialio mmc_core snd_pcm rfkill snd_timer snd
[  669.543087]  i2c_i801 pcc_cpufreq mei_me soundcore spi_pxa2xx_pci intel_pch_thermal mei lpc_ich apple_bl binfmt_misc btrfs libcrc32c xor zstd_decompress zstd_compress xxhash raid6_pq i915 kvmgt mdev vfio kvm crc32c_intel irqbypass i2c_algo_bit drm_kms_helper nvme drm nvme_core 8250_lpss video uas usb_storage r8152 mii
[  669.543119] CPU: 1 PID: 2326 Comm: kworker/u8:0 Tainted: G           OE     4.21.0-0.rc0.git1.1.fc30.x86_64 #1
[  669.543122] Hardware name: Apple Inc. MacBook8,1/Mac-BE0E8AC46FE800CC, BIOS 177.0.0.0.0 09/17/2018
[  669.543128] Workqueue: events_unbound async_run_entry_fn
[  669.543139] RIP: 0010:brcmf_pno_remove_request+0xae/0xd0 [brcmfmac]
[  669.543143] Code: 08 48 89 74 d3 08 48 63 d0 39 ca 7e e9 31 db 4c 89 e7 e8 a5 fb d8 ce 89 d8 5b 5d 41 5c c3 48 c7 c7 01 8e cf c0 e8 e6 11 3e ce <0f> 0b bb fe ff ff ff 4c 89 e7 e8 83 fb d8 ce 89 d8 5b 5d 41 5c c3
[  669.543145] RSP: 0018:ffffad8ec803fcd0 EFLAGS: 00010286
[  669.543148] RAX: 0000000000000000 RBX: ffff8fec204c7000 RCX: 0000000000000006
[  669.543151] RDX: 0000000000000007 RSI: ffff8fec09698dd0 RDI: ffff8fec267d6c20
[  669.543153] RBP: 0000000000000000 R08: 0000000000000002 R09: 0000000000000000
[  669.543155] R10: 0000000000000000 R11: 0000000000000000 R12: ffff8fec204c7088
[  669.543158] R13: ffff8fec0ce3c640 R14: ffff8fec0ccf8000 R15: ffffffff9038a5d7
[  669.543161] FS:  0000000000000000(0000) GS:ffff8fec26600000(0000) knlGS:0000000000000000
[  669.543164] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  669.543166] CR2: 0000559369cceec8 CR3: 0000000216612006 CR4: 00000000003606e0
[  669.543169] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  669.543171] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  669.543173] Call Trace:
[  669.543186]  brcmf_pno_stop_sched_scan+0x22/0x50 [brcmfmac]
[  669.543196]  brcmf_cfg80211_sched_scan_stop+0x28/0x60 [brcmfmac]
[  669.543206]  brcmf_cfg80211_suspend+0x303/0x340 [brcmfmac]
[  669.543236]  wiphy_suspend+0xb0/0x460 [cfg80211]
[  669.543256]  ? wiphy_resume+0x220/0x220 [cfg80211]
[  669.543263]  dpm_run_callback+0x70/0x240
[  669.543271]  __device_suspend+0x10a/0x570
[  669.543279]  async_suspend+0x1a/0x90
[  669.543285]  async_run_entry_fn+0x39/0x160
[  669.543292]  process_one_work+0x27d/0x600
[  669.543307]  worker_thread+0x3c/0x390
[  669.543315]  ? process_one_work+0x600/0x600
[  669.543319]  kthread+0x120/0x140
[  669.543324]  ? kthread_create_on_node+0x60/0x60
[  669.543332]  ret_from_fork+0x3a/0x50
[  669.543350] irq event stamp: 6136
[  669.543356] hardirqs last  enabled at (6135): [<ffffffff8f13e377>] vprintk_emit+0x307/0x320
[  669.543360] hardirqs last disabled at (6136): [<ffffffff8f0037e8>] trace_hardirqs_off_thunk+0x1a/0x1c
[  669.543365] softirqs last  enabled at (6098): [<ffffffff8f8a2ab1>] peernet2id+0x51/0x80
[  669.543369] softirqs last disabled at (6096): [<ffffffff8f8a2a92>] peernet2id+0x32/0x80
[  669.543372] ---[ end trace ae21641c73a90019 ]---
[  670.555933] PM: suspend devices took 1.019 seconds
[  670.559073] brcmfmac: brcmf_fil_cmd_data: bus is down. we have nothing to do.
[  670.559202] brcmfmac: brcmf_cfg80211_reg_notifier: Country code iovar returned err = -5
[  670.580797] ACPI: EC: interrupt blocked
[  670.626950] ACPI: Preparing to enter system sleep state S3
[  670.784908] ACPI: EC: event blocked
[  670.784932] ACPI: EC: EC stopped
[  670.784936] PM: Saving platform NVS memory
[  670.785055] Disabling non-boot CPUs ...
[  670.809757] smpboot: CPU 1 is now offline
[  670.832228] smpboot: CPU 2 is now offline
[  670.850014] smpboot: CPU 3 is now offline
[  670.893097] ACPI: Low-level resume complete
[  670.893259] ACPI: EC: EC started
[  670.893267] PM: Restoring platform NVS memory
[  670.898042] Enabling non-boot CPUs ...
[  670.899443] x86: Booting SMP configuration:
[  670.899603] smpboot: Booting Node 0 Processor 1 APIC 0x2
[  670.934082] hrtimer: interrupt took 12285264 ns
[  673.001218]  cache: parent cpu1 should not be sleeping
[  675.366771] CPU1 is up
[  675.367992] smpboot: Booting Node 0 Processor 2 APIC 0x1
[  675.370340]  cache: parent cpu2 should not be sleeping
[  675.392029] CPU2 is up
[  675.392102] smpboot: Booting Node 0 Processor 3 APIC 0x3
[  676.042622]  cache: parent cpu3 should not be sleeping
[  677.614914] CPU3 is up
[  677.645144] ACPI: Waking up from system sleep state S3
[  677.648622] ACPI: EC: interrupt unblocked
[  677.685864] ACPI: EC: event unblocked
[  677.692318] nvme nvme0: detected Apple NVMe controller, set queue depth=2 to work around controller resets
[  677.697906] nvme nvme0: IO queues not created
[  677.708581] ACPI: button: The lid device is not compliant to SW_LID.
[  678.120254] applespi: spi-device resume done.
[  678.127814] PM: resume devices took 0.444 seconds
[  678.158642] OOM killer enabled.
[  678.160627] Restarting tasks ... done.
[  678.247686] video LNXVIDEO:00: Restoring backlight state
[  678.250884] PM: suspend exit
[  678.322803] applespi spi-APP000D:00: SPI transfer timed out
[  678.328816] applespi: Error writing to device: -110
[  678.335790] spi_master spi0: failed to transfer one message from queue
[  678.546883] applespi spi-APP000D:00: SPI transfer timed out
[  678.552434] applespi: Error reading from device: -110
[  678.557994] spi_master spi0: failed to transfer one message from queue
[  678.762857] applespi spi-APP000D:00: SPI transfer timed out
[  678.767334] applespi: Error reading from device: -110
[  678.771668] spi_master spi0: failed to transfer one message from queue

Now I can successfully rmmod applespi. But reloading it resumes the (now steady automatic) timeout messages and of course the keyboard not working.

When I turn on keyboard light it is switched off during standby but remains dark after resume. Trying again to turn it on fails.

[roadrunner2]

So there are two distinct issues with the keyboard/touchpad on MB8,1:

1. the system sometimes/often needs to be booted with irqfixup (this issue)
2. the keyboard/touchpad is non-functional after resume (Keyboard/trackpad not responsive on resume for Macbook 8,1 (12" 2015) #49)

While they are both related to the interrupt for the spi bus, they are different because this issue here is about the handler not getting installed properly (or something removing it again), whereas the resume issue is about the interrupt not firing at all anymore.

So sticking to the boot/irqfixup issue only here. (i.e. let's keep discussions about suspend/resume on the relevant ticket #49).

With either of irqpoll/irqfixup modprobe succeeds (no better than when integrated into initramfs except for 7 seconds earlier loading with still seting up inputs 7 seconds later). Still keyboard is not lit up automatically.

The keyboard lighting up is controlled by two things: when the driver loads (usually early in boot, if it's in the initramfs) it looks for a stored value in an EFI variable - this variable is written with the current value on shutdown. I.e. the driver tries to preserve the setting across reboots (mainly so the keyboard lights up during early boot, e.g. when entering a disk encryption password). Second, the desktop environment will generally set the light level when it starts up. But as I said above, there's a race issue with upowerd.

So if the keyboard is not lighting up by itself, try these things:

• ensure the keyboard light is on when you shut down (so the driver saves the value in the EFI variable)
• restart upowerd after logging in (systemctl restart upower)

Does the corrupted packet tell you something?

Not much: it's quite rare to get a corrupted packet, but it does very occasionally happen. Ideally we'd reset things when that happens, but it's not currently known how to do that, and things seem to recover by themselves even without a reset. So I've mostly just ignored these.

Now, back to the core issue of the interrupt handler not registered properly: @andy-shev, do you have any ideas here? (to summarize: on MB8,1 only, unless booted with irqfixup spi tranfers will usually all fail with "applespi spi-APP000D:00: SPI transfer timed out", though there are cases where folks have reported that by loading the applespi (and related spi drivers) in initramfs the irqfixup is not necessary, but that isn't always the case - so this looks to be some race related to the registration of the interrupt handler for the spi device?).

[TheChatty]

@roadrunner2: I manually turned the keyboard light on in runlevel 3 (as only from there I am successfully able to reboot - otherwise some stop jobs from Fedora are hanging) and my keyboard successfully lit up automatically. But quite late: after modeswitch is done (@8s), module already loaded @2s according to dmesg. I had not to deal with upower. When display turns off and I press a key (wake up call), the keyboard light turns on as well. So this is all working fine.
Only after a rmmod/modprobe cycle even restarting upower doesn't help to make it take care of the backlight again (just stays on even though the display going dark).

I see the corrupted packet once on every load of the module (thus also on a rmmod/modprobe cycle).

[roadrunner2]

@TheChatty Sorry for the slow reply. Regarding the keyboard light, if restarting upower doesn't fix the issue and after reloading the module, then I don't know what the issue is - in any case, since the driver exposes the backlight controls properly and you can manually change the brightness, it's not an issue with the driver, but some userspace issue. I'm sorry, but you'll have to debug that yourself.

Regarding the corrupted packet, while it doesn't appear to be a serious issue (shows up only once), it would be nice to understand what's going on. To that end I've pushed an update to the applespi driver on my branch which allows logging of the corrupted packet. If you can pull that, rebuild, and then (re)load with

sudo insmod applespi.ko debug=0x1000

and then send me the output of dmesg | grep applespi, that would be great.

Lastly, regarding the irqfixup issue, I've prepared a patch to print out some debug info about the irq allocation and handling (spi-debug.patch.txt). You'll need to rebuild and reinstall your kernel with this patch. Also, it will be somewhat noisy, so you'll need to grab the output from journalctl -k instead of dmesg as it will quickly overflow the ringbuffer. With this patch could you post the logs from each of the following:

• booting without irqfixup
• booting with irqfixup
• suspend/resume (when booted with irqfixup) (not sure if it'll help debug that issue, but I figure once you've gone through the trouble of patching the kernel we might as well see the additional logs have to say)

[andy-shev]

I didn’t find /proc/interrupts for non-working case on most recent kernel + driver to advise something.