[PATCH v6 08/12] efi_loader: Disable ANSI output for tests

Sat Oct 12 00:16:28 CEST 2024

Hi Heinrich, Tom,

On Tue, 1 Oct 2024 at 16:18, Heinrich Schuchardt <xypron.glpk at gmx.de> wrote:
>
> On 10/1/24 20:02, Tom Rini wrote:
> > On Tue, Oct 01, 2024 at 04:34:54AM +0200, Heinrich Schuchardt wrote:
> >> On 10/1/24 02:24, Tom Rini wrote:
> >>> On Tue, Oct 01, 2024 at 01:38:56AM +0200, Heinrich Schuchardt wrote:
> >>>> On 26.09.24 23:59, Simon Glass wrote:
> >>>>> We don't want ANSI characters written in tests since it is a pain to
> >>>>> check the output with ut_assert_nextline() et al.
> >>>>>
> >>>>> Provide a way to tests to request that ANSI characters not be sent.
> >>>>>
> >>>>> Add a proper function comment while we are here, to encourage others.
> >>>>>
> >>>>> Signed-off-by: Simon Glass <sjg at chromium.org>
> >>>>
> >>>> Please, consider prior review before resubmitting patches.
> >>>>
> >>>> As responded to all prior submissions:
> >>>>
> >>>> We want to test the code running on actual machines.
> >>>> We don't want to have sandbox code everywhere.
> >>>>
> >>>> I cannot see any test that is not passing due to the current behavior.
> >>>
> >>> The pytests for the EFI selftests are unreliable for me, on Raspberry Pi
> >>> 3, more often in 32bit mode than 64bit mode, but I feel like I see it
> >>> there too. And when they fail, the console log is full of ANSI escape
> >>> sequences. Is this specific test a test you run regularly on real
> >>> hardware?
> >>>
> >>
> >> It is not only the EFI test but also pytest adding color to the console
> >> output.
> >
> > Alright, so at least for the problems I have _today_, I've figured it
> > out, and the problem is that the watchdog test fails too quickly:
> >
> > [snip]
> > test/py/tests/test_efi_selftest.py ..F
> > test/py/u_boot_console_base.p
> > =================================== FAILURES ===================================
> > ______________________ test_efi_selftest_watchdog_reboot _______________________
> > test/py/tests/test_efi_selftest.py:61: in test_efi_selftest_watchdog_reboot
> >      u_boot_console.restart_uboot()
> > test/py/u_boot_console_base.py:478: in restart_uboot
> >      self.ensure_spawned(expect_reset)
> > test/py/u_boot_console_base.py:442: in ensure_spawned
> >      self.wait_for_boot_prompt(loop_num = loop_num)
> > test/py/u_boot_console_base.py:195: in wait_for_boot_prompt
> >      raise Exception('Bad pattern found on console: ' +
> > E   Exception: Bad pattern found on console: spl_signon
> > ----------------------------- Captured stdout call -----------------------------
> > => setenv efi_selftest list
> > => => bootefi selftest
> >  7 [r [999;999H [6n 8No EFI system partition
> > No EFI system partition
> > Failed to persist EFI variables
> > No EFI system partition
> > Failed to persist EFI variables
> > No EFI system partition
> > Failed to persist EFI variables
> >
> > Available tests:
> > 'block image transfer' - on request
> > 'block device'
> > 'configuration tables'
> > 'controllers'
> > 'crc32'
> > 'device path'
> > 'device path utilities protocol'
> > 'conformance profile table'
> > 'event groups'
> > 'event services'
> > 'exception' - on request
> > 'ExitBootServices'
> > 'device tree'
> > 'graphical output'
> > 'HII database protocols'
> > 'load file protocol'
> > 'loaded image'
> > 'load image from file'
> > 'mem'
> > 'memory'
> > 'open protocol'
> > 'manage protocols'
> > 'register protocol notify'
> > 'reset system' - on request
> > 'reset system runtime' - on request
> > 'real time clock'
> > 'simple network protocol'
> > 'start image return'
> > 'start image exit'
> > 'text input' - on request
> > 'extended text input' - on request
> > 'text output'
> > 'task priority levels'
> > 'unicode collation'
> > 'variables'
> > 'variables at runtime'
> > 'virtual address map'
> > 'watchdog timer'
> > 'watchdog reboot' - on request
> > => => setenv efi_selftest watchdog reboot
> > => => bootefi selftest
> >  [1;37;40m
> > Testing EFI API implementation
> >  [0;37;40m [1;37;40m
> > Selected test: 'watchdog reboot'
> >  [0;37;40m [1;34;40m
> > Setting up 'watchdog reboot'
> >  [0;37;40m [1;32;40mSetting up 'watchdog reboot' succeeded
> >  [0;37;40m [1;34;40m
> > Executing 'watchdog reboot'
> >  [0;37;40m
> > EFI: Watchdog timeout
> > resetting ...
> > +u-boot-test-reset am64x_evm_a53 na
> > Selected role am64-sk from configuration file
> > Selected role am64-sk from configuration file
> > connecting to NetworkSerialPort(target=Target(name='am64-sk', env=Environment(config_file='/home/trini/u-boot/lg_env.yaml')), name='USBSerialPort', state=<BindingState.bound: 1>, avail=True, host='ti-lab-host', port=57479, speed=115200, protocol='rfc2217') calling microcom -s 115200 -t ti-lab-host:57479
> > connected to 192.168.116.10 (port 57479)
> > Escape character: Ctrl-\
> > Type the escape character to get to the prompt.
> >
> > U-Boot SPL 2024.10-rc5-00022-g17da9795c115 (Oct 01 2024 - 14:29:10 +0000)
> > SYSFW ABI: 3.1 (firmware rev 0x0009 '9.2.7--v09.02.07 (Kool Koala)')
> > EEPROM not available at 0x50, trying to read at 0x51
> > SPL initial stack usage: 13368 bytes
> > Trying to boot from MMC2
> > Loading Environment from MMC... MMC Device 0 not found
> > *** Warning - No MMC card found, using default environment
> >
> > Starting ATF on ARM64 core...
> >
> > NOTICE:  BL31: v2.10.0(release):v2.10.0-729-gc8be7c08c
> > NOTICE:  BL31: Built : 13:50:07, Apr 24 2024
> > I/TC:
> > I/TC: OP-TEE version: 4.2.0-22-g16fbd46d2 (gcc version 13.2.0 (GCC)) #2 Wed Apr 24 19:50:23 UTC 2024 aarch64
> > I/TC: WARNING: This OP-TEE configuration might be insecure!
> > I/TC: WARNING: Please check https://optee.readthedocs.io/en/latest/architecture/porting_guidelines.html
> > I/TC: Primary CPU initializing
> > I/TC: GIC redistributor base address not provided
> > I/TC: Assuming default GIC group status and modifier
> > I/TC: SYSFW ABI: 3.1 (firmware rev 0x0009 '9.2.7--v09.02.07 (Kool Koala)')
> > I/TC: HUK Initialized
> > I/TC: Activated SA2UL device
> > I/TC: Fixing SA2UL firewall owner for GP device
> > I/TC: Enabled firewalls for SA2UL TRNG device
> > I/TC: SA2UL TRNG initialized
> > I/TC: SA2UL Drivers initialized
> > I/TC: Primary CPU switching to normal world boot
> >
> > U-Boot SPL 2024.10-rc5-00022-g17da9795c115 (Oct 01 2024 - 14:31:31 +0000)
> > SYSFW ABI: 3.1 (firmware rev 0x0009 '9.2.7--v09.02.07 (Kool Koala)')
> > Trying to boot from MMC2
> > ?
> > U-Boot SPL 2024.10-rc5-00022-g17da9795c115 (Oct 01 2024 - 14:29:10 +0000)
> > Resetting on cold boot to workaround ErrataID:i2331
> > Please resend tiboot3.bin in case of UART/DFU boot
> > resetting ...
> >
> > U-Boot SPL 2024.10-rc5-00022-g17da9795c115 (Oct 01 2024 - 14:29:10 +0000)
> > =========================== short test summary info ============================
> > SKIPPED [47] test/py/conftest.py:512: board "am64x_evm_a53" not supported
> > SKIPPED [5] test/py/conftest.py:531: .config feature "cmd_avb" not enabled
> > SKIPPED [1] test/py/conftest.py:531: .config feature "optee_ta_avb" not enabled
> > SKIPPED [1] test/py/conftest.py:531: .config feature "cmd_bootstage" not enabled
> > SKIPPED [2] test/py/conftest.py:531: .config feature "bootstage_stash" not enabled
> > SKIPPED [1] test/py/tests/test_dfu.py:114: got empty parameter set ['env__usb_dev_port'], function test_dfu at /home/trini/u-boot/u-boot/test/py/tests/test_dfu.py:113
> > SKIPPED [1] test/py/tests/test_efi_fit.py:401: No env__efi_fit_tftp_file binary specified in environment
> > FAILED test/py/tests/test_efi_selftest.py::test_efi_selftest_watchdog_reboot
> > !!!!!!!!!!!!!!!!!!!!!!!!!! stopping after 1 failures !!!!!!!!!!!!!!!!!!!!!!!!!!!
> > ================== 1 failed, 17 passed, 58 skipped in 58.92s ===================
> >
> > I thought it was the escape sequences confusing the check rather than
> > the platform takes longer than expected to provide whatever the expected
> > string is. Another TI K3 platform gets slightly farther along before
> > failing the same way. I'm going back to looping over Pis to see if they
> > fail in a way that they used to in my previous lab setup.
> >
>
> The relevant error message is:
>
>      E   Exception: Bad pattern found on console: spl_signon
>
> The error occurs because the substring
>
>      U-Boot SPL 2024.10
>
> occurs multiple times during the reboot process. This is not expected in
> wait_for_boot_prompt().
>
> The EFI test is resetting the board and then calling restart_uboot()
> which by itself does another reset.

We had this discussion a while back and I was very-much opposed to
restarting U-Boot within a test. It has set a bad precedent and now
several tests do it.

This is another EFI thing that I would like to resolve at some point.
As previously mentioned, I understand we might be one test to check
that U-Boot does actually kick up a firmware update when started, but
I don't think we should be restarting willy-nilly.

>
> While the watchdog triggered reboot is running thee test environment may
> need some time before triggering a reboot itself. This may lead to the
> observed duplicate output of the U-Boot greeter which is recorded as an
> error.
>
> Maybe we should directly call wait_for_boot_prompt(loop_num = 2).
>
>
> diff --git a/test/py/tests/test_efi_selftest.py
> b/test/py/tests/test_efi_selftest.py
> index 43f24245582..c3ee1888afb 100644
> --- a/test/py/tests/test_efi_selftest.py
> +++ b/test/py/tests/test_efi_selftest.py
> @@ -58,7 +58,7 @@ def test_efi_selftest_watchdog_reboot(u_boot_console):
>       u_boot_console.run_command(cmd='bootefi selftest',
> wait_for_prompt=False)
>       if u_boot_console.p.expect(['resetting', 'U-Boot']):
>           raise Exception('Reset failed in \'watchdog reboot\' test')
> -    u_boot_console.restart_uboot()
> +    u_boot_console.wait_for_boot_prompt(loop_num = 2)
>
>   @pytest.mark.buildconfigspec('cmd_bootefi_selftest')
>   def test_efi_selftest_text_input(u_boot_console):
>
> Thanks for bringing the issue to my attention.

Regards,
Simon