From 6f0942b723df9441fe3304e8ab6d87bb17f88a1e Mon Sep 17 00:00:00 2001 From: "Daniel P. Berrangé" Date: Thu, 21 Nov 2024 16:57:39 +0000 Subject: tests/functional: logs details of console interaction operations MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit When functional tests go wrong, it will often be related to the console interaction wait state. By logging the messages that we're looking for, and data we're about to be sending, it'll be easier to diagnose where tests are getting stuck. Signed-off-by: Daniel P. Berrangé Message-Id: <20241121154218.1423005-13-berrange@redhat.com> Reviewed-by: Thomas Huth Signed-off-by: Alex Bennée Message-Id: <20241121165806.476008-13-alex.bennee@linaro.org> --- tests/functional/qemu_test/cmd.py | 3 +++ 1 file changed, 3 insertions(+) (limited to 'tests/functional/qemu_test/cmd.py') diff --git a/tests/functional/qemu_test/cmd.py b/tests/functional/qemu_test/cmd.py index cbabb1ceed..98722a9cf6 100644 --- a/tests/functional/qemu_test/cmd.py +++ b/tests/functional/qemu_test/cmd.py @@ -85,6 +85,9 @@ def _console_interaction(test, success_message, failure_message, vm = test.vm console = vm.console_file console_logger = logging.getLogger('console') + test.log.debug( + f"Console interaction: success_msg='{success_message}' " + + f"failure_msg='{failure_message}' send_string='{send_string}'") while True: if send_string: vm.console_socket.sendall(send_string.encode()) -- cgit 1.4.1 From f03a81897db14bb56109b6adc8699a91774b3389 Mon Sep 17 00:00:00 2001 From: "Daniel P. Berrangé" Date: Thu, 21 Nov 2024 16:57:41 +0000 Subject: tests/functional: require non-NULL success_message for console wait MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit When waiting for expected output, the 'success_message' is a mandatory parameter, with 'failure_message' defaulting to None. The code has logic which indicates it was trying to cope with 'success_message' being None and 'failure_message' being non-None but it does not appear able to actually do anything useful. The check for 'success_message is None' will break out of the loop before any check for 'failure_message' has been performed. IOW, for practcal purposes 'success_message' must be non-None unless 'send_string' is set. Assert this expectation and simplify the loop logic. Signed-off-by: Daniel P. Berrangé Message-Id: <20241121154218.1423005-15-berrange@redhat.com> Reviewed-by: Thomas Huth Signed-off-by: Alex Bennée Message-Id: <20241121165806.476008-15-alex.bennee@linaro.org> --- tests/functional/qemu_test/cmd.py | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) (limited to 'tests/functional/qemu_test/cmd.py') diff --git a/tests/functional/qemu_test/cmd.py b/tests/functional/qemu_test/cmd.py index 98722a9cf6..f6c4e4dda1 100644 --- a/tests/functional/qemu_test/cmd.py +++ b/tests/functional/qemu_test/cmd.py @@ -81,6 +81,8 @@ def is_readable_executable_file(path): def _console_interaction(test, success_message, failure_message, send_string, keep_sending=False, vm=None): assert not keep_sending or send_string + assert success_message or send_string + if vm is None: vm = test.vm console = vm.console_file @@ -95,7 +97,7 @@ def _console_interaction(test, success_message, failure_message, send_string = None # send only once # Only consume console output if waiting for something - if success_message is None and failure_message is None: + if success_message is None: if send_string is None: break continue @@ -107,7 +109,7 @@ def _console_interaction(test, success_message, failure_message, if not msg: continue console_logger.debug(msg) - if success_message is None or success_message in msg: + if success_message in msg: break if failure_message and failure_message in msg: console.close() @@ -138,6 +140,7 @@ def interrupt_interactive_console_until_pattern(test, success_message, :param interrupt_string: a string to send to the console before trying to read a new line """ + assert success_message _console_interaction(test, success_message, failure_message, interrupt_string, True) @@ -152,6 +155,7 @@ def wait_for_console_pattern(test, success_message, failure_message=None, :param success_message: if this message appears, test succeeds :param failure_message: if this message appears, test fails """ + assert success_message _console_interaction(test, success_message, failure_message, None, vm=vm) def exec_command(test, command): @@ -180,6 +184,7 @@ def exec_command_and_wait_for_pattern(test, command, :param success_message: if this message appears, test succeeds :param failure_message: if this message appears, test fails """ + assert success_message _console_interaction(test, success_message, failure_message, command + '\r') def get_qemu_img(test): -- cgit 1.4.1 From cdad03b74f759857d784e074755f0d96a64d69af Mon Sep 17 00:00:00 2001 From: "Daniel P. Berrangé" Date: Thu, 21 Nov 2024 16:57:42 +0000 Subject: tests/functional: rewrite console handling to be bytewise MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The console interaction that waits for predicted strings uses readline(), and thus is only capable of waiting for strings that are followed by a newline. This is inconvenient when needing to match on some things, particularly login prompts, or shell prompts, causing tests to use time.sleep(...) instead, which is unreliable. Switch to reading the console 1 byte at a time, comparing against the success/failure messages until we see a match, regardless of whether a newline is encountered. The success/failure comparisons are done with the python bytes type, rather than strings, to avoid the problem of needing to decode partially received multibyte utf8 characters. Heavily inspired by a patch proposed by Cédric, but written again to work in bytes, rather than strings. Co-developed-by: Cédric Le Goater Signed-off-by: Daniel P. Berrangé Message-Id: <20241121154218.1423005-16-berrange@redhat.com> Signed-off-by: Alex Bennée Message-Id: <20241121165806.476008-16-alex.bennee@linaro.org> --- tests/functional/qemu_test/cmd.py | 79 +++++++++++++++++++++++++++++++-------- 1 file changed, 64 insertions(+), 15 deletions(-) (limited to 'tests/functional/qemu_test/cmd.py') diff --git a/tests/functional/qemu_test/cmd.py b/tests/functional/qemu_test/cmd.py index f6c4e4dda1..11c8334a7c 100644 --- a/tests/functional/qemu_test/cmd.py +++ b/tests/functional/qemu_test/cmd.py @@ -78,6 +78,54 @@ 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) +# @test: functional test to fail if @failure is seen +# @vm: the VM whose console to process +# @success: a non-None string to look for +# @failure: a string to look for that triggers test failure, or None +# +# Read up to 1 line of text from @vm, looking for @success +# and optionally @failure. +# +# If @success or @failure are seen, immediately return True, +# even if end of line is not yet seen. ie remainder of the +# line is left unread. +# +# If end of line is seen, with neither @success or @failure +# return False +# +# If @failure is seen, then mark @test as failed +def _console_read_line_until_match(test, vm, success, failure): + msg = bytes([]) + done = False + while True: + c = vm.console_socket.recv(1) + if c is None: + done = True + test.fail( + f"EOF in console, expected '{success}'") + break + msg += c + + if success in msg: + done = True + break + if failure and failure in msg: + done = True + vm.console_socket.close() + test.fail( + f"'{failure}' found in console, expected '{success}'") + + if c == b'\n': + break + + console_logger = logging.getLogger('console') + try: + console_logger.debug(msg.decode().strip()) + except: + console_logger.debug(msg) + + return done + def _console_interaction(test, success_message, failure_message, send_string, keep_sending=False, vm=None): assert not keep_sending or send_string @@ -85,11 +133,22 @@ def _console_interaction(test, success_message, failure_message, if vm is None: vm = test.vm - console = vm.console_file - console_logger = logging.getLogger('console') + test.log.debug( f"Console interaction: success_msg='{success_message}' " + f"failure_msg='{failure_message}' send_string='{send_string}'") + + # We'll process console in bytes, to avoid having to + # deal with unicode decode errors from receiving + # partial utf8 byte sequences + success_message_b = None + if success_message is not None: + success_message_b = success_message.encode() + + failure_message_b = None + if failure_message is not None: + failure_message_b = failure_message.encode() + while True: if send_string: vm.console_socket.sendall(send_string.encode()) @@ -102,20 +161,10 @@ def _console_interaction(test, success_message, failure_message, break continue - try: - msg = console.readline().decode().strip() - except UnicodeDecodeError: - msg = None - if not msg: - continue - console_logger.debug(msg) - if success_message in msg: + if _console_read_line_until_match(test, vm, + success_message_b, + failure_message_b): break - if failure_message and failure_message in msg: - console.close() - fail = 'Failure message found in console: "%s". Expected: "%s"' % \ - (failure_message, success_message) - test.fail(fail) def interrupt_interactive_console_until_pattern(test, success_message, failure_message=None, -- cgit 1.4.1