bot_update/gclient: kill git fetch after timeout regardless of output.

gclient_utils.py

 # Copyright (c) 2012 The Chromium Authors. All rights reserved.
 # Use of this source code is governed by a BSD-style license that can be
 # found in the LICENSE file.
 
 """Generic utils."""
 
 import codecs
 import cStringIO
 import datetime
 import logging
@@ skipping 448 matching lines @@
           print >> sys.stderr, '  ', zombie.pid
 
 
 class _KillTimer(object):
   """Timer that kills child process after certain interval since last poke or
   creation.
   """
   # TODO(tandrii): we really want to make use of subprocess42 here, and not
   # re-invent the wheel, but it's too much work :(
 
-  def __init__(self, timeout, child):
+  def __init__(self, timeout, child, child_info):
     self._timeout = timeout
     self._child = child
+    self._child_info = child_info
 
     self._cv = threading.Condition()
     # All items below are protected by condition above.
     self._kill_at = None
+    self._killing_attempted = False
     self._working = True
     self._thread = None
 
     # Start the timer immediately.
     if self._timeout:
       self._kill_at = time.time() + self._timeout
       self._thread = threading.Thread(name='_KillTimer', target=self._work)
       self._thread.daemon = True
       self._thread.start()
 
+  @property
+  def killing_attempted(self):
+    return self._killing_attempted
+
   def poke(self):
     if not self._timeout:
       return
     with self._cv:
       self._kill_at = time.time() + self._timeout
 
   def cancel(self):
     with self._cv:
       self._working = False
       self._cv.notifyAll()
 
   def _work(self):
     if not self._timeout:
       return
     while True:
       with self._cv:
         if not self._working:
           return
         left = self._kill_at - time.time()
         if left > 0:
           self._cv.wait(timeout=left)
           continue
         try:
-          logging.warn('killing child %s because of no output for %fs',
-                       self._child, self._timeout)
+          logging.warn('killing child %s %s because of no output for %fs',
+                       self._child.pid, self._child_info, self._timeout)
+          self._killing_attempted = True
           self._child.kill()
         except OSError:
           logging.exception('failed to kill child %s', self._child)
         return
 
 
 def CheckCallAndFilter(args, stdout=None, filter_fn=None,
                        print_stdout=None, call_filter_on_first_line=False,
                        retry=False, kill_timeout=None, **kwargs):
   """Runs a command and calls back a filter function if needed.
 
   Accepts all subprocess2.Popen() parameters plus:
     print_stdout: If True, the command's stdout is forwarded to stdout.
     filter_fn: A function taking a single string argument called with each line
                of the subprocess2's output. Each line has the trailing newline
                character trimmed.
     stdout: Can be any bufferable output.
     retry: If the process exits non-zero, sleep for a brief interval and try
            again, up to RETRY_MAX times.
     kill_timeout: (float) if given, number of seconds after which process would
-           be killed if there is no output. Must not be used with shell=True as
-           only shell process would be killed, but not processes spawned by
-           shell.
+           be killed. Must not be used with shell=True as only shell process
+           would be killed, but not processes spawned by shell.
 
   stderr is always redirected to stdout.
   """
   assert print_stdout or filter_fn
   assert not kwargs.get('shell', False) or not kill_timeout, (
       'kill_timeout should not be used with shell=True')
   stdout = stdout or sys.stdout
   output = cStringIO.StringIO()
   filter_fn = filter_fn or (lambda x: None)
 
   sleep_interval = RETRY_INITIAL_SLEEP
   run_cwd = kwargs.get('cwd', os.getcwd())
+  debug_kid_info = "'%s' in %s" % (' '.join('"%s"' % x for x in args), run_cwd)

[Michael Achenbach, 2016/08/30 15:02:52]

Wouldn't str(args) be sufficient?

Never mind. Saw now that it's copied from below.

+
   for _ in xrange(RETRY_MAX + 1):
     kid = subprocess2.Popen(
         args, bufsize=0, stdout=subprocess2.PIPE, stderr=subprocess2.STDOUT,
         **kwargs)
 
     GClientChildren.add(kid)
 
     # Do a flush of stdout before we begin reading from the subprocess2's stdout
     stdout.flush()
 
     # Also, we need to forward stdout to prevent weird re-ordering of output.
     # This has to be done on a per byte basis to make sure it is not buffered:
     # normally buffering is done for each line, but if svn requests input, no
     # end-of-line character is output after the prompt and it would not show up.
     try:
-      timeout_killer = _KillTimer(kill_timeout, kid)
+      timeout_killer = _KillTimer(kill_timeout, kid, debug_kid_info)

[Michael Achenbach, 2016/08/30 15:02:52]

naming nit: child vs. kid - well, it's from the old code...

       in_byte = kid.stdout.read(1)
       if in_byte:
         if call_filter_on_first_line:
           filter_fn(None)
         in_line = ''
         while in_byte:
-          timeout_killer.poke()
           output.write(in_byte)
           if print_stdout:
             stdout.write(in_byte)
           if in_byte not in ['\r', '\n']:
             in_line += in_byte
           else:
             filter_fn(in_line)
             in_line = ''
           in_byte = kid.stdout.read(1)
         # Flush the rest of buffered output. This is only an issue with
         # stdout/stderr not ending with a \n.
         if len(in_line):
           filter_fn(in_line)
       rv = kid.wait()
       timeout_killer.cancel()
 
       # Don't put this in a 'finally,' since the child may still run if we get
       # an exception.
       GClientChildren.remove(kid)
 
     except KeyboardInterrupt:
       print >> sys.stderr, 'Failed while running "%s"' % ' '.join(args)
       raise
 
     if rv == 0:
       return output.getvalue()
     if not retry:
       break
-    print ("WARNING: subprocess '%s' in %s failed; will retry after a short "
-           'nap...' % (' '.join('"%s"' % x for x in args), run_cwd))
+    print ("WARNING: subprocess %s failed; will retry after a short nap..." %
+           debug_kid_info)
+    if timeout_killer.killing_attempted:
+      print('The subprocess above was likely killed because it looked hung. '
+            'Output thus far:\n> %s' %
+            ('\n> '.join(output.getvalue().splitlines())))
     time.sleep(sleep_interval)
     sleep_interval *= 2
   raise subprocess2.CalledProcessError(
       rv, args, kwargs.get('cwd', None), None, None)
 
 
 class GitFilter(object):
   """A filter_fn implementation for quieting down git output messages.
 
   Allows a custom function to skip certain lines (predicate), and will throttle
@@ skipping 674 matching lines @@
     # Just incase we have some ~/blah paths.
     target = os.path.abspath(os.path.expanduser(target))
     if os.path.isfile(target) and os.access(target, os.X_OK):
       return target
     if sys.platform.startswith('win'):
       for suffix in ('.bat', '.cmd', '.exe'):
         alt_target = target + suffix
         if os.path.isfile(alt_target) and os.access(alt_target, os.X_OK):
           return alt_target
   return None