Driver fails to initialize when booting with EFISTUB (`invalid dma rx data`)

[christophfink]

I’m having troubles getting the touchscreen on a Surface Pro 9 to work. I tested linux-surface kernels 6.3.2, 6.2.13 and 6.1.12 from the [linux-surface] repository on Arch Linux, in all combinations of intel_iommu and intremap settings.

dmesg | grep ithc outputs the following:

[   12.583823] ithc 0000:00:10.6: enabling device (0000 -> 0002)
[   12.815479] ithc 0000:00:10.6: config: e0000002 00000000 001fc0ff 00000010 00000014 43495424 0ce3d2e8 0c52045e 00000001 f5e81be4 002fcb5b 00000000 a404acd8 00040302 460a0c60 a78e200a
[   12.822904] ithc 0000:00:10.6: invalid dma rx data! channel 1, buffer 0, size 1360, code 0, data size 0
[   13.847092] ithc 0000:00:10.6: ithc_start: hid_add_device failed with -110
[   13.847101] ithc: probe of 0000:00:10.6 failed with error -110

Before wiping Windows off, I still installed the currently newest version of firmware (SurfacePro9_Win11_22621_23.044.40352.0.msi) - was that a mistake?

(not sure whether this belongs here, or into linux-surface, please transfer the issue if appopriate)

[christophfink]

Here’s still the output with dyndbg=+pflmt:

