[rom_ext] BootLog incorrect for currently executing ROM_EXT slot

jettr commented 4 months ago

Description

It appears that the boot log that reports the active ROM_EXT is incorrect in some scenarios. Notice the following from the abridge firmware log after performing a firmware update that contains both a new ROM_EXT and new Owner Firmware.

Starting ROM_EXT 0.2
0x406007a8: 5f5f4141 00000000 00000002 00010000 (memory dump of BootLog section start with rom_ext_slot
Starting ROM_EXT 0.3
0x406007a8: 5f5f4141 00000000 00000003 00010000
- This is especially concerning since the rom_ext_slot is reporting SlotA (AA__), but the version is reporting 0.3, but SlotA contains 0.2, and SlotB contains 0.3. I am pretty sure 0.3 is what actually ran since it printed Starting ROM_EXT 0.3 on the UART.

The boot log remains incorrect event after performing soft reboots from FW (via reboot console command). Only after I perform a chip reset with the RESET_L pin, do I see the boot log be correct.

Log from a ROM_EXT and owner firmware update:

Starting ROM_EXT 0.2
Warning: UDS certificate not valid.
0: 40130000 NAPOT L--- sz=00001000
1: 40480000 NAPOT L--- sz=00000400
2: a0010400 ----- ---- sz=00000000
3: a0071d0c   TOR -X-R sz=0006190c
4: a0000000 NAPOT ---R sz=00080000
5: 00000000 ----- ---- sz=00000000
6: 00000000 ----- ---- sz=00000000
7: 00000000 ----- ---- sz=00000000
8: 00000000 ----- ---- sz=00000000
9: 00000000 ----- ---- sz=00000000
10: 20000400 ----- ---- sz=00000000
11: 20008a78   TOR -X-R sz=00008678
12: 20000000 NAPOT ---R sz=00100000
13: 00000000 ----- ---- sz=00000000
14: 40000000 NAPOT --WR sz=10000000
15: 10000000 NAPOT --WR sz=00020000
mseccfg = 00000002
entry: 0xa0010730

[       0.001] Starting OpenTitan RO 0.0.2 RW 0.36.1
[       0.001] DBG/ti50_common_tot:v0.0.1372-09498a29 libtock-rs:v0.0.925-1213708 tock:v0.0.9673-2649e0509 ms-tpm-20-ref:v0.0.318-9942b1f jettrink@rink.bld.corp.google.com 2024-07-01 10:20:26
> md 0x406007a8 16
md 0x406007a8 16
0x406007a8: 5f5f4141 00000000 00000002 00010000
0x406007b8: 00000000 00000000 5f5f4141 00000000
0x406007c8: 00000000 00000000 00000000 5f5f4141
0x406007d8: 00000000 00000000 00000000 00000000
>
[     272.146] at 0x090000
[     272.157] at 0x090400
...
[     276.413] at 0x08a000
[     276.422] at 0x08a400
[     276.438] Erase on active bank.
[     276.440] turn_update_on: rebooting in 100 ms
Starting ROM_EXT 0.3
Warning: UDS certificate not valid.
CDI_0 certificate not valid. Updating it ...
CDI_1 certificate not valid. Updating it ...
0: 40130000 NAPOT L--- sz=00001000
1: 40480000 NAPOT L--- sz=00000400
2: a0010400 ----- ---- sz=00000000
3: a0071d0c   TOR -X-R sz=0006190c
4: a0000000 NAPOT ---R sz=00080000
5: 00000000 ----- ---- sz=00000000
6: 00000000 ----- ---- sz=00000000
7: 00000000 ----- ---- sz=00000000
8: 00000000 ----- ---- sz=00000000
9: 00000000 ----- ---- sz=00000000
10: 20080400 ----- ---- sz=00000000
11: 200889a4   TOR -X-R sz=000085a4
12: 20000000 NAPOT ---R sz=00100000
13: 00000000 ----- ---- sz=00000000
14: 40000000 NAPOT --WR sz=10000000
15: 10000000 NAPOT --WR sz=00020000
mseccfg = 00000002
entry: 0xa0010730

[       0.000] Starting OpenTitan RO 0.0.2 RW 0.36.1
[       0.000] DBG/ti50_common_tot:v0.0.1372-09498a29 libtock-rs:v0.0.925-1213708 tock:v0.0.9673-2649e0509 ms-tpm-20-ref:v0.0.318-9942b1f jettrink@rink.bld.corp.google.com 2024-07-01 10:20:26

> md 0x406007a8 16
md 0x406007a8 16
0x406007a8: 5f5f4141 00000000 00000003 00010000
0x406007b8: 00000000 00000000 5f5f4141 00000000
0x406007c8: 00000000 00000000 00000000 5f5f4141
0x406007d8: 00000000 00000000 00000000 00000000

Log from firmware initiated soft reboot

> reboot

Starting ROM_EXT 0.3
Warning: UDS certificate not valid.
0: 40130000 NAPOT L--- sz=00001000
1: 40480000 NAPOT L--- sz=00000400
2: a0010400 ----- ---- sz=00000000
3: a0071d0c   TOR -X-R sz=0006190c
4: a0000000 NAPOT ---R sz=00080000
5: 00000000 ----- ---- sz=00000000
6: 00000000 ----- ---- sz=00000000
7: 00000000 ----- ---- sz=00000000
8: 00000000 ----- ---- sz=00000000
9: 00000000 ----- ---- sz=00000000
10: 20080400 ----- ---- sz=00000000
11: 200889a4   TOR -X-R sz=000085a4
12: 20000000 NAPOT ---R sz=00100000
13: 00000000 ----- ---- sz=00000000
14: 40000000 NAPOT --WR sz=10000000
15: 10000000 NAPOT --WR sz=00020000
mseccfg = 00000002
entry: 0xa0010730

[       0.000] Starting OpenTitan RO 0.0.2 RW 0.36.1
[       0.000] DBG/ti50_common_tot:v0.0.1372-09498a29 libtock-rs:v0.0.925-1213708 tock:v0.0.9673-2649e0509 ms-tpm-20-ref:v0.0.318-9942b1f jettrink@rink.bld.corp.google.com 2024-07-01 10:20:26

> md 0x406007a8 16
md 0x406007a8 16
0x406007a8: 5f5f4141 00000000 00000003 00010000
0x406007b8: 00000000 00000000 5f5f4141 00000000
0x406007c8: 00000000 00000000 00000000 5f5f4141
0x406007d8: 00000000 00000000 00000000 00000000

Log after performing ott gpio apply RESET && ott gpio remove RESET

Starting ROM_EXT 0.3
Warning: UDS certificate not valid.
0: 40130000 NAPOT L--- sz=00001000
1: 40480000 NAPOT L--- sz=00000400
2: a0010400 ----- ---- sz=00000000
3: a0071d0c   TOR -X-R sz=0006190c
4: a0000000 NAPOT ---R sz=00080000
5: 00000000 ----- ---- sz=00000000
6: 00000000 ----- ---- sz=00000000
7: 00000000 ----- ---- sz=00000000
8: 00000000 ----- ---- sz=00000000
9: 00000000 ----- ---- sz=00000000
10: 20080400 ----- ---- sz=00000000
11: 200889a4   TOR -X-R sz=000085a4
12: 20000000 NAPOT ---R sz=00100000
13: 00000000 ----- ---- sz=00000000
14: 40000000 NAPOT --WR sz=10000000
15: 10000000 NAPOT --WR sz=00020000
mseccfg = 00000002
entry: 0xa0010730

[       0.000] Starting OpenTitan RO 0.0.3 RW 0.36.1
[       0.000] DBG/ti50_common_tot:v0.0.1372-09498a29 libtock-rs:v0.0.925-1213708 tock:v0.0.9673-2649e0509 ms-tpm-20-ref:v0.0.318-9942b1f jettrink@rink.bld.corp.google.com 2024-07-01 10:20:26
> md 0x406007a8 16
md 0x406007a8 16
0x406007a8: 42425f5f 00000000 00000003 00010000
0x406007b8: 00000000 00000000 5f5f4141 00000000
0x406007c8: 00000000 00000000 00000000 5f5f4141
0x406007d8: 00000000 00000000 00000000 00000000

Notice that 0x406007a8: 42425f5f 00000000 00000003 00010000 correct indicates that SlotB (__BB) is executing ROM_EXT version 0.3 now.

zhangarino commented 3 weeks ago

I think this issue is also occurring for the primary boot slot field if you attempt to swap it using boot services. This is what I'm doing:

In each slot have two valid BL0 images. The primary slot is boot slot A, and the active slot is A as well.
Put the boot service request to change the primary slot to the inactive slot B.
Make a SW reset request through rstmgr peripheral
On bl0 re-entry the primary slot is swapped because the active slot is now B. However checking the boot log it reports the old primary slot A.

If I reboot the device again, the primary slot updates to the correct value. Having the primary slot being correctly reported by ROM_EXT is useful to know if an image update was successful or not.

zhangarino commented 3 weeks ago

I'm seeing this issue on the earlgrey_es_sival branch using the ROM_EXT 0.4 prebuilt.

Edit: Sorry I think this is probably a different issue... this one is for reporting the booted ROM_EXT slot, but the issue I'm seeing is about the reported primary BL0 slot. I'll file a new issue.

lowRISC / opentitan

[rom_ext] BootLog incorrect for currently executing ROM_EXT slot #23869

Description