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
diff --git a/tests/gclient_scm_test.py b/tests/gclient_scm_test.py
index a0a0887..6b667a0 100755
--- a/tests/gclient_scm_test.py
+++ b/tests/gclient_scm_test.py
@@ -13,6 +13,7 @@
 
 import logging
 import os
+import re
 import sys
 import tempfile
 import unittest
@@ -28,6 +29,14 @@
 # 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 @@
       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 @@
                             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 @@
     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 @@
     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 @@
     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 @@
                             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 @@
     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 @@
   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 @@
     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 @@
     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, '.'))