Revamped terminal output for update.

Features:

- Non-verbose output is now limited to a one-line progress
indicator.

- Verbose output is now collated per subprocess.  As soon as a
subprocess finishes, its full output is dumped to terminal.

- Verbose output is prefixed with timestamps representing elapsed
time since the beginning of the gclient invocation.

- git progress indicators ("Receiving objects", etc.) are limited to
one line every 10 seconds.

- In both verbose and non-verbose mode, if a failure occurs, the
full output of the failed update operation is dumped to terminal
just before exit.

- In the event that updates are progressing, but slowly,
"Still working" messages will be printed periodically, to pacify
users and buildbots.

BUG=
R=hinoka@google.com

Review URL: https://codereview.chromium.org/227163002

git-svn-id: svn://svn.chromium.org/chrome/trunk/tools/depot_tools@262500 0039d316-1c4b-4281-b951-d872f2087c98

gclient.py

@@ -444,7 +444,8 @@ class Dependency(gclient_utils.WorkItem, DependencySettings):
         parent_url = self.parent.parsed_url
         if isinstance(parent_url, self.FileImpl):
           parent_url = parent_url.file_location
-        scm = gclient_scm.CreateSCM(parent_url, self.root.root_dir, None)
+        scm = gclient_scm.CreateSCM(
+            parent_url, self.root.root_dir, None, self.outbuf)
         parsed_url = scm.FullUrlForRelativeUrl(url)
       else:
         parsed_url = url
@@ -657,7 +658,8 @@ class Dependency(gclient_utils.WorkItem, DependencySettings):
           # pylint: disable=E1103
           options.revision = parsed_url.GetRevision()
           self._used_scm = gclient_scm.SVNWrapper(
-              parsed_url.GetPath(), self.root.root_dir, self.name)
+              parsed_url.GetPath(), self.root.root_dir, self.name,
+              out_cb=work_queue.out_cb)
           self._used_scm.RunCommand('updatesingle',
               options, args + [parsed_url.GetFilename()], file_list)
       else:
@@ -667,7 +669,8 @@ class Dependency(gclient_utils.WorkItem, DependencySettings):
         self.maybeGetParentRevision(
             command, options, parsed_url, self.parent.name, revision_overrides)
         self._used_scm = gclient_scm.CreateSCM(
-            parsed_url, self.root.root_dir, self.name)
+            parsed_url, self.root.root_dir, self.name, self.outbuf,
+            out_cb=work_queue.out_cb)
         self._got_revision = self._used_scm.RunCommand(command, options, args,
                                                        file_list)
         if file_list:
@@ -724,7 +727,7 @@ class Dependency(gclient_utils.WorkItem, DependencySettings):
 
               match = re.match('^Binary file ([^\0]+) matches$', line)
               if match:
-                print 'Binary file %s matches' % mod_path(match.group(1))
+                print 'Binary file %s matches\n' % mod_path(match.group(1))
                 return
 
               items = line.split('\0')
