Hikey960 4GB RAM board AOSP + OPTEE booting issue

[dvyurij]

Hi. I’m trying to use AOSP + OPTEE

My board is hikey960 with 4GB RAM and host machine is VMware Linux Ubuntu 18.04.1

But I couldn’t boot well though there’s NO ERROR log in my process.
I’m stuck in here for a week. Please help me if you know.

First, here are my rough processes

1. clone optee android git master (3.6.1) branch
   git clone https://github.com/linaro-swg/optee_android_manifest

2. sync and build
   ./sync-p-hikey960.sh
   ./build-p-hikey960.sh

3. copy image files and flash using fastboot
   cp -a out/target/product/hikey960/*.img device/linaro/hikey/installer/hikey960/
   sudo ./device/linaro/hikey/installer/hikey960/flash-all.sh /dev/ttyUSBn

(this command MUST have run under optee_android_manifest directory and it drove me crazy.)

hikey960 normal boot UART logs after finished fastboot flashing (selected critical part to my thought)

==================================================================
Press ESCAPE for boot options .EFI stub: Booting Linux Kernel…
EFI stub: EFI_RNG_PROTOCOL unavailable, no randomness supplied
EFI stub: Using DTB from configuration table
Failed to handle fs_proto
EFI stub: ERROR: Failed initrd from command line!
EFI stub: Exiting boot services and installing virtual address map…
D/TC:1 generic_boot_cpu_on_handler:1148 cpu 1: a0 0x0
D/TC:1 init_secondary_helper:1133 Secondary CPU Switching to normal world boot
D/TC:2 generic_boot_cpu_on_handler:1148 cpu 2: a0 0x0
D/TC:2 init_secondary_helper:1133 Secondary CPU Switching to normal world boot
D/TC:3 generic_boot_cpu_on_handler:1148 cpu 3: a0 0x0
D/TC:3 init_secondary_helper:1133 Secondary CPU Switching to normal world boot
D/TC:4 generic_boot_cpu_on_handler:1148 cpu 4: a0 0x0
D/TC:4 select_vector:909 SMCCC_ARCH_WORKAROUND_1 (0x80008000) available
D/TC:4 select_vector:910 SMC Workaround for CVE-2017-5715 used
D/TC:4 init_secondary_helper:1133 Secondary CPU Switching to normal world boot
D/TC:5 generic_boot_cpu_on_handler:1148 cpu 5: a0 0x0

====================================================================

…

====================================================================

[ 13.859513] init: SVC_EXEC pid 2434 (uid 0 gid 0+1 context default) started; waiting…
[ 13.868120] init: Service ‘tee-supplicant’ (pid 2431) exited with status 0
D/TC:? 0 tee_ta_init_pseudo_ta_session:280 Lookup pseudo TA dba51a17-0563-11e7[ 13.8a052871wait_for_keymaster_optee: Waiting for Keymaster device
D/TC:? 0 load_ldelf:707 ldelf load address 0x40006000
D/LD: ldelf:134 Loading TA dba51a17-0563-11e7-93b1-6fa7b0071a51
D/TC:? 0 tee_ta_init_pseudo_ta_session:280 Lookup pseudo TA 3a2f8978-5dc0-11e8-9c2d-fa7ae01bbebc
[ 13.922643] init: Received control message ‘interface_start’ for ‘android.hardware.keymaster@3.0::IKeymasterDevice/default’ from pid: 2421 (/system/bin/hwservicemanager)
D/TC:? 0 tee_ta_init_pseudo_ta_session:293 Open system.pta
D/TC:? 0 tee_ta_init_pseudo_ta_session:307 system.pta : 3a2f8978-5dc0-11e8-9c2d-fa7ae01bbebc
D/TC:? 0 system_open_ta_binary:239 Lookup user TA ELF dba51a17-0563-11e[ 11.952873]7in5t: Raceived control message ‘interface_start’ for ‘android.hardware.keymaster@3.0::IKeymasterDevice/default’ from pid: 2421 (/system/bin/hwservicemanager)
D/TC:? 0 system_open_ta_binary:242 res=0xffff0008
D/TC:? 0 system_open_ta_binary:239 Lookup user TA ELF dba51a17-0563-11e7-93b1-6fa7b0071a51 (Secure Storage TA)
D/TC:? 0 system_open_ta_binary:242 res=0xf0100003
D/TC:? 0 system_open_ta_binary:239 Lookup user TA ELF dba51a17-0563-11e7-93b1-6fa7b0071a51 (REE [buffered])
D/TC:? 0 system_open_ta_binary:242 res=0x0
D/LD: ldelf:169 ELF (dba51a17-0563-11e7-93b1-6fa7b0071a51) at 0x40035000
D/TC:? 0 tee_ta_close_session:498 csess 0x3f0a22e0 id 1
D/TC:? 0 tee_ta_close_session:517 Destroy session
D/TA: TA_CreateEntryPoint:50 TA_CreateEntryPoint 50
D/TA: TA_create_secret_key:98 TA_create_secret_key 98
E/TA: TA_create_secret_key:140 Failed to open secret key, res=f0100003
E/TA: TA_CreateEntryPoint:56 Something wrong with secret key (f0100003)
D/TC:? 0 tee_ta_close_session:498 csess 0x3f0a2b00 id 1
D/TC:? 0 tee_ta_close_session:517 Destroy session
D/TC:? 0 destroy_context:297 Destroy TA ctx (0x3f0a2aa0)
E/TC:? 0 tee_ta_open_session:727 Failed. Return error 0xf0100003
[ 14.923453] ServiceManagement: Waited one second for android.hardware.keymaster@3.0::IKeymasterDevice/default. Waiting another…
[ 15.938679] ServiceManagement: Waited one second for android.hardware.keymaster@3.0::IKeymasterDevice/default. Waiting another…

=====================================================================

I think “Failed to handle fs_proto” is the problem but I can’t solve

“ServiceManagement: Waited one second for android.hardware.keymaster@3.0::IKeymasterDevice/default. Waiting another…” prints repeatedly below and I’m stuck in here.

I have full log file but I can’t attach due to 32000 character limit
Please tell me if you want to see some part or full log

[ric96]

can you use pastebin.com to provide full log?

[dvyurij]

hikey960 master(3.6.1) logs

hikey960 master (3.6.1) - Pastebin.com

hikey960 3.4.2 logs
3.4.1 is mistype. these are 3.4.2 logs

hikey960 3.4.1 - Pastebin.com

I’ve tried 3.4.2 branch following this link but occurred another booting issue

OPTEE 3.6.x & AOSP not finishing boot

Hi! I downloaded and compiled AOSP & OPTEE 3.6.2 “git clone https://github.com/linaro-swg/optee_android_manifest -b 3.6.2” (first tried 3.6.2, then 3.6.1 - result is the same) After doing flash-all.sh I can see over HiKey960 UART that it boots and then gets stuck. Just every second prints out this: [ 23.687303] ServiceManagement: Waited one second for android.hardware.keymaster@3.0::IKeymasterDevice/default. Waiting another… No UI over HDMI. No USB device for ADB. No console over UART (by…

[vchong]

Remove exec_start wait_for_keymaster_optee from device/linaro/hikey/init.common.rc and rebuild. Or try the master branch.

What’s the booting issue with the 3.4.2 branch? Can’t really tell from the logs.

[dvyurij]

@vchong

Remove exec_start wait_for_keymaster_optee from device/linaro/hikey/init.common.rc and rebuild. Or try the master branch.

Thanks for comment. I’ll try it tomorrow.
I’ve tried in master branch exactly.

@vchong

What’s the booting issue with the 3.4.2 branch? Can’t really tell from the logs.

In 3.4.2 branch build, logs bottom 16 lines below repeated and I was stuck in here.

=====================================================================

[ 14.355105] logd: logdr: UID=1000 GID=1003 PID=2890 n tail=50 logMask=8 pid=2836 start=0ns timeout=0ns
[ 14.366389] logd: logdr: UID=1000 GID=1003 PID=2890 n tail=50 logMask=1 pid=2836 start=0ns timeout=0ns
[ 14.398389] logd: logdr: UID=1000 GID=1003 PID=2890 n tail=0 logMask=8 pid=2836 start=0ns timeout=0ns
[ 14.408426] logd: logdr: UID=1000 GID=1003 PID=2890 n tail=0 logMask=1 pid=2836 start=0ns timeout=0ns
[ 14.471423] binder: release 2836:2836 transaction 1052 in, still active
[ 14.480471] binder: release 2836:2836 transaction 1049 out, still active
[ 14.487537] binder: send failed reply for transaction 1052 to 2838:2838
[ 14.487716] healthd: battery none chg=
[ 14.498210] binder: 2838:2838 transaction failed 29189/0, size 4-0 line 2944
[ 14.505323] binder: send failed reply for transaction 1049, target dead
[ 14.515990] binder: undelivered TRANSACTION_COMPLETE
[ 14.522025] binder: undelivered transaction 1237, process died.
[ 14.555597] logd: logdr: UID=1000 GID=1003 PID=2920 n tail=50 logMask=8 pid=2838 start=0ns timeout=0ns
[ 14.566330] logd: logdr: UID=1000 GID=1003 PID=2920 n tail=50 logMask=1 pid=2838 start=0ns timeout=0ns
[ 14.584015] logd: logdr: UID=1000 GID=1003 PID=2920 n tail=0 logMask=8 pid=2838 start=0ns timeout=0ns
[ 14.594402] logd: logdr: UID=1000 GID=1003 PID=2920 n tail=0 logMask=1 pid=2838 start=0ns timeout=0ns

=====================================================================

(Edited) I noticed PID changes now, so I’ll check it tomorrow if logs repeat unchanged or not.
They repeated similarly but I can’t remember exactly now.

Thanks.

[dvyurij]

I reflashed AOSP OPTEE 3.4.2 as same way as I did yesterday. And finally I could open adb shell today…

VMware recognized “Google adb Gadget”.

xtest result seems fine also.

==============================

23284 subtests of which 0 failed
93 test cases of which 0 failed
0 test cases were skipped
TEE test application done!

==============================

One problem is that I can’t see hdmi display though hikey960 is connected to 1920x1080 resolution display monitor.

I’m searching the way to solve this problem.

dmesg hdmi grep log is:

============================================================================

hikey960:/ # dmesg | grep -i hdmi
[ 2.851184] [drm] wait for external HDMI bridge driver.
[ 6.811944] [drm] client change to HDMI
[ 7.074231] hdmi-audio-codec hdmi-audio-codec.1.auto: ASoC: no source widget found for Playback
[ 7.084798] hdmi-audio-codec hdmi-audio-codec.1.auto: ASoC: Failed to add route Playback → direct → TX
[ 7.176018] #0: hikey-hdmi

============================================================================

dmesg log file

hikey960 3.4.2 dmesg logs - Pastebin.com

logcat log file

hikey960 3.4.2 logcat logs - Pastebin.com

@dvyurij

Thanks for comment. I’ll try it tomorrow.

Sync error occured in 3.6.1 branch (not master) so I couldn’t build again
I’m giving priority to enable hdmi in 3.4.2 branch now.

I changed host machine since VMware sync and build took so much time.

• Linux 4.15.0-91-generic-Ubuntu with x86_64 CPU

Still, connects adb shell in VMware Ubuntu.

==================================================

build/make/: discarding 1 commits
frameworks/base/: discarding 2 commits
prebuilts/clang/host/linux-x86/: discarding 1 commits
system/bt/: discarding 1 commits
error: system/core/: prior sync failed; rebase still in progress
error: Cannot checkout platform/system/core

error: Unable to fully sync the tree.
error: Checking out local projects failed.
Failing repos:
system/core
Try re-running with “-j1 --fail-fast” to exit at the first error.

==================================================

[doitright]

Possible known limitations with regards to hikey960 HDMI output. The clock frequencies generated by kirin 960 are not HDMI compliant, so if your monitor is particularly sensitive, it just won’t work. Unless you have seen that monitor previously activate on a hikey960 with a different OS build, I would suggest trying several different monitors.

[dvyurij]

@ric96 @vchong @doitright
Anyway, booting issue is solved. Thanks a lot.
I’ll post another new topic about hdmi problem if I can’t solve.

[quincysquarrel]

@dvyurij Hi, I just find I ran into the same HDMI issue with my Hikey960 board.
I flashed my hikey960 with AOSP OPTEE 3.4.2 and I can use adb shell.
I even have the same hdmi dmesg log like yours.

=========================================
hikey960:/ # dmesg | grep -i hdmi
[ 2.851184] [drm] wait for external HDMI bridge driver.
[ 6.811944] [drm] client change to HDMI
[ 7.074231] hdmi-audio-codec hdmi-audio-codec.1.auto: ASoC: no source widget found for Playback
[ 7.084798] hdmi-audio-codec hdmi-audio-codec.1.auto: ASoC: Failed to add route Playback → direct → TX
[ 7.176018] #0: hikey-hdmi

But one observation I have is that before I reflash the board with this 3.4.2 image, the board has a factory setting image of Android O(I guess) and it works well with my Monitor, which means hikey960 hardware has no problem support my monitor.

Do you have any new findings about this hdmi issue?

Thanks!
Ethan

[dvyurij]

@quincysquarrel
I’ve solved my problem. It may need specific type of monitor.
I hope this way could help you.

HiKey960 AOSP+OP-TEE display distortion issue

Hi, I have a problem with AOSP+OP-TEE hdmi displaying board: HiKey960 4GB branch version: 3.4.2 display monitor: 7inch HDMI LCD(B) USB Capacitive Touch 800x480 Pixel Rev2.1 [KakaoTalk_20200408_182815597] Touch works but display distortion happens. Monitor display and touch works well with my windows PC. I’ve edited resolution params in BoardConfig.mk or device-hikey960.mk at optee_android_manifest/device/linaro/hikey/hikey960 and built, but I couldn’t solve this problem. It would be very…

[quincysquarrel]

It works, thank you very much!

[Anjali]

After removing this from init.common.rc, I am getting the following error.

android.hardware.keymaster@3.0-service.optee: Loading…
OpteeKeymaster_ipc: TEEC_Opensession failed with code 0xf0100003 origin 0x4
OpteeKeymaster_cpp: Failed to connect to optee keymaster -267386877
android.hardware.keymaster@3.0-service.optee: Could not create keymaster instance
android.hardware.gatekeeper@1.0-service.optee: Checking gk connection to optee_os
OpteeGatekeeper: TEEC_Opensession failed with code 0xf0100003 origin 0x4
OpteeGateKeeper: Fail to load Gatekeeper TA
OpteeGateKeeper: getConnected 47 connected_ = android.hardware.gatekeeper@1.0-service.optee: gatekeeper failed to connect to optee_os

Where 0xf0100003 refers to TEEC_ERROR_STORAGE_NOT_AVAILABLE. Please help with issue if you know.

[doitright]

Depending on what the kernel source is that you are using, there may be more or less display configurations enabled and/or working.

[vchong]

@Anjali Can you please try the 3.4.2 build for now, with the above mentioned fix for the monitor? The current code base doesn’t seem very stable so we’re planning to upgrade to Q, but it might take some time.

[Anjali]

Thanks for the response, but I am still getting the same error with 3.4.2 tag also.
Is there any issue related to SElinux?
getenforce is giving SElinux:disabled.

Is there any possibility of getting TEEC_ERROR_STORAGE_NOT_AVAILABLE error from thread_rpc?

[vchong]

That shouldn’t happen. Are you sure you flashed the images properly? You can check the initial boot log for the OP-TEE version. Something like:
I/TC: OP-TEE version: 3.x.x #1 Day Mon Date HH:MM:SS UTC YYYY arch

Is there any possibility of getting TEEC_ERROR_STORAGE_NOT_AVAILABLE error from thread_rpc?

So it seems like your error is different than the OP although the error code is the same. The error is due to failure accessing secure storage at /data/vendor/tee/. Did you make any changes of your own to the build?

[doitright]

I don’t think that AOSP is expected to be able to boot with selinux DISABLED. Permissive, yes, but not disabled.

[Anjali]

Keymaster and gatekeeper services are starting properly with OP-TEE version 3.4.2.
Thank you so much for the help!

[vchong]

Setting selinux to permissive helped, or what?

[Anjali]

No sync was not done properly… it was still in 3.6.2 tag.
3.4.2 is working both in permissive and enforcing mode.
But is this tag is supported for hikey960?