Refactor tests for more synergy

.rubocop.yml

@@ -16,6 +16,9 @@ Layout/IndentationWidth:
 Layout/LineLength:
   Max: 100
 
+Lint/UnusedMethodArgument:
+  AutoCorrect: False
+
 Metrics/AbcSize:
   Max: 25
 

06_uart_chainloader/README.md

@@ -550,7 +550,7 @@ diff -uNr 05_drivers_gpio_uart/tests/boot_test_string.rb 06_uart_chainloader/tes
 diff -uNr 05_drivers_gpio_uart/tests/chainboot_test.rb 06_uart_chainloader/tests/chainboot_test.rb
 --- 05_drivers_gpio_uart/tests/chainboot_test.rb
 +++ 06_uart_chainloader/tests/chainboot_test.rb
-@@ -0,0 +1,80 @@
+@@ -0,0 +1,78 @@
 +# frozen_string_literal: true
 +
 +# SPDX-License-Identifier: MIT OR Apache-2.0
@@ -564,11 +564,33 @@ diff -uNr 05_drivers_gpio_uart/tests/chainboot_test.rb 06_uart_chainloader/tests
 +# Match for the last print that 'demo_payload_rpiX.img' produces.
 +EXPECTED_PRINT = 'Echoing input now'
 +
++# Wait for request to power the target.
++class PowerTargetRequestTest < SubtestBase
++    MINIPUSH_POWER_TARGET_REQUEST = 'Please power the target now'
++
++    def initialize(qemu_cmd, pty_main)
++        super()
++        @qemu_cmd = qemu_cmd
++        @pty_main = pty_main
++    end
++
++    def name
++        'Waiting for request to power target'
++    end
++
++    def run(qemu_out, _qemu_in)
++        expect_or_raise(qemu_out, MINIPUSH_POWER_TARGET_REQUEST)
++
++        # Now is the time to start QEMU with the chainloader binary. QEMU's virtual tty connects to
++        # the MiniPush instance spawned on pty_main, so that the two processes talk to each other.
++        Process.spawn(@qemu_cmd, in: @pty_main, out: @pty_main, err: '/dev/null')
++    end
++end
++
 +# Extend BootTest so that it listens on the output of a MiniPush instance, which is itself connected
 +# to a QEMU instance instead of a real HW.
 +class ChainbootTest < BootTest
 +    MINIPUSH = '../common/serial/minipush.rb'
-+    MINIPUSH_POWER_TARGET_REQUEST = 'Please power the target now'
 +
 +    def initialize(qemu_cmd, payload_path)
 +        super(qemu_cmd, EXPECTED_PRINT)
@@ -581,46 +603,22 @@ diff -uNr 05_drivers_gpio_uart/tests/chainboot_test.rb 06_uart_chainloader/tests
 +    private
 +
 +    # override
-+    def post_process_and_add_output(output)
-+        temp = output.join.split("\r\n")
-+
-+        # Should a line have solo carriage returns, remove any overridden parts of the string.
-+        temp.map! { |x| x.gsub(/.*\r/, '') }
-+
-+        @test_output += temp
-+    end
-+
-+    def wait_for_minipush_power_request(mp_out)
-+        output = []
-+        Timeout.timeout(MAX_WAIT_SECS) do
-+            loop do
-+                output << mp_out.gets
-+                break if output.last.include?(MINIPUSH_POWER_TARGET_REQUEST)
-+            end
-+        end
-+    rescue Timeout::Error
-+        @test_error = 'Timed out waiting for power request'
-+    rescue StandardError => e
-+        @test_error = e.message
-+    ensure
-+        post_process_and_add_output(output)
-+    end
-+
-+    # override
 +    def setup
 +        pty_main, pty_secondary = PTY.open
 +        mp_out, _mp_in = PTY.spawn("ruby #{MINIPUSH} #{pty_secondary.path} #{@payload_path}")
 +
-+        # Wait until MiniPush asks for powering the target.
-+        wait_for_minipush_power_request(mp_out)
++        # The subtests (from this class and the parents) listen on @qemu_out_wrapped. Hence, point
++        # it to MiniPush's output.
++        @qemu_out_wrapped = PTYLoggerWrapper.new(mp_out, "\r\n")
 +
-+        # Now is the time to start QEMU with the chainloader binary. QEMU's virtual tty is connected
-+        # to the MiniPush instance spawned above, so that the two processes talk to each other.
-+        Process.spawn(@qemu_cmd, in: pty_main, out: pty_main)
++        # Important: Run this subtest before the one in the parent class.
++        @console_subtests.prepend(PowerTargetRequestTest.new(@qemu_cmd, pty_main))
++    end
 +
