commit core: generic_entry: add enable_mmu() causes hangup on firefly-rk3399

[Dvergatal]

Finally i had more time to check commit by commit what's causing the hang up during BL32 initialization on rk3399 between 3.7.0 and 3.8.0 tags and found out that this commit between tags v3.7.0 and v3.8.0 causes a regression on firefly-rk3399 and optee is not being initialized, it simply hangs:

U-Boot TPL 2022.01-rc1-00226-ga51673eb75 (Nov 14 2021 - 23:10:49)
Channel 0: DDR3, 800MHz
BW=32 Col=10 Bk=8 CS0 Row=15 CS1 Row=15 CS=2 Die BW=16 Size=2048MB
Channel 1: DDR3, 800MHz
BW=32 Col=10 Bk=8 CS0 Row=15 CS1 Row=15 CS=2 Die BW=16 Size=2048MB
256B stride
Trying to boot from BOOTROM
Returning to boot ROM...

U-Boot SPL 2022.01-rc1-00226-ga51673eb75 (Nov 14 2021 - 23:10:49 +0100)
Trying to boot from MMC1
NOTICE:  BL31: v2.5(release):v2.6-rc0-dirty
NOTICE:  BL31: Built : 20:56:11, Nov 14 2021
INFO:    GICv3 with legacy support detected.
INFO:    ARM GICv3 driver initialized in EL3
INFO:    Maximum SPI INTID supported: 287
INFO:    plat_rockchip_pmu_init(1624): pd status 3e
INFO:    BL31: Initializing runtime services
INFO:    BL31: Initializing BL32

This is the issue for which i had problems in #4197. I honestly admit that I do not know asm and more over i don't know if it is possible to debug what line is causing this situation.

@jenswi-linaro maybe you have some clues?

[jenswi-linaro]

My guess is that this platform does something special with the memory mappings that none of the tested upstream platforms do.

[Dvergatal]

Hi @jenswi-linaro,
thx for quick reply. The question now is how could we fix the issue? I could help with debbuging the issue, but for that i would need your support if that's possible.

P.S. Btw. i dunno if that concerns the issue, but for running optee I'm using TPL/SPL uboot script which is packing BL31 together with TEE into the image.

[Dvergatal]

Hi @jenswi-linaro,
thx for quick reply. The question now is how could we fix the issue? I could help with debbuging the issue, but for that i would need your support if that's possible.

P.S. Btw. i dunno if that concerns the issue, but for running optee I'm using TPL/SPL uboot script which is packing BL31 together with TEE into the image.

[jenswi-linaro]

I'm not sure I can help much here. I assume that the code you're testing with isn't upstream.
It would help a bit if you have jtag debugger. The first objective is to get any debug prints at all, especially if you don't have a jtag debugger.

It's quite likely that there's something wrong with the translation tables so try to enable as much debug prints related to that as possible.

[Dvergatal]

It's upstream with mixed changes from higher versions for pkcs11 TA. I don't have jtag debbuger i use UART for debugging. Btw. i have read #4542 and i think it is related.

I'll give a try with setting CONFIG_LOG=y in u-boot and see what will it do, because for now, even if I'm setting CFG_TEE_CORE_LOG_LEVEL=4 I don't have any output from asm code.

P.S. @jenswi-linaro the code is in my repo on branch rockchip-3.8-regression.

[Dvergatal]

OK:] i should be thankful to @ydirson, because thx to his post i was finally able to debug the optee with his CONFIG_LOG=y setting for u-boot. Now i am finally able to debug optee 👍

The log output is slightly different:

U-Boot TPL 2022.01-rc1-00226-ga51673eb75-dirty (Nov 15 2021 - 17:08:34)
Channel 0: DDR3, 800MHz
BW=32 Col=10 Bk=8 CS0 Row=15 CS1 Row=15 CS=2 Die BW=16 Size=2048MB
Channel 1: DDR3, 800MHz
BW=32 Col=10 Bk=8 CS0 Row=15 CS1 Row=15 CS=2 Die BW=16 Size=2048MB
256B stride
Trying to boot from BOOTROM
Returning to boot ROM...

