diff --git a/src/python/pants/task/testrunner_task_mixin.py b/src/python/pants/task/testrunner_task_mixin.py index d8fd0a8dcbe..cb41756937c 100644 --- a/src/python/pants/task/testrunner_task_mixin.py +++ b/src/python/pants/task/testrunner_task_mixin.py @@ -9,7 +9,6 @@ import re import xml.etree.ElementTree as ET from abc import abstractmethod -from threading import Timer from pants.base.exceptions import ErrorWhileTesting, TaskError from pants.build_graph.files import Files @@ -260,21 +259,19 @@ def _spawn_and_wait(self, *args, **kwargs): process_handler = self._spawn(*args, **kwargs) def maybe_terminate(wait_time): - if process_handler.poll() < 0: + polled_result = process_handler.poll() + if polled_result is None: process_handler.terminate() - def kill_if_not_terminated(): - if process_handler.poll() < 0: - # We can't use the context logger because it might not exist when this delayed function - # is executed by the Timer below. - import logging - logger = logging.getLogger(__name__) - logger.warn('Timed out test did not terminate gracefully after {} seconds, killing...' - .format(wait_time)) - process_handler.kill() - - timer = Timer(wait_time, kill_if_not_terminated) - timer.start() + try: + process_handler.wait(timeout=wait_time) + except subprocess.TimeoutExpired: + self.context.log.warn( + 'Timed out test did not terminate gracefully after {} seconds, killing...'.format(wait_time)) + process_handler.kill() + + elif polled_result < 0: + self.context.log.error('FAILURE: Test was killed by signal {}.'.format(-polled_result)) try: return process_handler.wait(timeout=timeout) diff --git a/testprojects/tests/python/pants/timeout/BUILD b/testprojects/tests/python/pants/timeout/BUILD index d220046b39c..57357fb5ddd 100644 --- a/testprojects/tests/python/pants/timeout/BUILD +++ b/testprojects/tests/python/pants/timeout/BUILD @@ -10,3 +10,8 @@ python_tests( name = 'ignores_terminate', sources = ['test_ignores_terminate.py'] ) + +python_tests( + name = 'terminates_self', + sources = ['test_terminates_self.py'] +) diff --git a/testprojects/tests/python/pants/timeout/test_terminates_self.py b/testprojects/tests/python/pants/timeout/test_terminates_self.py new file mode 100644 index 00000000000..c7430e2ee9d --- /dev/null +++ b/testprojects/tests/python/pants/timeout/test_terminates_self.py @@ -0,0 +1,12 @@ +# Copyright 2018 Pants project contributors (see CONTRIBUTORS.md). +# Licensed under the Apache License, Version 2.0 (see LICENSE). + +import os +import signal +import time + + +def test_terminates_self(): + time.sleep(1) + + os.kill(os.getpid(), signal.SIGTERM) diff --git a/tests/python/pants_test/backend/jvm/tasks/test_junit_run_integration.py b/tests/python/pants_test/backend/jvm/tasks/test_junit_run_integration.py index a98f26c5bed..cb040fdd153 100644 --- a/tests/python/pants_test/backend/jvm/tasks/test_junit_run_integration.py +++ b/tests/python/pants_test/backend/jvm/tasks/test_junit_run_integration.py @@ -137,7 +137,7 @@ def test_junit_run_timeout_succeeds(self): pants_run = self.run_pants(['clean-all', 'test.junit', '--timeouts', - '--timeout-default=1', + '--timeout-default=5', '--timeout-terminate-wait=1', '--test=org.pantsbuild.testproject.timeout.ShortSleeperTest', sleeping_target]) @@ -149,7 +149,7 @@ def test_junit_run_timeout_fails(self): pants_run = self.run_pants(['clean-all', 'test.junit', '--timeouts', - '--timeout-default=1', + '--timeout-default=5', '--timeout-terminate-wait=1', '--test=org.pantsbuild.testproject.timeout.LongSleeperTest', sleeping_target]) @@ -160,7 +160,7 @@ def test_junit_run_timeout_fails(self): self.assertLess(end - start, 120) # Ensure that the timeout triggered. - self.assertIn(" timed out after 1 seconds", pants_run.stdout_data) + self.assertIn(" timed out after 5 seconds", pants_run.stdout_data) def test_junit_tests_using_cucumber(self): test_spec = 'testprojects/tests/java/org/pantsbuild/testproject/cucumber' diff --git a/tests/python/pants_test/backend/python/tasks/test_pytest_run_integration.py b/tests/python/pants_test/backend/python/tasks/test_pytest_run_integration.py index c8727afc688..b06f79bcaa7 100644 --- a/tests/python/pants_test/backend/python/tasks/test_pytest_run_integration.py +++ b/tests/python/pants_test/backend/python/tasks/test_pytest_run_integration.py @@ -59,7 +59,7 @@ def test_pytest_run_timeout_cant_terminate(self): pants_run = self.run_pants(['clean-all', 'test.pytest', '--timeout-terminate-wait=2', - '--timeout-default=1', + '--timeout-default=5', '--coverage=auto', '--cache-ignore', 'testprojects/tests/python/pants/timeout:ignores_terminate']) @@ -73,11 +73,28 @@ def test_pytest_run_timeout_cant_terminate(self): self.assertIn("No .coverage file was found! Skipping coverage reporting", pants_run.stdout_data) # Ensure that the timeout message triggered. - self.assertIn("FAILURE: Timeout of 1 seconds reached.", pants_run.stdout_data) + self.assertIn("FAILURE: Timeout of 5 seconds reached.", pants_run.stdout_data) # Ensure that the warning about killing triggered. - self.assertIn("WARN] Timed out test did not terminate gracefully after 2 seconds, " - "killing...", pants_run.stderr_data) + self.assertIn("Timed out test did not terminate gracefully after 2 seconds, " + "killing...", pants_run.stdout_data) + + def test_pytest_run_killed_by_signal(self): + start = time.time() + pants_run = self.run_pants(['clean-all', + 'test.pytest', + '--timeout-terminate-wait=2', + '--timeout-default=5', + '--cache-ignore', + 'testprojects/tests/python/pants/timeout:terminates_self']) + end = time.time() + self.assert_failure(pants_run) + + # Ensure that the failure took less than 100 seconds to run to allow for test overhead. + self.assertLess(end - start, 100) + + # Ensure that we get a message indicating the abnormal exit. + self.assertIn("FAILURE: Test was killed by signal", pants_run.stdout_data) def test_pytest_explicit_coverage(self): with temporary_dir(cleanup=False) as coverage_dir: diff --git a/tests/python/pants_test/projects/test_testprojects_integration.py b/tests/python/pants_test/projects/test_testprojects_integration.py index 897d2e21f5e..0d739cfe663 100644 --- a/tests/python/pants_test/projects/test_testprojects_integration.py +++ b/tests/python/pants_test/projects/test_testprojects_integration.py @@ -61,6 +61,7 @@ def targets(self): 'testprojects/tests/python/pants/dummies:failing_target', 'testprojects/tests/scala/org/pantsbuild/testproject/non_exports:C', 'testprojects/src/scala/org/pantsbuild/testproject/exclude_direct_dep', + 'testprojects/tests/python/pants/timeout:terminates_self', # These don't pass without special config. 'testprojects/tests/java/org/pantsbuild/testproject/depman:new-tests', 'testprojects/tests/java/org/pantsbuild/testproject/depman:old-tests', diff --git a/tests/python/pants_test/task/test_testrunner_task_mixin.py b/tests/python/pants_test/task/test_testrunner_task_mixin.py index 517b7db4fa9..73e6a767d74 100644 --- a/tests/python/pants_test/task/test_testrunner_task_mixin.py +++ b/tests/python/pants_test/task/test_testrunner_task_mixin.py @@ -203,8 +203,9 @@ def test_timeout_disabled(self): class TestRunnerTaskMixinGracefulTimeoutTest(TaskTestBase): - def create_process_handler(self, poll_returns): + def create_process_handler(self, poll_returns, wait_succeeds): poll_return_values = iter(poll_returns) + wait_succeeds_values = iter(wait_succeeds) class FakeProcessHandler(ProcessHandler): call_list = [] @@ -212,7 +213,10 @@ class FakeProcessHandler(ProcessHandler): def wait(self, timeout=None): self.call_list.append(['process_handler.wait']) - raise subprocess.TimeoutExpired(cmd='', timeout=timeout) + if next(wait_succeeds_values): + return 0 + else: + raise subprocess.TimeoutExpired(cmd='', timeout=timeout) def kill(self): self.call_list.append(['process_handler.kill']) @@ -273,8 +277,9 @@ def start(): yield - def test_graceful_terminate_if_poll_is_none(self): - self.process_handler = self.create_process_handler(poll_returns=[None, -1]) + def test_graceful_kill_if_terminate_expires(self): + self.process_handler = self.create_process_handler(poll_returns=[None], + wait_succeeds=[False, False]) self.set_options(timeouts=True) task = self.create_task(self.context()) @@ -287,11 +292,12 @@ def test_graceful_terminate_if_poll_is_none(self): [[u'process_handler.wait'], [u'process_handler.poll'], [u'process_handler.terminate'], - [u'process_handler.poll'], + [u'process_handler.wait'], [u'process_handler.kill']]) - def test_graceful_terminate_if_poll_is_zero(self): - self.process_handler = self.create_process_handler(poll_returns=[-1, 0]) + def test_graceful_terminate(self): + self.process_handler = self.create_process_handler(poll_returns=[None], + wait_succeeds=[False, True]) self.set_options(timeouts=True) task = self.create_task(self.context()) @@ -305,7 +311,7 @@ def test_graceful_terminate_if_poll_is_zero(self): [[u'process_handler.wait'], [u'process_handler.poll'], [u'process_handler.terminate'], - [u'process_handler.poll']]) + [u'process_handler.wait']]) class TestRunnerTaskMixinMultipleTargets(TaskTestBase): @@ -319,14 +325,14 @@ def _execute(self, all_targets): self._spawn_and_wait() def _spawn(self, *args, **kwargs): - timeouts = self.get_options().timeouts + terminate_wait = self.get_options().timeout_terminate_wait class FakeProcessHandler(ProcessHandler): def wait(_, timeout=None): - self.wait_time = timeout - if timeouts and timeout: - raise subprocess.TimeoutExpired(cmd='', timeout=timeout) - return 0 + # If this is not a call to `wait` for the termination timeout, count it. + if timeout != terminate_wait: + self.wait_time = timeout + raise subprocess.TimeoutExpired(cmd='', timeout=timeout) def kill(_): pass @@ -351,14 +357,9 @@ def _get_test_targets_for_spawn(self): return TestRunnerTaskMixinMultipleTargetsTask def test_multiple_targets(self): - self.set_options(timeouts=True) + self.set_options(timeouts=True, timeout_terminate_wait=1337) task = self.create_task(self.context()) - # The targetA has a `None` timeout which disables all timeouts for this batch. - task.current_targets = [targetA, targetB, targetC] - task.execute() - self.assertEqual(None, task.wait_time) - task.current_targets = [targetB] with self.assertRaises(ErrorWhileTesting) as cm: task.execute()