Improve logging/handling of signaled, killed, and terminated tests

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)

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']
+)

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)

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'

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:

tests/python/pants_test/task/test_testrunner_task_mixin.py

@@ -203,16 +203,20 @@ 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 = []
       poll_called = False
 
       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()