Periodically log while waiting for subprocess to complete so that the bot doe...

tools/purify/common.py

 #!/bin/env python
 # Copyright (c) 2006-2008 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.
 
 # common.py
 
 """ Common code used by purify_test.py and quantify_test.py in order to automate
 running of Rational Purify and Quantify in a consistent manner.
 """
@@ skipping 40 matching lines @@
 
 def _print_line(line, flush=True):
   # Printing to a text file (including stdout) on Windows always winds up
   # using \r\n automatically.  On buildbot, this winds up being read by a master
   # running on Linux, so we manually convert crlf to '\n'
   print line.rstrip() + '\n',
   if flush:
     sys.stdout.flush()
 
 def RunSubprocess(proc, timeout=0, detach=False):
-  """ Runs a subprocess, polling every .2 seconds until it finishes or until
-  timeout is reached.  Then kills the process with taskkill.  A timeout <= 0
-  means no timeout.
+  """ Runs a subprocess, until it finishes or |timeout| is exceeded and the
+  process is killed with taskkill.  A |timeout| <= 0  means no timeout.
   
   Args:
     proc: list of process components (exe + args)
     timeout: how long to wait before killing, <= 0 means wait forever
     detach: Whether to pass the DETACHED_PROCESS argument to CreateProcess
         on Windows.  This is used by Purify subprocesses on buildbot which
         seem to get confused by the parent console that buildbot sets up.
   """
   logging.info("running %s" % (" ".join(proc)))
   if detach:
     # see MSDN docs for "Process Creation Flags"
     DETACHED_PROCESS = 0x8
     p = subprocess.Popen(proc, creationflags=DETACHED_PROCESS)
   else:
     # For non-detached processes, manually read and print out stdout and stderr.
     # By default, the subprocess is supposed to inherit these from its parent,
     # however when run under buildbot, it seems unable to read data from a
     # grandchild process, so we have to read the child and print the data as if
     # it came from us for buildbot to read it.  We're not sure why this is
     # necessary.
     # TODO(erikkay): should we buffer stderr and stdout separately?
     p = subprocess.Popen(proc, stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
-  if timeout <= 0:
-    while p.poll() is None:
-      if not detach:
+
+  # How long to wait (in seconds) before printing progress log messages.
+  progress_delay = 300
+  progress_delay_time = time.time() + progress_delay
+  did_timeout = False
+  if timeout > 0:
+    wait_until = time.time() + timeout
+  while p.poll() is None and not did_timeout:
+    if not detach:
+      line = p.stdout.readline()
+      while line:
+        _print_line(line)
         line = p.stdout.readline()
-        while line:
-          _print_line(line)
-          line = p.stdout.readline()
-      time.sleep(0.2)
-  else:
-    wait_until = time.time() + timeout
-    while p.poll() is None and time.time() < wait_until:
-      if not detach:
-        line = p.stdout.readline()
-        while line:
-          _print_line(line)
-          line = p.stdout.readline()
-      time.sleep(0.2)
-  if not detach:
+    else:
+      # When we detach, blocking on reading stdout doesn't work, so we sleep
+      # a short time and poll.
+      time.sleep(0.5)
+      if time.time() >= progress_delay_time:
+        # Force output on a periodic basis to avoid getting killed off by the
+        # buildbot.
+        # TODO(erikkay): I'd prefer a less obtrusive 'print ".",' with a flush
+        # but because of how we're doing subprocesses, this doesn't appear to
+        # work reliably.
+        logging.info("%s still running..." % os.path.basename(proc[0]))
+        progress_delay_time = time.time() + progress_delay
+    if timeout > 0:
+      did_timeout = time.time() > wait_until
+
+  if did_timeout:
+    subprocess.call(["taskkill", "/T", "/F", "/PID", str(p.pid)])
+    logging.error("KILLED %d" % p.pid)
+    # Give the process a chance to actually die before continuing
+    # so that cleanup can happen safely.
+    time.sleep(1.0)
+    logging.error("TIMEOUT waiting for %s" % proc[0])
+    raise TimeoutError(proc[0])
+  elif not detach:
     for line in p.stdout.readlines():
       _print_line(line, False)
     p.stdout.flush()
+
   result = p.poll()
-  if result is None:
-    subprocess.call(["taskkill", "/T", "/F", "/PID", str(p.pid)])
-    logging.error("KILLED %d" % p.pid)
-    # give the process a chance to actually die before continuing
-    # so that cleanup can happen safely
-    time.sleep(1.0)
-    logging.error("TIMEOUT waiting for %s" % proc[0])
-    raise TimeoutError(proc[0])
   if result:
     logging.error("%s exited with non-zero result code %d" % (proc[0], result))
   return result
 
 
 def FixPath(path):
   """We pass computed paths to Rational as arguments, so these paths must be
   valid windows paths.  When running in cygwin's python, computed paths
   wind up looking like /cygdrive/c/..., so we need to call out to cygpath
   to fix them up.
@@ skipping 181 matching lines @@
           file = os.path.join(self._cache_dir, cfile);
           if os.path.isfile(file):
             try:
               os.remove(file)
             except:
               logging.warning("unable to delete file %s: %s" % (file, 
                               sys.exc_info()[0]))