search

chipsalliance / caliptra-sw

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

Verilator test failure: caliptra-test::smoke_test fips_cmd_test_rt #849

Closed korran closed 1 year ago

korran commented 1 year ago 
2023-09-20T08:34:06.5599111Z         FAIL [25432.699s] caliptra-test::smoke_test fips_cmd_test_rt
2023-09-20T08:34:06.5599442Z 
2023-09-20T08:34:06.5601342Z --- STDOUT:              caliptra-test::smoke_test fips_cmd_test_rt ---
2023-09-20T08:34:06.5601597Z 
2023-09-20T08:34:06.5615492Z running 1 test
2023-09-20T08:34:06.5616367Z       6,155 ready_for_fuses is high
2023-09-20T08:34:06.5616698Z       6,333 writing to cptra_bootfsm_go
2023-09-20T08:34:06.5620832Z test fips_cmd_test_rt has been running for over 60 seconds
2023-09-20T08:34:06.5621319Z     195,201 UART: 
2023-09-20T08:34:06.5621762Z     195,256 UART: Running Caliptra ROM ...
2023-09-20T08:34:06.5622066Z     196,662 UART: 
2023-09-20T08:34:06.5627929Z     202,819 UART: [state] CFI Enabled
2023-09-20T08:34:06.5628303Z     205,066 UART: [state] LifecycleState = Unprovisioned
2023-09-20T08:34:06.5628692Z     207,326 UART: [state] DebugLocked = No
2023-09-20T08:34:06.5629137Z     210,234 UART: [state] Watchdog Timer is not started because the device is not locked for debugging
2023-09-20T08:34:06.5629794Z     356,810 UART: ROM Digest: BBB6BA0BFBA2F1E2103A1060EB333FF6613A1F43E352AA823F62EF22650FF80F
2023-09-20T08:34:06.5630317Z     368,050 UART: [kat] ++
2023-09-20T08:34:06.5630888Z     368,562 UART: [kat] sha1
2023-09-20T08:34:06.5631395Z     377,722 UART: [kat] SHA2-256
2023-09-20T08:34:06.5631744Z     380,594 UART: [kat] SHA2-384
2023-09-20T08:34:06.5632102Z     384,859 UART: [kat] SHA2-384-ACC
2023-09-20T08:34:06.5640680Z     387,156 UART: [kat] ECC-384
2023-09-20T08:34:06.5641314Z   3,957,510 UART: [kat] HMAC-384
2023-09-20T08:34:06.5641745Z   3,968,562 UART: [kat] LMS
2023-09-20T08:34:06.5642110Z   5,070,364 UART: [kat] --
2023-09-20T08:34:06.5642857Z   5,074,457 UART: [cold-reset] ++
2023-09-20T08:34:06.5643160Z   5,076,533 UART: [idev] ++
2023-09-20T08:34:06.5643449Z   5,077,112 UART: [idev] CDI.KEYID = 6
2023-09-20T08:34:06.5643757Z   5,078,362 UART: [idev] SUBJECT.KEYID = 7
2023-09-20T08:34:06.5644818Z   5,079,834 UART: [idev] UDS.KEYID = 0
2023-09-20T08:34:06.5645257Z   5,097,479 UART: [idev] Erasing UDS.KEYID = 0
2023-09-20T08:34:06.5645608Z   8,363,415 UART: [idev] Using Sha1 for KeyId Algorithm
2023-09-20T08:34:06.5646359Z   8,385,927 UART: [idev] --
2023-09-20T08:34:06.5646647Z   8,392,090 UART: [ldev] ++
2023-09-20T08:34:06.5667682Z   8,392,683 UART: [ldev] CDI.KEYID = 6
2023-09-20T08:34:06.5668159Z   8,393,925 UART: [ldev] SUBJECT.KEYID = 5
2023-09-20T08:34:06.5668535Z   8,395,397 UART: [ldev] AUTHORITY.KEYID = 7
2023-09-20T08:34:06.5669233Z   8,396,979 UART: [ldev] FE.KEYID = 1
2023-09-20T08:34:06.5669678Z   8,407,774 UART: [ldev] Erasing FE.KEYID = 1
2023-09-20T08:34:06.5670150Z  11,692,303 UART: [ldev] Signing Cert with AUTHORITY.KEYID = 7
2023-09-20T08:34:06.5670735Z  15,289,012 UART: [ldev] PUB.X = 504D38CA45D997901F48BA333A149A2FB2668B973AAC64D3B79ECC09A663F02ED2FABA133F5FA499677AEB7687C99B25
2023-09-20T08:34:06.5671435Z  15,304,710 UART: [ldev] PUB.Y = A5CD31125698B3322C086E4398A591946BF20A3ECEA8EB7D7C23410D49FA877E7ECFBE47BD883BD53D7DA865AC217F1D
2023-09-20T08:34:06.5672188Z  15,320,780 UART: [ldev] SIG.R = 14B5D494DF875AC7CEE9FE3E9A6168A6B64BFB01171F5ECC5216C8BB945FAF957CED1BE6C7CFBB1DDB2B7F4BFD76A492
2023-09-20T08:34:06.5672906Z  15,336,692 UART: [ldev] SIG.S = 821D8CC92F40AFF934771D7652C9BC3C59D47E5635E110A8486B76F7433B02B3C6B0FD8B1B6548B5994C481547111FC5
2023-09-20T08:34:06.5673545Z  15,358,949 UART: [ldev] --
2023-09-20T08:34:06.5673808Z  15,365,377 ready_for_fw is high
2023-09-20T08:34:06.5674167Z  15,365,379 <<< Executing mbox cmd 0x46574c44 (63908 bytes) from SoC
2023-09-20T08:34:06.5674554Z  15,365,438 UART: [fwproc] Waiting for Commands...
2023-09-20T08:34:06.5674944Z  15,401,987 UART: [fwproc] Received command 0x46574c44
2023-09-20T08:34:06.5675338Z  15,404,600 UART: [fwproc] Received Image of size 63908 bytes
2023-09-20T08:34:06.5675747Z  18,126,163 UART: [fwproc] Image verified using Vendor ECC Key Index 0
2023-09-20T08:34:06.5676169Z  18,208,341 UART: [fwproc] Loading FMC at address 0x40000000 len 12964
2023-09-20T08:34:06.5676569Z  18,289,747 UART: [fwproc] Loading Runtime at address 0x40004000 len 45060
2023-09-20T08:34:06.5676941Z  18,564,460 >>> mbox cmd response: success
2023-09-20T08:34:06.5677236Z  18,568,530 UART: [afmc] ++
2023-09-20T08:34:06.5677965Z  18,569,109 UART: [afmc] CDI.KEYID = 6
2023-09-20T08:34:06.5678587Z  18,570,360 UART: [afmc] SUBJECT.KEYID = 7
2023-09-20T08:34:06.5679402Z  18,571,817 UART: [afmc] AUTHORITY.KEYID = 5
2023-09-20T08:34:06.5680360Z  21,883,107 UART: [afmc] Signing Cert with AUTHORITY.KEYID = 5
2023-09-20T08:34:06.5681192Z  24,177,568 UART: [afmc] Erasing AUTHORITY.KEYID = 5
2023-09-20T08:34:06.5682399Z  25,486,425 UART: [afmc] PUB.X = 502B3613B07F44C7DCE69BC38E2821D8B174A42D9E294448689595E4DCDA6DA4B70B7EE8722B4287C47011A58DA983F1
2023-09-20T08:34:06.5683618Z  25,502,021 UART: [afmc] PUB.Y = A2C06904C86B1E19B3CC4922E728A1E6B9473540759BA5007E34B5ABEC7E9220392ADEF25D79D879CB8DF8B8B8F4ADAA
2023-09-20T08:34:06.5685078Z  25,518,061 UART: [afmc] SIG.R = 348D346C907343A9B8592CA606F848C40B303D0A27CB74FBB57DF1BD0B25634D7B66E414D1F30550085573CACEC62A6A
2023-09-20T08:34:06.5686580Z  25,533,722 UART: [afmc] SIG.S = D88D5C14721A52B5667EC2151CE3C49A87BCEF0B77A5BCBA8633E89299AFAFDB82FB4C58CE5414A64372A13725E7FFE7
2023-09-20T08:34:06.5687467Z  25,561,279 UART: [afmc] --
2023-09-20T08:34:06.5687820Z  25,566,717 UART: [cold-reset] --
2023-09-20T08:34:06.5688124Z  25,580,670 UART: [fht] Storing FHT @ 0x50003400
2023-09-20T08:34:06.5688581Z  25,597,245 UART: [state] Watchdog Timer is not stopped because the device is not locked for debugging
2023-09-20T08:34:06.5689026Z  25,604,073 UART: [state] Locking Datavault
2023-09-20T08:34:06.5689363Z  25,607,860 UART: [state] Locking PCR0, PCR1 and PCR31
2023-09-20T08:34:06.5689992Z  25,609,936 UART: [state] Locking ICCM
2023-09-20T08:34:06.5690424Z  25,612,767 UART: [exit] Launching FMC @ 0x40000134
2023-09-20T08:34:06.5690701Z  25,621,584 UART: 
2023-09-20T08:34:06.5690990Z  25,621,617 UART: Running Caliptra FMC ...
2023-09-20T08:34:06.5691273Z  25,622,461 UART: 
2023-09-20T08:34:06.5691537Z  25,625,453 UART: [alias rt] Extend RT PCRs
2023-09-20T08:34:06.5693935Z  25,658,535 UART: [alias rt] Extend RT PCRs Done
2023-09-20T08:34:06.5694832Z  25,659,576 UART: [alias rt] Lock RT PCRs
2023-09-20T08:34:06.5695539Z  25,660,386 UART: [alias rt] Lock RT PCRs Done
2023-09-20T08:34:06.5696169Z  25,661,365 UART: [alias rt] Populate DV
2023-09-20T08:34:06.5696915Z  25,662,264 UART: [alias rt] Populate DV Done
2023-09-20T08:34:06.5697591Z  25,663,245 UART: Handoff : FMC CDI: 6
2023-09-20T08:34:06.5698796Z  25,664,013 UART: FMC Alias Private Key: 7
2023-09-20T08:34:06.5699541Z  25,665,923 UART: [alias rt] Derive CDI
2023-09-20T08:34:06.5700383Z  25,666,665 UART: [alias rt] Store in in slot 0x4
2023-09-20T08:34:06.5701182Z  25,700,401 UART: [alias rt] Derive Key Pair
2023-09-20T08:34:06.5702012Z  25,701,309 UART: [alias rt] Store priv key in slot 0x5
2023-09-20T08:34:06.5703178Z  28,940,508 UART: [alias rt] Derive Key Pair - Done
2023-09-20T08:34:06.5704053Z  28,951,526 UART: [alias rt] Signing Cert with AUTHO
2023-09-20T08:34:06.5704854Z  28,952,693 UART:             RITY.KEYID = 7
2023-09-20T08:34:06.5705645Z  31,230,813 UART: [alias rt] Erasing AUTHORITY.KEYID = 7
2023-09-20T08:34:06.5706281Z  31,232,323 UART: [alias rt] PUB.X = E81D936693DDBF36F97C18B541187B4099953FC98AE6B007E54729C22B4D6862B67894E95D2F6254FD90956F8FC9F1B7
2023-09-20T08:34:06.5706963Z  31,239,733 UART: [alias rt] PUB.Y = 5D84C1D7422E353490EA62CB8548384A35A6B59D33237B642EB8E09B8C0F63220CFCB8392E86203CAD86368C77FBF319
2023-09-20T08:34:06.5707683Z  31,247,307 UART: [alias rt] SIG.R = F6EC2072A05884BFB16667DA9B5CA5C3414B01E0D7B0EBD42EFC18E64CB1171BD6F7515913A746B7699AAC0C90892A77
2023-09-20T08:34:06.5708364Z  31,254,709 UART: [alias rt] SIG.S = 5B0DD43E0DD1267C5053F169F73766052EA532EB592B3C7179145BAC802C08039F758E2E5C832924BE8F8E59DECD691D
2023-09-20T08:34:06.5708799Z  32,558,244 UART: 
2023-09-20T08:34:06.5709100Z  32,558,278 UART:   ____      _ _       _               ____ _____
2023-09-20T08:34:06.5709450Z  32,559,910 UART:  / ___|__ _| (_)_ __ | |_ _ __ __ _  |  _ \_   _|
2023-09-20T08:34:06.5709892Z  32,561,575 UART: | |   / _` | | | '_ \| __| '__/ _` | | |_) || |
2023-09-20T08:34:06.5710316Z  32,563,174 UART: | |__| (_| | | | |_) | |_| | | (_| | |  _ < | |
2023-09-20T08:34:06.5710668Z  32,564,773 UART:  \____\__,_|_|_| .__/ \__|_|  \__,_| |_| \_\|_|
2023-09-20T08:34:06.5710963Z  32,566,372 UART:                |_|
2023-09-20T08:34:06.5711220Z  32,567,014 UART: 
2023-09-20T08:34:06.5711559Z  32,663,610 UART: Caliptra RT listening for mailbox commands...
2023-09-20T08:34:06.5711977Z  32,665,156 <<< Executing mbox cmd 0x46505652 (4 bytes) from SoC
2023-09-20T08:34:06.5712354Z  32,669,744 UART: [rt] Received command=0x46505652, len=4
2023-09-20T08:34:06.5712684Z  32,671,163 UART: [rt] FIPS Version
2023-09-20T08:34:06.5712992Z  32,674,940 >>> mbox cmd response data (36 bytes)
2023-09-20T08:34:06.5713365Z  32,674,969 <<< Executing mbox cmd 0x46504c54 (4 bytes) from SoC
2023-09-20T08:34:06.5713743Z  32,679,357 UART: [rt] Received command=0x46504c54, len=4
2023-09-20T08:34:06.5714097Z  32,683,711 >>> mbox cmd response data (8 bytes)
2023-09-20T08:34:06.5714453Z  32,683,725 <<< Executing mbox cmd 0x46504c54 (4 bytes) from SoC
2023-09-20T08:34:06.5714830Z  32,688,116 UART: [rt] Received command=0x46504c54, len=4
2023-09-20T08:34:06.5715217Z  32,689,510 >>> mbox cmd response: failed
2023-09-20T08:34:06.5715549Z  32,689,518 <<< Executing mbox cmd 0x46504c67 (4 bytes) from SoC
2023-09-20T08:34:06.5715921Z  32,693,914 UART: [rt] Received command=0x46504c67, len=4
2023-09-20T08:34:06.5716262Z  32,695,304 >>> mbox cmd response: failed
2023-09-20T08:34:06.5716555Z  32,695,407 UART: [rt] FIPS self test
2023-09-20T08:34:06.5717202Z  32,822,099 UART: ROM Digest: BBB6BA0BFBA2F1E2103A1060EB333FF6613A1F43E352AA823F62EF22650FF80F
2023-09-20T08:34:06.5719061Z  32,826,809 UART: [kat] ++
2023-09-20T08:34:06.5719392Z  32,827,115 UART: [kat] sha1
2023-09-20T08:34:06.5719835Z  32,831,487 UART: [kat] SHA2-256
2023-09-20T08:34:06.5720183Z  32,833,232 UART: [kat] SHA2-384
2023-09-20T08:34:06.5720536Z  32,835,620 UART: [kat] SHA2-384-ACC
2023-09-20T08:34:06.5720874Z  32,837,484 UART: [kat] ECC-384
2023-09-20T08:34:06.5721503Z  36,402,948 UART: [kat] HMAC-384
2023-09-20T08:34:06.5721796Z  36,408,405 UART: [kat] LMS
2023-09-20T08:34:06.5722081Z  36,816,523 UART: [kat] --
2023-09-20T08:34:06.5722382Z  39,736,363 UART: [rt] Verify complete
2023-09-20T08:34:06.5722745Z  39,746,043 <<< Executing mbox cmd 0x46504c67 (4 bytes) from SoC
2023-09-20T08:34:06.5723228Z  39,750,436 UART: [rt] Received command=0x46504c67, len=4
2023-09-20T08:34:06.5723692Z  39,754,799 >>> mbox cmd response data (8 bytes)
2023-09-20T08:34:06.5724078Z  39,754,814 <<< Executing mbox cmd 0x46505344 (4 bytes) from SoC
2023-09-20T08:34:06.5724446Z  39,759,205 UART: [rt] Received command=0x46505344, len=4
2023-09-20T08:34:06.5724797Z  39,780,079 >>> mbox cmd response: success
2023-09-20T08:34:06.5725170Z  39,780,084 <<< Executing mbox cmd 0x46505652 (4 bytes) from SoC
2023-09-20T08:34:06.5725647Z  39,784,468 UART: [rt] Received command=0x46505652, len=4
2023-09-20T08:34:06.5725966Z  39,785,867 UART: [rt] FIPS Version
2023-09-20T08:34:06.5726308Z  39,789,593 >>> mbox cmd response data (36 bytes)
2023-09-20T08:34:06.5726636Z test fips_cmd_test_rt ... FAILED
2023-09-20T08:34:06.5726807Z 
2023-09-20T08:34:06.5726901Z failures:
2023-09-20T08:34:06.5727052Z 
2023-09-20T08:34:06.5727144Z failures:
2023-09-20T08:34:06.5727390Z     fips_cmd_test_rt
2023-09-20T08:34:06.5727556Z 
2023-09-20T08:34:06.5727804Z test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 5 filtered out; finished in 25432.68s
rusty1968 commented 1 year ago

The error seems to be we are handling fips version command after shutdown.

2023-09-20T08:34:06.5725170Z 39,780,084 <<< Executing mbox cmd 0x46505652 (4 bytes) from SoC 2023-09-20T08:34:06.5725647Z 39,784,468 UART: [rt] Received command=0x46505652, len=4 2023-09-20T08:34:06.5725966Z 39,785,867 UART: [rt] FIPS Version 2023-09-20T08:34:06.5726308Z 39,789,593 >>> mbox cmd response data (36 bytes)