Merge pull request #158 from lmr/ctrl-c-improvements-last

Ctrl c improvements last

avocado/job.py

@@ -135,14 +135,8 @@ class TestRunner(object):
             raise exceptions.TestTimeoutError(e_msg)
 
         def interrupt_handler(signum, frame):
-            instance.status = exceptions.TestInterruptedError.status
-            instance.fail_class = exceptions.TestInterruptedError.__class__.__name__
-            e_msg = 'Interrupted by user'
-            instance.fail_reason = exceptions.TestInterruptedError(e_msg)
-            instance.traceback = 'Traceback not available'
-            with open(instance.logfile, 'r') as log_file_obj:
-                instance.text_output = log_file_obj.read()
-            sys.exit(error_codes.numeric_status['AVOCADO_JOB_INTERRUPTED'])
+            e_msg = "Test %s interrupted by user" % instance
+            raise exceptions.TestTimeoutError(e_msg)
 
         signal.signal(signal.SIGUSR1, timeout_handler)
         signal.signal(signal.SIGINT, interrupt_handler)
@@ -200,6 +194,12 @@ class TestRunner(object):
 
             time_deadline = time_started + timeout
 
+            ctrl_c_count = 0
+            ignore_window = 2.0
+            ignore_time_started = time.time()
+            stage_1_msg_displayed = False
+            stage_2_msg_displayed = False
+
             while True:
                 try:
                     if time.time() >= time_deadline:
@@ -216,10 +216,37 @@ class TestRunner(object):
 
                 except Queue.Empty:
                     if p.is_alive():
-                        self.job.result_proxy.throbber_progress()
+                        if ctrl_c_count == 0:
+                            self.job.result_proxy.throbber_progress()
                     else:
                         break
 
+                except KeyboardInterrupt:
+                    time_elapsed = time.time() - ignore_time_started
+                    ctrl_c_count += 1
+                    if ctrl_c_count == 2:
+                        if not stage_1_msg_displayed:
+                            k_msg_1 = ("SIGINT sent to tests, waiting for their "
+                                       "reaction")
+                            k_msg_2 = ("Ignoring Ctrl+C during the next "
+                                       "%d seconds so they can try to finish" %
+                                       ignore_window)
+                            k_msg_3 = ("A new Ctrl+C sent after that will send a "
+                                       "SIGKILL to them")
+                            self.job.output_manager.log_header("\n")
+                            self.job.output_manager.log_header(k_msg_1)
+                            self.job.output_manager.log_header(k_msg_2)
+                            self.job.output_manager.log_header(k_msg_3)
+                            stage_1_msg_displayed = True
+                        ignore_time_started = time.time()
+                    if (ctrl_c_count > 2) and (time_elapsed > ignore_window):
+                        if not stage_2_msg_displayed:
+                            k_msg_3 = ("Ctrl+C received after the ignore window. "
+                                       "Killing all active tests")
+                            self.job.output_manager.log_header(k_msg_3)
+                            stage_2_msg_displayed = True
+                        os.kill(p.pid, signal.SIGKILL)
+
             # If test_state is None, the test was aborted before it ended.
             if test_state is None:
                 try:
@@ -227,10 +254,10 @@ class TestRunner(object):
                 except Queue.Empty:
                     early_state['time_elapsed'] = time.time() - time_started
                     test_state = self._fill_aborted_test_state(early_state)
-
-                test_log = logging.getLogger('avocado.test')
-                test_log.error('ERROR %s -> TestAbortedError: '
-                               'Test aborted unexpectedly', test_state['name'])
+                    test_log = logging.getLogger('avocado.test')
+                    test_log.error('ERROR %s -> TestAbortedError: '
+                                   'Test aborted unexpectedly',
+                                   test_state['name'])
 
             self.result.check_test(test_state)
             if not status.mapping[test_state['status']]:
@@ -471,32 +498,6 @@ class Job(object):
         except exceptions.OptionValidationError, details:
             self.output_manager.log_fail_header(str(details))
             return error_codes.numeric_status['AVOCADO_JOB_FAIL']
-        except KeyboardInterrupt:
-            kill_prompt_displayed = False
-            time_elapsed = 0
-            ignore_window = 2.0
-            self.output_manager.log_header('\n')
-            self.output_manager.log_header('Interrupted by user request')
-            start_time = time.time()
-            while multiprocessing.active_children():
-                time_elapsed = time.time() - start_time
-                try:
-                    time.sleep(0.1)
-                except KeyboardInterrupt:
-                    if not kill_prompt_displayed:
-                        k_msg = ('Waiting for tests to end. Ignoring Ctrl+C '
-                                 'for %d seconds' % ignore_window)
-                        self.output_manager.log_header(k_msg)
-                        k_msg = ('After that, a new Ctrl+C will send a SIGKILL '
-                                 'to them')
-                        self.output_manager.log_header(k_msg)
-                        kill_prompt_displayed = True
-                    if time_elapsed < ignore_window:
-                        continue
-                    else:
-                        for child in multiprocessing.active_children():
-                            os.kill(child.pid, signal.SIGKILL)
-            sys.exit(error_codes.numeric_status['AVOCADO_JOB_INTERRUPTED'])
 
         except Exception, details:
             self.status = "ERROR"

avocado/utils/process.py

@@ -20,7 +20,6 @@ import logging
 import os
 import StringIO
 import signal
-import shlex
 import subprocess
 import time
 import threading
@@ -117,13 +116,14 @@ class SubProcess(object):
         :param verbose: Whether to log the command run and stdout/stderr.
         :type verbose: bool
         """
-        args = shlex.split(cmd)
+        self.cmd = cmd
         self.verbose = verbose
         if self.verbose:
             log.info("Running '%s'", cmd)
-        self.sp = subprocess.Popen(args,
+        self.sp = subprocess.Popen(cmd,
                                    stdout=subprocess.PIPE,
-                                   stderr=subprocess.PIPE)
+                                   stderr=subprocess.PIPE,
+                                   shell=True)
         self.start_time = time.time()
         self.result = CmdResult(cmd)
         self.stdout_file = StringIO.StringIO()
@@ -141,6 +141,17 @@ class SubProcess(object):
         self.stdout_thread.start()
         self.stderr_thread.start()
 
+        def signal_handler(signum, frame):
+            self.wait()
+        signal.signal(signal.SIGINT, signal_handler)
+
+    def __str__(self):
+        if self.result.exit_status is None:
+            rc = '(still running)'
+        else:
+            rc = self.result.exit_status
+        return 'SubProcess(cmd="%s", rc="%s")' % (self.cmd, rc)
+
     def _fd_drainer(self, input_pipe):
         """
         Read from input_pipe, storing and logging output.
@@ -175,6 +186,25 @@ class SubProcess(object):
             finally:
                 lock.release()
 
+    def _fill_results(self, rc):
+        self.result.exit_status = rc
+        if self.result.duration == 0:
+            self.result.duration = time.time() - self.start_time
+        self._fill_streams()
+
+    def _fill_streams(self):
+        """
+        Close subprocess stdout and stderr, and put values into result obj.
+        """
+        # Cleaning up threads
+        self.stdout_thread.join()
+        self.stderr_thread.join()
+        # Clean subprocess pipes and populate stdout/err
+        self.sp.stdout.close()
+        self.sp.stderr.close()
+        self.result.stdout = self.get_stdout()
+        self.result.stderr = self.get_stderr()
+
     def get_stdout(self):
         """
         Get the full stdout of the subprocess so far.
@@ -219,7 +249,25 @@ class SubProcess(object):
         """
         self.sp.send_signal(sig)
 
