Stm32mp157 optee ETC panic 0 0 ECO 5.0.3

[MWoło.2]

Hello,

I encountered a problem with optee that I could not resolve due to a misunderstanding of debug information.

During boot up the board, I get the following debug log

Spoiler

...
F/TC:0 0 __clk_enable:1195 Clock 192 has been enabled
D/TC:0 0 probe_driver_node:550 element: stm32-rtc on node rtc@5c004000 initialized
F/TC:0 0 probe_driver_node:543 Probing stm32-iwdg on node watchdog@5a002000
F/TC:0 0 pager_deploy_page:1469 Mapped 0x30023000 -> 0x2fffa000
F/TC:0 0 pager_deploy_page:1469 Mapped 0x30056000 -> 0x2ffea000
F/TC:0 0 pager_deploy_page:1469 Mapped 0x30021000 -> 0x2fffd000
D/TC:0 0 gic_it_set_cpu_mask:410 cpu_mask: writing 0xff000000 to 0x349218b4
D/TC:0 0 gic_it_set_cpu_mask:412 cpu_mask: 0x3000000
D/TC:0 0 gic_it_set_prio:426 prio: writing 0x1 to 0x349214b7
D/TC:0 0 dt_driver_device_from_node_idx_prop:370 Property resets missing in node watchdog@5a002000
F/TC:0 0 __clk_enable:1195 Clock 58 has been enabled
D/TC:0 0 iwdg_wdt_get_version_and_status:528 Watchdog is enabled
F/TC:0 0 pager_deploy_page:1469 Mapped 0x30055000 -> 0x2ffed000
F/TC:0 0 pager_deploy_page:1469 Mapped 0x3001c000 -> 0x2fffb000
D/TC:0 0 register_periph_iomem:331 IO for non-secure resource 0x5a002000
E/TC:0 0 Panic

and with Panic at the end. I have to admit that I don't see any trouble with the debug text above.

I also attached two dts files tf-a and optee and full log. 

The files were generated from the latest STMCubeIde 1.17.0 with the necessary supplementation.

Thanks for any help

BR Michal

[GatienC]

Hello Michal,

In order to have some more information on what causes the panic, you can print the call stack. Please have a look at https://optee.readthedocs.io/en/latest/debug/abort_dumps.html.

This will heavily narrow down the search to the root cause.

Br,

Gatien

[MWoło.2]

Hi GatienC,

I think Your suggestion did not resolve my problem because in my debug-log.txt there are no records with just empty addresses or data dumps like

"E/TC:0  0x001044a8" 

 Besides in my log, I have no records like "E/TC" without the last 'panic'.

Can I find the example dts of optee for DK2 board or ED1.

In my opinion Cube generator did something improper or I defined something wrong in it.

BR,

Michal

[GatienC]

It most probably is linked to this but the backtrace will allow you to know which part of the code makes the platform panic.

Can you check in the "conf.mk" file in the build directory, that you have 

CFG_UNWIND=y

You can also set 

CFG_TEE_CORE_DEBUG=y

as well.

BR,

Gatien

[MWoło.2]

OK, I check and try new options and let You know soon.

Thanks for now.

BR,

Michal

My activity now is

Enabled options

CFG_UNWIND=y
CFG_TEE_CORE_DEBUG=y

cat debug-full-log.txt | ./scripts/symbolize.py -d tee-stm32mp157c-telemach-mx-optee.elf > debug-log-full-info.txt

How to correct read such log

Spoiler

