Hi Enric
[...]
D/TC:? 0 spm_handle_scall:867 Received FFA direct request D/TC:? 0 spm_handle_scall:867 Received FFA direct request D/TC:? 0 spm_handle_scall:867 Received FFA direct request D/TC:? 0 spm_handle_scall:867 Received FFA direct request D/TC:? 0 spm_handle_scall:867 Received FFA direct request ... stuck here ... traces indicates never outs from the efi_setup, so looks like hungs
Let me try with BeaglePlay and read a bit more, as I feel I'm a bit lost right now.
Sure, let me know if you need anything else.
Same behaviour on BeaglePlay, so either it's currently broken or I'm making the same mistake in my process on both boards.
Ilias, by chance, do you have in which versions did you test?
So it looks like it is a problem with edk2 and/or edk2-platform, since reverting those repositories back to September, things started to look a lot better and I'm able to see en UEFI variables programmed.
FWIW I just found this project [1] from you, thank you for it. Turns out that it is easy to reproduce the issue I'm facing even with qemu. I'll try to bisect what's the problem and report properly.
There were recently some patches in EDK2 changing some aspects and you also have to update edk2-platforms & OP-TEE [0] to test this, but this is not merged yet. I did try those changes and they worked fine. When you bisect why EDK2 is broken please let me know otherwise I'll have a look.
Thank you very much for your guidance and support.
You're welcome. Keep in mind that [1] is _very_ hacky and it's just testing variable accesses in the firmware since U-Boot emulates the RPMB, not QEMU. IOW it's fine to use it and test U-Boot but the changes won't survive ExitBootServris and won't work in Linux.
Cheers, Enric
[1] https://git.linaro.org/people/ilias.apalodimas/efi_optee_variables.git/
[0] https://github.com/tianocore/edk2/pull/6116 [1] https://git.linaro.org/people/ilias.apalodimas/efi_optee_variables.git/
Cheers /Ilias
Thanks, Enric
/Ilias
=> optee_rpmb read test 4 D/TC:? 0 tee_ta_init_pseudo_ta_session:303 Lookup pseudo TA 023f8f1a-292a-432b-8fc4-de8471358067 D/TC:? 0 ldelf_load_ldelf:110 ldelf load address 0x40007000 D/LD: ldelf:142 Loading TS 023f8f1a-292a-432b-8fc4-de8471358067 F/TC:? 0 trace_syscall:147 syscall #3 (syscall_get_property) F/TC:? 0 trace_syscall:147 syscall #5 (syscall_open_ta_session) D/TC:? 0 ldelf_syscall_open_bin:135 > ldelf_syscall_open_bin D/TC:? 0 ldelf_syscall_open_bin:164 Lookup user TA ELF 023f8f1a-292a-432b-8fc4-de8471358067 (early TA) D/TC:? 0 ldelf_syscall_open_bin:168 res=0 F/TC:? 0 trace_syscall:147 syscall #7 (syscall_invoke_ta_command) F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 trace_syscall:147 syscall #11 (syscall_mask_cancellation) F/TC:? 0 trace_syscall:147 syscall #7 (syscall_invoke_ta_command) F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 492 bytes F/TC:? 0 trace_syscall:147 syscall #3 (syscall_get_property) F/TC:? 0 trace_syscall:147 syscall #8 (syscall_check_access_rights) F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 1024 bytes F/TC:? 0 read_compressed:178 532 bytes F/TC:? 0 read_compressed:178 924 bytes F/TC:? 0 trace_syscall:147 syscall #8 (syscall_check_access_rights) F/TC:? 0 read_compressed:178 248 bytes F/TC:? 0 read_compressed:178 760 bytes F/TC:? 0 trace_syscall:147 syscall #6 (syscall_close_ta_session) F/TC:? 0 trace_syscall:147 syscall #3 (syscall_get_property) D/LD: ldelf:176 ELF (023f8f1a-292a-432b-8fc4-de8471358067) at 0x40048000 F/TC:? 0 trace_syscall:147 syscall #33 (syscall_cryp_random_number_generate) F/TC:? 0 trace_syscall:147 syscall #8 (syscall_check_access_rights) F/TC:? 0 trace_syscall:147 syscall #8 (syscall_check_access_rights) F/TC:? 0 trace_syscall:147 syscall #4 (syscall_get_property_name_to_index) F/TC:? 0 trace_syscall:147 syscall #8 (syscall_check_access_rights) F/TC:? 0 trace_syscall:147 syscall #41 (syscall_storage_obj_open) D/TC:? 0 rpmb_fs_open_internal:2356 >>> rpmb_fs_open_internal D/TC:? 0 tee_rpmb_init:1205 >>> core/tee/tee_rpmb_fs.c:1205 D/TC:? 0 tee_rpmb_init:1214 >>> core/tee/tee_rpmb_fs.c:1214 D/TC:? 0 tee_rpmb_init:1253 >>> core/tee/tee_rpmb_fs.c:1253 D/TC:? 0 legacy_rpmb_init:1142 Trying legacy RPMB init D/TC:? 0 rpmb_set_dev_info:1111 RPMB: Syncing device information D/TC:? 0 rpmb_set_dev_info:1113 RPMB: RPMB size is 32*128 KB D/TC:? 0 rpmb_set_dev_info:1114 RPMB: Reliable Write Sector Count is 1 D/TC:? 0 rpmb_set_dev_info:1116 RPMB: CID D/TC:? 0 rpmb_set_dev_info:1117 000000009e93ab30 13 01 4e 47 31 4d 31 35 4c 10 27 91 28 07 a9 00 D/TC:? 0 legacy_rpmb_init:1162 RPMB INIT: Deriving key D/TC:? 0 tee_rpmb_key_gen:308 RPMB: Using test key D/TC:? 0 legacy_rpmb_init:1176 RPMB INIT: Verifying Key F/TC:? 0 plat_prng_add_jitter_entropy:68 0x61 D/TC:? 0 legacy_rpmb_init:1180 Found working RPMB device D/TC:? 0 tee_rpmb_init:1205 >>> core/tee/tee_rpmb_fs.c:1205 D/TC:? 0 tee_rpmb_init:1214 >>> core/tee/tee_rpmb_fs.c:1214 D/TC:? 0 tee_rpmb_read:1362 Read 1 block at index 0 D/TC:? 0 tee_rpmb_write_blk:1494 Write 1 block at index 0 D/TC:? 0 tee_rpmb_init:1205 >>> core/tee/tee_rpmb_fs.c:1205 D/TC:? 0 tee_rpmb_init:1214 >>> core/tee/tee_rpmb_fs.c:1214 D/TC:? 0 tee_rpmb_init:1205 >>> core/tee/tee_rpmb_fs.c:1205 D/TC:? 0 tee_rpmb_init:1214 >>> core/tee/tee_rpmb_fs.c:1214 D/TC:? 0 tee_rpmb_read:1362 Read 1 block at index 0 E/TC:? 0 rpmb_fs_setup:2143 **** Clearing Storage **** D/TC:? 0 tee_rpmb_write_blk:1494 Write 1 block at index 2 F/TC:? 0 plat_prng_add_jitter_entropy:68 0xD3 D/TC:? 0 tee_rpmb_read:1362 Read 1 block at index 0 D/TC:? 0 tee_rpmb_write_blk:1494 Write 1 block at index 0 D/TC:? 0 tee_rpmb_read:1362 Read 8 blocks at index 2 F/TC:? 0 dump_fat:1951 flags 0x2, size 0, address 0, filename '' D/TC:? 0 read_fat:2221 fat_address 0 D/TC:? 0 tee_rpmb_read:1362 Read 8 blocks at index 2 F/TC:? 0 plat_prng_add_jitter_entropy:68 0x18 E/TA: read_persist_value:338 Can't open named object value, res = 0xffff0008 D/TC:? 0 tee_ta_invoke_command:798 Error: ffff0008 of 4 D/TC:? 0 tee_ta_close_session:460 csess 0x9e925a50 id 1 D/TC:? 0 tee_ta_close_session:479 Destroy session D/TC:? 0 destroy_context:318 Destroy TA ctx (0x9e9259f0) Failed to read persistent value
> Cheers > /Ilias > > > => optee_rpmb read test 4 > > D/TC:? 0 tee_ta_init_pseudo_ta_session:303 Lookup pseudo TA > > 023f8f1a-292a-432b-8fc4-de8471358067 > > D/TC:? 0 ldelf_load_ldelf:110 ldelf load address 0x40007000 > > D/LD: ldelf:142 Loading TS 023f8f1a-292a-432b-8fc4-de8471358067 > > F/TC:? 0 trace_syscall:147 syscall #3 (syscall_get_property) > > F/TC:? 0 trace_syscall:147 syscall #5 (syscall_open_ta_session) > > D/TC:? 0 ldelf_syscall_open_bin:163 Lookup user TA ELF > > 023f8f1a-292a-432b-8fc4-de8471358067 (early TA) > > D/TC:? 0 ldelf_syscall_open_bin:167 res=0 > > F/TC:? 0 trace_syscall:147 syscall #7 (syscall_invoke_ta_command) > > F/TC:? 0 read_compressed:178 1024 bytes > > F/TC:? 0 read_compressed:178 1024 bytes > > F/TC:? 0 read_compressed:178 1024 bytes > > F/TC:? 0 read_compressed:178 1024 bytes > > F/TC:? 0 trace_syscall:147 syscall #11 (syscall_mask_cancellation) > > F/TC:? 0 trace_syscall:147 syscall #7 (syscall_invoke_ta_command) > > > > => efidebug query -bs -rt -nv > > MMC: no card present > > mmc_init: -123, time 2002 > > D/TC:? 0 load_stmm:297 stmm load address 0x40004000 > > D/TC:? 0 spm_handle_scall:859 Received FFA version > > D/TC:? 0 spm_handle_scall:867 Received FFA direct request > > D/TC:? 0 spm_handle_scall:867 Received FFA direct request > > D/TC:? 0 spm_handle_scall:867 Received FFA direct request > > D/TC:? 0 spm_handle_scall:867 Received FFA direct request > > D/TC:? 0 spm_handle_scall:867 Received FFA direct request > > D/TC:? 0 spm_handle_scall:867 Received FFA direct request > > D/TC:? 0 spm_handle_scall:867 Received FFA direct request > > D/TC:? 0 spm_handle_scall:867 Received FFA direct request > > D/TC:? 0 spm_handle_scall:867 Received FFA direct request > > D/TC:? 0 spm_handle_scall:867 Received FFA direct request > > > > > > > > > > > > > Thanks > > > > /Ilias > > > > > > > > > > => efidebug query -bs -rt -nv > > > > > D/TC:? 0 load_stmm:297 stmm load address 0x40004000 > > > > > D/TC:? 0 spm_handle_scall:859 Received FFA version > > > > > D/TC:? 0 spm_handle_scall:867 Received FFA direct request > > > > > D/TC:? 0 spm_handle_scall:867 Received FFA direct request > > > > > D/TC:? 0 spm_handle_scall:867 Received FFA direct request > > > > > D/TC:? 0 spm_handle_scall:867 Received FFA direct request > > > > > D/TC:? 0 spm_handle_scall:867 Received FFA direct request > > > > > D/TC:? 0 spm_handle_scall:867 Received FFA direct request > > > > > D/TC:? 0 spm_handle_scall:867 Received FFA direct request > > > > > D/TC:? 0 spm_handle_scall:867 Received FFA direct request > > > > > D/TC:? 0 spm_handle_scall:867 Received FFA direct request > > > > > D/TC:? 0 spm_handle_scall:867 Received FFA direct request > > > > > D/TC:? 0 spm_handle_scall:867 Received FFA direct request > > > > > D/TC:? 0 spm_handle_scall:867 Received FFA direct request > > > > > D/TC:? 0 spm_handle_scall:867 Received FFA direct request > > > > > D/TC:? 0 spm_handle_scall:867 Received FFA direct request > > > > > D/TC:? 0 spm_handle_scall:867 Received FFA direct request > > > > > D/TC:? 0 spm_handle_scall:867 Received FFA direct request > > > > > ... stuck here ... I need to reset the board > > > > > > > > > > Will continue to see if I can get more useful messages > > > > > > > > > > Thanks, > > > > > Enric > > > > > > > > > > > Thanks > > > > > > /Ilias > > > > > > > > > > > > > > I'll try to add some more prints to verify if REE is used as a store > > > > > > > system, I assume this should say something about RPMB. Am I right with > > > > > > > this? > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > And tracing the function calls gives me that: > > > > > > > > > > > > > > > > > > > > > > tee_stmm_efi_probe() { > > > > > > > > > > > tee_client_open_context() { > > > > > > > > > > > optee_get_version() { > > > > > > > > > > > tee_get_drvdata(); (ret=0xffff000002e55800) > > > > > > > > > > > } (ret=0xd) > > > > > > > > > > > tee_ctx_match(); (ret=0x1) > > > > > > > > > > > optee_smc_open() { > > > > > > > > > > > tee_get_drvdata(); (ret=0xffff000002e55800) > > > > > > > > > > > optee_open() { > > > > > > > > > > > tee_get_drvdata(); (ret=0xffff000002e55800) > > > > > > > > > > > } (ret=0x0) > > > > > > > > > > > } (ret=0x0) > > > > > > > > > > > } (ret=0xffff000004e71c80) > > > > > > > > > > > tee_client_open_session() { > > > > > > > > > > > optee_open_session() { > > > > > > > > > > > tee_get_drvdata(); (ret=0xffff000002e55800) > > > > > > > > > > > optee_get_msg_arg() { > > > > > > > > > > > tee_get_drvdata(); (ret=0xffff000002e55800) > > > > > > > > > > > tee_shm_get_va(); (ret=0xffff000002909000) > > > > > > > > > > > } (ret=0xffff000002909000) > > > > > > > > > > > tee_session_calc_client_uuid(); (ret=0x0) > > > > > > > > > > > optee_to_msg_param(); (ret=0x0) > > > > > > > > > > > optee_smc_do_call_with_arg() { > > > > > > > > > > > tee_get_drvdata(); (ret=0xffff000002e55800) > > > > > > > > > > > tee_shm_get_va(); (ret=0xffff000002909000) > > > > > > > > > > > tee_shm_get_va(); (ret=0xffff000002909060) > > > > > > > > > > > optee_cq_wait_init(); (ret=0xffff000002e55910) > > > > > > > > > > > optee_smccc_smc(); (ret=0xffff0004) > > > > > > > > > > > tee_get_drvdata(); (ret=0xffff000002e55800) > > > > > > > > > > > optee_smccc_smc(); (ret=0xffff0004) > > > > > > > > > > > tee_get_drvdata(); (ret=0xffff000002e55800) > > > > > > > > > > > optee_smccc_smc(); (ret=0xffff0004) > > > > > > > > > > > tee_get_drvdata(); (ret=0xffff000002e55800) > > > > > > > > > > > optee_smccc_smc(); (ret=0xffff0004) > > > > > > > > > > > tee_get_drvdata(); (ret=0xffff000002e55800) > > > > > > > > > > > optee_smccc_smc(); (ret=0xffff0004) > > > > > > > > > > > ... continues sending this forever ... > > > > > > > > > > > ... Hit ^C to stop recording ... > > > > > > > > > > > tee_get_drvdata(); (ret=0xffff000002e55800) > > > > > > > > > > > optee_smccc_smc() { > > > > > > > > > > > > > > > > > > > > > > [1] https://docs.u-boot.org/en/latest/develop/uefi/uefi.html#using-op-tee-for-ef... > > > > > > > > > > > > > > > > > > > > > > Thanks in advance, > > > > > > > > > > > > > > > > > > > > The most common problem with this is miscompiling the tee_supplicant > > > > > > > > > > application. > > > > > > > > > > Since we don't know if the system has an RPMB, we emulate it in the > > > > > > > > > > tee_supplicant. How did you get the supplicant and can you check if it > > > > > > > > > > was compiled with RPMB_EMU=0 or 1? > > > > > > > > > > > > > > > > > > > > > > > > > > > > I'm using the tee-supplicant provided by the fedora package which is > > > > > > > > > built with ` -DRPMB_EMU=0`, I think that's correct, right? > > > > > > > > > > > > > > > > > > > > > > > > > Yes, this is correct. We fixed the Fedora package to compile the > > > > > > > > supplicant correctly a while back. > > > > > > > > > > > > > > > > [0] https://www.linaro.org/blog/uefi-secureboot-in-u-boot/ > > > > > > > > [1] https://apalos.github.io/Protected%20UEFI%20variables%20with%20U-Boot.html#P... > > > > > > > > > > > > > > > > > > > > > > > > Regards > > > > > > > > /Ilias > > > > > > > > > Thanks, > > > > > > > > > Enric > > > > > > > > > > > > > > > > > > > Thanks > > > > > > > > > > /Ilias > > > > > > > > > > > > > > > > > > > > > Enric > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > >