Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

applespi sporadically times out on boot: "spi-APP000D:00: Timed out waiting for device info" #40

Open
arno01 opened this issue Feb 21, 2020 · 5 comments
Open

applespi sporadically times out on boot: "spi-APP000D:00: Timed out waiting for device info" #40

arno01 opened this issue Feb 21, 2020 · 5 comments

Comments

@arno01
Copy link

arno01 commented Feb 21, 2020 •
edited
Loading

applespi sporadically times out on boot, at around 2 times out of 10 times:

applespi spi-APP000D:00: Timed out waiting for device info
applespi: probe of spi-APP000D:00 failed with error -110

whilst touch bar stays active, I have to press power button for 5 seconds to reboot.

Any ideas?
@roadrunner2
Copy link
Owner

Are there no other related messages before this? In particular, I'd expect some read error to be logged (most likely a bad-crc error).

I've just fixed an issue with reading bad packets when the system is under load - if you are indeed seeing crc errors then pulling the latest driver should hopefully fix the problem. If this isn't the problem or the new code doesn't fix things, try booting with the following added your kernel command line:

trace_events=applespi:*

You'll then need to ssh into your laptop from elsewhere to dump the trace buffer, as it's not persisted:

cat /sys/kernel/debug/tracing/trace <some-file>

@arno01
Copy link
Author

arno01 commented Feb 23, 2020

Are there no other related messages before this? In particular, I'd expect some read error to be logged (most likely a bad-crc error).

Yeah, here are the logs:

$ grep -iE 'apple|pxa2xx|lpss' dmesg.log
[Sun Feb 23 17:08:59 2020] efi: EFI v2.40 by Apple
[Sun Feb 23 17:08:59 2020] DMI: Apple Inc. MacBookPro14,3/Mac-551B86E5744E2388, BIOS 203.0.0.0.0 10/30/2019
[Sun Feb 23 17:08:59 2020] ACPI: RSDP 0x000000007AFFE014 000024 (v02 APPLE )
[Sun Feb 23 17:08:59 2020] ACPI: XSDT 0x000000007AFC5188 0000D4 (v01 APPLE  Apple00  00000000      01000013)
[Sun Feb 23 17:08:59 2020] ACPI: FACP 0x000000007AFF8000 0000F4 (v05 APPLE  Apple00  00000000 Loki 0000005F)
[Sun Feb 23 17:08:59 2020] ACPI: DSDT 0x000000007AFEB000 00876C (v02 APPLE  MacBookP 00140003 INTL 20140424)
[Sun Feb 23 17:08:59 2020] ACPI: ECDT 0x000000007AFFA000 000053 (v01 APPLE  Apple00  00000001 Loki 0000005F)
[Sun Feb 23 17:08:59 2020] ACPI: HPET 0x000000007AFF7000 000038 (v01 APPLE  Apple00  00000001 Loki 0000005F)
[Sun Feb 23 17:08:59 2020] ACPI: APIC 0x000000007AFF6000 0000BC (v02 APPLE  Apple00  00000001 Loki 0000005F)
[Sun Feb 23 17:08:59 2020] ACPI: MCFG 0x000000007AFF5000 00003C (v01 APPLE  Apple00  00000001 Loki 0000005F)
[Sun Feb 23 17:08:59 2020] ACPI: SBST 0x000000007AFF4000 000030 (v01 APPLE  Apple00  00000001 Loki 0000005F)
[Sun Feb 23 17:08:59 2020] ACPI: SSDT 0x000000007AFEA000 000024 (v01 APPLE  SmcDppt  00001000 INTL 20140424)
[Sun Feb 23 17:08:59 2020] ACPI: SSDT 0x000000007AFE9000 0007FD (v02 APPLE  PEG0GFX0 00001000 INTL 20140424)
[Sun Feb 23 17:08:59 2020] ACPI: SSDT 0x000000007AFE8000 000024 (v01 APPLE  PEG0SSD0 00001000 INTL 20140424)
[Sun Feb 23 17:08:59 2020] ACPI: SSDT 0x000000007AFE5000 000031 (v01 APPLE  SsdtS3   00001000 INTL 20140424)
[Sun Feb 23 17:08:59 2020] ACPI: SSDT 0x000000007AFE4000 0000DD (v01 APPLE  SataAhci 00001000 INTL 20140424)
[Sun Feb 23 17:08:59 2020] ACPI: SSDT 0x000000007AFE3000 0000B8 (v01 APPLE  Sdxc     00001000 INTL 20140424)
[Sun Feb 23 17:08:59 2020] ACPI: SSDT 0x000000007AFCE000 009C80 (v02 APPLE  TbtPEG12 00001000 INTL 20140424)
[Sun Feb 23 17:08:59 2020] ACPI: SSDT 0x000000007AFCC000 001062 (v02 APPLE  Xhci     00001000 INTL 20140424)
[Sun Feb 23 17:08:59 2020] ACPI: RMAD 0x000000007AFC6000 000160 (v01 APPLE  KBL      00000001 INTL 00000001)
[Sun Feb 23 17:08:59 2020] ACPI: VFCT 0x000000007AFB5000 00F284 (v01 APPLE  Apple00  00000001 AMD  31504F47)
[Sun Feb 23 17:08:59 2020] ACPI: DMI detected to setup _OSI("Darwin"): Apple hardware
[Sun Feb 23 17:09:00 2020] Kernel command line: placeholder root=/dev/mapper/qubes_dom0-root ro rd.luks.uuid=luks-23f16e1e-c5a0-4c0a-850a-ffe166870749 rd.lvm.lv=qubes_dom0/root rd.lvm.lv=qubes_dom0/swap plymouth.ignore-serial-consoles vconsole.font=latarcyrheb-sun32 console_timestamps=datems qubes.skip_autostart trace_event=applespi:*
[Sun Feb 23 17:09:00 2020] Failed to enable trace event: applespi:*
[Sun Feb 23 17:09:00 2020] Failed to enable trace event: applespi:*
[Sun Feb 23 17:09:03 2020] applespi: loading out-of-tree module taints kernel.
[Sun Feb 23 17:09:03 2020] apple_ibridge: loading out-of-tree module taints kernel.
[Sun Feb 23 17:09:04 2020] intel-lpss 0000:00:15.0: enabling device (0000 -> 0002)
[Sun Feb 23 17:09:04 2020] intel-lpss 0000:00:19.0: enabling device (0000 -> 0002)
[Sun Feb 23 17:09:04 2020] intel-lpss 0000:00:1e.0: enabling device (0000 -> 0002)
[Sun Feb 23 17:09:04 2020] intel-lpss 0000:00:1e.1: enabling device (0000 -> 0002)
[Sun Feb 23 17:09:04 2020] intel-lpss 0000:00:1e.2: enabling device (0000 -> 0002)
[Sun Feb 23 17:09:04 2020] intel-lpss 0000:00:1e.3: enabling device (0000 -> 0002)
[Sun Feb 23 17:09:04 2020] Modules linked in: spi_pxa2xx_platform(+) amdkfd amd_iommu_v2 apple_ib_tb(O) crct10dif_pclmul crc32_pclmul crc32c_intel amdgpu(+) chash i2c_algo_bit nvme ghash_clmulni_intel gpu_sched drm_kms_helper nvme_core intel_lpss_pci intel_lpss ttm xhci_pci xhci_hcd drm apple_ibridge(O) applespi(O) xen_privcmd xen_pciback xen_blkback xen_gntalloc xen_gntdev xen_evtchn uinput
[Sun Feb 23 17:09:04 2020] Hardware name: Apple Inc. MacBookPro14,3/Mac-551B86E5744E2388, BIOS 203.0.0.0.0 10/30/2019
[Sun Feb 23 17:09:04 2020] input: Apple SPI Keyboard as /devices/pci0000:00/0000:00:1e.3/pxa2xx-spi.5/spi_master/spi2/spi-APP000D:00/input/input4
[Sun Feb 23 17:09:04 2020] applespi spi-APP000D:00: Received corrupted packet (crc mismatch)
[Sun Feb 23 17:09:04 2020] usb 1-3: Manufacturer: Apple Inc.
[Sun Feb 23 17:09:04 2020] input: Apple Inc. iBridge as /devices/pci0000:00/0000:00:14.0/usb1/1-3/1-3:1.2/0003:05AC:8600.0001/input/input5
[Sun Feb 23 17:09:04 2020] apple-ibridge-hid 0003:05AC:8600.0001: input,hidraw0: USB HID v1.01 Keyboard [Apple Inc. iBridge] on usb-0000:00:14.0-3/input2
[Sun Feb 23 17:09:04 2020] apple-ibridge-hid 0003:05AC:8600.0002: hiddev96,hidraw1: USB HID v1.01 Device [Apple Inc. iBridge] on usb-0000:00:14.0-3/input3
[Sun Feb 23 17:09:07 2020] applespi spi-APP000D:00: Timed out waiting for device info
[Sun Feb 23 17:09:07 2020] applespi: probe of spi-APP000D:00 failed with error -110
[Sun Feb 23 17:09:11 2020] apple_gmux: Found gmux version 4.0.29 [indexed]
[Sun Feb 23 17:09:11 2020] input: Apple Inc. iBridge as /devices/pci0000:00/0000:00:14.0/usb1/1-3/1-3:1.2/0003:05AC:8600.0001/input/input7
[Sun Feb 23 17:09:11 2020] apple-ibridge-hid 0003:05AC:8600.0001: input,hidraw0: USB HID v1.01 Keyboard [Apple Inc. iBridge] on usb-0000:00:14.0-3/input2
[Sun Feb 23 17:09:11 2020] apple-ibridge-hid 0003:05AC:8600.0002: hiddev96,hidraw1: USB HID v1.01 Device [Apple Inc. iBridge] on usb-0000:00:14.0-3/input3
[Sun Feb 23 17:09:12 2020] applesmc: key=862 fan=2 temp=46 index=45 acc=0 lux=0 kbd=0
[Sun Feb 23 17:09:12 2020] applesmc applesmc.768: hwmon_device_register() is deprecated. Please convert the driver to use hwmon_device_register_with_info().
[Sun Feb 23 17:09:12 2020] Bluetooth: hci0: BCM20703A2 Generic UART UHE Apple 40MHz wlcsp_x100