U-Boot SPL 2022.01-rc1-00226-ga51673eb75-dirty (Nov 15 2021 - 17:08:34 +0100)
Trying to boot from MMC1
NOTICE:  BL31: v2.5(release):v2.6-rc0-dirty
NOTICE:  BL31: Built : 20:56:11, Nov 14 2021
INFO:    GICv3 with legacy support detected.
INFO:    ARM GICv3 driver initialized in EL3
INFO:    Maximum SPI INTID supported: 287
INFO:    plat_rockchip_pmu_init(1624): pd status 3e
INFO:    BL31: Initializing runtime services
INFO:    BL31: Initializing BL32
D/TC:0 0 add_phys_mem:576 TEE_SHMEM_START type NSEC_SHM 0x32000000 size 0x00400000
D/TC:0 0 add_phys_mem:576 TA_RAM_START type TA_RAM 0x30200000 size 0x01e00000
D/TC:0 0 add_phys_mem:576 VCORE_UNPG_RW_PA type TEE_RAM_RW 0x3005d000 size 0x001a3000
D/TC:0 0 add_phys_mem:576 VCORE_UNPG_RX_PA type TEE_RAM_RX 0x30000000 size 0x0005d000
D/TC:0 0 add_phys_mem:576 ROUNDDOWN((0xF8000000 + 0x06E00000), CORE_MMU_PGDIR_SIZE) type IO_SEC 0xfee00000 size 0x00200000
D/TC:0 0 add_phys_mem:576 ROUNDDOWN((0xF8000000 + 0x071A0000), CORE_MMU_PGDIR_SIZE) type IO_NSEC 0xff000000 size 0x00200000
D/TC:0 0 add_phys_mem:576 ROUNDDOWN((0xF8000000 + 0x07330000), CORE_MMU_PGDIR_SIZE) type IO_SEC 0xff200000 size 0x00200000
D/TC:0 0 verify_special_mem_areas:515 No NSEC DDR memory area defined
D/TC:0 0 add_va_space:616 type RES_VASPACE size 0x00a00000
D/TC:0 0 add_va_space:616 type SHM_VASPACE size 0x02000000
D/TC:0 0 dump_mmap_table:721 type IO_SEC       va 0x2a800000..0x2a9fffff pa 0xff200000..0xff3fffff size 0x00200000 (pgdir)
D/TC:0 0 dump_mmap_table:721 type IO_NSEC      va 0x2aa00000..0x2abfffff pa 0xff000000..0xff1fffff size 0x00200000 (pgdir)
D/TC:0 0 dump_mmap_table:721 type IO_SEC       va 0x2ac00000..0x2adfffff pa 0xfee00000..0xfeffffff size 0x00200000 (pgdir)
D/TC:0 0 dump_mmap_table:721 type NSEC_SHM     va 0x2ae00000..0x2b1fffff pa 0x32000000..0x323fffff size 0x00400000 (pgdir)
D/TC:0 0 dump_mmap_table:721 type TA_RAM       va 0x2b200000..0x2cffffff pa 0x30200000..0x31ffffff size 0x01e00000 (pgdir)
D/TC:0 0 dump_mmap_table:721 type RES_VASPACE  va 0x2d200000..0x2dbfffff pa 0x00000000..0x009fffff size 0x00a00000 (pgdir)
D/TC:0 0 dump_mmap_table:721 type SHM_VASPACE  va 0x2de00000..0x2fdfffff pa 0x00000000..0x01ffffff size 0x02000000 (pgdir)
D/TC:0 0 dump_mmap_table:721 type TEE_RAM_RX   va 0x30000000..0x3005cfff pa 0x30000000..0x3005cfff size 0x0005d000 (smallpg)
D/TC:0 0 dump_mmap_table:721 type TEE_RAM_RW   va 0x3005d000..0x301fffff pa 0x3005d000..0x301fffff size 0x001a3000 (smallpg)
D/TC:0 0 core_mmu_entry_to_finer_grained:785 xlat tables used 1 / 5
D/TC:0 0 core_mmu_entry_to_finer_grained:785 xlat tables used 2 / 5

