[PATCH v2 0/4] tests/functional: Finish conversion of Aspeed tests

[PATCH v2 0/4] tests/functional: Finish conversion of Aspeed tests

[Cédric Le Goater]

Hello,

The first patch is a proposal to fix a long-standing issue when
capturing the console output. In some cases, the expected string does
not match in the output, causing the test to fail with a timeout. The
change introduces a _console_read() routine that processes the console
output character by character as a possible fix.

Last patches complete the conversion of the Aspeed tests and remove
the console workarounds.

Thanks,

C.

Changes in v2:

 - Redirected all console output in console.log file
 - Added a "found" prefix when an expected string is captured
 - Used a user mode network backend in SDK tests
 - Changed the expected string to "login:" in buildroot tests
 
Cédric Le Goater (4):
  tests/functional: Introduce _console_read()
  tests/functional: Convert Aspeed aarch64 SDK tests
  tests/functional: Convert Aspeed arm SDK tests
  tests/functional: Remove sleep workarounds from Aspeed tests

 tests/avocado/machine_aspeed.py         | 202 ------------------------
 tests/functional/meson.build            |   2 +
 tests/functional/qemu_test/cmd.py       |  22 ++-
 tests/functional/test_aarch64_aspeed.py |  97 ++++++++++++
 tests/functional/test_arm_aspeed.py     |  79 ++++++++-
 5 files changed, 191 insertions(+), 211 deletions(-)
 delete mode 100644 tests/avocado/machine_aspeed.py
 create mode 100644 tests/functional/test_aarch64_aspeed.py

-- 
2.47.0

[PATCH v2 1/4] tests/functional: Introduce _console_read()

[Cédric Le Goater]

Interaction with the console has been a problem in our avocado
tests. In some cases, the expected string does not match in the
output, causing the test to fail with a timeout. These were worked
around by sleeping before reading the console and even with SSH
connections in some places.

To fix, process the console output char by char and not with
readline. This routine was largely inspired by console_wait() in
tests/vm/basevm.py.

Signed-off-by: Cédric Le Goater <clg@redhat.com>
---
 tests/functional/qemu_test/cmd.py | 22 ++++++++++++++++++++--
 1 file changed, 20 insertions(+), 2 deletions(-)

diff --git a/tests/functional/qemu_test/cmd.py b/tests/functional/qemu_test/cmd.py
index cbabb1ceed3c..5bca29d1d721 100644
--- a/tests/functional/qemu_test/cmd.py
+++ b/tests/functional/qemu_test/cmd.py
@@ -12,6 +12,7 @@
 # later.  See the COPYING file in the top-level directory.
 
 import logging
+import re
 import os
 import os.path
 import subprocess
@@ -78,6 +79,23 @@ def run_cmd(args):
 def is_readable_executable_file(path):
     return os.path.isfile(path) and os.access(path, os.R_OK | os.X_OK)
 
+def _console_read(vm, expect):
+    console_logger = logging.getLogger('console')
+    output = ""
+    while True:
+        data = vm.console_socket.recv(1)
+        if not data:
+            break
+        output += data.decode("latin1")
+        if expect in output:
+            break
+        if "\r" in output or "\n" in output:
+            lines = re.split("[\r\n]", output)
+            if lines[0]:
+                console_logger.debug(lines[0])
+            output = lines.pop()
+    return output
+
 def _console_interaction(test, success_message, failure_message,
                          send_string, keep_sending=False, vm=None):
     assert not keep_sending or send_string
@@ -98,12 +116,12 @@ def _console_interaction(test, success_message, failure_message,
             continue
 
         try:
-            msg = console.readline().decode().strip()
+            msg = _console_read(vm, success_message)
         except UnicodeDecodeError:
             msg = None
         if not msg:
             continue
-        console_logger.debug(msg)
+        console_logger.debug('found "%s"', msg)
         if success_message is None or success_message in msg:
             break
         if failure_message and failure_message in msg:
-- 
2.47.0

[PATCH v2 2/4] tests/functional: Convert Aspeed aarch64 SDK tests

[Cédric Le Goater]

Drop the SSH connection which was introduced in the avocado tests to
workaround read issues when interacting with console.

Signed-off-by: Cédric Le Goater <clg@redhat.com>
Reviewed-by: Thomas Huth <thuth@redhat.com>
---
 tests/avocado/machine_aspeed.py         | 78 --------------------
 tests/functional/meson.build            |  2 +
 tests/functional/test_aarch64_aspeed.py | 97 +++++++++++++++++++++++++
 3 files changed, 99 insertions(+), 78 deletions(-)
 create mode 100644 tests/functional/test_aarch64_aspeed.py

diff --git a/tests/avocado/machine_aspeed.py b/tests/avocado/machine_aspeed.py
index 241ef180affc..2240c82abff9 100644
--- a/tests/avocado/machine_aspeed.py
+++ b/tests/avocado/machine_aspeed.py
@@ -59,17 +59,6 @@ def do_test_arm_aspeed_sdk_start(self, image):
             self, 'boot', '## Loading kernel from FIT Image')
         self.wait_for_console_pattern('Starting kernel ...')
 
