search

OP-TEE / optee_os

Trusted side of the TEE
Other
1.57k stars 1.06k forks source link

How to debug when the Linux kernel does not boot? #4495

Closed zeroalphat closed 3 years ago

zeroalphat commented 3 years ago

After making the changes to OP-TEE, I followed the documentation to build and run it on a Raspberry Pi 3B. However, after the serial console shows "Starting kernel", there is no output and the Linux Kernel does not boot. I decided to enable earlyprintk by referring to other issue #3816. I tried to enable config_early_printk with make menuconfig, but earlyprintk was not enabled. I would like to know how to debug when the Linux Kernl does not boot.

I've attached the boot log obtained through serial communication below.

The execution environment is as follows. OP-TEE 3.6 Board: Raspberry Pi 3B

NOTICE:  Booting Trusted Firmware
NOTICE:  BL1: v2.0(debug):v2.0-580-g023bc019e
NOTICE:  BL1: Built : 05:59:10, Mar 14 2021
INFO:    BL1: RAM 0x100ee000 - 0x100f7000
INFO:    BL1: cortex_a53: CPU workaround for 843419 was applied
INFO:    BL1: cortex_a53: CPU workaround for 855873 was applied
ERROR:   rpi3: Unknown board revision 0x00a32082
NOTICE:  rpi3: Detected: Unknown (Unknown) [0x00a32082]
INFO:    BL1: Loading BL2
INFO:    Loading image id=1 at address 0x100b4000
INFO:    Image id=1 loaded: 0x100b4000 - 0x100b9410
NOTICE:  BL1: Booting BL2
INFO:    Entry point address = 0x100b4000
INFO:    SPSR = 0x3c5
NOTICE:  BL2: v2.0(debug):v2.0-580-g023bc019e
NOTICE:  BL2: Built : 05:59:10, Mar 14 2021
INFO:    BL2: Doing platform setup
INFO:    BL2: Loading image id 3
INFO:    Loading image id=3 at address 0x100e0000
INFO:    Image id=3 loaded: 0x100e0000 - 0x100e9078
INFO:    BL2: Loading image id 4
INFO:    Loading image id=4 at address 0x10100000
INFO:    Image id=4 loaded: 0x10100000 - 0x1010001c
INFO:    OPTEE ep=0x10100000
INFO:    OPTEE header info:
INFO:          magic=0x4554504f
INFO:          version=0x2
INFO:          arch=0x1
INFO:          flags=0x0
INFO:          nb_images=0x1
INFO:    BL2: Loading image id 21
INFO:    Loading image id=21 at address 0x10100000
INFO:    Image id=21 loaded: 0x10100000 - 0x10156380
INFO:    BL2: Skip loading image id 22
INFO:    BL2: Loading image id 5
INFO:    Loading image id=5 at address 0x11000000
INFO:    Image id=5 loaded: 0x11000000 - 0x110764a0
NOTICE:  BL1: Booting BL31
INFO:    Entry point address = 0x100e0000
INFO:    SPSR = 0x3cd
NOTICE:  BL31: v2.0(debug):v2.0-580-g023bc019e
NOTICE:  BL31: Built : 05:59:10, Mar 14 2021
INFO:    rpi3: Checking DTB...
INFO:    BL31: Initializing runtime services
INFO:    BL31: cortex_a53: CPU workaround for 843419 was applied
INFO:    BL31: cortex_a53: CPU workaround for 855873 was applied
INFO:    BL31: Initializing BL32
D/TC:0 0 add_phys_mem:576 TEE_SHMEM_START type NSEC_SHM 0x08000000 size 0x00400000
D/TC:0 0 add_phys_mem:576 TA_RAM_START type TA_RAM 0x10800000 size 0x00800000
D/TC:0 0 add_phys_mem:576 VCORE_UNPG_RW_PA type TEE_RAM_RW 0x10156000 size 0x006aa000
D/TC:0 0 add_phys_mem:576 VCORE_UNPG_RX_PA type TEE_RAM_RX 0x10100000 size 0x00056000
D/TC:0 0 add_phys_mem:576 ROUNDDOWN(0x3f215040, CORE_MMU_PGDIR_SIZE) type IO_NSEC 0x3f200000 size 0x00200000
D/TC:0 0 verify_special_mem_areas:514 No NSEC DDR memory area defined
D/TC:0 0 add_va_space:615 type RES_VASPACE size 0x00a00000
D/TC:0 0 add_va_space:615 type SHM_VASPACE size 0x02000000
D/TC:0 0 dump_mmap_table:751 type TEE_RAM_RX   va 0x10100000..0x10155fff pa 0x10100000..0x10155fff size 0x00056000 (smallpg)
D/TC:0 0 dump_mmap_table:751 type TEE_RAM_RW   va 0x10156000..0x107fffff pa 0x10156000..0x107fffff size 0x006aa000 (smallpg)
D/TC:0 0 dump_mmap_table:751 type NSEC_SHM     va 0x10800000..0x10bfffff pa 0x08000000..0x083fffff size 0x00400000 (pgdir)
D/TC:0 0 dump_mmap_table:751 type RES_VASPACE  va 0x10c00000..0x115fffff pa 0x00000000..0x009fffff size 0x00a00000 (pgdir)
D/TC:0 0 dump_mmap_table:751 type SHM_VASPACE  va 0x11600000..0x135fffff pa 0x00000000..0x01ffffff size 0x02000000 (pgdir)
D/TC:0 0 dump_mmap_table:751 type TA_RAM       va 0x13600000..0x13dfffff pa 0x10800000..0x10ffffff size 0x00800000 (pgdir)
D/TC:0 0 dump_mmap_table:751 type IO_NSEC      va 0x13e00000..0x13ffffff pa 0x3f200000..0x3f3fffff size 0x00200000 (pgdir)
D/TC:0 0 core_mmu_entry_to_finer_grained:795 xlat tables used 1 / 5
D/TC:0 0 core_mmu_entry_to_finer_grained:795 xlat tables used 2 / 5
I/TC: 
D/TC:0 0 init_canaries:161 #Stack canaries for stack_tmp[0] with top at 0x10191b38
D/TC:0 0 init_canaries:161 watch *0x10191b3c
D/TC:0 0 init_canaries:161 #Stack canaries for stack_tmp[1] with top at 0x10192378
D/TC:0 0 init_canaries:161 watch *0x1019237c
D/TC:0 0 init_canaries:161 #Stack canaries for stack_tmp[2] with top at 0x10192bb8
D/TC:0 0 init_canaries:161 watch *0x10192bbc
D/TC:0 0 init_canaries:161 #Stack canaries for stack_tmp[3] with top at 0x101933f8
D/TC:0 0 init_canaries:161 watch *0x101933fc
D/TC:0 0 init_canaries:162 #Stack canaries for stack_abt[0] with top at 0x10186d38
D/TC:0 0 init_canaries:162 watch *0x10186d3c
D/TC:0 0 init_canaries:162 #Stack canaries for stack_abt[1] with top at 0x10187978
D/TC:0 0 init_canaries:162 watch *0x1018797c
D/TC:0 0 init_canaries:162 #Stack canaries for stack_abt[2] with top at 0x101885b8
D/TC:0 0 init_canaries:162 watch *0x101885bc
D/TC:0 0 init_canaries:162 #Stack canaries for stack_abt[3] with top at 0x101891f8
D/TC:0 0 init_canaries:162 watch *0x101891fc
D/TC:0 0 init_canaries:164 #Stack canaries for stack_thread[0] with top at 0x1018b238
D/TC:0 0 init_canaries:164 watch *0x1018b23c
D/TC:0 0 init_canaries:164 #Stack canaries for stack_thread[1] with top at 0x1018d278
D/TC:0 0 init_canaries:164 watch *0x1018d27c
D/TC:0 0 init_canaries:164 #Stack canaries for stack_thread[2] with top at 0x1018f2b8
D/TC:0 0 init_canaries:164 watch *0x1018f2bc
D/TC:0 0 init_canaries:164 #Stack canaries for stack_thread[3] with top at 0x101912f8
D/TC:0 0 init_canaries:164 watch *0x101912fc
I/TC: OP-TEE version: Unknown (gcc version 8.3.0 (GNU Toolchain for the A-profile Architecture 8.3-2019.03 (arm-rel-8.36))) #1 Sat Mar 13 13:46:15 UTC 2021 aarch64
D/TC:0 0 check_ta_store:638 TA store: "Secure Storage TA"
D/TC:0 0 check_ta_store:638 TA store: "REE [buffered]"
D/TC:0 0 mobj_mapped_shm_init:447 Shared memory address range: 11600000, 13600000
I/TC: Initialized
D/TC:0 0 init_primary_helper:1109 Primary CPU switching to normal world boot
INFO:    BL31: Preparing for EL3 exit to normal world
INFO:    Entry point address = 0x11000000
INFO:    SPSR = 0x3c9