[   52.840204] [1036] ithc:ithc_probe:468: ithc 0000:00:10.6: device probe
[   52.840207] [1036] ithc:ithc_start:396: ithc 0000:00:10.6: starting
[   52.840680] [1036] ithc:waitl:16: ithc 0000:00:10.6: waiting for reg 0x1008 mask 0x00000004 val 0x00000004
[   52.840682] [1036] ithc:waitl:22: ithc 0000:00:10.6: done waiting
[   52.840736] [1036] ithc:waitl:16: ithc 0000:00:10.6: waiting for reg 0x1008 mask 0x20000000 val 0x20000000
[   52.840739] [1036] ithc:waitl:22: ithc 0000:00:10.6: done waiting
[   52.840739] [1036] ithc:ithc_set_spi_config:38: ithc 0000:00:10.6: setting SPI speed to 10, mode 0
[   52.840758] [1036] ithc:waitl:16: ithc 0000:00:10.6: waiting for reg 0x1008 mask 0x00000004 val 0x00000000
[   52.840761] [1036] ithc:waitl:22: ithc 0000:00:10.6: done waiting
[   52.840764] [1036] ithc:waitl:16: ithc 0000:00:10.6: waiting for reg 0x10bc mask 0x0000000f val 0x00000002
[   53.070865] [1036] ithc:waitl:22: ithc 0000:00:10.6: done waiting
[   53.070869] [1036] ithc:waitl:16: ithc 0000:00:10.6: waiting for reg 0x1110 mask 0x00000010 val 0x00000010
[   53.070910] [1036] ithc:waitl:22: ithc 0000:00:10.6: done waiting
[   53.070913] [1036] ithc:ithc_spi_command:47: ithc 0000:00:10.6: SPI command 4, size 64, offset 0
[   53.070917] [1036] ithc:waitl:16: ithc 0000:00:10.6: waiting for reg 0x1044 mask 0x00000008 val 0x00000000
[   53.070957] [1036] ithc:waitl:22: ithc 0000:00:10.6: done waiting
[   53.070979] [1036] ithc:waitl:16: ithc 0000:00:10.6: waiting for reg 0x1044 mask 0x00000008 val 0x00000000
[   53.071212] [1036] ithc:waitl:22: ithc 0000:00:10.6: done waiting
[   53.071249] ithc 0000:00:10.6: config: e0000002 00000000 001fc0ff 00000010 00000014 43495424 0ce3d2e8 0c52045e 00000001 f5e81be5 002f4b5b 00000000 a404acd8 00040302 422a0c60 a78e200a
[   53.071260] [1036] ithc:ithc_set_spi_config:38: ithc 0000:00:10.6: setting SPI speed to 4, mode 3
[   53.071299] [1036] ithc:ithc_spi_command:47: ithc 0000:00:10.6: SPI command 6, size 4, offset 12
[   53.071302] [1036] ithc:waitl:16: ithc 0000:00:10.6: waiting for reg 0x1044 mask 0x00000008 val 0x00000000
[   53.071344] [1036] ithc:waitl:22: ithc 0000:00:10.6: done waiting
[   53.071368] [1036] ithc:waitl:16: ithc 0000:00:10.6: waiting for reg 0x1044 mask 0x00000008 val 0x00000000
[   53.071544] [1036] ithc:waitl:22: ithc 0000:00:10.6: done waiting
[   53.071626] [1036] ithc:ithc_dma_rx_init:118: ithc 0000:00:10.6: allocating rx buffers: num = 16, size = 16384, pages = 4
[   53.071767] [1036] ithc:ithc_dma_tx_init:143: ithc 0000:00:10.6: allocating tx buffers: size = 8192, pages = 2
[   53.072091] [1036] ithc:waitl:16: ithc 0000:00:10.6: waiting for reg 0x1210 mask 0x00000100 val 0x00000100
[   53.072140] [1036] ithc:waitl:22: ithc 0000:00:10.6: done waiting
[   53.072149] [1036] ithc:ithc_dma_tx_unlocked:230: ithc 0000:00:10.6: dma tx command 7, size 8
[   53.072193] [1036] ithc:waitb:27: ithc 0000:00:10.6: waiting for reg 0x1098 mask 0x01 val 0x00
[   53.072446] [1036] ithc:waitb:33: ithc 0000:00:10.6: done waiting
[   53.073128] [1037] ithc:ithc_interrupt_thread:267: ithc 0000:00:10.6: IRQ! err=00000000/00000000/00000000, cmd=00/00000000, rx0=00/00000010, rx1=29/00000120, tx=00/00000000
[   53.073166] ithc 0000:00:10.6: invalid dma rx data! channel 1, buffer 0, size 1360, code 0, data size 0
[   53.073173] ithc data: 00000000: 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
[   53.073177] ithc data: 00000020: 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
[   53.073180] ithc data: 00000040: 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
[   53.073182] ithc data: 00000060: 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
[   53.073184] ithc data: 00000080: 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
[   53.073186] ithc data: 000000a0: 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
[   53.073188] ithc data: 000000c0: 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
[   53.073190] ithc data: 000000e0: 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
[   53.073192] ithc data: 00000100: 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
[   53.073195] ithc data: 00000120: 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
[   53.073197] ithc data: 00000140: 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
[   53.073199] ithc data: 00000160: 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
[   53.073201] ithc data: 00000180: 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
[   53.073203] ithc data: 000001a0: 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
[   53.073205] ithc data: 000001c0: 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
[   53.073207] ithc data: 000001e0: 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
[   53.073209] ithc data: 00000200: 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
[   53.073211] ithc data: 00000220: 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
[   53.073214] ithc data: 00000240: 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
[   53.073216] ithc data: 00000260: 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
[   53.073218] ithc data: 00000280: 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
[   53.073220] ithc data: 000002a0: 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
[   53.073222] ithc data: 000002c0: 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
[   53.073224] ithc data: 000002e0: 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
[   53.073226] ithc data: 00000300: 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
[   53.073228] ithc data: 00000320: 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
[   53.073230] ithc data: 00000340: 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
[   53.073232] ithc data: 00000360: 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
[   53.073234] ithc data: 00000380: 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
[   53.073236] ithc data: 000003a0: 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
[   53.073238] ithc data: 000003c0: 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
[   53.073240] ithc data: 000003e0: 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
[   54.084891] ithc 0000:00:10.6: ithc_start: hid_add_device failed with -110
[   54.084893] ithc: probe of 0000:00:10.6 failed with error -110
[   54.084964] [1036] ithc:ithc_stop:369: ithc 0000:00:10.6: stopping
[   54.084966] [1036] ithc:ithc_spi_command:47: ithc 0000:00:10.6: SPI command 6, size 4, offset 12
[   54.084967] [1036] ithc:waitl:16: ithc 0000:00:10.6: waiting for reg 0x1044 mask 0x00000008 val 0x00000000
[   54.085005] [1036] ithc:waitl:22: ithc 0000:00:10.6: done waiting
[   54.085009] [1036] ithc:waitl:16: ithc 0000:00:10.6: waiting for reg 0x1044 mask 0x00000008 val 0x00000000
[   54.085233] [1036] ithc:waitl:22: ithc 0000:00:10.6: done waiting
[   54.085240] [1036] ithc:waitl:16: ithc 0000:00:10.6: waiting for reg 0x1008 mask 0x00000004 val 0x00000004
[   54.085243] [1036] ithc:waitl:22: ithc 0000:00:10.6: done waiting
[   54.085259] [1036] ithc:waitl:16: ithc 0000:00:10.6: waiting for reg 0x1110 mask 0x00000100 val 0x00000000
[   54.085262] [1036] ithc:waitl:22: ithc 0000:00:10.6: done waiting
[   54.085263] [1036] ithc:waitl:16: ithc 0000:00:10.6: waiting for reg 0x1210 mask 0x00000100 val 0x00000000
[   54.085266] [1036] ithc:waitl:22: ithc 0000:00:10.6: done waiting
[   54.085267] [1036] ithc:ithc_stop:387: ithc 0000:00:10.6: stopped

