From 88848a56b1644fa3c90929d72e197e4a1684ece0 Mon Sep 17 00:00:00 2001 From: Lucas Meneghel Rodrigues Date: Thu, 13 Aug 2015 11:47:44 -0300 Subject: [PATCH 1/5] Revert "avocado.core.runner: Do better Ctrl+C handling" This reverts commit c400b2f48890cd9c53e60f59ea1d21b19c22e689. As a matter of fact the reversion had to be fixed due to a conflict with new code that entered that particular part of the code. The behavior previous to the commit was kept the same, so that we can change things in the next commits. Signed-off-by: Lucas Meneghel Rodrigues --- avocado/core/runner.py | 146 +++++++++++++++++++---------------------- 1 file changed, 67 insertions(+), 79 deletions(-) diff --git a/avocado/core/runner.py b/avocado/core/runner.py index a7c1811b58..78c3e49ea3 100644 --- a/avocado/core/runner.py +++ b/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,61 @@ 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(True) + 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: + self.job.result_proxy.notify_progress() 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 == 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.view.notify(event='message', msg=k_msg_1) + self.job.view.notify(event='message', msg=k_msg_2) + self.job.view.notify(event='message', msg=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.view.notify(event='message', msg=k_msg_3) + 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 +229,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 +250,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,23 +262,18 @@ 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 + 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 runtime.CURRENT_TEST = None self.result.end_tests() if self.job.sysinfo is not None: From a3a20c171b71802fa195f9970d0ff8ce93e951a6 Mon Sep 17 00:00:00 2001 From: Lucas Meneghel Rodrigues Date: Thu, 13 Aug 2015 12:00:40 -0300 Subject: [PATCH 2/5] avocado.core.runner: Restore behavior of the 'Change the throbber colors' commit On commit d2d6623af02aeff4deecfcb084ce75553be31154, ldoktor changes the throbber color. This commit reverts the behavior to the one before the Ctrl+C reversion, since that'll be better in terms of bisectability. Signed-off-by: Lucas Meneghel Rodrigues --- avocado/core/runner.py | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/avocado/core/runner.py b/avocado/core/runner.py index 78c3e49ea3..3b1cdd695c 100644 --- a/avocado/core/runner.py +++ b/avocado/core/runner.py @@ -180,7 +180,7 @@ def run_test(self, test_factory, queue, failures, job_deadline=0): if not test_state['running']: break else: - self.job.result_proxy.notify_progress(True) + self.job.result_proxy.notify_progress(False) if test_state['paused']: msg = test_state['paused_msg'] if msg: @@ -188,7 +188,10 @@ def run_test(self, test_factory, queue, failures, job_deadline=0): elif proc.is_alive(): if ctrl_c_count == 0: - self.job.result_proxy.notify_progress() + 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 except KeyboardInterrupt: From 24daf923db178eb37b699c052afd50741bfa6a18 Mon Sep 17 00:00:00 2001 From: Lucas Meneghel Rodrigues Date: Thu, 13 Aug 2015 12:11:27 -0300 Subject: [PATCH 3/5] avocado.core.runner: Fix Ctrl+C management After a not so successful attempt to fix Ctrl+C management (see c400b2f), I finally figured out the actual problem with the way we were doing handling: We just needed a clean way to break out of the test loop. Since TestRunner.run_test will return False if avocado received a Ctrl+C, let's use it to establish a condition for breaking the TestRunner.run_suite loop. Signed-off-by: Lucas Meneghel Rodrigues --- avocado/core/runner.py | 12 ++++++++++-- 1 file changed, 10 insertions(+), 2 deletions(-) diff --git a/avocado/core/runner.py b/avocado/core/runner.py index 3b1cdd695c..8e07a41dca 100644 --- a/avocado/core/runner.py +++ b/avocado/core/runner.py @@ -267,17 +267,25 @@ def run_suite(self, test_suite, mux, timeout=0): for test_template in test_suite: 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) - self.run_test(test_factory, queue, failures) + break_loop = not self.run_test(test_factory, queue, + failures) + if break_loop: + break else: - if not self.run_test(test_factory, queue, failures, deadline): + 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() From b9c44e88485770f072f6ff3236ca4eaaf9ea1d16 Mon Sep 17 00:00:00 2001 From: Lucas Meneghel Rodrigues Date: Thu, 13 Aug 2015 12:31:16 -0300 Subject: [PATCH 4/5] avocado.core.runner: Change the Ctrl+C handling behavior We are too verbose when Ctrl+C is pressed, we can convey a sufficient amount of information more concisely. Also, instead of printing the first message on the 2nd Ctrl+C pressed, print it right away so the user knows that avocado understood his/her request. Signed-off-by: Lucas Meneghel Rodrigues --- avocado/core/runner.py | 20 +++++++------------- 1 file changed, 7 insertions(+), 13 deletions(-) diff --git a/avocado/core/runner.py b/avocado/core/runner.py index 8e07a41dca..72d18148c7 100644 --- a/avocado/core/runner.py +++ b/avocado/core/runner.py @@ -197,25 +197,19 @@ def run_test(self, test_factory, queue, failures, job_deadline=0): except KeyboardInterrupt: time_elapsed = time.time() - ignore_time_started ctrl_c_count += 1 - if ctrl_c_count == 2: + if ctrl_c_count == 1: 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" % + k_msg_1 = ('\nInterrupt requested. Waiting %d seconds ' + 'for test to finish ' + '(ignoring new Ctrl+C until then)' % ignore_window) - k_msg_3 = ("A new Ctrl+C sent after that will send a " - "SIGKILL to them") self.job.view.notify(event='message', msg=k_msg_1) - self.job.view.notify(event='message', msg=k_msg_2) - self.job.view.notify(event='message', msg=k_msg_3) stage_1_msg_displayed = True ignore_time_started = time.time() - if (ctrl_c_count > 2) and (time_elapsed > ignore_window): + if (ctrl_c_count > 1) 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.view.notify(event='message', msg=k_msg_3) + 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) From f99b37021a7e7742e566becdab7832dcb81760f4 Mon Sep 17 00:00:00 2001 From: Lucas Meneghel Rodrigues Date: Thu, 13 Aug 2015 12:34:45 -0300 Subject: [PATCH 5/5] selftests: Add interrupt tests Add functional automated tests for the Ctrl+C feature. They use aexpect and psutil, so add their dependencies to the relevant requirement files. Signed-off-by: Lucas Meneghel Rodrigues --- requirements-selftests.txt | 2 + requirements-travis.txt | 2 + .../all/functional/avocado/interrupt_tests.py | 143 ++++++++++++++++++ 3 files changed, 147 insertions(+) create mode 100644 selftests/all/functional/avocado/interrupt_tests.py diff --git a/requirements-selftests.txt b/requirements-selftests.txt index 856f498acf..9d5471b875 100644 --- a/requirements-selftests.txt +++ b/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 diff --git a/requirements-travis.txt b/requirements-travis.txt index d4c73ea715..cd855e233f 100644 --- a/requirements-travis.txt +++ b/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 diff --git a/selftests/all/functional/avocado/interrupt_tests.py b/selftests/all/functional/avocado/interrupt_tests.py new file mode 100644 index 0000000000..57cf64503d --- /dev/null +++ b/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()