-+        # The remainder of the test is done by the parent class' run_concrete_test, which listens on
-+        # @qemu_serial. Hence, point it to MiniPush's output.
-+        @qemu_serial = mp_out
++    # override
++    def finish
++        super()
++        @test_output.map! { |x| x.gsub(/.*\r/, '  ') }
 +    end
 +end
 +

06_uart_chainloader/tests/chainboot_test.rb

@@ -11,11 +11,33 @@ require 'pty'
 # Match for the last print that 'demo_payload_rpiX.img' produces.
 EXPECTED_PRINT = 'Echoing input now'
 
+# Wait for request to power the target.
+class PowerTargetRequestTest < SubtestBase
+    MINIPUSH_POWER_TARGET_REQUEST = 'Please power the target now'
+
+    def initialize(qemu_cmd, pty_main)
+        super()
+        @qemu_cmd = qemu_cmd
+        @pty_main = pty_main
+    end
+
+    def name
+        'Waiting for request to power target'
+    end
+
+    def run(qemu_out, _qemu_in)
+        expect_or_raise(qemu_out, MINIPUSH_POWER_TARGET_REQUEST)
+
+        # Now is the time to start QEMU with the chainloader binary. QEMU's virtual tty connects to
+        # the MiniPush instance spawned on pty_main, so that the two processes talk to each other.
+        Process.spawn(@qemu_cmd, in: @pty_main, out: @pty_main, err: '/dev/null')
+    end
+end
+
 # Extend BootTest so that it listens on the output of a MiniPush instance, which is itself connected
 # to a QEMU instance instead of a real HW.
 class ChainbootTest < BootTest
     MINIPUSH = '../common/serial/minipush.rb'
-    MINIPUSH_POWER_TARGET_REQUEST = 'Please power the target now'
 
     def initialize(qemu_cmd, payload_path)
         super(qemu_cmd, EXPECTED_PRINT)
@@ -27,47 +49,23 @@ class ChainbootTest < BootTest
 
     private
 
-    # override
-    def post_process_and_add_output(output)
-        temp = output.join.split("\r\n")
-
-        # Should a line have solo carriage returns, remove any overridden parts of the string.
-        temp.map! { |x| x.gsub(/.*\r/, '') }
-
-        @test_output += temp
-    end
-
-    def wait_for_minipush_power_request(mp_out)
-        output = []
-        Timeout.timeout(MAX_WAIT_SECS) do
-            loop do
-                output << mp_out.gets
-                break if output.last.include?(MINIPUSH_POWER_TARGET_REQUEST)
-            end
-        end
-    rescue Timeout::Error
-        @test_error = 'Timed out waiting for power request'
-    rescue StandardError => e
-        @test_error = e.message
-    ensure
-        post_process_and_add_output(output)
-    end
-
     # override
     def setup
         pty_main, pty_secondary = PTY.open
         mp_out, _mp_in = PTY.spawn("ruby #{MINIPUSH} #{pty_secondary.path} #{@payload_path}")
 
-        # Wait until MiniPush asks for powering the target.
-        wait_for_minipush_power_request(mp_out)
+        # The subtests (from this class and the parents) listen on @qemu_out_wrapped. Hence, point
+        # it to MiniPush's output.
+        @qemu_out_wrapped = PTYLoggerWrapper.new(mp_out, "\r\n")
 
-        # Now is the time to start QEMU with the chainloader binary. QEMU's virtual tty is connected
-        # to the MiniPush instance spawned above, so that the two processes talk to each other.
-        Process.spawn(@qemu_cmd, in: pty_main, out: pty_main)
+        # Important: Run this subtest before the one in the parent class.
+        @console_subtests.prepend(PowerTargetRequestTest.new(@qemu_cmd, pty_main))
+    end
 
-        # The remainder of the test is done by the parent class' run_concrete_test, which listens on
-        # @qemu_serial. Hence, point it to MiniPush's output.
-        @qemu_serial = mp_out
+    # override
+    def finish
+        super()
+        @test_output.map! { |x| x.gsub(/.*\r/, '  ') }
     end
 end
 

07_timestamps/README.md

@@ -759,7 +759,7 @@ diff -uNr 06_uart_chainloader/tests/boot_test_string.rb 07_timestamps/tests/boot
 diff -uNr 06_uart_chainloader/tests/chainboot_test.rb 07_timestamps/tests/chainboot_test.rb
 --- 06_uart_chainloader/tests/chainboot_test.rb
 +++ 07_timestamps/tests/chainboot_test.rb