U-Boot 2019.01-00093-gaac0c29d4b-dirty (Mar 14 2021 - 05:58:56 +0900)

DRAM:  948 MiB
RPI 3 Model B (0xa32082)
MMC:   mmc@7e202000: 0, sdhci@7e300000: 1
Loading Environment from FAT... OK
In:    serial
Out:   serial
Err:   serial
Net:   No ethernet found.
starting USB...
USB0:   scanning bus 0 for devices... 3 USB Device(s) found
       scanning usb for storage devices... 0 Storage Device(s) found
Hit any key to stop autoboot:  3  2  1  0 
15110656 bytes read in 628 ms (22.9 MiB/s)
## Flattened Device Tree blob at 01000000
   Booting using the fdt blob at 0x1000000
   reserving fdt memory region: addr=8000000 size=2000000
   reserving fdt memory region: addr=0 size=1000
   Loading Device Tree to 000000003af3e000, end 000000003af476c7 ... OK

Starting kernel ...

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:3   tee_entry_exchange_capabilities:101 Dynamic shared memory is disabled
jforissier commented 3 years ago

Hi @zeroalphat,

D/TC:3   init_secondary_helper:1133 Secondary CPU Switching to normal world boot
D/TC:3   tee_entry_exchange_capabilities:101 Dynamic shared memory is disabled

At this point the kernel has started booting on CPU 0 and each secondary CPU has re-entered OP-TEE to initialize. So everything looks good from an OP-TEE point of view. I would think the reason you are not seeing any log from the kernel is some mis-consfiguration of the kernel console, bad kernel command line arguments perhaps?

zeroalphat commented 3 years ago

Thanks for the quick reply. It is indeed possible that the kernel output is not being displayed on the serial console. Where can I find the settings for kernel console and kernel command line?

jforissier commented 3 years ago

Perhaps in https://github.com/OP-TEE/build/blob/3.6.0/rpi3/firmware/uboot.env.txt? I will let people more familiar with the RPi board comment further.

zeroalphat commented 3 years ago

Thank you very much. I'll try it.

github-actions[bot] commented 3 years ago

This issue has been marked as a stale issue because it has been open (more than) 30 days with no activity. Remove the stale label or add a comment, otherwise this issue will automatically be closed in 5 days. Note, that you can always re-open a closed issue at any time.