@@ -1050,7 +1053,8 @@ solutions = [
     solutions."""
     for dep in self.dependencies:
       if dep.managed and dep.url:
-        scm = gclient_scm.CreateSCM(dep.url, self.root_dir, dep.name)
+        scm = gclient_scm.CreateSCM(
+            dep.url, self.root_dir, dep.name, self.outbuf)
         actual_url = scm.GetActualRemoteURL(self._options)
         if actual_url and not scm.DoesRemoteURLMatch(self._options):
           raise gclient_utils.Error('''
@@ -1234,7 +1238,8 @@ want to set 'managed': False in .gclient.
           'It appears your safesync_url (%s) is not working properly\n'
           '(as it returned an empty response). Check your config.' %
           dep.safesync_url)
-    scm = gclient_scm.CreateSCM(dep.url, dep.root.root_dir, dep.name)
+    scm = gclient_scm.CreateSCM(
+        dep.url, dep.root.root_dir, dep.name, self.outbuf)
     safe_rev = scm.GetUsableRev(rev, self._options)
     if self._options.verbose:
       print('Using safesync_url revision: %s.\n' % safe_rev)
@@ -1265,7 +1270,8 @@ want to set 'managed': False in .gclient.
       elif command == 'recurse':
         pm = Progress(' '.join(args), 1)
     work_queue = gclient_utils.ExecutionQueue(
-        self._options.jobs, pm, ignore_requirements=ignore_requirements)
+        self._options.jobs, pm, ignore_requirements=ignore_requirements,
+        verbose=self._options.verbose)
     for s in self.dependencies:
       work_queue.enqueue(s)
     work_queue.flush(revision_overrides, command, args, options=self._options)
@@ -1301,7 +1307,8 @@ want to set 'managed': False in .gclient.
         if (entry not in entries and
             (not any(path.startswith(entry + '/') for path in entries)) and
             os.path.exists(e_dir)):
-          scm = gclient_scm.CreateSCM(prev_url, self.root_dir, entry_fixed)
+          scm = gclient_scm.CreateSCM(
+              prev_url, self.root_dir, entry_fixed, self.outbuf)
 
           # Check to see if this directory is now part of a higher-up checkout.
           if scm.GetCheckoutRoot() in full_entries:
@@ -1332,7 +1339,8 @@ want to set 'managed': False in .gclient.
     if not self.dependencies:
       raise gclient_utils.Error('No solution specified')
     # Load all the settings.
-    work_queue = gclient_utils.ExecutionQueue(self._options.jobs, None, False)
+    work_queue = gclient_utils.ExecutionQueue(
+        self._options.jobs, None, False, verbose=self._options.verbose)
     for s in self.dependencies:
       work_queue.enqueue(s)
     work_queue.flush({}, None, [], options=self._options)
@@ -1346,7 +1354,8 @@ want to set 'managed': False in .gclient.
       else:
         original_url = dep.parsed_url
       url, _ = gclient_utils.SplitUrlRevision(original_url)
-      scm = gclient_scm.CreateSCM(original_url, self.root_dir, dep.name)
+      scm = gclient_scm.CreateSCM(
+          original_url, self.root_dir, dep.name, self.outbuf)
       if not os.path.isdir(scm.checkout_path):
         return None
       return '%s@%s' % (url, scm.revinfo(self._options, [], None))

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,8 @@ class WorkItem(object):
   def __init__(self, name):
     # A unique string representing this work item.
     self._name = name
+    self.outbuf = cStringIO.StringIO()
+    self.start = self.finish = None
 
   def run(self, work_queue):
     """work_queue is passed as keyword argument so it should be
@@ -704,7 +716,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 +737,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 +758,30 @@ class ExecutionQueue(object):
     finally:
       self.ready_cond.release()
 
+  def out_cb(self, _):
+    self.last_subproc_output = datetime.datetime.now()
+    return True
+
+  @staticmethod
+  def format_task_output(task, comment=''):
+    if comment:
+      comment = ' (%s)' % comment
+    if task.start and task.finish:
+      elapsed = ' (Elapsed: %s)' % (
+          str(task.finish - task.start).partition('.')[0])
+    else:
+      elapsed = ''
+    return """
+%s%s%s
+----------------------------------------
+%s
+----------------------------------------""" % (
+    task.name, comment, task.outbuf.getvalue().strip(), elapsed)
+
   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 +814,17 @@ 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()
+          if (now - self.last_join > datetime.timedelta(seconds=60) and
+              self.last_subproc_output > self.last_join):
+            if self.progress:
+              print >> sys.stdout, ''
+            elapsed = Elapsed()
+            print >> sys.stdout, '[%s] Still working on:' % elapsed
+            for task in self.running:
+              print >> sys.stdout, '[%s]   %s' % (elapsed, task.item.name)
         except KeyboardInterrupt:
           # Help debugging by printing some information:
           print >> sys.stderr, (
@@ -788,7 +835,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 +846,14 @@ class ExecutionQueue(object):
 
     assert not self.running, 'Now guaranteed to be single-threaded'
     if not self.exceptions.empty():
+      if self.progress:
+        print >> sys.stdout, ''
       # 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 +865,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)
         if self.progress:
           self.progress.update(1, t.item.name)
         if t.item.name in self.ran:
@@ -832,10 +888,26 @@ 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.start = datetime.datetime.now()
+        print >> task_item.outbuf, '[%s] Started.' % Elapsed(task_item.start)
+        task_item.run(*args, **kwargs)
+        task_item.finish = datetime.datetime.now()
+        print >> task_item.outbuf, '[%s] Finished.' % Elapsed(task_item.finish)
+        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."""
@@ -853,17 +925,21 @@ class ExecutionQueue(object):
       logging.debug('_Worker.run(%s)' % self.item.name)
       work_queue = self.kwargs['work_queue']
       try:
+        self.item.start = datetime.datetime.now()
+        print >> self.item.outbuf, '[%s] Started.' % Elapsed(self.item.start)
         self.item.run(*self.args, **self.kwargs)
+        self.item.finish = datetime.datetime.now()
+        print >> self.item.outbuf, '[%s] Finished.' % Elapsed(self.item.finish)
       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()

tests/gclient_scm_test.py

@@ -13,6 +13,7 @@ from subprocess import Popen, PIPE, STDOUT
 
 import logging
 import os
+import re
 import sys
 import tempfile
 import unittest
@@ -28,6 +29,14 @@ import subprocess2
 # Shortcut since this function is used often
 join = gclient_scm.os.path.join
 
+TIMESTAMP_RE = re.compile('\[[0-9]{1,2}:[0-9]{2}:[0-9]{2}\] (.*)', re.DOTALL)
+def strip_timestamps(value):
+  lines = value.splitlines(True)
+  for i in xrange(len(lines)):
+    m = TIMESTAMP_RE.match(lines[i])
+    if m:
+      lines[i] = m.group(1)
+  return ''.join(lines)
 
 # Access to a protected member XXX of a client class
 # pylint: disable=W0212
@@ -89,6 +98,12 @@ class SVNWrapperTestCase(BaseTestCase):
       self.jobs = 1
       self.delete_unversioned_trees = False
 
+  def checkstdout(self, expected):
+    value = sys.stdout.getvalue()
+    sys.stdout.close()
+    # pylint: disable=E1101
+    self.assertEquals(expected, strip_timestamps(value))
+
   def Options(self, *args, **kwargs):
     return self.OptionsObject(*args, **kwargs)
 
@@ -179,7 +194,7 @@ class SVNWrapperTestCase(BaseTestCase):
                             relpath=self.relpath)
     scm.revert(options, self.args, files_list)
     self.checkstdout(
-        ('\n_____ %s is missing, synching instead\n' % self.relpath))
+        ('_____ %s is missing, synching instead\n' % self.relpath))
 
   def testRevertNoDotSvn(self):
     options = self.Options(verbose=True, force=True)
@@ -416,7 +431,7 @@ class SVNWrapperTestCase(BaseTestCase):
     scm = self._scm_wrapper(url=self.url, root_dir=self.root_dir,
                             relpath=self.relpath)
     scm.update(options, (), files_list)
-    self.checkstdout('\n_____ %s at 42\n' % self.relpath)
+    self.checkstdout('_____ %s at 42\n' % self.relpath)
 
   def testUpdateResetDeleteUnversionedTrees(self):
     options = self.Options(verbose=True)
@@ -461,8 +476,8 @@ class SVNWrapperTestCase(BaseTestCase):
     files_list = []
     scm.update(options, (), files_list)
     self.checkstdout(
-      ('\n_____ %s at 42\n'
-       '\n_____ removing unversioned directory dir\n') % self.relpath)
+      ('_____ %s at 42\n'
+       '_____ removing unversioned directory dir\n') % self.relpath)
 
   def testUpdateSingleCheckout(self):
     options = self.Options(verbose=True)
@@ -509,7 +524,7 @@ class SVNWrapperTestCase(BaseTestCase):
     scm = self._scm_wrapper(url=self.url, root_dir=self.root_dir,
                             relpath=self.relpath)
     scm.updatesingle(options, ['DEPS'], files_list)
-    self.checkstdout('\n_____ %s at 42\n' % self.relpath)
+    self.checkstdout('_____ %s at 42\n' % self.relpath)
 
   def testUpdateSingleCheckoutSVN14(self):
     options = self.Options(verbose=True)
@@ -581,7 +596,7 @@ class SVNWrapperTestCase(BaseTestCase):
                             relpath=self.relpath)
     scm.updatesingle(options, ['DEPS'], files_list)
     self.checkstdout(
-        ('\n_____ %s at 42\n' % self.relpath))
+        ('_____ %s at 42\n' % self.relpath))
 
   def testUpdateSingleUpdate(self):
     options = self.Options(verbose=True)
@@ -616,7 +631,7 @@ class SVNWrapperTestCase(BaseTestCase):
     scm = self._scm_wrapper(url=self.url, root_dir=self.root_dir,
                             relpath=self.relpath)
     scm.updatesingle(options, ['DEPS'], files_list)
-    self.checkstdout('\n_____ %s at 42\n' % self.relpath)
+    self.checkstdout('_____ %s at 42\n' % self.relpath)
 
   def testUpdateGit(self):
     options = self.Options(verbose=True)
@@ -745,6 +760,12 @@ from :3
   def Options(self, *args, **kwargs):
     return self.OptionsObject(*args, **kwargs)
 
+  def checkstdout(self, expected):
+    value = sys.stdout.getvalue()
+    sys.stdout.close()
+    # pylint: disable=E1101
+    self.assertEquals(expected, strip_timestamps(value))
+
   @staticmethod
   def CreateGitRepo(git_import, path):
     """Do it for real."""
@@ -895,7 +916,7 @@ class ManagedGitWrapperTestCase(BaseGitWrapperTestCase):
     scm.status(options, self.args, file_list)
     self.assertEquals(file_list, [file_path])
     self.checkstdout(
-        ('\n________ running \'git diff --name-status '
+        ('running \'git diff --name-status '
          '069c602044c5388d2d15c3f875b057c852003458\' in \'%s\'\nM\ta\n') %
             join(self.root_dir, '.'))
 
@@ -915,7 +936,7 @@ class ManagedGitWrapperTestCase(BaseGitWrapperTestCase):
     expected_file_list = [join(self.base_path, x) for x in ['a', 'b']]
     self.assertEquals(sorted(file_list), expected_file_list)
     self.checkstdout(
-        ('\n________ running \'git diff --name-status '
+        ('running \'git diff --name-status '
          '069c602044c5388d2d15c3f875b057c852003458\' in \'%s\'\nM\ta\nM\tb\n') %
             join(self.root_dir, '.'))
 

tests/gclient_test.py

@@ -72,7 +72,7 @@ class GclientTest(trial_dir.TestCase):
     os.chdir(self.previous_dir)
     super(GclientTest, self).tearDown()
 
-  def _createscm(self, parsed_url, root_dir, name):
+  def _createscm(self, parsed_url, root_dir, name, out_fh=None, out_cb=None):
     self.assertTrue(parsed_url.startswith('svn://example.com/'), parsed_url)
     self.assertTrue(root_dir.startswith(self.root_dir), root_dir)
     return SCMMock(self, parsed_url)

third_party/repo/progress.py

@@ -59,15 +59,17 @@ class Progress(object):
       return
 
     if self._total <= 0:
-      sys.stdout.write('%s: %d, done.\n' % (
+      text = '%s: %d, done.' % (
         self._title,
-        self._done))
-      sys.stdout.flush()
+        self._done)
     else:
       p = (100 * self._done) / self._total
-      sys.stdout.write('%s: %3d%% (%d/%d), done.\n' % (
+      text = '%s: %3d%% (%d/%d), done.' % (
         self._title,
         p,
         self._done,
-        self._total))
-      sys.stdout.flush()
+        self._total)
+
+    spaces = max(self._width - len(text), 0)
+    sys.stdout.write('%s%*s\n' % (text, spaces, ''))
+    sys.stdout.flush()