-@@ -1,80 +0,0 @@
+@@ -1,78 +0,0 @@
 -# frozen_string_literal: true
 -
 -# SPDX-License-Identifier: MIT OR Apache-2.0
@@ -773,11 +773,33 @@ diff -uNr 06_uart_chainloader/tests/chainboot_test.rb 07_timestamps/tests/chainb
 -# Match for the last print that 'demo_payload_rpiX.img' produces.
 -EXPECTED_PRINT = 'Echoing input now'
 -
+-# Wait for request to power the target.
+-class PowerTargetRequestTest < SubtestBase
+-    MINIPUSH_POWER_TARGET_REQUEST = 'Please power the target now'
+-
+-    def initialize(qemu_cmd, pty_main)
+-        super()
+-        @qemu_cmd = qemu_cmd
+-        @pty_main = pty_main
+-    end
+-
+-    def name
+-        'Waiting for request to power target'
+-    end
+-
+-    def run(qemu_out, _qemu_in)
+-        expect_or_raise(qemu_out, MINIPUSH_POWER_TARGET_REQUEST)
+-
+-        # Now is the time to start QEMU with the chainloader binary. QEMU's virtual tty connects to
+-        # the MiniPush instance spawned on pty_main, so that the two processes talk to each other.
+-        Process.spawn(@qemu_cmd, in: @pty_main, out: @pty_main, err: '/dev/null')
+-    end
+-end
+-
 -# Extend BootTest so that it listens on the output of a MiniPush instance, which is itself connected
 -# to a QEMU instance instead of a real HW.
 -class ChainbootTest < BootTest
 -    MINIPUSH = '../common/serial/minipush.rb'
--    MINIPUSH_POWER_TARGET_REQUEST = 'Please power the target now'
 -
 -    def initialize(qemu_cmd, payload_path)
 -        super(qemu_cmd, EXPECTED_PRINT)
@@ -790,46 +812,22 @@ diff -uNr 06_uart_chainloader/tests/chainboot_test.rb 07_timestamps/tests/chainb
 -    private
 -
 -    # override
--    def post_process_and_add_output(output)
--        temp = output.join.split("\r\n")
--
--        # Should a line have solo carriage returns, remove any overridden parts of the string.
--        temp.map! { |x| x.gsub(/.*\r/, '') }
--
--        @test_output += temp
--    end
--
--    def wait_for_minipush_power_request(mp_out)
--        output = []
--        Timeout.timeout(MAX_WAIT_SECS) do
--            loop do
--                output << mp_out.gets
--                break if output.last.include?(MINIPUSH_POWER_TARGET_REQUEST)
--            end
--        end
--    rescue Timeout::Error
--        @test_error = 'Timed out waiting for power request'
--    rescue StandardError => e
--        @test_error = e.message
--    ensure
--        post_process_and_add_output(output)
--    end
--
--    # override
 -    def setup
 -        pty_main, pty_secondary = PTY.open
 -        mp_out, _mp_in = PTY.spawn("ruby #{MINIPUSH} #{pty_secondary.path} #{@payload_path}")
 -
--        # Wait until MiniPush asks for powering the target.
--        wait_for_minipush_power_request(mp_out)
+-        # The subtests (from this class and the parents) listen on @qemu_out_wrapped. Hence, point
+-        # it to MiniPush's output.
+-        @qemu_out_wrapped = PTYLoggerWrapper.new(mp_out, "\r\n")
 -
--        # Now is the time to start QEMU with the chainloader binary. QEMU's virtual tty is connected
--        # to the MiniPush instance spawned above, so that the two processes talk to each other.
--        Process.spawn(@qemu_cmd, in: pty_main, out: pty_main)
+-        # Important: Run this subtest before the one in the parent class.
+-        @console_subtests.prepend(PowerTargetRequestTest.new(@qemu_cmd, pty_main))
+-    end
 -
--        # The remainder of the test is done by the parent class' run_concrete_test, which listens on
--        # @qemu_serial. Hence, point it to MiniPush's output.
--        @qemu_serial = mp_out
+-    # override
+-    def finish
+-        super()
+-        @test_output.map! { |x| x.gsub(/.*\r/, '  ') }
 -    end
 -end
 -

12_integrated_testing/README.md

@@ -460,7 +460,7 @@ when 'libkernel'
     ExitCodeTest.new(qemu_cmd, 'Kernel library unit tests').run # Doesn't return
 ```
 
-The easy case is `QEMU` existing by itself by means of `aarch64::exit_success()` or
+The easy case is `QEMU` exiting by itself by means of `aarch64::exit_success()` or
 `aarch64::exit_failure()`. But the script can also catch the case of a test that gets stuck, e.g. in
 an unintentional busy loop or a crash. If `ExitCodeTest` does not observe any output of the test
 kernel for `MAX_WAIT_SECS`, it cancels the execution and marks the test as failed. Test success or
@@ -471,20 +471,16 @@ is thrown):
 
 ```ruby
 def run_concrete_test