E/TC:0 0 Panic at /usr/src/debug/optee-os-stm32mp/4.0.0-stm32mp-r1/core/arch/arm/plat-stm32mp1/shared_resources.c:333 <register_periph_iomem>
E/TC:0 0 TEE load address @ 0x2ffc0000
E/TC:0 0 Call stack:
E/TC:0 0 0x2ffc2155 print_kernel_stack w /usr/src/debug/optee-os-stm32mp/4.0.0-stm32mp-r1/core/arch/arm/kernel/unwind_arm32.c:109
E/TC:0 0 0x2ffc8623 __do_panic w /usr/src/debug/optee-os-stm32mp/4.0.0-stm32mp-r1/core/kernel/panic.c:88
E/TC:0 0 0x300311ef register_periph_iomem w /usr/src/debug/optee-os-stm32mp/4.0.0-stm32mp-r1/core/arch/arm/plat-stm32mp1/shared_resources.c:338
E/TC:0 0 0x30039549 stm32_iwdg_register w /usr/src/debug/optee-os-stm32mp/4.0.0-stm32mp-r1/core/drivers/stm32_iwdg.c:585
E/TC:0 0 0x3004726b probe_driver_node w /usr/src/debug/optee-os-stm32mp/4.0.0-stm32mp-r1/core/kernel/dt_driver.c:545
E/TC:0 0 0x300474b7 process_probe_list w /usr/src/debug/optee-os-stm32mp/4.0.0-stm32mp-r1/core/kernel/dt_driver.c:680
E/TC:0 0 0x30047dcd probe_dt_drivers_early w /usr/src/debug/optee-os-stm32mp/4.0.0-stm32mp-r1/core/kernel/dt_driver.c:881
E/TC:0 0 0x3004a741 call_initcalls w /usr/src/debug/optee-os-stm32mp/4.0.0-stm32mp-r1/core/kernel/initcall.c:41
E/TC:0 0 0x3006eae5 init_tee_runtime w /usr/src/debug/optee-os-stm32mp/4.0.0-stm32mp-r1/core/arch/arm/kernel/boot.c:1118
E/TC:0 0 0x3002f7cb boot_init_primary_late w /usr/src/debug/optee-os-stm32mp/4.0.0-stm32mp-r1/core/arch/arm/kernel/boot.c:1240
E/TC:0 0 0x2ffc01ac clear_bss w /home/mw/openstlinux-6.6-yocto-scarthgap-mpu-v24.12.05/build-openstlinuxweston-telemach-som/workspace/sources/optee-os-stm32mp/core/arch/arm/kernel/entry_a32.S:565

BR,

Michal

[MWoło.2]

Finally, I resolved a panic problem. The problem was related to iwdg2. Cube generates an iwdg2 section but without providing information into 

&etzpc {

DECPROT(STM32MP1_ETZPC_IWDG2_ID, DECPROT_S_RW, DECPROT_UNLOCK)

}

When I change iwdg2 to iwdg1 cube put the above information for IWDG1. I'm not sure if it is a feature or a bug.

Now log look much better

Spoiler

