nailgun connect timeout error message fix (#7437)

### Problem

We previously had an untested code path (`NailgunExecutor._await_socket()`) which constructed a `NailgunClient.NailgunError` upon a timeout when connecting to a started nailgun subprocess. The `NailgunError` constructor was changed a while ago to create its own error message, and instead accept arguments such as the pid and pgrp in its constructor, but this untested code path hadn't been updated to provide those arguments. This caused a strange error when this unlikely timeout occurred while compiling zinc in an osx laptop environment.

### Solution

- Raise a `self.InitialNailgunConnectTimedOut` and convert it into a `self.Error` in a try/except instead of raising a `NailgunError`.
- Add testing for nailgun connection timeouts.
- Create a separate option `--nailgun-subprocess-startup-timeout` to cover the time to wait for the nailgun subprocess to start up, using `--nailgun-timeout-seconds` to cover the time to wait after that for the nailgun subprocess to begin producing output.

### Result

Another code path in our nailgun interactions is tested, and a bug in that code path is fixed.

Author: cosmicexplorer

src/python/pants/backend/jvm/tasks/nailgun_task.py

@@ -34,8 +34,10 @@ def register_options(cls, register):
              help='If set to nailgun, nailgun will be enabled and repeated invocations of this '
                   'task will be quicker. If set to subprocess, then the task will be run without '
                   'nailgun. Hermetic execution is an experimental subprocess execution framework.')
+    register('--nailgun-subprocess-startup-timeout', advanced=True, default=10, type=float,
+             help='The time (secs) to wait for a nailgun subprocess to start.')
     register('--nailgun-timeout-seconds', advanced=True, default=10, type=float,
-             help='Timeout (secs) for nailgun startup.')
+             help='The time (secs) to wait for a nailgun subprocess to start writing to stdout.')
     register('--nailgun-connect-attempts', advanced=True, default=5, type=int,
              help='Max attempts for nailgun connects.')
     cls.register_jvm_tool(register,
@@ -83,6 +85,7 @@ def create_java_executor(self, dist=None):
                              self._executor_workdir,
                              classpath,
                              dist,
+                             startup_timeout=self.get_options().nailgun_subprocess_startup_timeout,
                              connect_timeout=self.get_options().nailgun_timeout_seconds,
                              connect_attempts=self.get_options().nailgun_connect_attempts)
     else:

src/python/pants/java/nailgun_client.py

