Re: How to proceed: usci_acpi: PPM init failed (-110)

["Samuel Čavoj" <samuel@cavoj.net>]

Hi

sorry about the delay.

On 2022-01-24 10:23, Heikki Krogerus wrote:
> On Sat, Jan 22, 2022 at 12:21:29AM +0000, Samuel Čavoj wrote:
>> Hi Heikki,
>> 
>> do you think we could get this back on track somehow? I'm not sure 
>> what to
>> try next, do you have any ideas? Are there any tools to try and trace 
>> what
>> the Windows driver does? Either from within Windows itself or 
>> intercept it
>> somehow externally -- a hypervisor approach? Are there any tools 
>> developed
>> for this purpose? I wasn't really able to find much.
> 
> I don't have any ideas right now, but I'll try to think of something
> that we could try. I'll also see if I can get my hands on one of those
> Asus Zenbook laptops. It was a Zenbook 13, right?

Yup, it's a Zenbook 13 OLED (UM325).

> 
> Did you try to see what happens if you don't reset the "PPM"?

No difference, as far as I can tell. I used the patch below to
get more output. This is right after boot, in the initramfs:

[    0.787887] ucsi_acpi USBC000:00: hi ucsi here
[    0.787893] ucsi_acpi USBC000:00: skipping reset
[    0.787894] ucsi_acpi USBC000:00: enable basic notifications
[    0.813169] ucsi_acpi USBC000:00: got notification:
[    0.814386] ucsi_acpi USBC000:00:     checking ua->flags: 2, cci: 0
[    1.859334] ucsi_acpi USBC000:00: PPM init failed (-110)

Same output after cold boot, reboot from linux and reboot from windows.

Thanks,
Samuel

diff --git a/drivers/usb/typec/ucsi/ucsi.c 
b/drivers/usb/typec/ucsi/ucsi.c
index 08561bf7c40c..f1880bdaa9f6 100644
--- a/drivers/usb/typec/ucsi/ucsi.c
+++ b/drivers/usb/typec/ucsi/ucsi.c
@@ -1185,25 +1185,34 @@ static int ucsi_init(struct ucsi *ucsi)
  	int ret;
  	int i;

+	dev_info(ucsi->dev, "hi ucsi here");
  	/* Reset the PPM */
+	dev_warn(ucsi->dev, "skipping reset");
+	/*
  	ret = ucsi_reset_ppm(ucsi);
  	if (ret) {
  		dev_err(ucsi->dev, "failed to reset PPM!\n");
  		goto err;
  	}
+	dev_info(ucsi->dev, "reset ok");
+	*/

  	/* Enable basic notifications */
  	ucsi->ntfy = UCSI_ENABLE_NTFY_CMD_COMPLETE | UCSI_ENABLE_NTFY_ERROR;
  	command = UCSI_SET_NOTIFICATION_ENABLE | ucsi->ntfy;
+	dev_info(ucsi->dev, "enable basic notifications");
  	ret = ucsi_send_command(ucsi, command, NULL, 0);
  	if (ret < 0)
  		goto err_reset;
+	dev_info(ucsi->dev, "done enable basic notifications");

  	/* Get PPM capabilities */
  	command = UCSI_GET_CAPABILITY;
+	dev_info(ucsi->dev, "get capabilities");
  	ret = ucsi_send_command(ucsi, command, &ucsi->cap, sizeof(ucsi->cap));
  	if (ret < 0)
  		goto err_reset;
