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

[Tom Rini <trini@konsulko.com>]

[-- Attachment #1: Type: text/plain, Size: 10695 bytes --]

On Wed, Oct 02, 2024 at 12:18:39AM +0200, Heinrich Schuchardt 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@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.
> 
> 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.

Thanks for digging in to this more. I suspect (and I'll try and confirm
soon) that we need to take in to account:
commit 645f75f6884a22905b0e3790ca9254fa1a13216e
Author: Tom Rini <trini@konsulko.com>
Date:   Wed Apr 24 16:45:37 2024 -0600

    test/py: Make the number of SPL banners seen a variable
    
    Currently we have the option to tell the console code that we should
    ignore the SPL banner. We also have an option to say that we can see it
    a second time, and ignore it. However, some platforms such as TI AM64x
    will have us see the SPL banner three times. Rather than add an
    "spl3_skipped" option, rework the code. By default we expect to see the
    banner once, but boards can specify seeing it as many times as they
    expect to.
    
    Signed-off-by: Tom Rini <trini@konsulko.com>

as well in this area.
> 
> Best regards
> 
> Heinrich
> 

-- 
Tom

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 659 bytes --]