search

chipsalliance / caliptra-sw

Caliptra software (ROM, FMC, runtime firmware), and libraries/tools needed to build and test
Apache License 2.0
94 stars 44 forks source link

Verilator test failure: caliptra-fmc::test_rtalias test_pcr_log #850

Closed korran closed 1 year ago

korran commented 1 year ago

Test executed against 046881797e05d0e956422ab0a85b3960acd9c7fd

2023-09-19T09:31:53.9936422Z         FAIL [31168.002s] caliptra-fmc::test_rtalias test_pcr_log
2023-09-19T09:31:54.0070321Z 
2023-09-19T09:31:54.0075821Z --- STDOUT:              caliptra-fmc::test_rtalias test_pcr_log ---
2023-09-19T09:31:54.0076272Z 
2023-09-19T09:31:54.0399856Z running 1 test
2023-09-19T09:31:54.0400871Z test test_pcr_log has been running for over 60 seconds
2023-09-19T09:31:54.0402139Z       6,155 ready_for_fuses is high
2023-09-19T09:31:54.0403251Z       6,333 writing to cptra_bootfsm_go
2023-09-19T09:31:54.0404036Z     195,201 UART: 
2023-09-19T09:31:54.0404851Z     195,256 UART: Running Caliptra ROM ...
2023-09-19T09:31:54.0840782Z     196,662 UART: 
2023-09-19T09:31:54.0841688Z     202,819 UART: [state] CFI Enabled
2023-09-19T09:31:54.0842681Z     205,066 UART: [state] LifecycleState = Unprovisioned
2023-09-19T09:31:54.0843597Z     207,326 UART: [state] DebugLocked = No
2023-09-19T09:31:54.0847708Z     209,730 UART: [state] Watchdog Timer is not started because the device is not locked for debugging
2023-09-19T09:31:54.0849304Z     357,594 UART: ROM Digest: BBB6BA0BFBA2F1E2103A1060EB333FF6613A1F43E352AA823F62EF22650FF80F
2023-09-19T09:31:54.0850290Z     368,834 UART: [kat] ++
2023-09-19T09:31:54.0850869Z     369,346 UART: [kat] sha1
2023-09-19T09:31:54.0902805Z     378,506 UART: [kat] SHA2-256
2023-09-19T09:31:54.0903955Z     381,378 UART: [kat] SHA2-384
2023-09-19T09:31:54.0904570Z     385,643 UART: [kat] SHA2-384-ACC
2023-09-19T09:31:54.0905148Z     387,940 UART: [kat] ECC-384
2023-09-19T09:31:54.0905696Z   3,958,294 UART: [kat] HMAC-384
2023-09-19T09:31:54.0906192Z   3,969,346 UART: [kat] LMS
2023-09-19T09:31:54.0906695Z   5,071,148 UART: [kat] --
2023-09-19T09:31:54.1360306Z   5,074,555 UART: [cold-reset] ++
2023-09-19T09:31:54.1360933Z   5,076,995 UART: [idev] ++
2023-09-19T09:31:54.1361467Z   5,077,574 UART: [idev] CDI.KEYID = 6
2023-09-19T09:31:54.1362113Z   5,078,824 UART: [idev] SUBJECT.KEYID = 7
2023-09-19T09:31:54.1362636Z   5,080,296 UART: [idev] UDS.KEYID = 0
2023-09-19T09:31:54.1363203Z   5,096,725 UART: [idev] Erasing UDS.KEYID = 0
2023-09-19T09:31:54.1363787Z   8,363,501 UART: [idev] Using Sha1 for KeyId Algorithm
2023-09-19T09:31:54.1364459Z   8,386,797 UART: [idev] --
2023-09-19T09:31:54.1365343Z   8,391,014 UART: [ldev] ++
2023-09-19T09:31:54.1365958Z   8,391,607 UART: [ldev] CDI.KEYID = 6
2023-09-19T09:31:54.1366475Z   8,392,849 UART: [ldev] SUBJECT.KEYID = 5
2023-09-19T09:31:54.1367077Z   8,394,321 UART: [ldev] AUTHORITY.KEYID = 7
2023-09-19T09:31:54.1367633Z   8,395,903 UART: [ldev] FE.KEYID = 1
2023-09-19T09:31:54.1368166Z   8,405,116 UART: [ldev] Erasing FE.KEYID = 1
2023-09-19T09:31:54.1368794Z  11,690,261 UART: [ldev] Signing Cert with AUTHORITY.KEYID = 7
2023-09-19T09:31:54.1369775Z  15,286,382 UART: [ldev] PUB.X = 504D38CA45D997901F48BA333A149A2FB2668B973AAC64D3B79ECC09A663F02ED2FABA133F5FA499677AEB7687C99B25
2023-09-19T09:31:54.1371068Z  15,302,080 UART: [ldev] PUB.Y = A5CD31125698B3322C086E4398A591946BF20A3ECEA8EB7D7C23410D49FA877E7ECFBE47BD883BD53D7DA865AC217F1D
2023-09-19T09:31:54.1372504Z  15,318,150 UART: [ldev] SIG.R = 14B5D494DF875AC7CEE9FE3E9A6168A6B64BFB01171F5ECC5216C8BB945FAF957CED1BE6C7CFBB1DDB2B7F4BFD76A492
2023-09-19T09:31:54.1373738Z  15,334,062 UART: [ldev] SIG.S = 821D8CC92F40AFF934771D7652C9BC3C59D47E5635E110A8486B76F7433B02B3C6B0FD8B1B6548B5994C481547111FC5
2023-09-19T09:31:54.1374643Z  15,357,005 UART: [ldev] --
2023-09-19T09:31:54.1375115Z  15,363,503 ready_for_fw is high
2023-09-19T09:31:54.1375798Z  15,363,505 <<< Executing mbox cmd 0x46574c44 (23288 bytes) from SoC
2023-09-19T09:31:54.1376442Z  15,363,564 UART: [fwproc] Waiting for Commands...
2023-09-19T09:31:54.1377038Z  15,377,210 UART: [fwproc] Received command 0x46574c44
2023-09-19T09:31:54.1377643Z  15,379,824 UART: [fwproc] Received Image of size 23288 bytes
2023-09-19T09:31:54.1380378Z  18,071,236 UART: [fwproc] Image verified using Vendor ECC Key Index 0
2023-09-19T09:31:54.1381122Z  18,155,053 UART: [fwproc] Loading FMC at address 0x40000000 len 12964
2023-09-19T09:31:54.1381799Z  18,236,459 UART: [fwproc] Loading Runtime at address 0x40004000 len 4440
2023-09-19T09:31:54.1680777Z  18,267,431 >>> mbox cmd response: success
2023-09-19T09:31:54.1681626Z  18,267,436 <<< Executing mbox cmd 0x10000001 (0 bytes) from SoC
2023-09-19T09:31:54.1682273Z  18,271,374 UART: [afmc] ++
2023-09-19T09:31:54.1682854Z  18,271,953 UART: [afmc] CDI.KEYID = 6
2023-09-19T09:31:54.1683404Z  18,273,203 UART: [afmc] SUBJECT.KEYID = 7
2023-09-19T09:31:54.1683955Z  18,274,649 UART: [afmc] AUTHORITY.KEYID = 5
2023-09-19T09:31:54.1684758Z  21,590,894 UART: [afmc] Signing Cert with AUTHORITY.KEYID = 5
2023-09-19T09:31:54.1685601Z  23,886,489 UART: [afmc] Erasing AUTHORITY.KEYID = 5
2023-09-19T09:31:54.1686944Z  25,195,583 UART: [afmc] PUB.X = 74A2DA8F43E3CF7B034EB91F9FEBBBEBD3F2BB8B9B15CCF6B2944AE9C548D4ACDD20742598EA46075F5EE3D570A3C884
2023-09-19T09:31:54.1691443Z  25,211,371 UART: [afmc] PUB.Y = F0B6D79EFAF624F13C60ACE8287337FA10B411125D5F76A85844E286F5E554EBD2D1B41B1DFB30A078203A651EFE8C34
2023-09-19T09:31:54.1692877Z  25,227,279 UART: [afmc] SIG.R = 8C94183EECD46495965C1F58565A801C567721535D1E46E8FBD8FE28C4361A17C85DDA0427F22D62A34CAFBA60DE91CF
2023-09-19T09:31:54.1694134Z  25,242,943 UART: [afmc] SIG.S = 57083EFAA8C09D86B408ABDEB8120F3A0A87C9C1DAD6EA4940C67CDFEED457B052E07185C310A798191C6F16BBB24B74
2023-09-19T09:31:54.1695724Z  25,269,252 UART: [afmc] --
2023-09-19T09:31:54.1696478Z  25,273,598 UART: [cold-reset] --
2023-09-19T09:31:54.1697093Z  25,288,461 UART: [fht] Storing FHT @ 0x50003400
2023-09-19T09:31:54.1697980Z  25,306,701 UART: [state] Watchdog Timer is not stopped because the device is not locked for debugging
2023-09-19T09:31:54.1698740Z  25,312,423 UART: [state] Locking Datavault
2023-09-19T09:31:54.1699368Z  25,317,301 UART: [state] Locking PCR0, PCR1 and PCR31
2023-09-19T09:31:54.1699945Z  25,319,377 UART: [state] Locking ICCM
2023-09-19T09:31:54.1700534Z  25,322,445 UART: [exit] Launching FMC @ 0x40000134
2023-09-19T09:31:54.1701085Z  25,331,255 UART: 
2023-09-19T09:31:54.1701567Z  25,331,288 UART: Running Caliptra FMC ...
2023-09-19T09:31:54.1702036Z  25,332,124 UART: 
2023-09-19T09:31:54.1702559Z  25,335,115 UART: [alias rt] Extend RT PCRs
2023-09-19T09:31:54.1703154Z  25,368,189 UART: [alias rt] Extend RT PCRs Done
2023-09-19T09:31:54.1703705Z  25,369,221 UART: [alias rt] Lock RT PCRs
2023-09-19T09:31:54.1704273Z  25,370,024 UART: [alias rt] Lock RT PCRs Done
2023-09-19T09:31:54.1704844Z  25,370,995 UART: [alias rt] Populate DV
2023-09-19T09:31:54.1705388Z  25,371,887 UART: [alias rt] Populate DV Done
2023-09-19T09:31:54.1705971Z  25,372,859 UART: Handoff : FMC CDI: 6
2023-09-19T09:31:54.1706696Z  25,373,622 UART: FMC Alias Private Key: 7
2023-09-19T09:31:54.1707310Z  25,375,525 UART: [alias rt] Derive CDI
2023-09-19T09:31:54.1707914Z  25,376,260 UART: [alias rt] Store in in slot 0x4
2023-09-19T09:31:54.1708518Z  25,409,991 UART: [alias rt] Derive Key Pair
2023-09-19T09:31:54.1709147Z  25,410,891 UART: [alias rt] Store priv key in slot 0x5
2023-09-19T09:31:54.1710111Z  28,650,087 UART: [alias rt] Derive Key Pair - Done
2023-09-19T09:31:54.1710761Z  28,661,092 UART: [alias rt] Signing Cert with AUTHO
2023-09-19T09:31:54.1711353Z  28,662,248 UART:             RITY.KEYID = 7
2023-09-19T09:31:54.1711976Z  30,940,366 UART: [alias rt] Erasing AUTHORITY.KEYID = 7
2023-09-19T09:31:54.1712966Z  30,941,865 UART: [alias rt] PUB.X = 52392ECE98D74317C65B97161A94C14FB020DCFBA7CF9EF95910E52A1E178EF526875037598894E2CFBA6C2D50DB6E3D
2023-09-19T09:31:54.1714153Z  30,949,283 UART: [alias rt] PUB.Y = FB503E4E8EF4F4EE3FF055F9879086684945D3F6FC7FB290589CD56D44D4B86800583BEC106EECB66E5E2EC694907FED
2023-09-19T09:31:54.1715394Z  30,956,852 UART: [alias rt] SIG.R = 27D5193BAA4A56402451FEF882EA18BF12FE9C8A4F613A02949AC348858A13E5FA980468ADAED803B06F40CBC7EED927
2023-09-19T09:31:54.1717754Z  30,964,252 UART: [alias rt] SIG.S = 42F11AFA12D187FCF55EC3915BBD157C62450CCB1571420F3C17739FF6C37D098D3392E3D1321CB7C38FED42492779C1
2023-09-19T09:31:54.1718607Z  32,267,768 UART: 
2023-09-19T09:31:54.1719134Z  32,267,801 UART:    _____                 __     __________   __   
2023-09-19T09:31:54.1719747Z  32,269,484 UART:   /     \   ____   ____ |  | __ \______   \_/  |_ 
2023-09-19T09:31:54.1720383Z  32,271,167 UART:  /  \ /  \ /  _ \_/ ___\|  |/ /  |       _/\   __\
2023-09-19T09:31:54.1721052Z  32,272,850 UART: /    Y    (  <_> )  \___|    <   |    |   \ |  |  
2023-09-19T09:31:54.1721664Z  32,274,533 UART: \____|__  /\____/ \___  >__|_ \  |____|_  / |__|  
2023-09-19T09:31:54.1722254Z  32,276,216 UART:         \/            \/     \/         \/       
2023-09-19T09:31:54.1722734Z  32,277,875 UART: 
2023-09-19T09:31:54.1723224Z  32,278,049 UART: Waiting for mailbox commands...
2023-09-19T09:31:54.1724216Z  32,279,143 UART: [fmc-test-harness] Received command: 0x10000001
2023-09-19T09:31:54.1724931Z  32,292,084 >>> mbox cmd response data (2048 bytes)
2023-09-19T09:31:54.1725665Z  32,293,234 <<< Executing mbox cmd 0x10000000 (0 bytes) from SoC
2023-09-19T09:31:54.1727594Z  32,293,298 UART: [fmc-test-harness] Received command: 0x10000000
2023-09-19T09:31:54.1728327Z  32,297,173 >>> mbox cmd response data (336 bytes)
2023-09-19T09:31:54.1728998Z  32,297,369 <<< Executing mbox cmd 0x10000002 (0 bytes) from SoC
2023-09-19T09:31:54.1729922Z  32,297,431 UART: [fmc-test-harness] Received command: 0x10000002
2023-09-19T09:31:54.1730994Z  32,318,903 >>> mbox cmd response data (1536 bytes)
2023-09-19T09:31:54.1731634Z  32,319,769 <<< Executing mbox cmd 0x46574c44 (23288 bytes) from SoC
2023-09-19T09:31:54.1732498Z  32,332,768 UART: [fmc-test-harness] Received command: 0x46574C44
2023-09-19T09:31:54.1733120Z  32,334,419 UART: RT Panic!!
2023-09-19T09:31:54.1733625Z  32,334,800 UART: RT Error: 0x0000DEAD
2023-09-19T09:31:54.1734223Z  32,335,537 >>> mbox cmd response: failed
2023-09-19T09:31:54.1734826Z test test_pcr_log ... FAILED
2023-09-19T09:31:54.1735165Z 
2023-09-19T09:31:54.1735326Z failures:
2023-09-19T09:31:54.1735588Z 
2023-09-19T09:31:54.1735739Z failures:
2023-09-19T09:31:54.1736266Z     test_pcr_log
2023-09-19T09:31:54.1736548Z 
2023-09-19T09:31:54.1737020Z test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 2 filtered out; finished in 31167.99s
bluegate010 commented 1 year ago

Probably the same root cause as https://github.com/chipsalliance/caliptra-sw/issues/786. The test is not performing hitless updates as it should.