Revamped terminal output for update.

gclient_utils.py

Index: gclient_utils.py
diff --git a/gclient_utils.py b/gclient_utils.py
index 3517946435a6efe346af97bb539f15f46f624166..75ef67590a916b3669a9c69d84fd2f845b43c98e 100644
--- a/gclient_utils.py
+++ b/gclient_utils.py
@@ -6,6 +6,7 @@
 
 import codecs
 import cStringIO
+import datetime
 import logging
 import os
 import pipes
@@ -25,6 +26,7 @@ import subprocess2
 
 RETRY_MAX = 3
 RETRY_INITIAL_SLEEP = 0.5
+START = datetime.datetime.now()
 
 
 _WARNINGS = []
@@ -47,6 +49,12 @@ class Error(Exception):
     super(Error, self).__init__(msg, *args, **kwargs)
 
 
+def Elapsed(until=None):
+  if until is None:
+    until = datetime.datetime.now()
+  return str(until - START).partition('.')[0]
+
+
 def PrintWarnings():
   """Prints any accumulated warnings."""
   if _WARNINGS:
@@ -483,12 +491,8 @@ def CheckCallAndFilter(args, stdout=None, filter_fn=None,
           output.write(in_byte)
           if print_stdout:
             stdout.write(in_byte)
-          if in_byte != '\r':
-            if in_byte != '\n':
-              in_line += in_byte
-            else:
-              filter_fn(in_line)
-              in_line = ''
+          if in_byte not in ['\r', '\n']:
+            in_line += in_byte
           else:
             filter_fn(in_line)
             in_line = ''
@@ -525,9 +529,9 @@ class GitFilter(object):
   Allows a custom function to skip certain lines (predicate), and will throttle
   the output of percentage completed lines to only output every X seconds.
   """
-  PERCENT_RE = re.compile('.* ([0-9]{1,2})% .*')
+  PERCENT_RE = re.compile('(.*) ([0-9]{1,3})% .*')
 
-  def __init__(self, time_throttle=0, predicate=None):
+  def __init__(self, time_throttle=0, predicate=None, out_fh=None):
     """
     Args:
       time_throttle (int): GitFilter will throttle 'noisy' output (such as the
@@ -535,10 +539,13 @@ class GitFilter(object):
         seconds apart.
       predicate (f(line)): An optional function which is invoked for every line.
         The line will be skipped if predicate(line) returns False.
+      out_fh: File handle to write output to.
     """
     self.last_time = 0
     self.time_throttle = time_throttle
     self.predicate = predicate
+    self.out_fh = out_fh or sys.stdout
+    self.progress_prefix = None
 
   def __call__(self, line):
     # git uses an escape sequence to clear the line; elide it.
@@ -549,11 +556,14 @@ class GitFilter(object):
       return
     now = time.time()
     match = self.PERCENT_RE.match(line)
-    if not match:
-      self.last_time = 0
-    if (now - self.last_time) >= self.time_throttle:
-      self.last_time = now
-      print line
+    if match:
+      if match.group(1) != self.progress_prefix:
+        self.progress_prefix = match.group(1)
+      elif now - self.last_time < self.time_throttle:
+        return
+    self.last_time = now
+    self.out_fh.write('[%s] ' % Elapsed())
+    print >> self.out_fh, line
 
 
 def FindGclientRoot(from_dir, filename='.gclient'):
@@ -683,6 +693,7 @@ class WorkItem(object):
   def __init__(self, name):
     # A unique string representing this work item.
     self._name = name
+    self.outbuf = cStringIO.StringIO()
 
   def run(self, work_queue):
     """work_queue is passed as keyword argument so it should be
@@ -704,7 +715,7 @@ class ExecutionQueue(object):
 
   Methods of this class are thread safe.
   """
-  def __init__(self, jobs, progress, ignore_requirements):
+  def __init__(self, jobs, progress, ignore_requirements, verbose=False):
     """jobs specifies the number of concurrent tasks to allow. progress is a
     Progress instance."""
     # Set when a thread is done or a new item is enqueued.
@@ -725,6 +736,9 @@ class ExecutionQueue(object):
       self.progress.update(0)
 
     self.ignore_requirements = ignore_requirements
+    self.verbose = verbose
+    self.last_join = None
+    self.last_subproc_output = None
 
   def enqueue(self, d):
     """Enqueue one Dependency to be executed later once its requirements are
@@ -743,9 +757,25 @@ class ExecutionQueue(object):
     finally:
       self.ready_cond.release()
 
+  def out_cb(self, _):

[Ryan Tseng, 2014/04/07 20:56:38]

What does "cb" stand for?

[szager1, 2014/04/08 20:41:14]

CallBack

+    self.last_subproc_output = datetime.datetime.now()
+    return True
+
+  @staticmethod
+  def format_task_output(task, comment=''):
+    if comment:
+      comment = ' (%s)' % comment
+    return """
+%s%s
+----------------------------------------
+%s
+---------------------------------------- """ % (
+    task.name, comment, task.outbuf.getvalue())

[Ryan Tseng, 2014/04/07 20:56:38]

trim task.outbuf.getvalue(), there seems to be an extraneous newline at the end
of the output

[0:07:42] HEAD is now at 2880170 Get rid of old keychain_reauthorize files.
[0:10:13] Checked out revision 28801705318615693b5688d036f7f5261498a418

---------------------------------------- 

Also annotating this with start/end/elapsed time would be useful, since there
are some tasks that don't print anything and we have no insight on how long they
take.

[szager1, 2014/04/08 20:41:14]

Done.

+
   def flush(self, *args, **kwargs):
     """Runs all enqueued items until all are executed."""
     kwargs['work_queue'] = self
+    self.last_subproc_output = self.last_join = datetime.datetime.now()
     self.ready_cond.acquire()
     try:
       while True:
@@ -778,6 +808,14 @@ class ExecutionQueue(object):
         # We need to poll here otherwise Ctrl-C isn't processed.
         try:
           self.ready_cond.wait(10)
+          # If we haven't printed to terminal for a while, but we have received
+          # spew from a suprocess, let the user know we're still progressing.
+          now = datetime.datetime.now()

[Ryan Tseng, 2014/04/07 20:56:38]

nit: time.time()? To match timekeeping style earlier in GitFilter()

[szager1, 2014/04/08 20:41:14]

Nice thing about datetime is the elegant arithmetic:

start = datetime.now()
do_stuff()
end = datetime.now()
elapsed = end - start  # elapsed is an instance of datetime.timedelta

timedelta objects have a nice default string representation.

+          if (now - self.last_join > datetime.timedelta(seconds=60) and
+              self.last_subproc_output > self.last_join):
+            if self.progress:
+              print >> sys.stdout, ''
+            print >> sys.stdout, '[%s] Still working...' % Elapsed()

[Ryan Tseng, 2014/04/07 20:56:38]

Not always clear what process is causing this to print out "still working"
sometimes, especially if its after the end of a process and before another one
starts.

...
---------------------------------------- 
[0:02:08] Still working...
[0:02:18] Still working...
<...snip...>
[0:05:18] Still working...
[0:05:20] Still working...

src/chrome/browser/google/linkdoctor_internal
----------------------------------------

Maybe add in a list of what's currently being worked on:
Still working on [this, that, foo, bar, ...]...

[szager1, 2014/04/08 20:41:14]

Done.

         except KeyboardInterrupt:
           # Help debugging by printing some information:
           print >> sys.stderr, (
@@ -788,7 +826,10 @@ class ExecutionQueue(object):
               ', '.join(self.ran),
               len(self.running)))
           for i in self.queued:
-            print >> sys.stderr, '%s: %s' % (i.name, ', '.join(i.requirements))
+            print >> sys.stderr, '%s (not started): %s' % (
+                i.name, ', '.join(i.requirements))
+          for i in self.running:
+            print >> sys.stderr, self.format_task_output(i.item, 'interrupted')
           raise
         # Something happened: self.enqueue() or a thread terminated. Loop again.
     finally:
@@ -796,11 +837,14 @@ class ExecutionQueue(object):
 
     assert not self.running, 'Now guaranteed to be single-threaded'
     if not self.exceptions.empty():
+      if self.progress:
+        sys.stdout.write('\n')

[Ryan Tseng, 2014/04/07 20:56:38]

nit: print >> sys.stdout, '', to match print style in surrounding lines.

[szager1, 2014/04/08 20:41:14]

Done.

       # To get back the stack location correctly, the raise a, b, c form must be
       # used, passing a tuple as the first argument doesn't work.
-      e = self.exceptions.get()
+      e, task = self.exceptions.get()
+      print >> sys.stderr, self.format_task_output(task.item, 'ERROR')
       raise e[0], e[1], e[2]
-    if self.progress:
+    elif self.progress:
       self.progress.end()
 
   def _flush_terminated_threads(self):
@@ -812,7 +856,10 @@ class ExecutionQueue(object):
         self.running.append(t)
       else:
         t.join()
+        self.last_join = datetime.datetime.now()
         sys.stdout.flush()
+        if self.verbose:
+          print >> sys.stdout, self.format_task_output(t.item)

[Ryan Tseng, 2014/04/07 20:56:38]

I think it'd be useful to also print the # of minutes elapse this therad took.

[szager1, 2014/04/08 20:41:14]

Done.

         if self.progress:
           self.progress.update(1, t.item.name)
         if t.item.name in self.ran:
@@ -832,10 +879,22 @@ class ExecutionQueue(object):
     else:
       # Run the 'thread' inside the main thread. Don't try to catch any
       # exception.
-      task_item.run(*args, **kwargs)
-      self.ran.append(task_item.name)
-      if self.progress:
-        self.progress.update(1, ', '.join(t.item.name for t in self.running))
+      try:
+        task_item.run(*args, **kwargs)
+        self.ran.append(task_item.name)
+        if self.verbose:
+          if self.progress:
+            print >> sys.stdout, ''
+          print >> sys.stdout, self.format_task_output(task_item)
+        if self.progress:
+          self.progress.update(1, ', '.join(t.item.name for t in self.running))
+      except KeyboardInterrupt:
+        print >> sys.stderr, self.format_task_output(task_item, 'interrupted')
+        raise
+      except Exception:
+        print >> sys.stderr, self.format_task_output(task_item, 'ERROR')
+        raise
+
 
   class _Worker(threading.Thread):
     """One thread to execute one WorkItem."""
@@ -857,13 +916,13 @@ class ExecutionQueue(object):
       except KeyboardInterrupt:
         logging.info('Caught KeyboardInterrupt in thread %s', self.item.name)
         logging.info(str(sys.exc_info()))
-        work_queue.exceptions.put(sys.exc_info())
+        work_queue.exceptions.put((sys.exc_info(), self))
         raise
       except Exception:
         # Catch exception location.
         logging.info('Caught exception in thread %s', self.item.name)
         logging.info(str(sys.exc_info()))
-        work_queue.exceptions.put(sys.exc_info())
+        work_queue.exceptions.put((sys.exc_info(), self))
       finally:
         logging.info('_Worker.run(%s) done', self.item.name)
         work_queue.ready_cond.acquire()