Bugfix: timeout limit for subprocesses

For security reasons svn and git do not use standard in/out/error to request
and process authentication. Instead, they use lower level system interfaces.
Python calling a subprocess can only interact with stdio, and can not intercept
or detect the lower level calls. On some systems, these requests are visible
to the user, on some systems they are not. When subprocess commands expect user
input they will wait and manage_externals appears to hang.

Change the subprocess calls to polling the running process and checking the
current run time. If the run time exceeds a timeout limit, then we display an
error message suggesting that the user verify authentication and then declare a
fatal error.

The default timeout interval of 5 minutes is probably too long and can be
shortened. But since svn requires network interaction and some large checkouts
can take a long time, this is a 'conservative' initial value.

Breakup up the subprocess call routine so it is easier to understand.

Testing:
  make test - python2/python3 - all tests pass.
  manually test with very short timeout to ensure error message is raised.

Author: bjandre

manic/utils.py

@@ -12,6 +12,7 @@
 import os
 import subprocess
 import sys
+import time
 
 from .global_constants import LOCAL_PATH_INDICATOR, LOG_FILE_NAME
 
@@ -198,6 +199,82 @@ def expand_local_url(url, field):
 # subprocess
 #
 # ---------------------------------------------------------------------
+_TIMEOUT_MSG = """ Timout errors typically occur when svn or git requires
+authentication to access a private repository. On some systems, svn
+and git requests for authentication information will not be displayed
+to the user.  In this case, the program will appear to hang and
+generate a timeout error. Ensure you can run svn and git manually and
+access all repositories without entering your authentication
+information."""
+
+_TIMEOUT_SEC = 300
+_POLL_DELTA_SEC = 0.02
+
+
+def _poll_subprocess(commands, status_to_caller, output_to_caller,
+                     timeout_sec=_TIMEOUT_SEC):
+    """Create a subprocess and poll the process until complete.
+
+    Impose a timeout limit and checkout process output for known
+    conditions that require user interaction.
+
+    NOTE: the timeout_delta has significant impact on run time. If it
+    is too long, and the many quick local subprocess calls will
+    drastically increase the run time, especially in tests.
+
+    NOTE: This function is broken out into for ease of
+    understanding. It does no error checking. It should only be called
+    from execute_subprocess, never directly.
+
+    """
+    logging.info(' '.join(commands))
+    output = []
+    start = time.time()
+
+    proc = subprocess.Popen(commands,
+                            shell=False,
+                            stdout=subprocess.PIPE,
+                            stderr=subprocess.STDOUT,
+                            universal_newlines=True)
+    while proc.poll() is None:
+        time.sleep(_POLL_DELTA_SEC)
+        if time.time() - start > timeout_sec:
+            proc.kill()
+            time.sleep(_POLL_DELTA_SEC * 5)
+            msg = ("subprocess call to  '{0}' has exceeded timeout limit of "
+                   "{1} seconds.\n{2}".format(commands[0], timeout_sec,
+                                              _TIMEOUT_MSG))
+            fatal_error(msg)
+    finish = time.time()
+
+    run_time_msg = "run time : {0:.2f} seconds".format(finish - start)
+    logging.info(run_time_msg)
+    output = proc.stdout.read()
+    log_process_output(output)
+    status = proc.returncode
+
+    # NOTE(bja, 2018-03) need to cleanup open files. In python3 use
+    # "with subprocess.Popen(...) as proc:", but that is not available
+    # with python2 unless we create a context manager.
+    proc.stdout.close()
+
+    if status != 0:
+        raise subprocess.CalledProcessError(returncode=status,
+                                            cmd=commands,
+                                            output=output)
+
+    if status_to_caller and output_to_caller:
+        ret_value = (status, output)
+    elif status_to_caller:
+        ret_value = status
+    elif output_to_caller:
+        ret_value = output
+    else:
+        ret_value = None
+
+    return ret_value
+
+
 def execute_subprocess(commands, status_to_caller=False,
                        output_to_caller=False):
     """Wrapper around subprocess.check_output to handle common
@@ -211,20 +288,30 @@ def execute_subprocess(commands, status_to_caller=False,
     return code, otherwise execute_subprocess treats non-zero return
     status as an error and raises an exception.
 
+    NOTE(bja, 2018-03) if the user doesn't have credentials setup
+    correctly, then svn and git will prompt for a username/password or
+    accepting the domain as trusted. We need to detect this and print
+    enough info for the user to determine what happened and enter the
+    appropriate information. When we detect some pre-determined
+    conditions, we turn on screen output so the user can see what is
+    needed. There doesn't appear to be a way to detect if the user
+    entered any information in the terminal. So there is no way to
+    turn off output.
+
+    NOTE(bja, 2018-03) we are polling the running process to avoid
+    having it hang indefinitely if there is input that we don't
+    detect. Some large checkouts are multiple minutes long. For now we
+    are setting the timeout interval to five minutes.
+
     """
     msg = 'In directory: {0}\nexecute_subprocess running command:'.format(
         os.getcwd())
     logging.info(msg)
     logging.info(commands)
     return_to_caller = status_to_caller or output_to_caller
-    status = -1
-    output = ''
     try:
-        logging.info(' '.join(commands))
-        output = subprocess.check_output(commands, stderr=subprocess.STDOUT,
-                                         universal_newlines=True)
-        log_process_output(output)
-        status = 0
+        ret_value = _poll_subprocess(
+            commands, status_to_caller, output_to_caller)
     except OSError as error:
         msg = failed_command_msg(
             'Command execution failed. Does the executable exist?',
@@ -246,24 +333,12 @@ def execute_subprocess(commands, status_to_caller=False,
         if not return_to_caller:
             msg_context = ('Process did not run successfully; '
                            'returned status {0}'.format(error.returncode))
-            msg = failed_command_msg(
-                msg_context,
-                commands,
-                output=error.output)
+            msg = failed_command_msg(msg_context, commands,
+                                     output=error.output)
             logging.error(error)
-            logging.error(msg)
             log_process_output(error.output)
             fatal_error(msg)
-        status = error.returncode
-
-    if status_to_caller and output_to_caller:
-        ret_value = (status, output)
-    elif status_to_caller:
-        ret_value = status
-    elif output_to_caller:
-        ret_value = output
-    else:
-        ret_value = None
+        ret_value = error.returncode
 
     return ret_value