Openpilot: Sensors Init Failure -- $1000 Bounty

Created on 19 Feb 2020  路  9Comments  路  Source: commaai/openpilot

After some reboots, the gyro does not initialize correctly, forcing the user to reboot to get the gyro back. Seems to affect the LeEco more than the OnePlus.

The alert this will fix is "No Data from Device Sensors" "Reboot your Device"

$1000 for a description of the root cause and merged pull request that fixes this issue.

bounty bug

Most helpful comment

I wrote a cheese-tastic boot-looping script, using the sensord test from leeco_selftest.sh together with a slightly modified version of sensord (necessary to avoid it bus-erroring on startup with nothing else running, maybe that stopped working after the move to msgq?).

After 339 reboots I have a LeEco EON booted in this no-sensor state sitting on my desk. In the affected state, no sensors at all are available, zero out of 40.

Trawling through the kernel message ring, it appears the Qualcomm SLPI (Sensor Low Power Island) gets firmware copied to it by the Peripheral Image Loader, it gets brought out of reset, then we expect an interrupt to signal its error monitoring/handling service is up, but it never arrives.

Good:

[   10.800885] subsys-pil-tz 9300000.qcom,lpass: adsp: loading from 0x000000008ea00000 to 0x0000000090400000
[   11.249226] subsys-pil-tz 9300000.qcom,lpass: adsp: Brought out of reset
[   11.268057] subsys-pil-tz 9300000.qcom,lpass: Subsystem error monitoring/handling services are up
[   11.268141] subsys-pil-tz 9300000.qcom,lpass: adsp: Power/Clock ready interrupt received
[   11.272060] subsys-pil-tz 1c00000.qcom,ssc: slpi: loading from 0x0000000090400000 to 0x0000000090e00000
[   11.505973] subsys-pil-tz 1c00000.qcom,ssc: slpi: Brought out of reset
[   11.557240] subsys-pil-tz 1c00000.qcom,ssc: Subsystem error monitoring/handling services are up
[   11.557269] subsys-pil-tz 1c00000.qcom,ssc: slpi: Power/Clock ready interrupt received
[   11.557709] sensors-ssc soc:qcom,msm-ssc-sensors: slpi_loader_do: SLPI image is loaded

Bad:

[   10.966730] subsys-pil-tz 9300000.qcom,lpass: adsp: loading from 0x000000008ea00000 to 0x0000000090400000
[   11.322297] subsys-pil-tz 9300000.qcom,lpass: adsp: Brought out of reset
[   11.341520] subsys-pil-tz 9300000.qcom,lpass: Subsystem error monitoring/handling services are up
[   11.341594] subsys-pil-tz 9300000.qcom,lpass: adsp: Power/Clock ready interrupt received
[   11.354393] subsys-pil-tz 1c00000.qcom,ssc: slpi: loading from 0x0000000090400000 to 0x0000000090e00000
[   11.697420] subsys-pil-tz 1c00000.qcom,ssc: slpi: Brought out of reset
[   21.703181] subsys-restart: wait_for_err_ready(): [slpi]: Error ready timed out
[   21.720827] sensors-ssc soc:qcom,msm-ssc-sensors: slpi_loader_do: pil get failed,
[   21.727324] sensors-ssc soc:qcom,msm-ssc-sensors: slpi_loader_do: SLPI image loading failed

In the bad case, we schedule a timer to wait for an interrupt signaling the SLPI error monitor is up, and we fall through to the 10 second timeout.

https://github.com/commaai/android_kernel_comma_msm8996/blob/c7420118c6633b6def876b6896ea71e6a9ee34a4/drivers/soc/qcom/subsystem_restart.c#L577-L592

In the good case, the interrupt does arrive, and it only takes 52ms in the log above, so the 10 second timeout does seem exceedingly lenient, no use in extending it.

https://github.com/commaai/android_kernel_comma_msm8996/blob/c7420118c6633b6def876b6896ea71e6a9ee34a4/drivers/soc/qcom/subsystem_restart.c#L1244-L1255

What Next?

I will see about making my boot-loop testing script slightly less cheese-tastic, and have it call the Spinner to visually show what's happening, so you can turn it loose on your testing closet.