cause i see 'D/TC:0 0 verify_special_mem_areas:515 No NSEC DDR memory area defined'.

I think that when logging is now visable i'll give i try with the newest master.

[Dvergatal]

Hmmm this is odd. With current a few times an output was produced:

U-Boot TPL 2022.01-rc1-00226-ga51673eb75-dirty (Nov 15 2021 - 20:08:58)
Channel 0: DDR3, 800MHz
BW=32 Col=10 Bk=8 CS0 Row=15 CS1 Row=15 CS=2 Die BW=16 Size=2048MB
Channel 1: DDR3, 800MHz
BW=32 Col=10 Bk=8 CS0 Row=15 CS1 Row=15 CS=2 Die BW=16 Size=2048MB
256B stride
Trying to boot from BOOTROM
Returning to boot ROM...

U-Boot SPL 2022.01-rc1-00226-ga51673eb75-dirty (Nov 15 2021 - 20:08:58 +0100)
Trying to boot from MMC1
NOTICE:  BL31: v2.5(release):v2.6-rc0-dirty
NOTICE:  BL31: Built : 20:56:11, Nov 14 2021
INFO:    GICv3 with legacy support detected.
INFO:    ARM GICv3 driver initialized in EL3
INFO:    Maximum SPI INTID supported: 287
INFO:    plat_rockchip_pmu_init(1624): pd status 3e
INFO:    BL31: Initializing runtime services
INFO:    BL31: Initializing BL32
D/TC:0   get_aslr_seed:1376 Bad fdt: -9
D/TC:0   plat_get_aslr_seed:109 Warning: no ASLR seed
D/TC:0   add_phys_mem:571 TEE_SHMEM_START type NSEC_SHM 0x32000000 size 0x00400000
D/TC:0   add_phys_mem:571 TA_RAM_START type TA_RAM 0x30200000 size 0x01e00000
D/TC:0   add_phys_mem:571 VCORE_UNPG_RW_PA type TEE_RAM_RW 0x30065000 size 0x0019b000
D/TC:0   add_phys_mem:571 VCORE_UNPG_RX_PA type TEE_RAM_RX 0x30000000 size 0x00065000
D/TC:0   add_phys_mem:571 ROUNDDOWN((0xF8000000 + 0x06E00000), CORE_MMU_PGDIR_SIZE) type IO_SEC 0xfee00000 size 0x00200000
D/TC:0   add_phys_mem:571 ROUNDDOWN((0xF8000000 + 0x071A0000), CORE_MMU_PGDIR_SIZE) type IO_NSEC 0xff000000 size 0x00200000
D/TC:0   add_phys_mem:571 ROUNDDOWN((0xF8000000 + 0x07330000), CORE_MMU_PGDIR_SIZE) type IO_SEC 0xff200000 size 0x00200000
D/TC:0   add_va_space:611 type RES_VASPACE size 0x00a00000
D/TC:0   add_va_space:611 type SHM_VASPACE size 0x02000000
D/TC:0   dump_mmap_table:724 type IO_SEC       va 0x2a800000..0x2a9fffff pa 0xff200000..0xff3fffff size 0x00200000 (pgdir)
D/TC:0   dump_mmap_table:724 type IO_NSEC      va 0x2aa00000..0x2abfffff pa 0xff000000..0xff1fffff size 0x00200000 (pgdir)
D/TC:0   dump_mmap_table:724 type IO_SEC       va 0x2ac00000..0x2adfffff pa 0xfee00000..0xfeffffff size 0x00200000 (pgdir)
D/TC:0   dump_mmap_table:724 type NSEC_SHM     va 0x2ae00000..0x2b1fffff pa 0x32000000..0x323fffff size 0x00400000 (pgdir)
D/TC:0   dump_mmap_table:724 type TA_RAM       va 0x2b200000..0x2cffffff pa 0x30200000..0x31ffffff size 0x01e00000 (pgdir)
D/TC:0   dump_mmap_table:724 type RES_VASPACE  va 0x2d200000..0x2dbfffff pa 0x00000000..0x009fffff size 0x00a00000 (pgdir)
D/TC:0   dump_mmap_table:724 type SHM_VASPACE  va 0x2de00000..0x2fdfffff pa 0x00000000..0x01ffffff size 0x02000000 (pgdir)
D/TC:0   dump_mmap_table:724 type TEE_RAM_RX   va 0x30000000..0x30064fff pa 0x30000000..0x30064fff size 0x00065000 (smallpg)
D/TC:0   dump_mmap_table:724 type TEE_RAM_RW   va 0x30065000..0x301fffff pa 0x30065000..0x301fffff size 0x0019b000 (smallpg)
D/TC:0   core_mmu_xlat_table_alloc:493 xlat tables used 1 / 5
D/TC:0   core_mmu_xlat_table_alloc:493 xlat tables used 2 / 5
I/TC: 
I/TC: No non-secure external DT
D/TC:0 0 get_console_node_from_dt:70 No console directive from DTB
I/TC: OP-TEE version: 3.15.0-35-g88544a9f (gcc version 9.3.0 (Ubuntu 9.3.0-17ubuntu1~20.04)) #1 Mon Nov 15 19:08:06 UTC 2021 aarch64
I/TC: Primary CPU initializing
D/TC:0 0 boot_init_primary_late:1256 Executing at offset 0 with virtual load address 0x30000000
D/TC:0 0 call_preinitcalls:21 level 2 mobj_mapped_shm_init()
D/TC:0 0 mobj_mapped_shm_init:448 Shared memory address range: 2de00000, 2fe00000
D/TC:0 0 call_initcalls:40 level 1 register_time_source()
D/TC:0 0 call_initcalls:40 level 1 teecore_init_pub_ram()
D/TC:0 0 call_initcalls:40 level 3 platform_init()
D/TC:0 0 platform_secure_ddr_region:35 protecting region 1: 0x30000000-0x32000000
D/TC:0 0 call_initcalls:40 level 3 check_ta_store()
D/TC:0 0 check_ta_store:408 TA store: "Secure Storage TA"
D/TC:0 0 check_ta_store:408 TA store: "REE"
D/TC:0 0 call_initcalls:40 level 3 verify_pseudo_tas_conformance()
D/TC:0 0 call_initcalls:40 level 3 tee_cryp_init()
D/TC:0 0 call_initcalls:40 level 4 tee_fs_init_key_manager()
D/TC:0 0 call_initcalls:40 level 6 mobj_init()
D/TC:0 0 call_initcalls:40 level 6 default_mobj_init()
D/TC:0 0 call_finalcalls:59 level 1 release_external_dt()
I/TC: Primary CPU switching to normal world boot
E/TC:0 0 
E/TC:0 0 Core data-abort at address 0x30200000 (translation fault)
E/TC:0 0  esr 0x96000146  ttbr0 0x30097000   ttbr1 0x00000000   cidr 0x0
E/TC:0 0  cpu #0          cpsr 0x800003c4
E/TC:0 0  x0  0000000030200000 x1  00000000600f3520
E/TC:0 0  x2  0000000000000040 x3  000000000000003f
E/TC:0 0  x4  0000000000000001 x5  0000000030067c30
E/TC:0 0  x6  ffffffffffffffff x7  000000003009d830
E/TC:0 0  x8  000000003009d830 x9  0000000030074d30
E/TC:0 0  x10 0000000000000000 x11 000000000e72963e
E/TC:0 0  x12 000000003009d7a0 x13 000000000000000a
E/TC:0 0  x14 00000000ffffffff x15 0000000000000020
E/TC:0 0  x16 000000003001431c x17 0000000000000000
E/TC:0 0  x18 0000000000000000 x19 0000000000000000
E/TC:0 0  x20 0000000000000000 x21 00000000300a4430
E/TC:0 0  x22 0000000030074790 x23 0000000000000000
E/TC:0 0  x24 0000000000000000 x25 0000000000000000
E/TC:0 0  x26 0000000000000000 x27 0000000000000000
E/TC:0 0  x28 0000000000000000 x29 0000000000000000
E/TC:0 0  x30 0000000030000174 elr 000000003000475c
E/TC:0 0  sp_el0 00000000300a4430
E/TC:0 0 TEE load address @ 0x30000000
E/TC:0 0 Call stack:
E/TC:0 0  0x3000475c
E/TC:0 0 Panic 'unhandled pageable abort' at core/arch/arm/kernel/abort.c:553 <abort_handler>
E/TC:0 0 TEE load address @ 0x30000000
E/TC:0 0 Call stack:
E/TC:0 0  0x30009188
E/TC:0 0  0x30015d40
E/TC:0 0  0x30007d5c