+	dev_info(ucsi->dev, "done get capabilities");

  	if (!ucsi->cap.num_connectors) {
  		ret = -ENODEV;
@@ -1228,9 +1237,11 @@ static int ucsi_init(struct ucsi *ucsi)
  	/* Enable all notifications */
  	ucsi->ntfy = UCSI_ENABLE_NTFY_ALL;
  	command = UCSI_SET_NOTIFICATION_ENABLE | ucsi->ntfy;
+	dev_info(ucsi->dev, "enable all notifications");
  	ret = ucsi_send_command(ucsi, command, NULL, 0);
  	if (ret < 0)
  		goto err_unregister;
+	dev_info(ucsi->dev, "done enable all notifications");

  	return 0;

diff --git a/drivers/usb/typec/ucsi/ucsi_acpi.c 
b/drivers/usb/typec/ucsi/ucsi_acpi.c
index 6771f05e32c2..765c89594c41 100644
--- a/drivers/usb/typec/ucsi/ucsi_acpi.c
+++ b/drivers/usb/typec/ucsi/ucsi_acpi.c
@@ -98,6 +98,7 @@ static void ucsi_acpi_notify(acpi_handle handle, u32 
event, void *data)
  	struct ucsi_acpi *ua = data;
  	u32 cci;
  	int ret;
+	dev_info(ua->dev, "got notification:\n");

  	ret = ucsi_acpi_read(ua->ucsi, UCSI_CCI, &cci, sizeof(cci));
  	if (ret)
@@ -106,9 +107,13 @@ static void ucsi_acpi_notify(acpi_handle handle, 
u32 event, void *data)
  	if (UCSI_CCI_CONNECTOR(cci))
  		ucsi_connector_change(ua->ucsi, UCSI_CCI_CONNECTOR(cci));

+	dev_info(ua->dev, "    checking ua->flags: %ld, cci: %d\n", ua->flags, 
cci);
  	if (test_bit(COMMAND_PENDING, &ua->flags) &&
-	    cci & (UCSI_CCI_ACK_COMPLETE | UCSI_CCI_COMMAND_COMPLETE))
+	    cci & (UCSI_CCI_ACK_COMPLETE | UCSI_CCI_COMMAND_COMPLETE)) {
+
+		dev_warn(ua->dev, "    complete\n");
  		complete(&ua->complete);
+	}
  }

  static int ucsi_acpi_probe(struct platform_device *pdev)