-    def wait(self, timeout=None, sig=signal.SIGTERM):
+    def poll(self):
+        """
+        Call the subprocess poll() method, fill results if rc is not None.
+        """
+        rc = self.sp.poll()
+        if rc is not None:
+            self._fill_results(rc)
+        return rc
+
+    def wait(self):
+        """
+        Call the subprocess poll() method, fill results if rc is not None.
+        """
+        rc = self.sp.wait()
+        if rc is not None:
+            self._fill_results(rc)
+        return rc
+
+    def run(self, timeout=None, sig=signal.SIGTERM):
         """
         Wait for the process to end, filling and returning the result attr.
 
@@ -230,59 +278,34 @@ class SubProcess(object):
         :returns: The command result object.
         :rtype: A :class:`avocado.utils.process.CmdResult` instance.
         """
+        start_time = time.time()
+
         if timeout is None:
-            self.sp.wait()
-            self.result.exit_status = self.sp.returncode
+            self.wait()
 
-        if timeout > 0:
-            start_time = time.time()
+        if timeout > 0.0:
             while time.time() - start_time < timeout:
-                self.result.exit_status = self.sp.poll()
+                self.poll()
                 if self.result.exit_status is not None:
                     break
-        else:
-            # Give one second to check if we can successfully kill the process
-            timeout = 1
 
         if self.result.exit_status is None:
+            internal_timeout = 1.0
             self.send_signal(sig)
-            # Timeout here should be 1 second (see comment above)
-            stop_time = time.time() + timeout
+            stop_time = time.time() + internal_timeout
             while time.time() < stop_time:
-                self.result.exit_status = self.sp.poll()
+                self.poll()
                 if self.result.exit_status is not None:
                     break
             else:
                 self.kill()
-                self.result.exit_status = self.sp.poll()
+                self.poll()
 
-        duration = time.time() - self.start_time
-        self.result.duration = duration
-
-        self.cleanup()
-
-        return self.result
-
-    def cleanup(self):
-        """
-        Close subprocess stdout and stderr, and put values into result obj.
-        """
-        # Cleaning up threads
-        self.stdout_thread.join(1)
-        self.stderr_thread.join(1)
-        # Last sanity check
-        e_msg = 'Stdout thread for %s is still alive' % self.sp.pid
-        assert not self.stdout_thread.isAlive(), e_msg
-        e_msg = 'Stderr thread for %s is still alive' % self.sp.pid
-        assert not self.stderr_thread.isAlive(), e_msg
-        # If this fails, we're dealing with a zombie process
+        # If all this work fails, we're dealing with a zombie process.
         e_msg = 'Zombie Process %s' % self.sp.pid
         assert self.result.exit_status is not None, e_msg
-        # Clean subprocess pipes and populate stdout/err
-        self.sp.stdout.close()
-        self.sp.stderr.close()
-        self.result.stdout = self.get_stdout()
-        self.result.stderr = self.get_stderr()
+
+        return self.result
 
 
 def run(cmd, timeout=None, verbose=True, ignore_status=False):
@@ -305,7 +328,7 @@ def run(cmd, timeout=None, verbose=True, ignore_status=False):
     :raise: :class:`avocado.core.exceptions.CmdError`, if ``ignore_status=False``.
     """
     sp = SubProcess(cmd=cmd, verbose=verbose)
-    cmd_result = sp.wait(timeout=timeout)
+    cmd_result = sp.run(timeout=timeout)
     if cmd_result.exit_status != 0 and not ignore_status:
         raise exceptions.CmdError(cmd, sp.result)
     return cmd_result

selftests/all/functional/avocado/basic_tests.py

@@ -17,7 +17,6 @@
 import json
 import unittest
 import os
-import signal
 import shutil
 import time
 import sys

tests/trinity.py

@@ -82,9 +82,7 @@ class trinity(test.Test):
             cmd += " -V " + self.params.victims_path
         else:
             cmd += " -V " + self.victims_path
-        cmd_result = process.run(cmd)
-        self.log.info(cmd_result)
-        os.chdir(self.cwd)
+        process.run(cmd)
 
 
 if __name__ == "__main__":