@@ -185,12 +185,12 @@ class NailgunError(Exception):
 {description} (address: {address}, remote_pid={pid}, remote_pgrp={pgrp}): {wrapped_exc!r}\
 """
 
-    def __init__(self, address, pid, pgrp, wrapped_exc, traceback):
+    # TODO: preserve the traceback somehow!
+    def __init__(self, address, pid, pgrp, wrapped_exc):
       self.address = address
       self.pid = pid
       self.pgrp = pgrp
       self.wrapped_exc = wrapped_exc
-      self.traceback = traceback
 
       # TODO: these should be ensured to be non-None in NailgunClientSession!
       if self.pid is not None:
@@ -300,7 +300,6 @@ def try_connect(self):
         pid=self._maybe_last_pid(),
         pgrp=self._maybe_last_pgrp(),
         wrapped_exc=e,
-        traceback=sys.exc_info()[2],
       )
     else:
       return sock
@@ -356,21 +355,12 @@ def execute(self, main_class, cwd=None, *args, **environment):
       remote_pgrp_callback=self._receive_remote_pgrp)
     try:
       return self._session.execute(cwd, main_class, *args, **environment)
-    except socket.error as e:
+    except (socket.error, NailgunProtocol.ProtocolError) as e:
       raise self.NailgunError(
         address=self._address_string,
         pid=self._maybe_last_pid(),
         pgrp=self._maybe_last_pgrp(),
         wrapped_exc=e,
-        traceback=sys.exc_info()[2]
-      )
-    except NailgunProtocol.ProtocolError as e:
-      raise self.NailgunError(
-        address=self._address_string,
-        pid=self._maybe_last_pid(),
-        pgrp=self._maybe_last_pgrp(),
-        wrapped_exc=e,
-        traceback=sys.exc_info()[2]
       )
     finally:
       sock.close()

src/python/pants/java/nailgun_executor.py

@@ -75,11 +75,11 @@ class NailgunExecutor(Executor, FingerprintedProcessManager):
   _PANTS_NG_BUILDROOT_ARG = '='.join((_PANTS_NG_ARG_PREFIX, get_buildroot()))
 
   _NAILGUN_SPAWN_LOCK = threading.Lock()
-  _SELECT_WAIT = 1
   _PROCESS_NAME = 'java'
 
   def __init__(self, identity, workdir, nailgun_classpath, distribution,
-               connect_timeout=10, connect_attempts=5, metadata_base_dir=None):
+               startup_timeout=10, connect_timeout=10, connect_attempts=5,
+               metadata_base_dir=None):
     Executor.__init__(self, distribution=distribution)
     FingerprintedProcessManager.__init__(self,
                                          name=identity,
@@ -94,6 +94,7 @@ def __init__(self, identity, workdir, nailgun_classpath, distribution,
     self._ng_stdout = os.path.join(workdir, 'stdout')
     self._ng_stderr = os.path.join(workdir, 'stderr')
     self._nailgun_classpath = maybe_list(nailgun_classpath)
+    self._startup_timeout = startup_timeout
     self._connect_timeout = connect_timeout
     self._connect_attempts = connect_attempts
 
@@ -140,14 +141,18 @@ def command(self):
         return list(command)
 
       def run(this, stdout=None, stderr=None, stdin=None, cwd=None):
-        nailgun = self._get_nailgun_client(jvm_options, classpath, stdout, stderr, stdin)
+        nailgun = None
         try:
+          nailgun = self._get_nailgun_client(jvm_options, classpath, stdout, stderr, stdin)
           logger.debug('Executing via {ng_desc}: {cmd}'.format(ng_desc=nailgun, cmd=this.cmd))
           return nailgun.execute(main, cwd, *args)
-        except nailgun.NailgunError as e:
+        except (NailgunClient.NailgunError, self.InitialNailgunConnectTimedOut) as e:
           self.terminate()
           raise self.Error('Problem launching via {ng_desc} command {main} {args}: {msg}'
-                           .format(ng_desc=nailgun, main=main, args=' '.join(args), msg=e))
+                           .format(ng_desc=nailgun or '<no nailgun connection>',
+                                   main=main,
+                                   args=' '.join(args),
+                                   msg=e))
 
     return Runner()
 
@@ -180,13 +185,35 @@ def _get_nailgun_client(self, jvm_options, classpath, stdout, stderr, stdin):
 
     return self._create_ngclient(self.socket, stdout, stderr, stdin)
 
+  class InitialNailgunConnectTimedOut(Exception):
+    _msg_fmt = """Failed to read nailgun output after {timeout} seconds!
+Stdout:
+{stdout}
+Stderr:
+{stderr}"""
+
+    def __init__(self, timeout, stdout, stderr):
+      msg = self._msg_fmt.format(timeout=timeout, stdout=stdout, stderr=stderr)
+      super(NailgunExecutor.InitialNailgunConnectTimedOut, self).__init__(msg)
+
   def _await_socket(self, timeout):
     """Blocks for the nailgun subprocess to bind and emit a listening port in the nailgun stdout."""
     with safe_open(self._ng_stdout, 'r') as ng_stdout:
       start_time = time.time()
       accumulated_stdout = ''
       while 1:
-        readable, _, _ = select.select([ng_stdout], [], [], self._SELECT_WAIT)
+        # TODO: share the decreasing timeout logic here with NailgunProtocol.iter_chunks() by adding
+        # a method to pants.util.contextutil!
+        remaining_time = time.time() - (start_time + timeout)
+        if remaining_time > 0:
+          stderr = read_file(self._ng_stderr, binary_mode=True)
+          raise self.InitialNailgunConnectTimedOut(
+            timeout=timeout,
+            stdout=accumulated_stdout,
+            stderr=stderr,
+          )
+
+        readable, _, _ = select.select([ng_stdout], [], [], (-1 * remaining_time))
         if readable:
           line = ng_stdout.readline()                          # TODO: address deadlock risk here.
           try:
@@ -195,17 +222,6 @@ def _await_socket(self, timeout):
             pass
           accumulated_stdout += line
 
-        if (time.time() - start_time) > timeout:
-          stderr = read_file(self._ng_stderr)
-          raise NailgunClient.NailgunError(
-            'Failed to read nailgun output after {sec} seconds!\n'
-            'Stdout:\n{stdout}\nStderr:\n{stderr}'.format(
-              sec=timeout,
-              stdout=accumulated_stdout,
-              stderr=stderr,
-            )
-          )
-
   def _create_ngclient(self, port, stdout, stderr, stdin):
     return NailgunClient(port=port, ins=stdin, out=stdout, err=stderr, workdir=get_buildroot())
 
@@ -247,7 +263,7 @@ def _spawn_nailgun_server(self, fingerprint, jvm_options, classpath, stdout, std
     self.daemon_spawn(post_fork_child_opts=post_fork_child_opts)
 
     # Wait for and write the port information in the parent so we can bail on exception/timeout.
-    self.await_pid(self._connect_timeout)
+    self.await_pid(self._startup_timeout)
     self.write_socket(self._await_socket(self._connect_timeout))
 
     logger.debug('Spawned nailgun server {i} with fingerprint={f}, pid={pid} port={port}'

tests/python/pants_test/java/BUILD

@@ -71,7 +71,8 @@ python_tests(
   name = 'nailgun_integration',
   sources = ['test_nailgun_integration.py'],
   dependencies = [
-    'tests/python/pants_test:int-test'
+    'tests/python/pants_test:int-test',
+    'tests/python/pants_test/testutils:py2_compat',
   ],
   tags = {'integration'},
 )

tests/python/pants_test/java/test_nailgun_client.py

@@ -158,7 +158,6 @@ def test_execute_propagates_connection_error_on_connect(self, mock_session, mock
       31337,
       -31336,
       Exception('oops'),
-      None
     )
 
     with self.assertRaises(NailgunClient.NailgunConnectionError):

tests/python/pants_test/java/test_nailgun_executor.py

@@ -4,6 +4,9 @@
 
 from __future__ import absolute_import, division, print_function, unicode_literals
 
+import os
+from contextlib import contextmanager
+
 import mock
 import psutil
 
@@ -20,6 +23,30 @@ def fake_process(**kwargs):
   return proc
 
 
+@contextmanager
+def rw_pipes(write_input=None):
+  """Create a pair of pipes wrapped in python file objects.
+
+  :param str write_input: If `write_input` is not None, the writable pipe will have that string
+                          written to it, then closed.
+  """
+  read_pipe, write_pipe = os.pipe()
+  read_fileobj = os.fdopen(read_pipe, 'r')
+  write_fileobj = os.fdopen(write_pipe, 'w')
+
+  if write_input is not None:
+    write_fileobj.write(write_input)
+    write_fileobj.close()
+    write_fileobj = None
+
+  yield read_fileobj, write_fileobj
+
+  read_fileobj.close()
+
+  if write_fileobj is not None:
+    write_fileobj.close()
+
+
 class NailgunExecutorTest(TestBase):
   def setUp(self):
     super(NailgunExecutorTest, self).setUp()
@@ -50,3 +77,19 @@ def test_is_alive_override_not_my_process(self):
       )
       self.assertFalse(self.executor.is_alive())
       mock_as_process.assert_called_with(self.executor)
+
+  def test_connect_timeout(self):
+    with rw_pipes() as (stdout_read, _),\
+         mock.patch('pants.java.nailgun_executor.safe_open') as mock_open,\
+         mock.patch('pants.java.nailgun_executor.read_file') as mock_read_file:
+      mock_open.return_value = stdout_read
+      mock_read_file.return_value = 'err'
+      # The stdout write pipe has no input and hasn't been closed, so the select.select() should
+      # time out regardless of the timemout argument, and raise.
+      with self.assertRaisesWithMessage(NailgunExecutor.InitialNailgunConnectTimedOut, """\
+Failed to read nailgun output after 0.0001 seconds!
+Stdout:
+
+Stderr:
+err"""):
+        self.executor._await_socket(timeout=0.0001)

tests/python/pants_test/java/test_nailgun_integration.py

@@ -5,16 +5,18 @@
 from __future__ import absolute_import, division, print_function, unicode_literals
 
 from pants_test.pants_run_integration_test import PantsRunIntegrationTest
+from pants_test.testutils.py2_compat import assertRegex
 
 
 class TestNailgunIntegration(PantsRunIntegrationTest):
+  target = 'examples/src/scala/org/pantsbuild/example/hello/welcome'
+
   def test_scala_repl_helloworld_input(self):
     """Integration test to exercise possible closed-loop breakages in NailgunClient, NailgunSession
     and InputReader.
     """
-    target = 'examples/src/scala/org/pantsbuild/example/hello/welcome'
     pants_run = self.run_pants(
-      command=['repl', target, '--quiet'],
+      command=['repl', self.target, '--quiet'],
       stdin_data=(
         'import org.pantsbuild.example.hello.welcome.WelcomeEverybody\n'
         'println(WelcomeEverybody("World" :: Nil).head)\n'
@@ -25,3 +27,17 @@ def test_scala_repl_helloworld_input(self):
     )
     self.assert_success(pants_run)
     self.assertIn('Hello, World!', pants_run.stdout_data.splitlines())
+
+  def test_nailgun_connect_timeout(self):
+    pants_run = self.run_pants(
+      ['compile', self.target],
+      # Override the PANTS_CONFIG_FILES="pants.travis-ci.ini" used within TravisCI to enable
+      # nailgun usage for the purpose of exercising that stack in the integration test.
+      config={'DEFAULT': {'execution_strategy': 'nailgun'},
+              'compile.zinc': {'nailgun_timeout_seconds': '0.00002'}}
+    )
+    self.assert_failure(pants_run)
+    assertRegex(self, pants_run.stdout_data, """\
+compile\\(examples/src/java/org/pantsbuild/example/hello/greet:greet\\) failed: \
+Problem launching via <no nailgun connection> command org\\.pantsbuild\\.zinc\\.compiler\\.Main .*: \
+Failed to read nailgun output after 2e\-05 seconds!""")