If you accept as good-enough the root cause statement "SLPI failed to init" with a solution of "reboot", this condition is pretty easy to check and mitigate. I can produce a PR that runs a sensor validation very early in the boot process and reboots if necessary. We'd probably limit it to two or three consecutive reboots just to avoid loop-bricking if the check runs into an unexpected problem.

It looks like we're running Android userland within 12-22 seconds of power-on, depending on whether we hit this 10-second timeout condition. If my 339 reboots-to-repro case is representative, then we have about an 0.3% chance of needing to reboot once, and an 0.001% chance of needing to reboot twice, at a cost of ~22 seconds each (10 for the timeout, 12 for the next probably-successful kernel boot). Doesn't seem too horrible.

If you want me (or anyone else) to get deeper on root cause, we'll need to discuss some way for me to do kernel/NEOS rebuilds here. The Comma modified kernel does some unusual things with interrupt routing and pinning, and repeating the test case with that stuff rolled back to vendor default is the very first thing I'd want to try.

dmesg_sensors_okay.txt
logcat_sensors_okay.txt

dmesg_sensors_bad.txt
logcat_sensors_bad.txt

bad-vs-good-dmesg-snippet.txt
sensord-test-bad-logcat-snippet.txt

All 9 comments

Hi, I think this has to do with a faulty Qualcomm firmware on the LeEco (Le Pro 3, the one in the EON) (faulty firmware on the SD 821 to be specific), When the Gyro doesn't initialize are there instances where other sensors don't initialize aswell? (such as the accelerometer), This might just require you to flash a recent firmware via Qfil. I could be completely wrong on this as I'm still a freshman at uni, but it could be worth a try. 馃槄

Do you have more information on this? Which firmware version is broken? Where is the new firmware?

A lot have used the Method below to "Un-brick" their phones, But many forums also suggest that having done this has fixed their Sensor Issues as well.

Link to the QFIL image file and QFIL itself:
https://forum.xda-developers.com/le-pro3/how-to/unbrick-leeco-phones-leeco-variants-t3847220
https://forum.xda-developers.com/le-pro3/leeco-le-pro-3-elite-model-x722-guides-development--and-mods/qfil-x722-t3846553
https://forum.xda-developers.com/le-pro3/help/leeco-pro3-x720-sensors-problem-t3753165

Some have also suggested modifications in the Persists folders with regards to Sensors:
https://forum.xda-developers.com/oneplus-3t/how-to/fix-sensors-stopped-t3630854
https://forum.xda-developers.com/xiaomi-redmi-5a/how-to/guide-restoring-persist-partition-to-t3906424
https://drive.google.com/file/d/1ZgaWydW4c7Eo5vuRw_Vhc6EVmBFThNV2/view

You could look into both,(I think the Second one is realistically the actual issue), As I've experienced a similar issue last yr on my "Redmi note 3' (Kate) and the method above got my Wifi working again. Hopefully, it's of some help.

I wrote a cheese-tastic boot-looping script, using the sensord test from leeco_selftest.sh together with a slightly modified version of sensord (necessary to avoid it bus-erroring on startup with nothing else running, maybe that stopped working after the move to msgq?).

After 339 reboots I have a LeEco EON booted in this no-sensor state sitting on my desk. In the affected state, no sensors at all are available, zero out of 40.

Trawling through the kernel message ring, it appears the Qualcomm SLPI (Sensor Low Power Island) gets firmware copied to it by the Peripheral Image Loader, it gets brought out of reset, then we expect an interrupt to signal its error monitoring/handling service is up, but it never arrives.

Good:

[   10.800885] subsys-pil-tz 9300000.qcom,lpass: adsp: loading from 0x000000008ea00000 to 0x0000000090400000
[   11.249226] subsys-pil-tz 9300000.qcom,lpass: adsp: Brought out of reset
[   11.268057] subsys-pil-tz 9300000.qcom,lpass: Subsystem error monitoring/handling services are up
[   11.268141] subsys-pil-tz 9300000.qcom,lpass: adsp: Power/Clock ready interrupt received
[   11.272060] subsys-pil-tz 1c00000.qcom,ssc: slpi: loading from 0x0000000090400000 to 0x0000000090e00000
[   11.505973] subsys-pil-tz 1c00000.qcom,ssc: slpi: Brought out of reset
[   11.557240] subsys-pil-tz 1c00000.qcom,ssc: Subsystem error monitoring/handling services are up
[   11.557269] subsys-pil-tz 1c00000.qcom,ssc: slpi: Power/Clock ready interrupt received
[   11.557709] sensors-ssc soc:qcom,msm-ssc-sensors: slpi_loader_do: SLPI image is loaded

