Merge pull request #773 from lmr/fix-ctrl-c-for-realz-v3

[V3] Fix Ctrl+C for realz

avocado/core/runner.py

@@ -52,7 +52,6 @@ def __init__(self, job, test_result):
         """
         self.job = job
         self.result = test_result
-        self.current_test_subprocess = None
 
     def _run_test(self, test_factory, queue):
         """
@@ -135,8 +134,6 @@ def run_test(self, test_factory, queue, failures, job_deadline=0):
         proc = multiprocessing.Process(target=self._run_test,
                                        args=(test_factory, queue,))
 
-        self.current_test_subprocess = proc
-
         cycle_timeout = 1
         time_started = time.time()
         test_state = None
@@ -163,33 +160,58 @@ def run_test(self, test_factory, queue, failures, job_deadline=0):
         else:
             deadline = test_deadline
 
+        ctrl_c_count = 0
+        ignore_window = 2.0
+        ignore_time_started = time.time()
+        stage_1_msg_displayed = False
+        stage_2_msg_displayed = False
         first = 0.01
         step = 0.1
 
         while True:
-            if time.time() >= deadline:
-                os.kill(proc.pid, signal.SIGUSR1)
-                break
-            wait.wait_for(lambda: not queue.empty() or not proc.is_alive(),
-                          cycle_timeout, first, step)
-            if not queue.empty():
-                test_state = queue.get()
-                if not test_state['running']:
+            try:
+                if time.time() >= deadline:
+                    os.kill(proc.pid, signal.SIGUSR1)
                     break
+                wait.wait_for(lambda: not queue.empty() or not proc.is_alive(),
+                              cycle_timeout, first, step)
+                if not queue.empty():
+                    test_state = queue.get()
+                    if not test_state['running']:
+                        break
+                    else:
+                        self.job.result_proxy.notify_progress(False)
+                        if test_state['paused']:
+                            msg = test_state['paused_msg']
+                            if msg:
+                                self.job.view.notify(event='partial', msg=msg)
+
+                elif proc.is_alive():
+                    if ctrl_c_count == 0:
+                        if test_state and not test_state.get('running'):
+                            self.job.result_proxy.notify_progress(False)
+                        else:
+                            self.job.result_proxy.notify_progress(True)
                 else:
-                    self.job.result_proxy.notify_progress(False)
-                    if test_state['paused']:
-                        msg = test_state['paused_msg']
-                        if msg:
-                            self.job.view.notify(event='partial', msg=msg)
-
-            elif proc.is_alive():
-                if test_state and not test_state.get('running'):
-                    self.job.result_proxy.notify_progress(False)
-                else:
-                    self.job.result_proxy.notify_progress(True)
-            else:
-                break
+                    break
+            except KeyboardInterrupt:
+                time_elapsed = time.time() - ignore_time_started
+                ctrl_c_count += 1
+                if ctrl_c_count == 1:
+                    if not stage_1_msg_displayed:
+                        k_msg_1 = ('\nInterrupt requested. Waiting %d seconds '
+                                   'for test to finish '
+                                   '(ignoring new Ctrl+C until then)' %
+                                   ignore_window)
+                        self.job.view.notify(event='message', msg=k_msg_1)
+                        stage_1_msg_displayed = True
+                    ignore_time_started = time.time()
+                if (ctrl_c_count > 1) and (time_elapsed > ignore_window):
+                    if not stage_2_msg_displayed:
+                        k_msg_2 = "Killing test subprocess %s" % proc.pid
+                        self.job.view.notify(event='message', msg=k_msg_2)
+                        stage_2_msg_displayed = True
+                    os.kill(proc.pid, signal.SIGKILL)
 
         # If test_state is None, the test was aborted before it ended.
         if test_state is None:
@@ -204,10 +226,16 @@ def run_test(self, test_factory, queue, failures, job_deadline=0):
                                'Test aborted unexpectedly',
                                test_state['name'])
 
+        # don't process other tests from the list
+        if ctrl_c_count > 0:
+            self.job.view.notify(event='minor', msg='')
+
         self.result.check_test(test_state)
         if not status.mapping[test_state['status']]:
             failures.append(test_state['name'])
 
+        if ctrl_c_count > 0:
+            return False
         return True
 
     def run_suite(self, test_suite, mux, timeout=0):