-    io = IO.popen(@qemu_cmd)
-
     Timeout.timeout(MAX_WAIT_SECS) do
-        @test_output << io.read_nonblock(1024) while IO.select([io])
+        @test_output << @qemu_serial.read_nonblock(1024) while @qemu_serial.wait_readable
     end
 rescue EOFError
-    io.close
+    @qemu_serial.close
     @test_error = $CHILD_STATUS.to_i.zero? ? false : 'QEMU exit status != 0'
 rescue Timeout::Error
     @test_error = 'Timed out waiting for test'
 rescue StandardError => e
-    @test_error = e.message
-ensure
-    post_process_output
+    @test_error = e.inspect
 end
 ```
 
@@ -742,15 +738,17 @@ Here is an excerpt from `00_console_sanity.rb` showing a subtest that does a han
 kernel over the console:
 
 ```ruby
+require_relative '../../common/tests/console_io_test'
+
 # Verify sending and receiving works as expected.
-class TxRxHandshake
+class TxRxHandshakeTest < SubtestBase
     def name
         'Transmit and Receive handshake'
     end
 
     def run(qemu_out, qemu_in)
         qemu_in.write_nonblock('ABC')
-        raise ExpectTimeoutError if qemu_out.expect('OK1234', TIMEOUT_SECS).nil?
+        expect_or_raise(qemu_out, 'OK1234')
     end
 end
 ```
@@ -824,6 +822,9 @@ Compiling integration test(s) - rpi3
            2. Transmit statistics.......................................[ok]
            3. Receive statistics........................................[ok]
 
+         Console log:
+           ABCOK123463
+
          -------------------------------------------------------------------
          ✅ Success: 00_console_sanity.rs
          -------------------------------------------------------------------
@@ -1761,55 +1762,46 @@ diff -uNr 11_exceptions_part1_groundwork/test-macros/src/lib.rs 12_integrated_te
 diff -uNr 11_exceptions_part1_groundwork/tests/00_console_sanity.rb 12_integrated_testing/tests/00_console_sanity.rb
 --- 11_exceptions_part1_groundwork/tests/00_console_sanity.rb
 +++ 12_integrated_testing/tests/00_console_sanity.rb
-@@ -0,0 +1,57 @@
+@@ -0,0 +1,48 @@
 +# frozen_string_literal: true
 +
 +# SPDX-License-Identifier: MIT OR Apache-2.0
 +#
 +# Copyright (c) 2019-2022 Andre Richter <andre.o.richter@gmail.com>
 +
-+require 'expect'
-+
-+TIMEOUT_SECS = 3
-+
-+# Error class for when expect times out.
-+class ExpectTimeoutError < StandardError
-+    def initialize
-+        super('Timeout while expecting string')
-+    end
-+end
++require_relative '../../common/tests/console_io_test'
 +
 +# Verify sending and receiving works as expected.
-+class TxRxHandshake
++class TxRxHandshakeTest < SubtestBase
 +    def name
 +        'Transmit and Receive handshake'
 +    end
 +
 +    def run(qemu_out, qemu_in)
 +        qemu_in.write_nonblock('ABC')
-+        raise ExpectTimeoutError if qemu_out.expect('OK1234', TIMEOUT_SECS).nil?
++        expect_or_raise(qemu_out, 'OK1234')
 +    end
 +end
 +
 +# Check for correct TX statistics implementation. Depends on test 1 being run first.
-+class TxStatistics
++class TxStatisticsTest < SubtestBase
 +    def name
 +        'Transmit statistics'
 +    end
 +
 +    def run(qemu_out, _qemu_in)
-+        raise ExpectTimeoutError if qemu_out.expect('6', TIMEOUT_SECS).nil?
++        expect_or_raise(qemu_out, '6')
 +    end
 +end
 +
 +# Check for correct RX statistics implementation. Depends on test 1 being run first.
-+class RxStatistics
++class RxStatisticsTest < SubtestBase
 +    def name
 +        'Receive statistics'
 +    end
 +
 +    def run(qemu_out, _qemu_in)
-+        raise ExpectTimeoutError if qemu_out.expect('3', TIMEOUT_SECS).nil?
++        expect_or_raise(qemu_out, '3')
 +    end
 +end
 +
@@ -1817,7 +1809,7 @@ diff -uNr 11_exceptions_part1_groundwork/tests/00_console_sanity.rb 12_integrate
 +## Test registration
 +##--------------------------------------------------------------------------------------------------
 +def subtest_collection
-+    [TxRxHandshake.new, TxStatistics.new, RxStatistics.new]
++    [TxRxHandshakeTest.new, TxStatisticsTest.new, RxStatisticsTest.new]
 +end
 
 diff -uNr 11_exceptions_part1_groundwork/tests/00_console_sanity.rs 12_integrated_testing/tests/00_console_sanity.rs

12_integrated_testing/tests/00_console_sanity.rb

@@ -4,48 +4,39 @@
 #
 # Copyright (c) 2019-2022 Andre Richter <andre.o.richter@gmail.com>
 
-require 'expect'
-
-TIMEOUT_SECS = 3
-
-# Error class for when expect times out.
-class ExpectTimeoutError < StandardError
-    def initialize
-        super('Timeout while expecting string')
-    end
-end
+require_relative '../../common/tests/console_io_test'
 
 # Verify sending and receiving works as expected.
-class TxRxHandshake
+class TxRxHandshakeTest < SubtestBase
     def name
         'Transmit and Receive handshake'
     end
 
     def run(qemu_out, qemu_in)
         qemu_in.write_nonblock('ABC')
-        raise ExpectTimeoutError if qemu_out.expect('OK1234', TIMEOUT_SECS).nil?
+        expect_or_raise(qemu_out, 'OK1234')
     end
 end
 
 # Check for correct TX statistics implementation. Depends on test 1 being run first.
-class TxStatistics
+class TxStatisticsTest < SubtestBase
     def name
         'Transmit statistics'
     end
 
     def run(qemu_out, _qemu_in)
-        raise ExpectTimeoutError if qemu_out.expect('6', TIMEOUT_SECS).nil?
+        expect_or_raise(qemu_out, '6')
     end
 end
 
 # Check for correct RX statistics implementation. Depends on test 1 being run first.
-class RxStatistics
+class RxStatisticsTest < SubtestBase
     def name
         'Receive statistics'
     end
 
     def run(qemu_out, _qemu_in)
-        raise ExpectTimeoutError if qemu_out.expect('3', TIMEOUT_SECS).nil?
+        expect_or_raise(qemu_out, '3')
     end
 end
 
@@ -53,5 +44,5 @@ end
 ## Test registration
 ##--------------------------------------------------------------------------------------------------
 def subtest_collection
-    [TxRxHandshake.new, TxStatistics.new, RxStatistics.new]
+    [TxRxHandshakeTest.new, TxStatisticsTest.new, RxStatisticsTest.new]
 end

13_exceptions_part2_peripheral_IRQs/tests/00_console_sanity.rb

@@ -4,48 +4,39 @@
 #
 # Copyright (c) 2019-2022 Andre Richter <andre.o.richter@gmail.com>
 
-require 'expect'
-
-TIMEOUT_SECS = 3
-
-# Error class for when expect times out.
-class ExpectTimeoutError < StandardError
-    def initialize
-        super('Timeout while expecting string')
-    end
-end
+require_relative '../../common/tests/console_io_test'
 
 # Verify sending and receiving works as expected.
-class TxRxHandshake
+class TxRxHandshakeTest < SubtestBase
     def name
         'Transmit and Receive handshake'
     end
 
     def run(qemu_out, qemu_in)
         qemu_in.write_nonblock('ABC')
-        raise ExpectTimeoutError if qemu_out.expect('OK1234', TIMEOUT_SECS).nil?
+        expect_or_raise(qemu_out, 'OK1234')
     end
 end
 
 # Check for correct TX statistics implementation. Depends on test 1 being run first.
-class TxStatistics
+class TxStatisticsTest < SubtestBase
     def name
         'Transmit statistics'
     end
 
     def run(qemu_out, _qemu_in)
-        raise ExpectTimeoutError if qemu_out.expect('6', TIMEOUT_SECS).nil?
+        expect_or_raise(qemu_out, '6')
     end
 end
 
 # Check for correct RX statistics implementation. Depends on test 1 being run first.
-class RxStatistics
+class RxStatisticsTest < SubtestBase
     def name
         'Receive statistics'
     end
 
     def run(qemu_out, _qemu_in)
-        raise ExpectTimeoutError if qemu_out.expect('3', TIMEOUT_SECS).nil?
+        expect_or_raise(qemu_out, '3')
     end
 end
 
@@ -53,5 +44,5 @@ end
 ## Test registration
 ##--------------------------------------------------------------------------------------------------
 def subtest_collection
-    [TxRxHandshake.new, TxStatistics.new, RxStatistics.new]
+    [TxRxHandshakeTest.new, TxStatisticsTest.new, RxStatisticsTest.new]
 end

14_virtual_mem_part2_mmio_remap/tests/00_console_sanity.rb

@@ -4,48 +4,39 @@
 #
 # Copyright (c) 2019-2022 Andre Richter <andre.o.richter@gmail.com>
 
-require 'expect'
-
-TIMEOUT_SECS = 3
-
-# Error class for when expect times out.
-class ExpectTimeoutError < StandardError
-    def initialize
-        super('Timeout while expecting string')
-    end
-end
+require_relative '../../common/tests/console_io_test'
 
 # Verify sending and receiving works as expected.
-class TxRxHandshake
+class TxRxHandshakeTest < SubtestBase
     def name
         'Transmit and Receive handshake'
     end
 
     def run(qemu_out, qemu_in)
         qemu_in.write_nonblock('ABC')
-        raise ExpectTimeoutError if qemu_out.expect('OK1234', TIMEOUT_SECS).nil?
+        expect_or_raise(qemu_out, 'OK1234')
     end
 end
 
 # Check for correct TX statistics implementation. Depends on test 1 being run first.
-class TxStatistics
+class TxStatisticsTest < SubtestBase
     def name
         'Transmit statistics'
     end
 
     def run(qemu_out, _qemu_in)
-        raise ExpectTimeoutError if qemu_out.expect('6', TIMEOUT_SECS).nil?
+        expect_or_raise(qemu_out, '6')
     end
 end
 
 # Check for correct RX statistics implementation. Depends on test 1 being run first.
-class RxStatistics
+class RxStatisticsTest < SubtestBase
     def name
         'Receive statistics'
     end
 
     def run(qemu_out, _qemu_in)
-        raise ExpectTimeoutError if qemu_out.expect('3', TIMEOUT_SECS).nil?
+        expect_or_raise(qemu_out, '3')
     end
 end
 
@@ -53,5 +44,5 @@ end
 ## Test registration
 ##--------------------------------------------------------------------------------------------------
 def subtest_collection
-    [TxRxHandshake.new, TxStatistics.new, RxStatistics.new]
+    [TxRxHandshakeTest.new, TxStatisticsTest.new, RxStatisticsTest.new]
 end

15_virtual_mem_part3_precomputed_tables/tests/00_console_sanity.rb

@@ -4,48 +4,39 @@
 #
 # Copyright (c) 2019-2022 Andre Richter <andre.o.richter@gmail.com>
 
-require 'expect'
-
-TIMEOUT_SECS = 3
-
-# Error class for when expect times out.
-class ExpectTimeoutError < StandardError
-    def initialize
-        super('Timeout while expecting string')
-    end
-end
+require_relative '../../common/tests/console_io_test'
 
 # Verify sending and receiving works as expected.
-class TxRxHandshake
+class TxRxHandshakeTest < SubtestBase
     def name
         'Transmit and Receive handshake'
     end
 
     def run(qemu_out, qemu_in)
         qemu_in.write_nonblock('ABC')
-        raise ExpectTimeoutError if qemu_out.expect('OK1234', TIMEOUT_SECS).nil?
+        expect_or_raise(qemu_out, 'OK1234')
     end
 end
 
 # Check for correct TX statistics implementation. Depends on test 1 being run first.
-class TxStatistics
+class TxStatisticsTest < SubtestBase
     def name
         'Transmit statistics'
     end
 
     def run(qemu_out, _qemu_in)
-        raise ExpectTimeoutError if qemu_out.expect('6', TIMEOUT_SECS).nil?
+        expect_or_raise(qemu_out, '6')
     end
 end
 
 # Check for correct RX statistics implementation. Depends on test 1 being run first.
-class RxStatistics
+class RxStatisticsTest < SubtestBase
     def name
         'Receive statistics'
     end
 
     def run(qemu_out, _qemu_in)
-        raise ExpectTimeoutError if qemu_out.expect('3', TIMEOUT_SECS).nil?
+        expect_or_raise(qemu_out, '3')
     end
 end
 
@@ -53,5 +44,5 @@ end
 ## Test registration
 ##--------------------------------------------------------------------------------------------------
 def subtest_collection
-    [TxRxHandshake.new, TxStatistics.new, RxStatistics.new]
+    [TxRxHandshakeTest.new, TxStatisticsTest.new, RxStatisticsTest.new]
 end

16_virtual_mem_part4_higher_half_kernel/tests/00_console_sanity.rb

@@ -4,48 +4,39 @@
 #
 # Copyright (c) 2019-2022 Andre Richter <andre.o.richter@gmail.com>
 
-require 'expect'
-
-TIMEOUT_SECS = 3
-
-# Error class for when expect times out.
-class ExpectTimeoutError < StandardError
-    def initialize
-        super('Timeout while expecting string')
-    end
-end
+require_relative '../../common/tests/console_io_test'
 
 # Verify sending and receiving works as expected.
-class TxRxHandshake
+class TxRxHandshakeTest < SubtestBase
     def name
         'Transmit and Receive handshake'
     end
 
     def run(qemu_out, qemu_in)
         qemu_in.write_nonblock('ABC')
-        raise ExpectTimeoutError if qemu_out.expect('OK1234', TIMEOUT_SECS).nil?
+        expect_or_raise(qemu_out, 'OK1234')
     end
 end
 
 # Check for correct TX statistics implementation. Depends on test 1 being run first.
-class TxStatistics
+class TxStatisticsTest < SubtestBase
     def name
         'Transmit statistics'
     end
 
     def run(qemu_out, _qemu_in)
-        raise ExpectTimeoutError if qemu_out.expect('6', TIMEOUT_SECS).nil?
+        expect_or_raise(qemu_out, '6')
     end
 end
 
 # Check for correct RX statistics implementation. Depends on test 1 being run first.
-class RxStatistics
+class RxStatisticsTest < SubtestBase
     def name
         'Receive statistics'
     end
 
     def run(qemu_out, _qemu_in)
-        raise ExpectTimeoutError if qemu_out.expect('3', TIMEOUT_SECS).nil?
+        expect_or_raise(qemu_out, '3')
     end
 end
 
@@ -53,5 +44,5 @@ end
 ## Test registration
 ##--------------------------------------------------------------------------------------------------
 def subtest_collection
-    [TxRxHandshake.new, TxStatistics.new, RxStatistics.new]
+    [TxRxHandshakeTest.new, TxStatisticsTest.new, RxStatisticsTest.new]
 end

common/tests/boot_test.rb

@@ -4,73 +4,29 @@
 #
 # Copyright (c) 2021-2022 Andre Richter <andre.o.richter@gmail.com>
 
-require_relative 'test'
-require 'io/wait'
-require 'timeout'
+require_relative 'console_io_test'
 
-# Check for an expected string when booting the kernel in QEMU.
-class BootTest < Test
-    MAX_WAIT_SECS = 5
-
-    def initialize(qemu_cmd, expected_print)
+# Wait for an expected print during boot.
+class ExpectedBootPrintTest < SubtestBase
+    def initialize(expected_print)
         super()
-
-        @qemu_cmd = qemu_cmd
         @expected_print = expected_print
-
-        @test_name = 'Boot test'
-        @test_description = "Checking for the string: '#{@expected_print}'"
-        @test_output = []
-        @test_error = nil
     end
 
-    private
-
-    def expected_string_observed?(qemu_output)
-        qemu_output.join.include?(@expected_print)
+    def name
+        "Checking for the string: '#{@expected_print}'"
     end
 
-    # Convert the recorded output to an array of lines.
-    def post_process_and_add_output(qemu_output)
-        @test_output += qemu_output.join.split("\n")
-    end
-
-    # override
-    def setup
-        @qemu_serial = IO.popen(@qemu_cmd, err: '/dev/null')
-        @qemu_pid = @qemu_serial.pid
-    end
-
-    # override
-    def cleanup
-        Timeout.timeout(MAX_WAIT_SECS) do
-            Process.kill('TERM', @qemu_pid)
-            Process.wait
-        end
-    rescue StandardError => e
-        puts 'QEMU graceful shutdown didn\'t work. Skipping it.'
-        puts e
+    def run(qemu_out, _qemu_in)
+        expect_or_raise(qemu_out, @expected_print)
     end
+end
 
-    def run_concrete_test
-        qemu_output = []
-        Timeout.timeout(MAX_WAIT_SECS) do
-            while @qemu_serial.wait_readable
-                qemu_output << @qemu_serial.read_nonblock(1024)
+# Check for an expected string when booting the kernel in QEMU.
+class BootTest < ConsoleIOTest
+    def initialize(qemu_cmd, expected_print)
+        subtests = [ExpectedBootPrintTest.new(expected_print)]
 
-                if expected_string_observed?(qemu_output)
-                    @test_error = false
-                    break
-                end
-            end
-        end
-    rescue EOFError
-        @test_error = 'QEMU quit unexpectedly'
-    rescue Timeout::Error
-        @test_error = 'Timed out waiting for magic string'
-    rescue StandardError => e
-        @test_error = e.message
-    ensure
-        post_process_and_add_output(qemu_output)
+        super(qemu_cmd, 'Boot test', subtests)
     end
 end

common/tests/console_io_test.rb

@@ -4,11 +4,62 @@
 #
 # Copyright (c) 2019-2022 Andre Richter <andre.o.richter@gmail.com>
 
+require 'expect'
 require 'pty'
+require 'timeout'
 require_relative 'test'
 
+# Error class for when expect times out.
+class ExpectTimeoutError < StandardError
+    def initialize(string)
+        super("Timeout while expecting string: #{string}")
+    end
+end
+
+# Provide boilderplate for expecting a string and throwing an error on failure.
+class SubtestBase
+    TIMEOUT_SECONDS = 3
+
+    def expect_or_raise(io, string, timeout = TIMEOUT_SECONDS)
+        raise ExpectTimeoutError, string if io.expect(string, timeout).nil?
+    end
+end
+
+# Monkey-patch IO so that we get access to the buffer of a previously unsuccessful expect().
+class IO
+    # rubocop:disable Naming:MethodName
+    attr_reader :unusedBuf
+    # rubocop:enable Naming:MethodName
+end
+
+# A wrapper class that records characters that have been received from a PTY.
+class PTYLoggerWrapper
+    def initialize(pty, linebreak = "\n")
+        @pty = pty
+        @linebreak = linebreak
+        @log = []
+    end
+
+    def expect(pattern, timeout)
+        result = @pty.expect(pattern, timeout)
+        @log << if result.nil?
+                    @pty.unusedBuf
+                else
+                    result
+                end
+
+        result
+    end
+
+    def log
+        @log.join.split(@linebreak)
+    end
+end
+
 # A test doing console I/O with the QEMU binary.
 class ConsoleIOTest < Test
+    MAX_TIME_ALL_TESTS_SECONDS = 20
+
     def initialize(qemu_cmd, test_name, console_subtests)
         super()
 
@@ -34,15 +85,33 @@ class ConsoleIOTest < Test
         @test_output.last.concat('[ok]')
     end
 
+    # override
+    def setup
+        qemu_out, @qemu_in = PTY.spawn(@qemu_cmd)
+        @qemu_out_wrapped = PTYLoggerWrapper.new(qemu_out)
+    end
+
+    # override
+    def finish
+        @test_output << ''
+        @test_output << 'Console log:'
+        @test_output += @qemu_out_wrapped.log.map { |line| "  #{line}" }
+    end
+
+    # override
     def run_concrete_test
         @test_error = false
 
-        PTY.spawn(@qemu_cmd) do |qemu_out, qemu_in|
+        Timeout.timeout(MAX_TIME_ALL_TESTS_SECONDS) do
             @console_subtests.each_with_index do |t, i|
-                run_subtest(t, i + 1, qemu_out, qemu_in)
+                run_subtest(t, i + 1, @qemu_out_wrapped, @qemu_in)
             end
-        rescue StandardError => e
-            @test_error = e.message
         end
+    rescue Errno::EIO => e
+        @test_error = "#{e.inspect} - QEMU might have quit early"
+    rescue Timeout::Error
+        @test_error = "Overall time for tests exceeded (#{MAX_TIME_ALL_TESTS_SECONDS}s)"
+    rescue StandardError => e
+        @test_error = e.inspect
     end
 end

common/tests/exit_code_test.rb

@@ -25,17 +25,19 @@ class ExitCodeTest < Test
 
     private
 
+    # override
+    def setup
+        @qemu_serial = IO.popen(@qemu_cmd)
+    end
+
+    # override
     # Convert the recorded output to an array of lines, and extract the test description.
-    def post_process_output
+    def finish
         @test_output = @test_output.join.split("\n")
         @test_description = @test_output.shift
     end
 
     # override
-    def setup
-        @qemu_serial = IO.popen(@qemu_cmd)
-    end
-
     def run_concrete_test
         Timeout.timeout(MAX_WAIT_SECS) do
             @test_output << @qemu_serial.read_nonblock(1024) while @qemu_serial.wait_readable
@@ -46,8 +48,6 @@ class ExitCodeTest < Test
     rescue Timeout::Error
         @test_error = 'Timed out waiting for test'
     rescue StandardError => e
-        @test_error = e.message
-    ensure
-        post_process_output
+        @test_error = e.inspect
     end
 end

common/tests/test.rb

@@ -52,7 +52,7 @@ class Test
     def setup; end
 
     # Template method.
-    def cleanup; end
+    def finish; end
 
     # Template method.
     def run_concrete_test
@@ -64,7 +64,7 @@ class Test
     def run
         setup
         run_concrete_test
-        cleanup
+        finish
 
         print_header
         print_output