> 
> diff --git a/drivers/usb/typec/ucsi/ucsi.c 
> b/drivers/usb/typec/ucsi/ucsi.c
> index f0c2fa19f3e0f..6e93ef0cbe006 100644
> --- a/drivers/usb/typec/ucsi/ucsi.c
> +++ b/drivers/usb/typec/ucsi/ucsi.c
> @@ -1199,13 +1199,6 @@ static int ucsi_init(struct ucsi *ucsi)
>         int ret;
>         int i;
> 
> -       /* Reset the PPM */
> -       ret = ucsi_reset_ppm(ucsi);
> -       if (ret) {
> -               dev_err(ucsi->dev, "failed to reset PPM!\n");
> -               goto err;
> -       }
> -
>         /* Enable basic notifications */
>         ucsi->ntfy = UCSI_ENABLE_NTFY_CMD_COMPLETE | 
> UCSI_ENABLE_NTFY_ERROR;
>         command = UCSI_SET_NOTIFICATION_ENABLE | ucsi->ntfy;
> 
> thanks,
> 
>> On 2021-08-26 12:41, Samuel Čavoj wrote:
>> > Hello,
>> >
>> > On 26.08.2021 10:53, Heikki Krogerus wrote:
>> > > Hi Samuel,
>> > >
>> > > >
>> > > > the command finishes instantly and does not seem to produce any error.
>> > > >
>> > > >     PS C:\Program Files (x86)\USBTest\x64> .\UcsiControl.exe Send 0 00010005
>> > > >     COMMAND:
>> > > >     AsUInt64: 10005
>> > > >     Command: 5
>> > > >     DataLength: 0
>> > > >
>> > > >     MESSAGE IN is empty.
>> > >
>> > > Thanks for testing that. So UCSI is definitely working on this
>> > > platform. I guess the ACPI notifications are simply not going through.
>> > >
>> > > Can you check if there are any events coming from the EC with the
>> > > following commands:
>> > >
>> > >         % modprobe -r ucsi_acpi
>> > >         % modprobe -r typec_ucsi
>> > >         % grep -i acpi /proc/interrupts
>> > >         ...
>> > >         % modprobe typec_ucsi
>> > >         % modprobe ucsi_acpi
>> > >         % grep -i acpi /proc/interrupts
>> > >         ...
>> > >
>> > > See if the number of interrupts increases considerable, or at all. The
>> > > ucsi drivers need to be modules of course in order for that to work.
>> >
>> > I made four snapshots of the (filtered) /proc/interrupts file:
>> >
>> >     1. with the modules loaded normally
>> >     2. right after unloading them
>> >     3. right after loading them again
>> >     4. after the timeout expires and the init failed message is logged
>> >
>> > Files 3 and 4 are identical. Between 1--2 and 2--3, IRQ 9 increases by
>> > exactly 1 each time. The IRQ is described as "IR-IO-APIC 9-fasteoi
>> > acpi".
>> > Here is the line in question from each of the files.
>> >
>> >             CPU0       CPU1       CPU2       CPU3       CPU4
>> > CPU5       CPU6       CPU7       CPU8       CPU9       CPU10
>> > CPU11      CPU12      CPU13      CPU14      CPU15
>> >    9:          0         52          0          0          0
>> > 0          0          0          0          0          0          0
>> >       0          0          0          0  IR-IO-APIC    9-fasteoi
>> > acpi
>> >    9:          0         53          0          0          0
>> > 0          0          0          0          0          0          0
>> >       0          0          0          0  IR-IO-APIC    9-fasteoi
>> > acpi
>> >    9:          0         54          0          0          0
>> > 0          0          0          0          0          0          0
>> >       0          0          0          0  IR-IO-APIC    9-fasteoi
>> > acpi
>> >    9:          0         54          0          0          0
>> > 0          0          0          0          0          0          0
>> >       0          0          0          0  IR-IO-APIC    9-fasteoi
>> > acpi
>> >
>> > To make it clear what I did in the first place, is to add a dev_err line
>> > in the error branch right after "Enable basic notifications" in
>> > ucsi_init. The line does get printed.
>> >
>> > My understanding is that the PPM is completely quiet during the reset
>> > procedure, and therefore the single notifications received should be the
>> > completion notification for the "enable basic notifications" command.
>> >
>> > I added a debug print to ucsi_acpi_notify, to see if the interrupt is
>> > getting routed correctly at all (I suspected the ACPI might be
>> > generating notifications for a different device). Another debug print
>> > was added to ucsi_init right after the reset completes.
>> >
>> > This is a snippet from ucsi_acpi_notify showing added printouts:
>> >
>> >     dev_err(ua->dev, "checking ua->flags: %ld, cci: %d\n", ua->flags,
>> > cci);
>> > 	if (test_bit(COMMAND_PENDING, &ua->flags) &&
>> > 	    cci & (UCSI_CCI_ACK_COMPLETE | UCSI_CCI_COMMAND_COMPLETE)) {
>> >
>> >         dev_err(ua->dev, "complete\n");
>> > 		complete(&ua->complete);
>> >     }
>> >
>> > Indeed, ucsi_acpi_notify gets called once when the module loads, after
>> > the reset procedure is completed (as long as the ordering of the
>> > messages in dmesg is good enough to tell, they are 20ms apart).
>> > This is the output in dmesg: (i shortened the timeout to 5s).
>> >
>> >     [ 1397.741701] ucsi_acpi USBC000:00: PPM reset succeeded
>> >     [ 1397.761319] ucsi_acpi USBC000:00: checking ua->flags: 2, cci: 0
>> >     [ 1402.941808] ucsi_acpi USBC000:00: failed to enable basic
>> > notifications
>> >     [ 1402.989510] ucsi_acpi USBC000:00: PPM init failed (-110)
>> >
>> > The completion condition is not satisfied and "complete" is not
>> > printed. Possibly the firmware has some quirk, a cci of 0 seems wrong to
>> > me.
>> >
>> > > Maybe there is something special that the OS should do with the EC on
>> >
>> > I suppose either that, or the PPM deviates from the spec. I don't know
>> > how to go about tracing what Windows does, but that would be a way to
>> > go.
>> >
>> > > your board... There is a weird message in your dmesg.
>> > >
>> > >         "ACPI: EC: interrupt blocked"
>> > >
>> > > I don't know if it's relevant at all in this case, but I've just never
>> > > seen that. I'm not an EC or ACPI expert, but I think that you only see
>> > > that if the EC event interrupt is a GPIO. I would expect there to be
>> > > also a message:
>> > >
>> > >         "ACPI: EC: interrupt unblocked"
>> >
>> > There is such a message in the log, on line 475. Also on every suspend,
>> > the interrupt is blocked before going to sleep and unblocked when waking
>> > up, which makes sense.
>> >
>> > > But as said, I'm really not an EC expert. We probable need to ask the
>> > > ACPI guys about this, but let's first check the interrupts.
>> > >
>> > > thanks,
>> > >
>> > > --
>> > > heikki
>> >
>> > Thank you very much for helping me with this.
>> >
>> > Regards,
>> > Samuel