tests: explicitly log on signal-induced crashes

Ideally we'd want a general way to include the relevant microvm logs
in the test report for any failing tests.

Since that's not possible/easy with current framework, at least
explicitly include logs for any microvm that is killed by a signal.
At the very least this provides visibility into any seccomp failures,
and other traps the microvm process might hit during tests.

Signed-off-by: Adrian Catangiu <[email protected]>

Author: acatangiu

tests/framework/microvm.py

@@ -144,18 +144,31 @@ def __init__(
         # External clone/exec tool, because Python can't into clone
         self.bin_cloner_path = bin_cloner_path
 
+        # Flag checked in destructor to see abnormal signal-induced crashes.
+        self.expect_kill_by_signal = False
+
     def kill(self):
         """All clean up associated with this microVM should go here."""
         # pylint: disable=subprocess-run-check
         if self.logging_thread is not None:
             self.logging_thread.stop()
 
+        if self.expect_kill_by_signal is False and \
+                "Shutting down VM after intercepting signal" in self.log_data:
+            # Too late to assert at this point, pytest will still report the
+            # test as passed. BUT we can dump full logs for debugging,
+            # as well as an intentional eye-sore in the test report.
+            print(self.log_data)
+
         if self._jailer.daemonize:
             if self.jailer_clone_pid:
                 utils.run_cmd(
                     'kill -9 {}'.format(self.jailer_clone_pid),
                     ignore_return_code=True)
         else:
+            # Killing screen will send SIGHUP to underlying Firecracker.
+            # Needed to avoid false positives in case kill() is called again.
+            self.expect_kill_by_signal = True
             utils.run_cmd(
                 'screen -XS {} kill || true'.format(self._session_name))
 

tests/integration_tests/functional/test_signals.py

@@ -67,6 +67,7 @@ def test_generic_signal_handler(test_microvm_with_api, signum):
         response = microvm.actions.put(action_type='FlushMetrics')
         assert microvm.api_session.is_status_no_content(response.status_code)
     else:
+        microvm.expect_kill_by_signal = True
         # Ensure that the process was terminated.
         utils.wait_process_termination(firecracker_pid)
         msg = 'Shutting down VM after intercepting signal {}'.format(signum)
@@ -119,6 +120,7 @@ def test_sigxfsz_handler(test_microvm_with_api):
         except ChildProcessError:
             break
 
+    microvm.expect_kill_by_signal = True
     msg = 'Shutting down VM after intercepting signal 25, code 0'
     microvm.check_log_message(msg)
     metric_line = json.loads(metrics_fd.readlines()[0])

tests/integration_tests/security/test_custom_seccomp.py

@@ -176,6 +176,7 @@ def test_failing_filter(test_microvm_with_api):
     # Give time for the process to get killed
     time.sleep(1)
 
+    test_microvm.expect_kill_by_signal = True
     # Check the logger output
     ioctl_num = 16 if platform.machine() == "x86_64" else 29
     assert "Shutting down VM after intercepting a bad syscall ({})".format(