[christophfink]

I now also tried with dkms modules (from current git main branch), same results

[christophfink]

Just realised there is an existing duplicate issue at https://github.com/quo/ithc-linux/issues/16 Sorry for the inconvenience, will close this one and re-open just in case the other issue turns out to be different after all

[christophfink]

polling does not make any difference, tried with and without intremap=nosid and intel_iommu=off

[StollD]

Are you booting your kernel with EFI stub? There is this issue on linux-surface, which is very similar or identical to yours: https://github.com/linux-surface/linux-surface/issues/1078

[christophfink]

Thanks, that was it.

I tried to implement the changes to the ithc module that @quo outlined in the linked issue (see https://github.com/quo/ithc-linux/compare/master...christophfink:ithc-linux:wait-for-pstate ), as I’d prefer to boot from an EFISTUB, directly, but that did not work.

Using a bootloader (systemd-boot in my case) solved the issue, completely.

[quo]

That's interesting. It suggests EFISTUB is doing something that breaks the DMA transfers. The weird thing is that the PRD DMA seems to work fine (since size = 1360, which is read from the PRDs), but then the actual data is just zeroes.

Can you post your dmesg with the retry-loop around hid_add_device?

Also, can you try adding the kernel parameter efi=no_disable_early_pci_dma and then booting with EFISTUB? I doubt it'll make a difference, but it's the only EFISTUB/DMA option I can find.

When I have some more time I'll try to reproduce this on my SP7+.

[christophfink]

I’m travelling, and left my SP9 at home (it still has other issues that I want to resolve before using it for anything serious). I’ll try once I return, probably not before the weekend. Thanks for this!

[morocz]

I have the same issue with the touch on an SP9 I use the latest kernel from pkg.surfacelinux.com (6.4.7) under Fedora 38 workstation, and the ithc module compiled from the latest repo [0b8b45d] The system is loaded by shim/grub 2.06

• if the 'GRUB_TIMEOUT' set to 0 (zero) the ithc module is unable to init the touch finally with 'invalid dma rx data ...' error
• if the 'GRUB_TIMEOUT' set to greater than zero ( 1 .. 5 ) the ithc module successfully inits the touch, and it works perfectly

when the grub menu pops up (because the timeout is greater than zero) it brings up the EFIs touch on screen keyboard, so the touch subsystem get initalized, maybe it makes some unknown initalisation which permits the successful init of the itch driver.

delay0_dmesg.txt delay1_dmesg.txt

how can i help the further investigation

[quo]

Can you try booting with the ithc.logregs parameter? That should generate a lot of extra "reg ...: ... -> ..." logging in dmesg.

If you post the dmesgs from a working and a non-working boot with that logging, we should be able to see if the problem is due to some THC register.

[morocz]

I made the test again d0_dmesg.txt d1_dmesg.txt

The init sequence is different as i see

I have to redo the test with the ithc module compiled from source (its made with the packaged version from pkg.surfacelinux.com /fedora /f38 ...)

[morocz]

The ithc logs with "logregs dyndbg=+pflmt", the module built from latest sources

d0_dmesg.txt d1_dmesg.txt

[quo]

Thanks! The only interesting difference seems to be that bit 5 is set in reg 0x1128 in the d1 logs. This bit doesn't seem to have an effect on my SP7+, but maybe it needs to be set on newer devices.

Could you try the following patch:

diff --git a/src/ithc-main.c b/src/ithc-main.c
index 87ed4aa..896752d 100644
--- a/src/ithc-main.c
+++ b/src/ithc-main.c
@@ -442,6 +442,7 @@ static int ithc_init_device(struct ithc *ithc)

    // Setting the following bit seems to make reading the config more reliable.
    bitsl_set(&ithc->regs->dma_rx[0].unknown_init_bits, 0x80000000);
+   bitsl_set(&ithc->regs->dma_rx[0].unknown_init_bits, 0x20);

    // If the device was previously enabled, wait a bit to make sure it's fully shut down.
    if (was_enabled)

[quo]

Hopefully fixed by 18afc6f. Please reopen if the problem still occurs with latest ithc.