SystemReady IR ACS v2.1.1 tests are terminated with an error

davidhuziji commented 5 months ago

Hi,

Recently I bumped IR ACS tests from v2.1.0 to v2.1.1. I just replaced previous prebuilt image with v24.03_2.1.1. Could you please tell me if any other component should be updated as well? I ask because, ACS v2.1.1 is terminated with an error on my system while v2.1.0 runs well. I'm also a bit confused with the error log. Do you mind taking a look at the logs below? Sorry they could be a bit long. I'd appreciate it if you can give me some suggestions on debugging the failure.

In my environment with ACS v2.1.1, UEFI SCT runs well until the last test case UpdatePackageListFunction. It reports timeout.

Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/pexpect/expect.py", line 111, in expect_loop
    incoming = spawn.read_nonblocking(spawn.maxread, timeout)
  File "/usr/lib/python3/dist-packages/pexpect/pty_spawn.py", line 482, in read_nonblocking
    raise TIMEOUT('Timeout exceeded.')
pexpect.exceptions.TIMEOUT: Timeout exceeded.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File ".../lib/oeqa/runtime/cases/arm_systemready_ir_acs.py", line 22, in test_acs
    match_id = self.target.expect(self.console, test_patterns,
  File "xxx/../layers/meta-arm/meta-arm/lib/oeqa/controllers/fvp.py", line 145, in call_pexpect
    result = attr(*args, **kwargs)
  File "/usr/lib/python3/dist-packages/pexpect/spawnbase.py", line 340, in expect
    return self.expect_list(compiled_pattern_list,
  File "/usr/lib/python3/dist-packages/pexpect/spawnbase.py", line 369, in expect_list
    return exp.expect_loop(timeout)
  File "/usr/lib/python3/dist-packages/pexpect/expect.py", line 119, in expect_loop
    return self.timeout(e)
  File "/usr/lib/python3/dist-packages/pexpect/expect.py", line 82, in timeout
    raise TIMEOUT(msg)
pexpect.exceptions.TIMEOUT: Timeout exceeded.
<pexpect.pty_spawn.spawn object at 0x7fe1e3d23340>
command: .../tmp_systemready-glibc/hosttools/telnet
args: ['.../tmp_systemready-glibc/hosttools/telnet', 'localhost', '5009']
buffer (last 100 chars): b'PE 4KB Granule Support          \r\r\n       PSCI_CPU_ON: failure[-2]\r\r\n       PSCI_CPU_ON: failure[-2]'
before (last 100 chars): b'PE 4KB Granule Support          \r\r\n       PSCI_CPU_ON: failure[-2]\r\r\n       PSCI_CPU_ON: failure[-2]'
after: <class 'pexpect.exceptions.TIMEOUT'>

But it still reports SCT completes and starts BSA test suite as usual. However, after BSA tests are running for a while, it will repeat the following steps (SCT completion message, lots of asserts and some BSA test cases) for several times.

WARNING: arm-systemready-ir-acs-2.1.1-r0 do_testimage: Could not load artifacts list, skip artifacts retrieval
Timed out waiting for login prompt.
Boot log follows:

[0;37;40mPress any key within 5 seconds 
Press any key within 4 seconds 
Press any key within 3 seconds 
Press any key within 2 seconds 
Press any key within 1 seconds 
SCT has completed run. Press any key to start SCT execution from the beginning. WARNING: Ensure you have backed up the existing logs.

[0;37;40mPress any key within 5 seconds 
Press any key within 4 seconds 
Press any key within 3 seconds 
Press any key within 2 seconds 
Press any key within 1 seconds 
Running CapsuleApp 

[0;37;40m

ASSERT_EFI_ERROR (Status = Not Found)

ASSERT [CapsuleApp] /home/runner/work/arm-systemready/arm-systemready/IR/Yocto/meta-woden/build/tmp/work/generic_arm64-oe-linux/uefi-apps/1.0-r0/edk2/MdeModulePkg/Library/UefiHiiServicesLib/UefiHiiServicesLib.c(94): !(((INTN)(RETURN_STATUS)(Status)) < 0)

... # Lots of ASSERTs

ASSERT [CapsuleApp] /home/runner/work/arm-systemready/arm-systemready/IR/Yocto/meta-woden/build/tmp/work/generic_arm64-oe-linux/uefi-apps/1.0-r0/edk2/MdePkg/Library/DxeHobLib/HobLib.c(49): mHobList != ((void *) 0)

Starting UEFI Debug dump

[0;37;40m[1;37;40mConnect[0;37;40m No drivers could be connected.

[0;37;40mPress any key to start BSA in verbose mode.

[0;37;40mIf no key is pressed then BSA will be run in normal mode

[0;37;40mPress any key within 10 seconds 
Press any key within 9 seconds 
Press any key within 8 seconds 
Press any key within 7 seconds 
Press any key within 6 seconds 
Press any key within 5 seconds 
Press any key within 4 seconds 
Press any key within 3 seconds 
Press any key within 2 seconds 
Press any key within 1 seconds 

 BSA Architecture Compliance Suite

          Version 1.0.8

 Starting tests with print level :  3

 Creating Platform Information Tables

  PE_INFO: Number of PE detected       :   16
  GIC CPUIF not present
   ...
  Peripheral: Num of UART controllers  :    1

      *** Starting PE tests ***

Operating System View:

   1 : Check Arch symmetry across PE         

       PSCI_CPU_ON: failure[-2]
       ...
       Checkpoint -- 290                           : Result:  FAIL

   2 : Check for number of PE                     : Result:  PASS

   3 : Check for AdvSIMD and FP support      

       PSCI_CPU_ON: failure[-2]
       ...
       PSCI_CPU_ON: failure[-2]

Eventually it reports an error and terminates the whole test.

WARNING: arm-systemready-ir-acs-2.1.1-r0 do_testimage: Can not get target disk usage: Failed to start FVP.
Transitioned to off
RESULTS:
RESULTS - arm_systemready_ir_acs.SystemReadyACSTest.test_acs: ERROR (72571.22s)
SUMMARY:
arm-systemready-ir-acs () - Ran 1 test in 72571.222s
arm-systemready-ir-acs - FAIL - Required tests failed (successes=0, skipped=0, failures=0, errors=1)

Thank you.

davidhuziji commented 5 months ago

More detailed logs during the repeated part are shown below. As this log shows, although time-out is reported above, the SCT test summary still claims that it completes well.

------------------------------------------------------------

  Remaining test cases: 0

  Protocol test: UpdatePackageListFunction

  Instances: 1/1

  Iterations: 1/1

------------------------------------------------------------

Arm ACS Version: SystemReady IR ACS v2.1.1

BBR ACS 1.0.5 (EBBR)

UpdatePackageListFunction

Revision 0x00010000

Test Entry Point GUID: 00C3A3A0-1A1E-4609-9B0F-F2835301432E

Test Support Library GUIDs: 

  1F9C2AE7-F147-4D19-A5E8-255AD005EB3E

------------------------------------------------------------

UEFI 2.6

Test Configuration #0

------------------------------------------------------------

Function auto test for HII Database Protocol UpdatePackageList().

------------------------------------------------------------

Logfile: "\EFI\BOOT\bbr\SCT\Log\HIITest\HIIDatabaseProtocolTest0\UpdatePackageListFunction_0_0_00C3A3A0-1A1E-4609-9B0F-F2835301432E.log"

Test Started: 06/15/24  08:04p

------------------------------------------------------------

Returned Status Code: Success

UpdatePackageListFunction: [NOT SUPPORTED]

  Passes........... 0

  Warnings......... 0

  Errors........... 0

------------------------------------------------------------

UEFI 2.6

Revision 0x00010000

Test Entry Point GUID: 00C3A3A0-1A1E-4609-9B0F-F2835301432E

------------------------------------------------------------

Logfile: "\EFI\BOOT\bbr\SCT\Log\HIITest\HIIDatabaseProtocolTest0\UpdatePackageListFunction_0_0_00C3A3A0-1A1E-4609-9B0F-F2835301432E.log"

Test Finished: 06/15/24  08:04p

Elapsed Time: 00 Days 00:00:00

------------------------------------------------------------

Done!

- [ok]

[0;37;40m- [ok]

[0;37;40m- [ok]

[0;37;40mReset the system ...

[0;37;40mresetting ...

U-Boot 2023.07.02 (Jul 11 2023 - 15:20:44 +0000) arm_fvp

Model: RD xxx
DRAM:  2 GiB (effective 4 GiB)
...
Hit any key to stop autoboot:  2  1  0 
Failed to load 'boot.img'
Failed to load 'Image'
## Executing script at 8fb00000
Wrong image format for "source" command
## Warning: Input data exceeds 1048576 bytes - truncated
## Info: input data size = 1048578 = 0x100002

Device 0: 0000 VirtIO Block Device
            Type: Hard Disk
            Capacity: 676.9 MB = 0.6 GB (1386368 x 512)
... is now current device
Scanning virtio 0:1...
7[r[999;999H[6n8Card did not respond to voltage select! : -110
FF-A driver 1.0
FF-A framework 1.0
FF-A versions are compatible
EFI: MM partition ID 0x8003
EFI: FVP: Capsule shared buffer at 0x81000000 , size 8192 pages
BootOrder not defined
EFI boot manager: Cannot load any image
Found EFI removable media binary efi/boot/bootaa64.efi
906752 bytes read in 4 ms (216.2 MiB/s)
Booting /efi\boot\bootaa64.efi
[0;30;47m[?25hWelcome to GRUB!

[0;37;40m[0;37;40m[0;37;40merror: no such device: ((hd0,gpt1)/efi/boot)/EFI/BOOT/grub.cfg.

error: serial port `com0' isn't found.

[?25l[0;37;40m[0;37;40m[0;37;40m[2J[1;1H[0;37;40m[2;30HGNU GRUB  version 2.06

[0;37;40m[4;2H┌────────────────────────────────────────────────────────────────────────────┐[5;2H│[5;79H│[6;2H│[6;79H│[7;2H│[7;79H│[8;2H│[8;79H│[9;2H│[9;79H│[10;2H│[10;79H│[11;2H│[11;79H│[12;2H│[12;79H│[13;2H│[13;79H│[14;2H│[14;79H│[15;2H│[15;79H│[16;2H│[16;79H│[17;2H│[17;79H│[18;2H└────────────────────────────────────────────────────────────────────────────┘[0;37;40m[19;2H[20;2H[0;37;40m     Use the ▲ and ▼ keys to select which entry is highlighted.          

      Press enter to boot the selected OS, `e' to edit the commands       

      before booting or `c' for a command-line.                           [5;80H [0;37;40m[5;3H Linux Boot                                                                 [0;37;40m[5;78H[0;37;40m[0;30;47m[6;3H*bbr/bsa                                                                    [0;37;40m[6;78H[0;37;40m[0;37;40m[7;3H SCT for Security Interface Extension (optional)                            [0;37;40m[7;78H[0;37;40m[0;37;40m[8;3H Linux Boot for Security Interface Extension (optional)                     [0;37;40m[8;78H[0;37;40m[0;37;40m[9;3H                                                                            [0;37;40m[9;78H[0;37;40m[0;37;40m[10;3H                                                                            [0;37;40m[10;78H[0;37;40m[0;37;40m[11;3H                                                                            [0;37;40m[11;78H[0;37;40m[0;37;40m[12;3H                                                                            [0;37;40m[12;78H[0;37;40m[0;37;40m[13;3H                                                                            [0;37;40m[13;78H[0;37;40m[0;37;40m[14;3H                                                                            [0;37;40m[14;78H[0;37;40m[0;37;40m[15;3H                                                                            [0;37;40m[15;78H[0;37;40m[0;37;40m[16;3H                                                                            [0;37;40m[16;78H[0;37;40m[0;37;40m[17;3H                                                                            [0;37;40m[17;78H[0;37;40m[17;80H [6;78H[23;1H   The highlighted entry will be executed automatically in 10s.                [6;78H[23;1H   The highlighted entry will be executed automatically in 9s.                 [6;78H[23;1H   The highlighted entry will be executed automatically in 8s.                 [6;78H[23;1H   The highlighted entry will be executed automatically in 7s.                 [6;78H[23;1H   The highlighted entry will be executed automatically in 6s.                 [6;78H[23;1H   The highlighted entry will be executed automatically in 5s.                 [6;78H[23;1H   The highlighted entry will be executed automatically in 4s.                 [6;78H[23;1H   The highlighted entry will be executed automatically in 3s.                 [6;78H[23;1H   The highlighted entry will be executed automatically in 2s.                 [6;78H[23;1H   The highlighted entry will be executed automatically in 1s.                 [6;78H[23;1H   The highlighted entry will be executed automatically in 0s.                 [6;78H[?25h[0;37;40m[0;37;40m[2J[1;1H[0;37;40m[0;37;40m[0;37;40m[2J[1;1H[0;37;40m  Booting `bbr/bsa'

/EndEntire

file path: /HardwareVendor(e61d73b9-a384-4acc-aeab-82e828f3628b)[0: ]

/HardwareVendor(63293792-adf5-9325-b99f-4e0e455c1b1e)[1: 00 ]

/HD(1,800,4b000,93b0673f6bc06444,2,2)/File(\EFI\BOOT)/File(Shell.efi)/EndEntire

[2J[1;1H[?25h[1;1HUEFI Interactive Shell v2.2

[0;37;40mEDK II

[0;37;40mUEFI v2.100 (Das U-Boot, 0x20230700)

[0;37;40m[1;33;40mMapping table[0;37;40m

[0;37;40m[1;33;40m      FS0:[0;37;40m [1;37;40mAlias(s):[0;37;40mHD0b:;BLK1:

          /VenHw(e61d73b9-a384-4acc-aeab-82e828f3628b)/VenHw(63293792-adf5-9325-b99f-4e0e455c1b1e,00)/HD(1,GPT,3f67b093-c06b-4464-b5de-e25bd3799a0f,0x800,0x4b000)

[0;37;40m[1;33;40m      FS1:[0;37;40m [1;37;40mAlias(s):[0;37;40mHD0c:;BLK2:

          /VenHw(e61d73b9-a384-4acc-aeab-82e828f3628b)/VenHw(63293792-adf5-9325-b99f-4e0e455c1b1e,00)/HD(2,GPT,aca83039-223d-40e0-b333-160db624d83a,0x4b800,0x106f5e)

[0;37;40m[1;33;40m     BLK0:[0;37;40m [1;37;40mAlias(s):[0;37;40m

          /VenHw(e61d73b9-a384-4acc-aeab-82e828f3628b)/VenHw(63293792-adf5-9325-b99f-4e0e455c1b1e,00)

[0;37;40m[?25l[16;1H[0;37;40mPress [1;37;40mESC[0;37;40m in 5 seconds to skip [1;33;40mstartup.nsh[0;37;40m or any other key to continue.[0;37;40m[16;1H[0;37;40mPress [1;37;40mESC[0;37;40m in 4 seconds to skip [1;33;40mstartup.nsh[0;37;40m or any other key to continue.[0;37;40m[16;1H[0;37;40mPress [1;37;40mESC[0;37;40m in 3 seconds to skip [1;33;40mstartup.nsh[0;37;40m or any other key to continue.[0;37;40m[16;1H[0;37;40mPress [1;37;40mESC[0;37;40m in 2 seconds to skip [1;33;40mstartup.nsh[0;37;40m or any other key to continue.[0;37;40m[16;1H[0;37;40mPress [1;37;40mESC[0;37;40m in 1 seconds to skip [1;33;40mstartup.nsh[0;37;40m or any other key to continue.[0;37;40m

[0;37;40m[?25h[1;33;40mShell> [0;37;40m[0;37;40mecho -off

[0;37;40mPress any key to stop the EFI SCT running

[0;37;40mPress any key within 5 seconds 
Press any key within 4 seconds 
Press any key within 3 seconds 
Press any key within 2 seconds 
Press any key within 1 seconds 
SCT has completed run. Press any key to start SCT execution from the beginning. WARNING: Ensure you have backed up the existing logs.

[0;37;40mPress any key within 5 seconds 
Press any key within 4 seconds 
Press any key within 3 seconds 
Press any key within 2 seconds 
Press any key within 1 seconds 
Running CapsuleApp 

[0;37;40m

ASSERT_EFI_ERROR (Status = Not Found)

ASSERT [CapsuleApp] /home/runner/work/arm-systemready/arm-systemready/IR/Yocto/meta-woden/build/tmp/work/generic_arm64-oe-linux/uefi-apps/1.0-r0/edk2/MdeModulePkg/Library/UefiHiiServicesLib/UefiHiiServicesLib.c(94): !(((INTN)(RETURN_STATUS)(Status)) < 0)

 ... # Lots of asserts

ASSERT [CapsuleApp] /home/runner/work/arm-systemready/arm-systemready/IR/Yocto/meta-woden/build/tmp/work/generic_arm64-oe-linux/uefi-apps/1.0-r0/edk2/MdePkg/Library/DxeHobLib/HobLib.c(49): mHobList != ((void *) 0)

Starting UEFI Debug dump

[0;37;40m[1;37;40mConnect[0;37;40m No drivers could be connected.

[0;37;40mPress any key to start BSA in verbose mode.

[0;37;40mIf no key is pressed then BSA will be run in normal mode

[0;37;40mPress any key within 10 seconds 
Press any key within 9 seconds 
Press any key within 8 seconds 
Press any key within 7 seconds 
Press any key within 6 seconds 
Press any key within 5 seconds 
Press any key within 4 seconds 
Press any key within 3 seconds 
Press any key within 2 seconds 
Press any key within 1 seconds 

 BSA Architecture Compliance Suite

          Version 1.0.8

 Starting tests with print level :  3

 Creating Platform Information Tables

 PE_INFO: Number of PE detected       :   16
 ...
 Peripheral: Num of UART controllers  :    1

      *** Starting PE tests ***

Operating System View:

   1 : Check Arch symmetry across PE         

       PSCI_CPU_ON: failure[-2]
       ...
       Checkpoint -- 290                           : Result:  FAIL

   2 : Check for number of PE                     : Result:  PASS

   3 : Check for AdvSIMD and FP support      

       PSCI_CPU_ON: failure[-2]
       ...
       PSCI_CPU_ON: failure[-2]Connection closed by foreign host.

chetan-rathore commented 5 months ago

Hi @davidhuziji,

We will look into the issue and will keep you updated on the findings. Can you also try the latest IR build image on the system and share observations.

Image Link: https://github.com/ARM-software/arm-systemready/actions/runs/9537746488/artifacts/1606480747

Thanks, ACS team

davidhuziji commented 5 months ago

Thanks a lot @chetan-rathore . I will try and update you.

davidhuziji commented 5 months ago

Hi @chetan-rathore, I tried this new prebuilt image and it worked as expected. Thank you so much.

May I know if you have a plan to update v24.03_2.1.1 prebuilt image in this public repo?

chetan-rathore commented 5 months ago

Hi @davidhuziji,

We have updated the stable build.

Thanks, ACS team

davidhuziji commented 5 months ago

Hi @chetan-rathore,

Thank you so much. May I know how to track the prebuilt image changes? Currently I can only rely on the SHA values to distinguish different image versions. Is any tags or minor versions available for reference? Thank you.

ARM-software / arm-systemready

SystemReady IR ACS v2.1.1 tests are terminated with an error #192