# here I connected an external USB keyboard, and did reload applespi module, after which the laptop keyboard & touchbar started to work:
# modprobe -r applespi; modprobe applespi

[Sun Feb 23 17:12:48 2020] input: Apple SPI Keyboard as /devices/pci0000:00/0000:00:1e.3/pxa2xx-spi.5/spi_master/spi2/spi-APP000D:00/input/input21
[Sun Feb 23 17:12:48 2020] applespi spi-APP000D:00: Received corrupted packet (crc mismatch)
[Sun Feb 23 17:12:48 2020] applespi spi-APP000D:00: Received corrupted packet (invalid message length 8 - num-fingers 0, tp-len 48)
[Sun Feb 23 17:12:48 2020] input: Apple SPI Touchpad as /devices/pci0000:00/0000:00:1e.3/pxa2xx-spi.5/spi_master/spi2/spi-APP000D:00/input/input22
[Sun Feb 23 17:12:48 2020] applespi spi-APP000D:00: Received corrupted packet (crc mismatch)
[Sun Feb 23 17:12:48 2020] applespi spi-APP000D:00: Received corrupted packet (invalid message length 8 - num-fingers 0, tp-len 48)
[Sun Feb 23 17:12:48 2020] applespi spi-APP000D:00: modeswitch done.

I've just fixed an issue with reading bad packets when the system is under load - if you are indeed seeing crc errors then pulling the latest driver should hopefully fix the problem. If this isn't the problem or the new code doesn't fix things, try booting with the following added your kernel command line:

trace_events=applespi:*

You'll then need to ssh into your laptop from elsewhere to dump the trace buffer, as it's not persisted:

cat /sys/kernel/debug/tracing/trace <some-file>

FYI: For anyone else reading this, that should be trace_event=applespi:* (without "s" on its end).

I've got x2 Failed to enable trace event: applespi:*, it looks like this is happening because the applespi driver is not loaded at the time the kernel is trying to establish tracing for it. (similar example http://lists.infradead.org/pipermail/linux-nvme/2019-May/024378.html )