-    def do_test_aarch64_aspeed_sdk_start(self, image):
-        self.vm.set_console()
-        self.vm.add_args('-drive', 'file=' + image + ',if=mtd,format=raw',
-                         '-net', 'nic', '-net', 'user,hostfwd=:127.0.0.1:0-:22')
-
-        self.vm.launch()
-
-        self.wait_for_console_pattern('U-Boot 2023.10')
-        self.wait_for_console_pattern('## Loading kernel from FIT Image')
-        self.wait_for_console_pattern('Starting kernel ...')
-
     @skipUnless(os.getenv('QEMU_TEST_FLAKY_TESTS'), 'Test is unstable on GitLab')
     def test_arm_ast2500_evb_sdk(self):
         """
@@ -133,70 +122,3 @@ def test_arm_ast2600_evb_sdk(self):
         year = time.strftime("%Y")
         self.ssh_command_output_contains('/sbin/hwclock -f /dev/rtc1', year);
 
-    def test_aarch64_ast2700_evb_sdk_v09_02(self):
-        """
-        :avocado: tags=arch:aarch64
-        :avocado: tags=machine:ast2700-evb
-        """
-
-        image_url = ('https://github.com/AspeedTech-BMC/openbmc/releases/'
-                     'download/v09.02/ast2700-default-obmc.tar.gz')
-        image_hash = 'ac969c2602f4e6bdb69562ff466b89ae3fe1d86e1f6797bb7969d787f82116a7'
-        image_path = self.fetch_asset(image_url, asset_hash=image_hash,
-                                      algorithm='sha256')
-        archive.extract(image_path, self.workdir)
-
-        num_cpu = 4
-        image_dir = self.workdir + '/ast2700-default/'
-        uboot_size = os.path.getsize(image_dir + 'u-boot-nodtb.bin')
-        uboot_dtb_load_addr = hex(0x400000000 + uboot_size)
-
-        load_images_list = [
-            {
-                'addr': '0x400000000',
-                'file': image_dir + 'u-boot-nodtb.bin'
-            },
-            {
-                'addr': str(uboot_dtb_load_addr),
-                'file': image_dir + 'u-boot.dtb'
-            },
-            {
-                'addr': '0x430000000',
-                'file': image_dir + 'bl31.bin'
-            },
-            {
-                'addr': '0x430080000',
-                'file': image_dir + 'optee/tee-raw.bin'
-            }
-        ]
-
-        for load_image in load_images_list:
-            addr = load_image['addr']
-            file = load_image['file']
-            self.vm.add_args('-device',
-                             f'loader,force-raw=on,addr={addr},file={file}')
-
-        for i in range(num_cpu):
-            self.vm.add_args('-device',
-                             f'loader,addr=0x430000000,cpu-num={i}')
-
-        self.vm.add_args('-smp', str(num_cpu))
-        self.vm.add_args('-device',
-                         'tmp105,bus=aspeed.i2c.bus.1,address=0x4d,id=tmp-test')
-        self.do_test_aarch64_aspeed_sdk_start(image_dir + 'image-bmc')
-        self.wait_for_console_pattern('nodistro.0 ast2700-default ttyS12')
-
-        self.ssh_connect('root', '0penBmc', False)
-        self.ssh_command('dmesg -c > /dev/null')
-
-        self.ssh_command_output_contains(
-            'echo lm75 0x4d > /sys/class/i2c-dev/i2c-1/device/new_device '
-            '&& dmesg -c',
-            'i2c i2c-1: new_device: Instantiated device lm75 at 0x4d');
-
-        self.ssh_command_output_contains(
-            'cat /sys/class/hwmon/hwmon20/temp1_input', '0')
-        self.vm.cmd('qom-set', path='/machine/peripheral/tmp-test',
-                    property='temperature', value=18000)
-        self.ssh_command_output_contains(
-            'cat /sys/class/hwmon/hwmon20/temp1_input', '18000')
diff --git a/tests/functional/meson.build b/tests/functional/meson.build
index 758145d1e5fa..c035eba4f9b8 100644
--- a/tests/functional/meson.build
+++ b/tests/functional/meson.build
@@ -11,6 +11,7 @@ endif
 
 # Timeouts for individual tests that can be slow e.g. with debugging enabled
 test_timeouts = {
+  'aarch64_aspeed' : 600,
   'aarch64_raspi4' : 480,
   'aarch64_sbsaref_alpine' : 720,
   'aarch64_sbsaref_freebsd' : 720,
@@ -47,6 +48,7 @@ tests_generic_bsduser = [
 ]
 
 tests_aarch64_system_thorough = [
+  'aarch64_aspeed',
   'aarch64_raspi3',
   'aarch64_raspi4',
   'aarch64_sbsaref',
diff --git a/tests/functional/test_aarch64_aspeed.py b/tests/functional/test_aarch64_aspeed.py
new file mode 100644
index 000000000000..53ee23ef2ce7
--- /dev/null
+++ b/tests/functional/test_aarch64_aspeed.py
@@ -0,0 +1,97 @@
+#!/usr/bin/env python3
+#
+# Functional test that boots the ASPEED SoCs with firmware
+#
+# Copyright (C) 2022 ASPEED Technology Inc
+#
+# SPDX-License-Identifier: GPL-2.0-or-later
+
+import sys
+import os
+
+from qemu_test import QemuSystemTest, Asset
+from qemu_test import wait_for_console_pattern
+from qemu_test import exec_command_and_wait_for_pattern
+from qemu_test.utils import archive_extract
+
+class AST2x00MachineSDK(QemuSystemTest):
+
+    def do_test_aarch64_aspeed_sdk_start(self, image):
+        self.vm.set_console()
+        self.vm.add_args('-drive', 'file=' + image + ',if=mtd,format=raw',
+                         '-net', 'nic', '-net', 'user', '-snapshot')
+
+        self.vm.launch()
+
+        wait_for_console_pattern(self, 'U-Boot 2023.10')
+        wait_for_console_pattern(self, '## Loading kernel from FIT Image')
+        wait_for_console_pattern(self, 'Starting kernel ...')
+
+    ASSET_SDK_V902_AST2700 = Asset(
+            'https://github.com/AspeedTech-BMC/openbmc/releases/download/v09.02/ast2700-default-obmc.tar.gz',
+            'ac969c2602f4e6bdb69562ff466b89ae3fe1d86e1f6797bb7969d787f82116a7')
+
+    def test_aarch64_ast2700_evb_sdk_v09_02(self):
+        self.set_machine('ast2700-evb')
+
+        image_path = self.ASSET_SDK_V902_AST2700.fetch()
+        archive_extract(image_path, self.workdir)
+
+        num_cpu = 4
+        image_dir = self.workdir + '/ast2700-default/'
+        uboot_size = os.path.getsize(image_dir + 'u-boot-nodtb.bin')
+        uboot_dtb_load_addr = hex(0x400000000 + uboot_size)
+
+        load_images_list = [
+            {
+                'addr': '0x400000000',
+                'file': image_dir + 'u-boot-nodtb.bin'
+            },
+            {
+                'addr': str(uboot_dtb_load_addr),
+                'file': image_dir + 'u-boot.dtb'
+            },
+            {
+                'addr': '0x430000000',
+                'file': image_dir + 'bl31.bin'
+            },
+            {
+                'addr': '0x430080000',
+                'file': image_dir + 'optee/tee-raw.bin'
+            }
+        ]
+
+        for load_image in load_images_list:
+            addr = load_image['addr']
+            file = load_image['file']
+            self.vm.add_args('-device',
+                             f'loader,force-raw=on,addr={addr},file={file}')
+
+        for i in range(num_cpu):
+            self.vm.add_args('-device',
+                             f'loader,addr=0x430000000,cpu-num={i}')
+
+        self.vm.add_args('-smp', str(num_cpu))
+        self.vm.add_args('-device',
+                         'tmp105,bus=aspeed.i2c.bus.1,address=0x4d,id=tmp-test')
+        self.do_test_aarch64_aspeed_sdk_start(image_dir + 'image-bmc')
+
+        wait_for_console_pattern(self, 'ast2700-default login:')
+
+        exec_command_and_wait_for_pattern(self, 'root', 'Password:')
+        exec_command_and_wait_for_pattern(self,
+            '0penBmc', 'root@ast2700-default:~#')
+
+        exec_command_and_wait_for_pattern(self,
+            'echo lm75 0x4d > /sys/class/i2c-dev/i2c-1/device/new_device ',
+            'i2c i2c-1: new_device: Instantiated device lm75 at 0x4d');
+        exec_command_and_wait_for_pattern(self,
+            'cat /sys/class/hwmon/hwmon20/temp1_input', '0')
+        self.vm.cmd('qom-set', path='/machine/peripheral/tmp-test',
+                    property='temperature', value=18000)
+        exec_command_and_wait_for_pattern(self,
+            'cat /sys/class/hwmon/hwmon20/temp1_input', '18000')
+
+
+if __name__ == '__main__':
+    QemuSystemTest.main()
-- 
2.47.0

[PATCH v2 3/4] tests/functional: Convert Aspeed arm SDK tests

[Cédric Le Goater]

Drop the SSH connection which was introduced in the avocado tests to
workaround read issues when interacting with console.

Signed-off-by: Cédric Le Goater <clg@redhat.com>
---
 tests/avocado/machine_aspeed.py     | 124 ----------------------------
 tests/functional/test_arm_aspeed.py |  67 +++++++++++++++
 2 files changed, 67 insertions(+), 124 deletions(-)
 delete mode 100644 tests/avocado/machine_aspeed.py

diff --git a/tests/avocado/machine_aspeed.py b/tests/avocado/machine_aspeed.py
deleted file mode 100644
index 2240c82abff9..000000000000
--- a/tests/avocado/machine_aspeed.py
+++ /dev/null
@@ -1,124 +0,0 @@
-# Functional test that boots the ASPEED SoCs with firmware
-#
-# Copyright (C) 2022 ASPEED Technology Inc
-#
-# This work is licensed under the terms of the GNU GPL, version 2 or
-# later.  See the COPYING file in the top-level directory.
-
-import time
-import os
-import tempfile
-import subprocess
-
-from avocado_qemu import LinuxSSHMixIn
-from avocado_qemu import QemuSystemTest
-from avocado_qemu import wait_for_console_pattern
-from avocado_qemu import exec_command
-from avocado_qemu import exec_command_and_wait_for_pattern
-from avocado_qemu import interrupt_interactive_console_until_pattern
-from avocado_qemu import has_cmd
-from avocado.utils import archive
-from avocado import skipUnless
-
-class AST2x00MachineSDK(QemuSystemTest, LinuxSSHMixIn):
-
-    EXTRA_BOOTARGS = (
-        'quiet '
-        'systemd.mask=org.openbmc.HostIpmi.service '
-        'systemd.mask=xyz.openbmc_project.Chassis.Control.Power@0.service '
-        'systemd.mask=modprobe@fuse.service '
-        'systemd.mask=rngd.service '
-        'systemd.mask=obmc-console@ttyS2.service '
-    )
-
-    # FIXME: Although these tests boot a whole distro they are still
-    # slower than comparable machine models. There may be some
-    # optimisations which bring down the runtime. In the meantime they
-    # have generous timeouts and are disable for CI which aims for all
-    # tests to run in less than 60 seconds.
-    timeout = 240
-
-    def wait_for_console_pattern(self, success_message, vm=None):
-        wait_for_console_pattern(self, success_message,
-                                 failure_message='Kernel panic - not syncing',
-                                 vm=vm)
-
-    def do_test_arm_aspeed_sdk_start(self, image):
-        self.require_netdev('user')
-        self.vm.set_console()
-        self.vm.add_args('-drive', 'file=' + image + ',if=mtd,format=raw',
-                         '-net', 'nic', '-net', 'user,hostfwd=:127.0.0.1:0-:22')
-        self.vm.launch()
-
-        self.wait_for_console_pattern('U-Boot 2019.04')
-        interrupt_interactive_console_until_pattern(
-            self, 'Hit any key to stop autoboot:', 'ast#')
-        exec_command_and_wait_for_pattern(
-            self, 'setenv bootargs ${bootargs} ' + self.EXTRA_BOOTARGS, 'ast#')
-        exec_command_and_wait_for_pattern(
-            self, 'boot', '## Loading kernel from FIT Image')
-        self.wait_for_console_pattern('Starting kernel ...')
-
-    @skipUnless(os.getenv('QEMU_TEST_FLAKY_TESTS'), 'Test is unstable on GitLab')
-    def test_arm_ast2500_evb_sdk(self):
-        """
-        :avocado: tags=arch:arm
-        :avocado: tags=machine:ast2500-evb
-        :avocado: tags=flaky
-        """
-
-        image_url = ('https://github.com/AspeedTech-BMC/openbmc/releases/'
-                     'download/v08.06/ast2500-default-obmc.tar.gz')
-        image_hash = ('e1755f3cadff69190438c688d52dd0f0d399b70a1e14b1d3d5540fc4851d38ca')
-        image_path = self.fetch_asset(image_url, asset_hash=image_hash,
-                                      algorithm='sha256')
-        archive.extract(image_path, self.workdir)
-
-        self.do_test_arm_aspeed_sdk_start(
-            self.workdir + '/ast2500-default/image-bmc')
-        self.wait_for_console_pattern('nodistro.0 ast2500-default ttyS4')
-
-    @skipUnless(os.getenv('QEMU_TEST_FLAKY_TESTS'), 'Test is unstable on GitLab')
-    def test_arm_ast2600_evb_sdk(self):
-        """
-        :avocado: tags=arch:arm
-        :avocado: tags=machine:ast2600-evb
-        :avocado: tags=flaky
-        """
-
-        image_url = ('https://github.com/AspeedTech-BMC/openbmc/releases/'
-                     'download/v08.06/ast2600-a2-obmc.tar.gz')
-        image_hash = ('9083506135f622d5e7351fcf7d4e1c7125cee5ba16141220c0ba88931f3681a4')
-        image_path = self.fetch_asset(image_url, asset_hash=image_hash,
-                                      algorithm='sha256')
-        archive.extract(image_path, self.workdir)
-
-        self.vm.add_args('-device',
-                         'tmp105,bus=aspeed.i2c.bus.5,address=0x4d,id=tmp-test');
-        self.vm.add_args('-device',
-                         'ds1338,bus=aspeed.i2c.bus.5,address=0x32');
-        self.do_test_arm_aspeed_sdk_start(
-            self.workdir + '/ast2600-a2/image-bmc')
-        self.wait_for_console_pattern('nodistro.0 ast2600-a2 ttyS4')
-
-        self.ssh_connect('root', '0penBmc', False)
-        self.ssh_command('dmesg -c > /dev/null')
-
-        self.ssh_command_output_contains(
-             'echo lm75 0x4d > /sys/class/i2c-dev/i2c-5/device/new_device ; '
-             'dmesg -c',
-             'i2c i2c-5: new_device: Instantiated device lm75 at 0x4d');
-        self.ssh_command_output_contains(
-                             'cat /sys/class/hwmon/hwmon19/temp1_input', '0')
-        self.vm.cmd('qom-set', path='/machine/peripheral/tmp-test',
-                    property='temperature', value=18000);
-        self.ssh_command_output_contains(
-                             'cat /sys/class/hwmon/hwmon19/temp1_input', '18000')
-
-        self.ssh_command_output_contains(
-             'echo ds1307 0x32 > /sys/class/i2c-dev/i2c-5/device/new_device ; '
-             'dmesg -c',
-             'i2c i2c-5: new_device: Instantiated device ds1307 at 0x32');
-        year = time.strftime("%Y")
-        self.ssh_command_output_contains('/sbin/hwclock -f /dev/rtc1', year);
-
diff --git a/tests/functional/test_arm_aspeed.py b/tests/functional/test_arm_aspeed.py
index 5fb1adf46439..7644ecbae750 100755
--- a/tests/functional/test_arm_aspeed.py
+++ b/tests/functional/test_arm_aspeed.py
@@ -252,6 +252,73 @@ def test_arm_ast2600_evb_buildroot_tpm(self):
 
         self.do_test_arm_aspeed_buildroot_poweroff()
 
+    def do_test_arm_aspeed_sdk_start(self, image):
+        self.vm.set_console()
+        self.vm.add_args('-drive', 'file=' + image + ',if=mtd,format=raw',
+                         '-net', 'nic', '-net', 'user', '-snapshot')
+        self.vm.launch()
+
+        self.wait_for_console_pattern('U-Boot 2019.04')
+        self.wait_for_console_pattern('## Loading kernel from FIT Image')
+        self.wait_for_console_pattern('Starting kernel ...')
+
+    ASSET_SDK_V806_AST2500 = Asset(
+        'https://github.com/AspeedTech-BMC/openbmc/releases/download/v08.06/ast2500-default-obmc.tar.gz',
+        'e1755f3cadff69190438c688d52dd0f0d399b70a1e14b1d3d5540fc4851d38ca')
+
+    def test_arm_ast2500_evb_sdk(self):
+        self.set_machine('ast2500-evb')
+
+        image_path = self.ASSET_SDK_V806_AST2500.fetch()
+
+        archive_extract(image_path, self.workdir)
+
+        self.do_test_arm_aspeed_sdk_start(
+            self.workdir + '/ast2500-default/image-bmc')
+
+        self.wait_for_console_pattern('ast2500-default login:')
+
+    ASSET_SDK_V806_AST2600_A2 = Asset(
+        'https://github.com/AspeedTech-BMC/openbmc/releases/download/v08.06/ast2600-a2-obmc.tar.gz',
+        '9083506135f622d5e7351fcf7d4e1c7125cee5ba16141220c0ba88931f3681a4')
+
+    def test_arm_ast2600_evb_sdk(self):
+        self.set_machine('ast2600-evb')
+
+        image_path = self.ASSET_SDK_V806_AST2600_A2.fetch()
+
+        archive_extract(image_path, self.workdir)
+
+        self.vm.add_args('-device',
+            'tmp105,bus=aspeed.i2c.bus.5,address=0x4d,id=tmp-test');
+        self.vm.add_args('-device',
+            'ds1338,bus=aspeed.i2c.bus.5,address=0x32');
+        self.do_test_arm_aspeed_sdk_start(
+            self.workdir + '/ast2600-a2/image-bmc')
+
+        self.wait_for_console_pattern('ast2600-a2 login:')
+
+        exec_command_and_wait_for_pattern(self, 'root', 'Password:')
+        exec_command_and_wait_for_pattern(self, '0penBmc', 'root@ast2600-a2:~#')
+
+        exec_command_and_wait_for_pattern(self,
+            'echo lm75 0x4d > /sys/class/i2c-dev/i2c-5/device/new_device',
+            'i2c i2c-5: new_device: Instantiated device lm75 at 0x4d');
+        exec_command_and_wait_for_pattern(self,
+             'cat /sys/class/hwmon/hwmon19/temp1_input', '0')
+        self.vm.cmd('qom-set', path='/machine/peripheral/tmp-test',
+                    property='temperature', value=18000);
+        exec_command_and_wait_for_pattern(self,
+             'cat /sys/class/hwmon/hwmon19/temp1_input', '18000')
+
+        exec_command_and_wait_for_pattern(self,
+             'echo ds1307 0x32 > /sys/class/i2c-dev/i2c-5/device/new_device',
+             'i2c i2c-5: new_device: Instantiated device ds1307 at 0x32');
+        year = time.strftime("%Y")
+        exec_command_and_wait_for_pattern(self,
+             '/sbin/hwclock -f /dev/rtc1', year);
+
+
 class AST2x00MachineMMC(LinuxKernelTest):
 
     ASSET_RAINIER_EMMC = Asset(
-- 
2.47.0

[PATCH v2 4/4] tests/functional: Remove sleep workarounds from Aspeed tests

[Cédric Le Goater]

These were introduced in the avocado tests to workaround read issues
when interacting with console. They are no longer necessary and we can
use the expected  "login:" string now.

Signed-off-by: Cédric Le Goater <clg@redhat.com>
---
 tests/functional/test_arm_aspeed.py | 12 +++++-------
 1 file changed, 5 insertions(+), 7 deletions(-)

diff --git a/tests/functional/test_arm_aspeed.py b/tests/functional/test_arm_aspeed.py
index 7644ecbae750..2c9009f686fd 100755
--- a/tests/functional/test_arm_aspeed.py
+++ b/tests/functional/test_arm_aspeed.py
@@ -136,10 +136,8 @@ def do_test_arm_aspeed_buildroot_start(self, image, cpu_id, pattern='Aspeed EVB'
         self.wait_for_console_pattern('lease of 10.0.2.15')
         # the line before login:
         self.wait_for_console_pattern(pattern)
-        time.sleep(0.1)
-        exec_command(self, 'root')
-        time.sleep(0.1)
-        exec_command(self, "passw0rd")
+        exec_command_and_wait_for_pattern(self, 'root', 'Password:')
+        exec_command_and_wait_for_pattern(self, 'passw0rd', '#')
 
     def do_test_arm_aspeed_buildroot_poweroff(self):
         exec_command_and_wait_for_pattern(self, 'poweroff',
@@ -158,7 +156,7 @@ def test_arm_ast2500_evb_buildroot(self):
         self.vm.add_args('-device',
                          'tmp105,bus=aspeed.i2c.bus.3,address=0x4d,id=tmp-test');
         self.do_test_arm_aspeed_buildroot_start(image_path, '0x0',
-                                                'Aspeed AST2500 EVB')
+                                                'ast2500-evb login:')
 
         exec_command_and_wait_for_pattern(self,
              'echo lm75 0x4d > /sys/class/i2c-dev/i2c-3/device/new_device',
@@ -188,7 +186,8 @@ def test_arm_ast2600_evb_buildroot(self):
                          'ds1338,bus=aspeed.i2c.bus.3,address=0x32');
         self.vm.add_args('-device',
                          'i2c-echo,bus=aspeed.i2c.bus.3,address=0x42');
-        self.do_test_arm_aspeed_buildroot_start(image_path, '0xf00', 'Aspeed AST2600 EVB')
+        self.do_test_arm_aspeed_buildroot_start(image_path, '0xf00',
+                                                'ast2600-evb login:')
 
         exec_command_and_wait_for_pattern(self,
              'echo lm75 0x4d > /sys/class/i2c-dev/i2c-3/device/new_device',
@@ -210,7 +209,6 @@ def test_arm_ast2600_evb_buildroot(self):
              'echo slave-24c02 0x1064 > /sys/bus/i2c/devices/i2c-3/new_device',
              'i2c i2c-3: new_device: Instantiated device slave-24c02 at 0x64');
         exec_command(self, 'i2cset -y 3 0x42 0x64 0x00 0xaa i');
-        time.sleep(0.1)
         exec_command_and_wait_for_pattern(self,
              'hexdump /sys/bus/i2c/devices/3-1064/slave-eeprom',
              '0000000 ffaa ffff ffff ffff ffff ffff ffff ffff');
-- 
2.47.0

Re: [PATCH v2 4/4] tests/functional: Remove sleep workarounds from Aspeed tests

[Thomas Huth]

On 12/11/2024 14.02, Cédric Le Goater wrote:
> These were introduced in the avocado tests to workaround read issues
> when interacting with console. They are no longer necessary and we can
> use the expected  "login:" string now.
> 
> Signed-off-by: Cédric Le Goater <clg@redhat.com>
> ---
>   tests/functional/test_arm_aspeed.py | 12 +++++-------
>   1 file changed, 5 insertions(+), 7 deletions(-)
> 
> diff --git a/tests/functional/test_arm_aspeed.py b/tests/functional/test_arm_aspeed.py
> index 7644ecbae750..2c9009f686fd 100755
> --- a/tests/functional/test_arm_aspeed.py
> +++ b/tests/functional/test_arm_aspeed.py
> @@ -136,10 +136,8 @@ def do_test_arm_aspeed_buildroot_start(self, image, cpu_id, pattern='Aspeed EVB'
>           self.wait_for_console_pattern('lease of 10.0.2.15')
>           # the line before login:
>           self.wait_for_console_pattern(pattern)
> -        time.sleep(0.1)
> -        exec_command(self, 'root')
> -        time.sleep(0.1)
> -        exec_command(self, "passw0rd")
> +        exec_command_and_wait_for_pattern(self, 'root', 'Password:')
> +        exec_command_and_wait_for_pattern(self, 'passw0rd', '#')
>   
>       def do_test_arm_aspeed_buildroot_poweroff(self):
>           exec_command_and_wait_for_pattern(self, 'poweroff',
> @@ -158,7 +156,7 @@ def test_arm_ast2500_evb_buildroot(self):
>           self.vm.add_args('-device',
>                            'tmp105,bus=aspeed.i2c.bus.3,address=0x4d,id=tmp-test');
>           self.do_test_arm_aspeed_buildroot_start(image_path, '0x0',
> -                                                'Aspeed AST2500 EVB')
> +                                                'ast2500-evb login:')
>   
>           exec_command_and_wait_for_pattern(self,
>                'echo lm75 0x4d > /sys/class/i2c-dev/i2c-3/device/new_device',
> @@ -188,7 +186,8 @@ def test_arm_ast2600_evb_buildroot(self):
>                            'ds1338,bus=aspeed.i2c.bus.3,address=0x32');
>           self.vm.add_args('-device',
>                            'i2c-echo,bus=aspeed.i2c.bus.3,address=0x42');
> -        self.do_test_arm_aspeed_buildroot_start(image_path, '0xf00', 'Aspeed AST2600 EVB')
> +        self.do_test_arm_aspeed_buildroot_start(image_path, '0xf00',
> +                                                'ast2600-evb login:')
>   
>           exec_command_and_wait_for_pattern(self,
>                'echo lm75 0x4d > /sys/class/i2c-dev/i2c-3/device/new_device',
> @@ -210,7 +209,6 @@ def test_arm_ast2600_evb_buildroot(self):
>                'echo slave-24c02 0x1064 > /sys/bus/i2c/devices/i2c-3/new_device',
>                'i2c i2c-3: new_device: Instantiated device slave-24c02 at 0x64');
>           exec_command(self, 'i2cset -y 3 0x42 0x64 0x00 0xaa i');

Could we please wait for the shell prompt here now? i.e.:

          exec_command_and_wait_for_pattern(self,
              'i2cset -y 3 0x42 0x64 0x00 0xaa i', '#')

or something similar?

With such a fix included:
Reviewed-by: Thomas Huth <thuth@redhat.com>


> -        time.sleep(0.1)
>           exec_command_and_wait_for_pattern(self,
>                'hexdump /sys/bus/i2c/devices/3-1064/slave-eeprom',
>                '0000000 ffaa ffff ffff ffff ffff ffff ffff ffff');

Re: [PATCH v2 1/4] tests/functional: Introduce _console_read()

[Thomas Huth]

On 12/11/2024 14.02, Cédric Le Goater wrote:
> Interaction with the console has been a problem in our avocado
> tests. In some cases, the expected string does not match in the
> output, causing the test to fail with a timeout. These were worked
> around by sleeping before reading the console and even with SSH
> connections in some places.
> 
> To fix, process the console output char by char and not with
> readline. This routine was largely inspired by console_wait() in
> tests/vm/basevm.py.
> 
> Signed-off-by: Cédric Le Goater <clg@redhat.com>
> ---
>   tests/functional/qemu_test/cmd.py | 22 ++++++++++++++++++++--
>   1 file changed, 20 insertions(+), 2 deletions(-)
> 
> diff --git a/tests/functional/qemu_test/cmd.py b/tests/functional/qemu_test/cmd.py
> index cbabb1ceed3c..5bca29d1d721 100644
> --- a/tests/functional/qemu_test/cmd.py
> +++ b/tests/functional/qemu_test/cmd.py
> @@ -12,6 +12,7 @@
>   # later.  See the COPYING file in the top-level directory.
>   
>   import logging
> +import re
>   import os
>   import os.path
>   import subprocess
> @@ -78,6 +79,23 @@ def run_cmd(args):
>   def is_readable_executable_file(path):
>       return os.path.isfile(path) and os.access(path, os.R_OK | os.X_OK)
>   
> +def _console_read(vm, expect):
> +    console_logger = logging.getLogger('console')
> +    output = ""
> +    while True:
> +        data = vm.console_socket.recv(1)
> +        if not data:
> +            break
> +        output += data.decode("latin1")
> +        if expect in output:
> +            break
> +        if "\r" in output or "\n" in output:
> +            lines = re.split("[\r\n]", output)
> +            if lines[0]:
> +                console_logger.debug(lines[0])
> +            output = lines.pop()
> +    return output
> +
>   def _console_interaction(test, success_message, failure_message,
>                            send_string, keep_sending=False, vm=None):
>       assert not keep_sending or send_string
> @@ -98,12 +116,12 @@ def _console_interaction(test, success_message, failure_message,
>               continue
>   
>           try:
> -            msg = console.readline().decode().strip()
> +            msg = _console_read(vm, success_message)
>           except UnicodeDecodeError:
>               msg = None
>           if not msg:
>               continue
> -        console_logger.debug(msg)
> +        console_logger.debug('found "%s"', msg)

Sorry for being picky (yay, bike shed painting!), but it's a little bit hard 
to distinguish these "found" markers in the console.log from the lines that 
just contain the normal output.

Maybe we could use some funky unicode character instead? For example:

         console_logger.debug('🔎 %s', msg)

or:

         console_logger.debug('✅ %s', msg)

?

Or maybe just indent the normal lines, i.e. in the _console_read() function
you could do this instead:

        console_logger.debug('      %s', lines[0])

so that the "found" string is more visually separated?

Or maybe even combine the two approaches?

  Thanks,
   Thomas

Re: [PATCH v2 4/4] tests/functional: Remove sleep workarounds from Aspeed tests

[Cédric Le Goater]

On 11/12/24 14:36, Thomas Huth wrote:
> On 12/11/2024 14.02, Cédric Le Goater wrote:
>> These were introduced in the avocado tests to workaround read issues
>> when interacting with console. They are no longer necessary and we can
>> use the expected  "login:" string now.
>>
>> Signed-off-by: Cédric Le Goater <clg@redhat.com>
>> ---
>>   tests/functional/test_arm_aspeed.py | 12 +++++-------
>>   1 file changed, 5 insertions(+), 7 deletions(-)
>>
>> diff --git a/tests/functional/test_arm_aspeed.py b/tests/functional/test_arm_aspeed.py
>> index 7644ecbae750..2c9009f686fd 100755
>> --- a/tests/functional/test_arm_aspeed.py
>> +++ b/tests/functional/test_arm_aspeed.py
>> @@ -136,10 +136,8 @@ def do_test_arm_aspeed_buildroot_start(self, image, cpu_id, pattern='Aspeed EVB'
>>           self.wait_for_console_pattern('lease of 10.0.2.15')
>>           # the line before login:
>>           self.wait_for_console_pattern(pattern)
>> -        time.sleep(0.1)
>> -        exec_command(self, 'root')
>> -        time.sleep(0.1)
>> -        exec_command(self, "passw0rd")
>> +        exec_command_and_wait_for_pattern(self, 'root', 'Password:')
>> +        exec_command_and_wait_for_pattern(self, 'passw0rd', '#')
>>       def do_test_arm_aspeed_buildroot_poweroff(self):
>>           exec_command_and_wait_for_pattern(self, 'poweroff',
>> @@ -158,7 +156,7 @@ def test_arm_ast2500_evb_buildroot(self):
>>           self.vm.add_args('-device',
>>                            'tmp105,bus=aspeed.i2c.bus.3,address=0x4d,id=tmp-test');
>>           self.do_test_arm_aspeed_buildroot_start(image_path, '0x0',
>> -                                                'Aspeed AST2500 EVB')
>> +                                                'ast2500-evb login:')
>>           exec_command_and_wait_for_pattern(self,
>>                'echo lm75 0x4d > /sys/class/i2c-dev/i2c-3/device/new_device',
>> @@ -188,7 +186,8 @@ def test_arm_ast2600_evb_buildroot(self):
>>                            'ds1338,bus=aspeed.i2c.bus.3,address=0x32');
>>           self.vm.add_args('-device',
>>                            'i2c-echo,bus=aspeed.i2c.bus.3,address=0x42');
>> -        self.do_test_arm_aspeed_buildroot_start(image_path, '0xf00', 'Aspeed AST2600 EVB')
>> +        self.do_test_arm_aspeed_buildroot_start(image_path, '0xf00',
>> +                                                'ast2600-evb login:')
>>           exec_command_and_wait_for_pattern(self,
>>                'echo lm75 0x4d > /sys/class/i2c-dev/i2c-3/device/new_device',
>> @@ -210,7 +209,6 @@ def test_arm_ast2600_evb_buildroot(self):
>>                'echo slave-24c02 0x1064 > /sys/bus/i2c/devices/i2c-3/new_device',
>>                'i2c i2c-3: new_device: Instantiated device slave-24c02 at 0x64');
>>           exec_command(self, 'i2cset -y 3 0x42 0x64 0x00 0xaa i');
> 
> Could we please wait for the shell prompt here now? i.e.:
> 
>           exec_command_and_wait_for_pattern(self,
>               'i2cset -y 3 0x42 0x64 0x00 0xaa i', '#')
> 
> or something similar?

Done and that's the last use of exec_command() in this file.

> With such a fix included:
> Reviewed-by: Thomas Huth <thuth@redhat.com>

Thanks,

C.

Re: [PATCH v2 1/4] tests/functional: Introduce _console_read()

[Cédric Le Goater]

> Maybe we could use some funky unicode character instead? For example:
> 
>          console_logger.debug('🔎 %s', msg)
> 
> or:
> 
>          console_logger.debug('✅ %s', msg)

How's that ?

https://paste.debian.net/1335303/

Thanks,

C.

Re: [PATCH v2 3/4] tests/functional: Convert Aspeed arm SDK tests

[Thomas Huth]

On 12/11/2024 14.02, Cédric Le Goater wrote:
> Drop the SSH connection which was introduced in the avocado tests to
> workaround read issues when interacting with console.
> 
> Signed-off-by: Cédric Le Goater <clg@redhat.com>
> ---
>   tests/avocado/machine_aspeed.py     | 124 ----------------------------
>   tests/functional/test_arm_aspeed.py |  67 +++++++++++++++
>   2 files changed, 67 insertions(+), 124 deletions(-)
>   delete mode 100644 tests/avocado/machine_aspeed.py
> 
> diff --git a/tests/avocado/machine_aspeed.py b/tests/avocado/machine_aspeed.py
> deleted file mode 100644
> index 2240c82abff9..000000000000
> --- a/tests/avocado/machine_aspeed.py
> +++ /dev/null
> @@ -1,124 +0,0 @@
> -# Functional test that boots the ASPEED SoCs with firmware
> -#
> -# Copyright (C) 2022 ASPEED Technology Inc
> -#
> -# This work is licensed under the terms of the GNU GPL, version 2 or
> -# later.  See the COPYING file in the top-level directory.
> -
> -import time
> -import os
> -import tempfile
> -import subprocess
> -
> -from avocado_qemu import LinuxSSHMixIn
> -from avocado_qemu import QemuSystemTest
> -from avocado_qemu import wait_for_console_pattern
> -from avocado_qemu import exec_command
> -from avocado_qemu import exec_command_and_wait_for_pattern
> -from avocado_qemu import interrupt_interactive_console_until_pattern
> -from avocado_qemu import has_cmd
> -from avocado.utils import archive
> -from avocado import skipUnless
> -
> -class AST2x00MachineSDK(QemuSystemTest, LinuxSSHMixIn):
> -
> -    EXTRA_BOOTARGS = (
> -        'quiet '
> -        'systemd.mask=org.openbmc.HostIpmi.service '
> -        'systemd.mask=xyz.openbmc_project.Chassis.Control.Power@0.service '
> -        'systemd.mask=modprobe@fuse.service '
> -        'systemd.mask=rngd.service '
> -        'systemd.mask=obmc-console@ttyS2.service '
> -    )

What about that EXTRA_BOOTARGS stuff? Is it not required/wanted in the new 
file anymore? ... maybe mention it at least in the commit description?

  Thomas

Re: [PATCH v2 1/4] tests/functional: Introduce _console_read()

[Thomas Huth]

On 12/11/2024 14.52, Cédric Le Goater wrote:
>> Maybe we could use some funky unicode character instead? For example:
>>
>>          console_logger.debug('🔎 %s', msg)
>>
>> or:
>>
>>          console_logger.debug('✅ %s', msg)
> 
> How's that ?
> 
> https://paste.debian.net/1335303/

Fine for me!

  Thanks,
   Thomas

Re: [PATCH v2 1/4] tests/functional: Introduce _console_read()

[Daniel P. Berrangé]

On Tue, Nov 12, 2024 at 02:02:43PM +0100, Cédric Le Goater wrote:
> Interaction with the console has been a problem in our avocado
> tests. In some cases, the expected string does not match in the
> output, causing the test to fail with a timeout. These were worked
> around by sleeping before reading the console and even with SSH
> connections in some places.
> 
> To fix, process the console output char by char and not with
> readline. This routine was largely inspired by console_wait() in
> tests/vm/basevm.py.
> 
> Signed-off-by: Cédric Le Goater <clg@redhat.com>
> ---
>  tests/functional/qemu_test/cmd.py | 22 ++++++++++++++++++++--
>  1 file changed, 20 insertions(+), 2 deletions(-)
> 
> diff --git a/tests/functional/qemu_test/cmd.py b/tests/functional/qemu_test/cmd.py
> index cbabb1ceed3c..5bca29d1d721 100644
> --- a/tests/functional/qemu_test/cmd.py
> +++ b/tests/functional/qemu_test/cmd.py
> @@ -12,6 +12,7 @@
>  # later.  See the COPYING file in the top-level directory.
>  
>  import logging
> +import re
>  import os
>  import os.path
>  import subprocess
> @@ -78,6 +79,23 @@ def run_cmd(args):
>  def is_readable_executable_file(path):
>      return os.path.isfile(path) and os.access(path, os.R_OK | os.X_OK)
>  
> +def _console_read(vm, expect):
> +    console_logger = logging.getLogger('console')
> +    output = ""
> +    while True:
> +        data = vm.console_socket.recv(1)
> +        if not data:
> +            break
> +        output += data.decode("latin1")

Decoding this as 'latin1' is going to mangle any output
that is not represented by a single-byte UTF-8 codepoint.

You can't simply switch this to 'utf8' though, as in the
socket.recv(1) call you're only reading a single byte,
and you can't guarantee that can be decoded if its part
of a multi-byte sequence.

I think you need to read into a bytearray, instead of
reading into a string. Then convert 'expect' into a
bytearray too, and compare bytes for a match, thus
avoiding problem of partial utf8 sequence decoding
errors.

> +        if expect in output:
> +            break
> +        if "\r" in output or "\n" in output:
> +            lines = re.split("[\r\n]", output)
> +            if lines[0]:
> +                console_logger.debug(lines[0])
> +            output = lines.pop()
> +    return output

In the commit message you talk about a problem with non-matched
text, and timeouts causing failure.

IIUC, the key difference between this code and the use of readline()
is that this code is checking for a match in the partial line. ie we
don't need to wait for a newline to arrive anymore.

That's an interesting difference, but its not obviously correlated
with the commit message description.

> +
>  def _console_interaction(test, success_message, failure_message,
>                           send_string, keep_sending=False, vm=None):
>      assert not keep_sending or send_string
> @@ -98,12 +116,12 @@ def _console_interaction(test, success_message, failure_message,
>              continue
>  
>          try:
> -            msg = console.readline().decode().strip()
> +            msg = _console_read(vm, success_message)
>          except UnicodeDecodeError:
>              msg = None
>          if not msg:
>              continue
> -        console_logger.debug(msg)
> +        console_logger.debug('found "%s"', msg)
>          if success_message is None or success_message in msg:
>              break
>          if failure_message and failure_message in msg:
> -- 
> 2.47.0
> 
> 

With regards,
Daniel
-- 
|: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org         -o-            https://fstop138.berrange.com :|
|: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|