@@ -219,44 +247,6 @@ def run_suite(self, test_suite, mux, timeout=0):
         :param timeout: maximum amount of time (in seconds) to execute.
         :return: a list of test failures.
         """
-        def wait_and_ignore_interrupt(ignore_window=2.0):
-            try:
-                signal.signal(signal.SIGINT, signal.SIG_IGN)
-                self.job.view.notify(event='minor', msg='')
-                self.job.view.notify(event='message',
-                                     msg=('Interrupt requested. Waiting %d '
-                                          'seconds for test to finish '
-                                          '(ignoring new Ctrl+C until then)' %
-                                          ignore_window))
-                end_time = time.time() + ignore_window
-
-                while time.time() < end_time:
-                    if not self.current_test_subprocess.is_alive():
-                        return
-                    time.sleep(1.0)
-            finally:
-                return
-
-        def kill_test_subprocess(signum, frame):
-            try:
-                self.job.view.notify(event='minor', msg='')
-                self.job.view.notify(event='message',
-                                     msg=('Killing test subprocess PID %s' %
-                                          self.current_test_subprocess.pid))
-                os.kill(self.current_test_subprocess.pid, signal.SIGKILL)
-            except OSError:
-                pass
-
-        def clean_test_subprocess():
-            try:
-                signal.signal(signal.SIGINT, kill_test_subprocess)
-                if self.current_test_subprocess.is_alive():
-                    self.job.view.notify(event='message',
-                                         msg=('Test still active. Press '
-                                              'Ctrl+C to kill it'))
-            except (OSError, AssertionError):
-                pass
-
         failures = []
         if self.job.sysinfo is not None:
             self.job.sysinfo.start_job_hook()
@@ -269,24 +259,27 @@ def clean_test_subprocess():
             deadline = None
 
         for test_template in test_suite:
-            try:
-                test_template[1]['base_logdir'] = self.job.logdir
-                test_template[1]['job'] = self.job
-                for test_factory in mux.itertests(test_template):
-                    if deadline is not None and time.time() > deadline:
-                        test_parameters = test_factory[1]
-                        if 'methodName' in test_parameters:
-                            del test_parameters['methodName']
-                        test_factory = (test.TimeOutSkipTest, test_parameters)
-                        self.run_test(test_factory, queue, failures)
-                    else:
-                        if not self.run_test(test_factory, queue, failures, deadline):
-                            break
-            except KeyboardInterrupt:
-                wait_and_ignore_interrupt(ignore_window=3.0)
-                clean_test_subprocess()
-                break
+            test_template[1]['base_logdir'] = self.job.logdir
+            test_template[1]['job'] = self.job
+            break_loop = False
+            for test_factory in mux.itertests(test_template):
+                if deadline is not None and time.time() > deadline:
+                    test_parameters = test_factory[1]
+                    if 'methodName' in test_parameters:
+                        del test_parameters['methodName']
+                    test_factory = (test.TimeOutSkipTest, test_parameters)
+                    break_loop = not self.run_test(test_factory, queue,
+                                                   failures)
+                    if break_loop:
+                        break
+                else:
+                    break_loop = not self.run_test(test_factory, queue, failures,
+                                                   deadline)
+                    if break_loop:
+                        break
             runtime.CURRENT_TEST = None
+            if break_loop:
+                break
         self.result.end_tests()
         if self.job.sysinfo is not None:
             self.job.sysinfo.end_job_hook()

requirements-selftests.txt

@@ -21,3 +21,5 @@ Pillow>=2.2.1
 snakefood>=1.4
 networkx>=1.9.1
 pygraphviz>=1.3rc2
+aexpect>=1.0.0
+psutil>=3.1.1

requirements-travis.txt

@@ -13,3 +13,5 @@ snakefood==1.4
 networkx==1.9.1
 pygraphviz==1.3rc2
 mock==1.2.0
+aexpect==1.0.0
+psutil==3.1.1

selftests/all/functional/avocado/interrupt_tests.py

@@ -0,0 +1,143 @@
+import os
+import sys
+import tempfile
+import time
+import logging
+import shutil
+
+import aexpect
+import psutil
+
+if sys.version_info[:2] == (2, 6):
+    import unittest2 as unittest
+else:
+    import unittest
+
+# simple magic for using scripts within a source tree
+basedir = os.path.join(os.path.dirname(os.path.abspath(__file__)), '..', '..',
+                       '..', '..')
+basedir = os.path.abspath(basedir)
+if os.path.isdir(os.path.join(basedir, 'avocado')):
+    sys.path.insert(0, basedir)
+
+from avocado.utils import wait
+from avocado.utils import process
+from avocado.utils import script
+from avocado.utils import data_factory
+
+BAD_TEST = """#!/usr/bin/env python
+import signal
+import time
+
+if __name__ == "__main__":
+    signal.signal(signal.SIGINT, signal.SIG_IGN)
+    signal.signal(signal.SIGTERM, signal.SIG_IGN)
+    signal.signal(signal.SIGQUIT, signal.SIG_IGN)
+    while True:
+        time.sleep(0.1)
+"""
+
+GOOD_TEST = """#!/usr/bin/python
+import time
+from avocado import Test
+from avocado import main
+
+class GoodTest(Test):
+    def test(self):
+        time.sleep(600)
+
+if __name__ == "__main__":
+    main()
+"""
+
+
+class InterruptTest(unittest.TestCase):
+
+    def setUp(self):
+        self.tmpdir = tempfile.mkdtemp()
+
+    def test_badly_behaved(self):
+        """
+        Make sure avocado can cleanly get out of a loop of badly behaved tests.
+        """
+        bad_test_basename = ('wontquit-%s' %
+                             data_factory.generate_random_string(5))
+        bad_test = script.TemporaryScript(bad_test_basename, BAD_TEST,
+                                          'avocado_interrupt_test',
+                                          mode=0755)
+        bad_test.save()
+
+        os.chdir(basedir)
+        cmd_line = ('./scripts/avocado run --sysinfo=off --job-results-dir %s '
+                    '%s %s %s' % (self.tmpdir,
+                                  bad_test.path,
+                                  bad_test.path,
+                                  bad_test.path))
+        proc = aexpect.Expect(command=cmd_line, linesep='',
+                              output_func=logging.critical)
+        proc.read_until_last_line_matches(os.path.basename(bad_test.path))
+        proc.sendline('\x03')
+        proc.read_until_last_line_matches('Interrupt requested. Waiting 2 '
+                                          'seconds for test to finish '
+                                          '(ignoring new Ctrl+C until then)')
+        # We have to actually wait 2 seconds until the ignore window is over
+        time.sleep(2)
+        proc.sendline('\x03')
+        proc.read_until_last_line_matches('TIME       : %d s')
+        wait.wait_for(lambda: not proc.is_alive(), timeout=1)
+
+        # Make sure the bad test will be really gone from the process table
+        def wait_until_no_badtest():
+            bad_test_processes = [psutil.Process(p) for p in psutil.pids()
+                                  if bad_test.path in
+                                  " ".join(psutil.Process(p).cmdline())]
+            return len(bad_test_processes) == 0
+
+        wait.wait_for(wait_until_no_badtest, timeout=2)
+        # Make sure the Killing test subprocess message did appear
+        self.assertIn('Killing test subprocess', proc.get_output())
+
+    def test_well_behaved(self):
+        """
+        Make sure avocado can cleanly get out of a loop of well behaved tests.
+        """
+        good_test_basename = ('goodtest-%s.py' %
+                              data_factory.generate_random_string(5))
+        good_test = script.TemporaryScript(good_test_basename, GOOD_TEST,
+                                           'avocado_interrupt_test',
+                                           mode=0755)
+        good_test.save()
+
+        os.chdir(basedir)
+        cmd_line = ('./scripts/avocado run --sysinfo=off --job-results-dir %s '
+                    '%s %s %s' % (self.tmpdir,
+                                  good_test.path,
+                                  good_test.path,
+                                  good_test.path))
+        proc = aexpect.Expect(command=cmd_line, linesep='',
+                              output_func=logging.critical)
+        proc.read_until_last_line_matches(os.path.basename(good_test.path))
+        proc.sendline('\x03')
+        proc.read_until_last_line_matches('TIME       : %d s')
+        wait.wait_for(lambda: not proc.is_alive(), timeout=1)
+
+        # Make sure the good test will be really gone from the process table
+        def wait_until_no_goodtest():
+            good_test_processes = [psutil.Process(p) for p in psutil.pids()
+                                   if good_test.path in
+                                   " ".join(psutil.Process(p).cmdline())]
+            return len(good_test_processes) == 0
+
+        wait.wait_for(wait_until_no_goodtest, timeout=2)
+        # Make sure the Killing test subprocess message is not there
+        self.assertNotIn('Killing test subprocess', proc.get_output())
+        # Make sure the Interrupted requested sentence is there
+        self.assertIn('Interrupt requested. Waiting 2 seconds for test to '
+                      'finish (ignoring new Ctrl+C until then)',
+                      proc.get_output())
+
+    def tearDown(self):
+        shutil.rmtree(self.tmpdir)
+
+if __name__ == '__main__':
+    unittest.main()