I think this could be related to the issue you've fixed.
Where can I find the code to try the fix?

@roadrunner2
Copy link
Owner

Apologies for the typo, and for not testing the kernel-command line instructions I gave.

Are there no other related messages before this? In particular, I'd expect some read error to be logged (most likely a bad-crc error).

Yeah, here are the logs:

[snip]

[Sun Feb 23 17:09:04 2020] applespi spi-APP000D:00: Received corrupted packet (crc mismatch)

Bingo - this is the one I expected to see. Thanks.

\# here I connected an external USB keyboard, and did reload applespi module, after which the laptop keyboard & touchbar started to work:
\# modprobe -r applespi; modprobe applespi

[Sun Feb 23 17:12:48 2020] input: Apple SPI Keyboard as /devices/pci0000:00/0000:00:1e.3/pxa2xx-spi.5/spi_master/spi2/spi-APP000D:00/input/input21
[Sun Feb 23 17:12:48 2020] applespi spi-APP000D:00: Received corrupted packet (crc mismatch)
[Sun Feb 23 17:12:48 2020] applespi spi-APP000D:00: Received corrupted packet (invalid message length 8 - num-fingers 0, tp-len 48)
[Sun Feb 23 17:12:48 2020] input: Apple SPI Touchpad as /devices/pci0000:00/0000:00:1e.3/pxa2xx-spi.5/spi_master/spi2/spi-APP000D:00/input/input22
[Sun Feb 23 17:12:48 2020] applespi spi-APP000D:00: Received corrupted packet (crc mismatch)
[Sun Feb 23 17:12:48 2020] applespi spi-APP000D:00: Received corrupted packet (invalid message length 8 - num-fingers 0, tp-len 48)
[Sun Feb 23 17:12:48 2020] applespi spi-APP000D:00: modeswitch done.

Hmm, things look even worse here.

I've just fixed an issue with reading bad packets when the system is under load - if you are indeed seeing crc errors then pulling the latest driver should hopefully fix the problem.
[snip]
I've got x2 Failed to enable trace event: applespi:*, it looks like this is happening because the applespi driver is not loaded at the time the kernel is trying to establish tracing for it. (similar example http://lists.infradead.org/pipermail/linux-nvme/2019-May/024378.html )

Argh, yes, didn't work as expected. I've now added a new module param to enable tracing of early messages. So the current instructions would be to boot with the following kernel command line (really tested this time, but you need the latest driver here for this)

applespi.trace_event=applespi_tp_ini_cmd,applespi_bad_crc

Where can I find the code to try the fix?

This repository - just do a git pull and then rebuild.

@arno01
Copy link
Author

arno01 commented Feb 24, 2020 •
edited
Loading

Where can I find the code to try the fix?

This repository - just do a git pull and then rebuild.

Oh, I see why I got confused.
It looks like you pushed the changes to the repo without keeping the original commit hash history track, so it forces one to remove the repo and re-do the git clone again instead of a simple git pull.
It would be much easier for many if you could be adding the new changes as a new commit, without amending the original commit hash history track.
This is also better from the security/auditing point of view.
I am using the commit hash for pointing to the code in your repo for adding it to the QubesOS, e.g. https://github.com/QubesOS/qubes-linux-kernel/pull/161/files#diff-b67911656ef5d18c4ae36cb6741b7965R62

Here are the changes between what I used and your new additions

--- ../old/macbook12-spi-driver/applespi.c	2020-01-28 13:23:43.453000000 +0100
+++ applespi.c	2020-02-24 10:28:16.793000000 +0100
@@ -55,6 +55,8 @@
 #include <linux/platform_device.h>
 #include <linux/spinlock.h>
 #include <linux/spi/spi.h>
+#include <linux/string.h>
+#include <linux/trace_events.h>
 #include <linux/version.h>
 #include <linux/wait.h>
 
@@ -73,6 +75,18 @@
 #include <linux/notifier.h>
 #endif
 