and now I'm not even able to re-produce it....

P.S. ha this is really odd because it turns out that the outputs sometimes are and sometimes are not and i really do not know what it depends on...
P.S.2 Ok on tag 3.15.0 i have some logs and it is the same:

D/TC:0   get_aslr_seed:1376 Bad fdt: -9
D/TC:0   plat_get_aslr_seed:109 Warning: no ASLR seed

If i turn off ASLR the logs are gone and nothing happens i can't debug... This is really frustrating. I need a jtag debugger, because i can't work like that.

[Dvergatal]

Hahahaha I'm sorry for my language, but this is some bloody bullshit. I've got it finally working with mainline 3.15.0 :] the problem was in newest u-boot. I have switched back to 2020.1 and first of all the debug outputs started to print out faster. Then i have turned ASLR off and the board has booted up :] I think i have to create a bug in u-boot.

[Dvergatal]

As i have confirmed that newest mainline is working i think i can close this one.

[sprhawk]

@Dvergatal I also encountered same issue, and I can boot with u-boot 2020.01 + optee-os 3.14 with ASLR disabled. Did you have filed a bug for u-boot ? Do they have response ?
with ASLR disabled, it is not a secure state. We still need to have ASLR enabled during production

[Dvergatal]

Hi @sprhawk, I have filled a bug to u-boot (google this [BUG] firefly-rk3399 tpl/spl with optee from tag v2020.07 hangs on booting kernel) but i was told to find on which commit it all breaks, which i haven’t done yet because of lack of time…

