Add logging to bot_update.py and gclient_scm.py

Bug: chromium:1014216
Change-Id: I620f197fe26d8817ddb51e7a30ae774439d79bdf
Recipe-Nontrivial-Roll: chromiumos
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/tools/depot_tools/+/1860854
Commit-Queue: Erik Chen <erikchen@chromium.org>
Reviewed-by: Edward Lesmes <ehmaldonado@chromium.org>
Reviewed-by: Andrii Shyshkalov <tandrii@google.com>
Auto-Submit: Erik Chen <erikchen@chromium.org>

gclient_scm.py

@@ -1275,6 +1275,7 @@ class GitWrapper(SCMWrapper):
         ['git'] + args, env=env, **kwargs).decode('utf-8')
     if strip:
       ret = ret.strip()
+    self.Print('Finished running: %s %s' % ('git', ' '.join(args)))
     return ret
 
   def _Checkout(self, options, ref, force=False, quiet=None):

recipes/recipe_modules/bot_update/resources/bot_update.py

@@ -12,6 +12,7 @@ import codecs
 from contextlib import contextmanager
 import copy
 import ctypes
+from datetime import datetime
 import json
 import optparse
 import os
@@ -152,7 +153,7 @@ def call(*args, **kwargs):  # pragma: no cover
     print('===Injecting Environment Variables===')
     for k, v in sorted(new_env.items()):
       print('%s: %s' % (k, v))
-  print('===Running %s ===' % (' '.join(args),))
+  print('%s ===Running %s ===' % (datetime.now(), ' '.join(args),))
   print('In directory: %s' % cwd)
   start_time = time.time()
   proc = subprocess.Popen(args, **kwargs)
@@ -185,13 +186,15 @@ def call(*args, **kwargs):  # pragma: no cover
   elapsed_time = ((time.time() - start_time) / 60.0)
   outval = out.getvalue()
   if code:
-    print('===Failed in %.1f mins of %s ===' % (elapsed_time, ' '.join(args)))
+    print('%s ===Failed in %.1f mins of %s ===' %
+          (datetime.now(), elapsed_time, ' '.join(args)))
     print()
     raise SubprocessFailed('%s failed with code %d in %s.' %
                            (' '.join(args), code, cwd),
                            code, outval)
 
-  print('===Succeeded in %.1f mins of %s ===' % (elapsed_time, ' '.join(args)))
+  print('%s ===Succeeded in %.1f mins of %s ===' %
+        (datetime.now(), elapsed_time, ' '.join(args)))
   print()
   return outval
 

tests/gclient_scm_test.py

@@ -160,8 +160,9 @@ from :3
   def checkstdout(self, expected):
     value = sys.stdout.getvalue()
     sys.stdout.close()
+    # Check that the expected output appears.
     # pylint: disable=no-member
-    self.assertEqual(expected, strip_timestamps(value))
+    self.assertIn(expected, strip_timestamps(value))
 
   @staticmethod
   def CreateGitRepo(git_import, path):
@@ -604,8 +605,9 @@ class ManagedGitWrapperTestCaseMock(unittest.TestCase):
   def checkstdout(self, expected):
     value = sys.stdout.getvalue()
     sys.stdout.close()
+    # Check that the expected output appears.
     # pylint: disable=no-member
-    self.assertEqual(expected, strip_timestamps(value))
+    self.assertIn(expected, strip_timestamps(value))
 
   def setUp(self):
     self.fake_hash_1 = 't0ta11yf4k3'