Bad:

[   10.966730] subsys-pil-tz 9300000.qcom,lpass: adsp: loading from 0x000000008ea00000 to 0x0000000090400000
[   11.322297] subsys-pil-tz 9300000.qcom,lpass: adsp: Brought out of reset
[   11.341520] subsys-pil-tz 9300000.qcom,lpass: Subsystem error monitoring/handling services are up
[   11.341594] subsys-pil-tz 9300000.qcom,lpass: adsp: Power/Clock ready interrupt received
[   11.354393] subsys-pil-tz 1c00000.qcom,ssc: slpi: loading from 0x0000000090400000 to 0x0000000090e00000
[   11.697420] subsys-pil-tz 1c00000.qcom,ssc: slpi: Brought out of reset
[   21.703181] subsys-restart: wait_for_err_ready(): [slpi]: Error ready timed out
[   21.720827] sensors-ssc soc:qcom,msm-ssc-sensors: slpi_loader_do: pil get failed,
[   21.727324] sensors-ssc soc:qcom,msm-ssc-sensors: slpi_loader_do: SLPI image loading failed

In the bad case, we schedule a timer to wait for an interrupt signaling the SLPI error monitor is up, and we fall through to the 10 second timeout.

https://github.com/commaai/android_kernel_comma_msm8996/blob/c7420118c6633b6def876b6896ea71e6a9ee34a4/drivers/soc/qcom/subsystem_restart.c#L577-L592

In the good case, the interrupt does arrive, and it only takes 52ms in the log above, so the 10 second timeout does seem exceedingly lenient, no use in extending it.

https://github.com/commaai/android_kernel_comma_msm8996/blob/c7420118c6633b6def876b6896ea71e6a9ee34a4/drivers/soc/qcom/subsystem_restart.c#L1244-L1255

What Next?

I will see about making my boot-loop testing script slightly less cheese-tastic, and have it call the Spinner to visually show what's happening, so you can turn it loose on your testing closet.

If you accept as good-enough the root cause statement "SLPI failed to init" with a solution of "reboot", this condition is pretty easy to check and mitigate. I can produce a PR that runs a sensor validation very early in the boot process and reboots if necessary. We'd probably limit it to two or three consecutive reboots just to avoid loop-bricking if the check runs into an unexpected problem.

It looks like we're running Android userland within 12-22 seconds of power-on, depending on whether we hit this 10-second timeout condition. If my 339 reboots-to-repro case is representative, then we have about an 0.3% chance of needing to reboot once, and an 0.001% chance of needing to reboot twice, at a cost of ~22 seconds each (10 for the timeout, 12 for the next probably-successful kernel boot). Doesn't seem too horrible.

If you want me (or anyone else) to get deeper on root cause, we'll need to discuss some way for me to do kernel/NEOS rebuilds here. The Comma modified kernel does some unusual things with interrupt routing and pinning, and repeating the test case with that stuff rolled back to vendor default is the very first thing I'd want to try.

dmesg_sensors_okay.txt
logcat_sensors_okay.txt

dmesg_sensors_bad.txt
logcat_sensors_bad.txt

bad-vs-good-dmesg-snippet.txt
sensord-test-bad-logcat-snippet.txt

I managed to get this to throw after booting up while repeatedly switching from off to accessory mode (which counts as ignition signal on my vehicle, activating the camera/carstate/etc). Perhaps it is creating a lock on a file which isn't properly removed if openpilot starts enabling itself before it's done disabling?
Well, I'm not too sure about the specifics, but it seems this can happen at runtime, not just during boot.

The aforementioned slightly less cheese-tastic testing script has been submitted as #1303. I have it running on my three devices, which are all LeEcos, I don't have any OP3Ts here at the house. We'll see how it does over the next couple days, but it's already caught one failure almost immediately.

@pd0wm, I'll be interested to know how the script does in the testing closet. Your new text display tool was very useful for this and I expect it'll be useful for other things in the future. Per our discussion I'm now working on getting kernel/NEOS builds running, thanks again for reopening the builder repo.