NOTICE: CPU: STM32MP157CAA Rev.Z
NOTICE: Model: Telemach SOM
INFO: PMIC version = 0x21
WARNING: VDD unknown
NOTICE: Reset reason (0x15):
INFO: Power-on Reset (rst_por)
INFO: FCONF: Reading TB_FW firmware configuration file from: 0x2ffe2000
INFO: FCONF: Reading firmware configuration information for: stm32mp_fuse
INFO: FCONF: Reading firmware configuration information for: stm32mp_io
INFO: Using EMMC
INFO: Instance 2
INFO: Boot used partition fsbl1
NOTICE: BL2: v2.10-stm32mp1-r1.0(debug):lts-v2.10.5-dirty(7c229848)
NOTICE: BL2: Built : 16:19:31, Jun 28 2024
INFO: BL2: Doing platform setup
INFO: RAM: DDR3-DDR3L 16bits 533000kHz
INFO: Memory size = 0x20000000 (512 MB)
INFO: BL2: Loading image id 1
INFO: Loading image id=1 at address 0x2ffff000
INFO: Image id=1 loaded: 0x2ffff000 - 0x2ffff1ea
INFO: FCONF: Reading FW_CONFIG firmware configuration file from: 0x2ffff000
INFO: FCONF: Reading firmware configuration information for: dyn_cfg
INFO: FCONF: Reading firmware configuration information for: stm32mp1_firewall
INFO: BL2: Loading image id 4
INFO: Loading image id=4 at address 0x2ffc0000
INFO: Image id=4 loaded: 0x2ffc0000 - 0x2ffc002c
INFO: OPTEE ep=0x2ffc0000
INFO: OPTEE header info:
INFO: magic=0x4554504f
INFO: version=0x2
INFO: arch=0x0
INFO: flags=0x0
INFO: nb_images=0x2
INFO: BL2: Loading image id 8
INFO: Loading image id=8 at address 0x2ffc0000
INFO: Image id=8 loaded: 0x2ffc0000 - 0x2ffd0a50
INFO: BL2: Loading image id 9
INFO: Loading image id=9 at address 0xde000000
INFO: Image id=9 loaded: 0xde000000 - 0xde06d000
INFO: BL2: Loading image id 2
INFO: Loading image id=2 at address 0xc0500000
INFO: Image id=2 loaded: 0xc0500000 - 0xc0514d50
INFO: BL2: Skip loading image id 16
INFO: BL2: Loading image id 5
INFO: Loading image id=5 at address 0xc0100000
INFO: Image id=5 loaded: 0xc0100000 - 0xc021e500
NOTICE: BL2: Booting BL32
INFO: Entry point address = 0x2ffc0000
INFO: SPSR = 0x1d3
I/TC: Early console on UART#4
I/TC:
I/TC: Pager is enabled. Hashes: 3584 bytes
I/TC: Pager pool size: 104kB
I/TC: Embedded DTB found
I/TC: OP-TEE version: devtool-patched-1-g548bebf78 (gcc version 13.3.0 (GCC)) #37 Sat Jan 11 19:21:36 UTC 2025 arm
I/TC: WARNING: This OP-TEE configuration might be insecure!
I/TC: WARNING: Please check https://optee.readthedocs.io/en/latest/architecture/porting_guidelines.html
I/TC: Primary CPU initializing
I/TC: Override the OTP 18: 0x7b4f0000 to 0x7b4f01e0
I/TC: WARNING: Embeds insecure stm32mp_provisioning driver
I/TC: Platform stm32mp1: flavor PLATFORM_FLAVOR - DT stm32mp157c-telemach-mx.dts
I/TC: OP-TEE ST profile: secure_and_system_services
E/TC:0 0 call_initcalls:43 Initcall __text_start + 0x000276b0 failed
I/TC: Primary CPU switching to normal world boot
I/TC: Reserved shared memory is disabled
I/TC: Dynamic shared memory is enabled
I/TC: Normal World virtualization support is disabled
I/TC: Asynchronous notifications are disabled
optee optee: OP-TEE: revision 4.0 (548bebf7)
serial_stm32 serial@40010000: pinctrl_select_state_full: uclass_get_device_by_phandle_id: err=-19

U-Boot 2023.10-stm32mp-r1 (Oct 02 2023 - 14:39:59 +0000)

CPU: STM32MP157CAA Rev.Z
Model: Telemach SOM
Board: stm32mp1 in trusted mode (st,stm32mp157c-telemach-mx)
DRAM: no /fwu-mdata node ?
512 MiB
optee optee: OP-TEE: revision 4.0 (548bebf7)
I/TC: Reserved shared memory is disabled
I/TC: Dynamic shared memory is enabled
I/TC: Normal World virtualization support is disabled
I/TC: Asynchronous notifications are disabled
Clocks:
- MPU : 650 MHz
- MCU : 200 MHz
- AXI : 64 MHz
- PER : 64 MHz
- DDR : 533 MHz
Core: 122 devices, 39 uclasses, devicetree: board
NAND: 0 MiB
MMC: STM32 SD/MMC: 0, STM32 SD/MMC: 1
Loading Environment from MMC... *** Warning - bad CRC, using default environment