…

________________________________ Od: sprhawk ***@***.***> Wysłane: Friday, January 7, 2022 11:25:20 AM Do: OP-TEE/optee_os ***@***.***> DW: Piotr Lobacz ***@***.***>; Mention ***@***.***> Temat: Re: [OP-TEE/optee_os] commit core: generic_entry: add enable_mmu() causes hangup on firefly-rk3399 (Issue #4977) @Dvergatal<https://github.com/Dvergatal> I also encountered same issue, and I can boot with u-boot 2020.01 + optee-os 3.14 with ASLR disabled. Did you have filed a bug for u-boot ? Do they have response ? with ASLR disabled, it is not a secure state. We still need to have ASLR enabled during production — Reply to this email directly, view it on GitHub<#4977 (comment)>, or unsubscribe<https://github.com/notifications/unsubscribe-auth/ARIYQXQOYMEEMEENZPRT4ALUU25RBANCNFSM5IALI3XA>. Triage notifications on the go with GitHub Mobile for iOS<https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675> or Android<https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub>. You are receiving this because you were mentioned.Message ID: ***@***.***> [Softgent logo]<https://www.softgent.com> Softgent Sp. z o.o., Budowlanych 31d, 80-298 Gdansk, POLAND KRS: 0000674406, NIP: 9581679801, REGON: 367090912 www.softgent.com<https://www.softgent.com> Sąd Rejonowy Gdańsk-Północ w Gdańsku, VII Wydział Gospodarczy Krajowego Rejestru Sądowego KRS 0000674406, Kapitał zakładowy: 25 000,00 zł wpłacony w całości. Jesteśmy uczestnikiem Programu RZETELNA Firma Sprawdź naszą rzetelność na https://www.rzetelnafirma.pl/F5IA32UW