@AskAlice, re: your experience, I can certainly believe that's possible, but ISTM it would be a second and fully separate failure mode. The failure I'm chasing would definitely persist from the time the device boots in the bad state until it's rebooted again. For your case though...

  • Is your failure repeatable or has it only happened once?
  • Was the ignition cycled very rapidly? (less than, say, 3 seconds off)
  • Did it recover with another ignition cycle, without rebooting?

I must confess I'm not sure what happens if you go through an ignition on>off>on cycle faster than OP/manager can complete its usual shutdown, but I do know manager already has to take special measures to kill sensord at ignition off, so there could easily be another gremlin hiding there.

I've had all three of my units (two LeEco EONs and a C2) running this for about ten hours and have produced a number of failures:

EON 1: 766/5
EON 2: 811/12
C2: 767/1

Sums up to a sub-0.8% failure rate, but there's enough spread accumulating between these units to wonder if some are more or less susceptible. Need to see a larger sample set though.

This morning I added instrumentation to the test script for taking dmesg/logcat logs on failure, and the three faults accumulated on EON 2 since then all have the same SLPI failed to init signature. So, I feel confident we're chasing the right thing, or at least one of the right things.

root@localhost:/tmp$ grep "slpi" dmesg-*.log
dmesg-1585757335.log:[   11.810822] subsys-pil-tz 1c00000.qcom,ssc: slpi: loading from 0x0000000090400000 to 0x0000000090e00000
dmesg-1585757335.log:[   12.139120] subsys-pil-tz 1c00000.qcom,ssc: slpi: Brought out of reset
dmesg-1585757335.log:[   22.140552] subsys-restart: wait_for_err_ready(): [slpi]: Error ready timed out
dmesg-1585757335.log:[   22.159569] sensors-ssc soc:qcom,msm-ssc-sensors: slpi_loader_do: pil get failed,
dmesg-1585757335.log:[   22.166048] sensors-ssc soc:qcom,msm-ssc-sensors: slpi_loader_do: SLPI image loading failed
dmesg-1585758500.log:[   11.784436] subsys-pil-tz 1c00000.qcom,ssc: slpi: loading from 0x0000000090400000 to 0x0000000090e00000
dmesg-1585758500.log:[   12.128060] subsys-pil-tz 1c00000.qcom,ssc: slpi: Brought out of reset
dmesg-1585758500.log:[   22.129922] subsys-restart: wait_for_err_ready(): [slpi]: Error ready timed out
dmesg-1585758500.log:[   22.148502] sensors-ssc soc:qcom,msm-ssc-sensors: slpi_loader_do: pil get failed,
dmesg-1585758500.log:[   22.155011] sensors-ssc soc:qcom,msm-ssc-sensors: slpi_loader_do: SLPI image loading failed
dmesg-1585760103.log:[   11.734410] subsys-pil-tz 1c00000.qcom,ssc: slpi: loading from 0x0000000090400000 to 0x0000000090e00000
dmesg-1585760103.log:[   12.076898] subsys-pil-tz 1c00000.qcom,ssc: slpi: Brought out of reset
dmesg-1585760103.log:[   22.082199] subsys-restart: wait_for_err_ready(): [slpi]: Error ready timed out
dmesg-1585760103.log:[   22.099810] sensors-ssc soc:qcom,msm-ssc-sensors: slpi_loader_do: pil get failed,
dmesg-1585760103.log:[   22.106323] sensors-ssc soc:qcom,msm-ssc-sensors: slpi_loader_do: SLPI image loading failed

I believe I have the fix in commaai/android_device_oneplus_oneplus3#1. Naturally the proposed fix needs to be burned-in awhile on the Comma testing closet, particularly on OP3T because I don't have one here.

20200511_104019

Free bonus: the Comma Two at the top of this picture is one that was RMAd for the "30 sensor issue" (as opposed to the usual 40), which I believe is something you're catching in QA now. I'd like to see it work on a few more QA rejects before declaring victory over that, but if it turns out that traces back to the same software/timing issue, reports of their demise may have been greatly exaggerated...

Thanks! Think this issue can be closed now :)

Was this page helpful?
0 / 5 - 0 ratings

Related issues

midfield99 picture midfield99  路  3Comments

hlezki picture hlezki  路  3Comments

noperdd picture noperdd  路  4Comments

cydia2020 picture cydia2020  路  7Comments

ShaneSmiskol picture ShaneSmiskol  路  4Comments