In: serial
Out: serial
Err: serial
invalid MAC address 0 in OTP 00:00:00:00:00:00
Net:
Error: ethernet@5800a000 address not set.
No ethernet found.

MMC: no card present
No EFI system partition
No EFI system partition
Failed to persist EFI variables

Error: ethernet@5800a000 address not set.

Error: ethernet@5800a000 address not set.
Hit any key to stop autoboot: 0
Boot over mmc1!
Saving Environment to MMC... Writing to MMC(1)... OK
switch to partitions #0, OK
mmc1(part 0) is current device
Scanning mmc 1:6...
Found U-Boot script /boot.scr.uimg
4187 bytes read in 72 ms (56.6 KiB/s)
## Executing script at c6100000
Executing SCRIPT on target=mmc1
FOUND /mmc1_extlinux/extlinux.conf
Saving Environment to MMC... Writing to MMC(1)... OK
switch to partitions #0, OK
mmc1(part 0) is current device
Scanning mmc 1:6...
Found /mmc1_extlinux/extlinux.conf
Retrieving file: /mmc1_extlinux/extlinux.conf
Retrieving file: /splash_portrait.bmp
1: OpenSTLinux
Enter choice: 1: OpenSTLinux
Retrieving file: /uImage
Retrieving file: /st-image-resize-initrd
append: root=PARTUUID=491f6117-415d-4f53-88c9-6e0de54deac6 rootwait rw console=ttySTM0,115200
Retrieving file: /stm32mp157c-telemach-mx.dtb
## Booting kernel from Legacy Image at c2000000 ...
Image Name: Linux-6.6.48
Created: 2024-08-29 15:33:59 UTC
Image Type: ARM Linux Kernel Image (uncompressed)
Data Size: 8613632 Bytes = 8.2 MiB
Load Address: c2000040
Entry Point: c2000040
Verifying Checksum ... OK
## Flattened Device Tree blob at c6000000
Booting using the fdt blob at 0xc6000000
Working FDT set to c6000000
XIP Kernel Image
Loading Ramdisk to cf9d1000, end cfffff6a ... OK
Loading Device Tree to cf9b9000, end cf9d04b9 ... OK
Working FDT set to cf9b9000

Starting kernel ...

I/TC: Secondary CI/TC: Secondary CPU 1 switching to normal world boot

Of course, there is still in the log some error but go up to the Kernel booting. Unfortunately stuck on the last line in the log and that's all. Do I need to add something special to the Kernel dts?

Shall I again add more debug logs to see a problem or it is something obvious I omit?

BR,

Michal

[GatienC]

Hello Michal,

Be aware that only secure peripherals will have their driver probed in OP-TEE, as you have figured while fixing this issue. I don't think the CubeMX is supposed to omit the firewall configuration if you select OP-TEE AFAIK but the IWDG2 peripheral is non-securable on stm32mp15x platforms so it's normal that it was not generated. Only securable watchdog is IWDG1 on these platforms.

Please note that if you're using a peripheral in the secure world (hence configuring it as secure) you cannot expect the non-secure world to access it directly.

The error log in OP-TEE indicates that a service failed to initialize so I would try to fix or understand this before going further. Adding more debug log will hopefully allow you to identify the service that failed, so yes, I would add a higher log level in OP-TEE.

Regarding the freeze in the kernel, I would also add the early console on the kernel side to get some more information as well.

[MWoło.2]

Hi GatienC,

First, thanks for the explanation. I'm a newbie in the trust zone, optee, and other security-related topics. Understanding it at a minimal level is necessary to go further.

Regarding IWDG2 I misunderstand the checkbox in the cube

The checkbox does not always mean that the peripheral is secured. In the documentation, I found confirmation of what You wrote above.

Documentation source RM0436 Rev 6 page 1121

Now I understand how many things I do wrong, and what I should fix in my dts files.

Today, I am going to try to re-enable all debug features of OP-TEE to investigate why the kernel is not starting and to remove all OP-TEE errors, even if they do not affect the boot process.

BR,

Michal