+#ifndef sizeof_field
+#define sizeof_field(TYPE, MEMBER)	sizeof((((TYPE *)0)->MEMBER))
+#endif
+
+#ifndef struct_size
+#define struct_size(p, member, n)	(sizeof(*(p)) + n * sizeof(*(p)->member))
+#endif
+
+#ifndef wait_event_lock_irq_timeout
+#define wait_event_lock_irq_timeout	wait_event_interruptible_lock_irq_timeout
+#endif
+
 #define APPLESPI_PACKET_SIZE	256
 #define APPLESPI_STATUS_SIZE	4
 
@@ -120,6 +134,10 @@
 		    sizeof(touchpad_dimensions), 0444);
 MODULE_PARM_DESC(touchpad_dimensions, "The pixel dimensions of the touchpad, as XxY+W+H .");
 
+static char* trace_event;
+module_param(trace_event, charp, 0444);
+MODULE_PARM_DESC(trace_event, "Enable early event tracing. It takes the form of a comma-separated list of events to enable.");
+
 /**
  * struct keyboard_protocol - keyboard message.
  * message.type = 0x0110, message.length = 0x000a
@@ -627,14 +645,20 @@
 {
 	struct applespi_complete_info *info = context;
 	struct applespi_data *applespi = info->applespi;
+	void (*complete)(void *);
 	unsigned long flags;
 
-	info->complete(applespi);
-
 	spin_lock_irqsave(&applespi->cmd_msg_lock, flags);
 
+	complete = info->complete;
 	info->complete = NULL;
 
+	spin_unlock_irqrestore(&applespi->cmd_msg_lock, flags);
+
+	complete(applespi);
+
+	spin_lock_irqsave(&applespi->cmd_msg_lock, flags);
+
 	if (applespi->cancel_spi && !applespi_async_outstanding(applespi))
 		wake_up_all(&applespi->drain_complete);
 
@@ -926,6 +950,8 @@
 					 applespi->tx_status,
 					 APPLESPI_STATUS_SIZE);
 
+	udelay(SPI_RW_CHG_DELAY_US);
+
 	if (!applespi_check_write_status(applespi, applespi->wr_m.status)) {
 		/*
 		 * If we got an error, we presumably won't get the expected
@@ -1808,6 +1834,30 @@
 			 "Error saving backlight level to EFI vars: %d\n", sts);
 }
 
+static void applespi_enable_early_event_tracing(struct device *dev)
+{
+	char *buf, *event;
+	int sts;
+
+	if (trace_event && trace_event[0]) {
+		buf = kstrdup(trace_event, GFP_KERNEL);
+		if (!buf)
+			return;
+
+		while ((event = strsep(&buf, ","))) {
+			if (event[0]) {
+				sts = trace_set_clr_event("applespi", event, 1);
+				if (sts)
+					dev_warn(dev,
+						 "Error setting trace event '%s': %d\n",
+						 event, sts);
+			}
+		}
+
+		kfree(buf);
+	}
+}
+
 static int applespi_probe(struct spi_device *spi)
 {
 	struct applespi_data *applespi;
@@ -1817,6 +1867,8 @@
 	int sts, i;
 	unsigned long long gpe, usb_status;
 
+	applespi_enable_early_event_tracing(&spi->dev);
+
 	/* check if the USB interface is present and enabled already */
 	acpi_sts = acpi_evaluate_integer(spi_handle, "UIST", NULL, &usb_status);
 	if (ACPI_SUCCESS(acpi_sts) && usb_status) {

I have been trying to reload the applespi module more in attempt to reproduce this issue without the reboot.
I cannot reproduce the issue anymore using the new applespi.

I will post here with the trace information if I hit the issue again.

Thank you!

@arno01 arno01 mentioned this issue Feb 24, 2020
Merged
@roadrunner2
Copy link
Owner

Sorry about the confusion: yes, I re-ordered the commits a bit, so it's not a fast-forward pull anymore, but you need not blow away the repo, just add the --force flag to git fetch or pull. I should probably split the applespi driver from the iBridge/touchbar/ALS stuff too so I won't be tempted to re-order the commits.

Anyway, great to hear this fixes the issue.

I'll leave this open a few more days in case the problem shows up again.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@roadrunner2 @arno01