Fix gsubtreed to only include logs from modules that we care about.

infra/services/gsubtreed/test/gsubtreed_test.py

 # Copyright 2014 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.
 
 import collections
 import json
 import logging
 import os
 import sys
 import tempfile
@@ skipping 46 matching lines @@
     mirrors[path_in_mirror] = TestRepo('mirror(%s)' % path_in_mirror, clock,
                                        'fake')
     mirrors[path_in_mirror]._repo_path = full_path
     mirrors[path_in_mirror].run('init', '--bare')
 
   class LogFormatter(logging.Formatter):
     def format(self, record):
       s = super(LogFormatter, self).format(record)
       return s.replace(base_repo_path, '[TMPDIR]')
 
+  class LogFilterer(logging.Filter):
+    def filter(self, record):
+      # infra.libs.git2.repo logs this message if the command took longer than

[martiniss, 2016/06/13 21:30:37]

:(

+      # 1s to run.  This causes test flakes occasionally.
+      if (record.name.startswith('infra.libs.git2.repo.Repo') and

[martiniss, 2016/06/13 21:45:01]

need a pragma: no cover for this, since it's flakily hit :(

+          record.msg.startswith('Finished in ')):
+        return False
+
+      return record.name.startswith((
+        'infra.services.gsubtreed',
+        'infra.libs.git2',
+      ))
+
   def checkpoint(message, include_committer=False, include_config=False):
     repos = collections.OrderedDict()
     repos['origin'] = origin.snap(include_committer, include_config)
     for _, mirror in sorted(mirrors.items()):
       repos[mirror.short_name] = mirror.snap(include_committer, include_config)
     ret.append([message, repos])
 
   def run():
     stdout = sys.stdout
     stderr = sys.stderr
 
     logout = StringIO()
     root_logger = logging.getLogger()
     shandler = logging.StreamHandler(logout)
     shandler.setFormatter(LogFormatter('%(levelname)s: %(message)s'))
+    shandler.addFilter(LogFilterer())
     root_logger.addHandler(shandler)
     shandler.setLevel(logging.INFO)
 
     # Run pusher threads sequentially and deterministically.
     gsubtreed.Pusher.FAKE_THREADING = True
 
     success = False
     processed = {}
     try:
       with open(os.devnull, 'w') as dn:
         # TODO(iannucci): Let expect_tests absorb stdio
         sys.stderr = sys.stdout = dn
         local.reify()
         success, processed = gsubtreed.inner_loop(local, cref)
     except Exception:  # pragma: no cover
       ret.append(traceback.format_exc().splitlines())
     finally:
       gsubtreed.Pusher.FAKE_THREADING = False
 
       sys.stdout = stdout
       sys.stderr = stderr
 
       root_logger.removeHandler(shandler)
 
-      # infra.libs.git2.repo logs this message if the command took longer than
-      # 1s to run.  This causes test flakes occasionally.
-      log_lines = [x for x in logout.getvalue().splitlines()
-                   if 'Finished in ' not in x]
-      ret.append({'log output': log_lines})
+      ret.append({'log output': logout.getvalue().splitlines()})
 
       ret.append({
         'inner_loop success': success,
         'processed': processed,
       })
 
   gsubtreed_test_definitions.GSUBTREED_TESTS[test_name](
     origin=origin, run=run, checkpoint=checkpoint, mirrors=mirrors,
     config=cref, local_origin_repo=local)
 
   return expect_tests.Result(ret)
 
 
 @expect_tests.test_generator
 def GenTests():
   for test_name, test in gsubtreed_test_definitions.GSUBTREED_TESTS.iteritems():
     yield expect_tests.Test(
         __package__ + '.' + test_name,
         expect_tests.FuncCall(RunTest, test_name),
         expect_base=test_name, ext='yaml', break_funcs=[test],
         covers=(
             expect_tests.Test.covers_obj(RunTest) +
             expect_tests.Test.covers_obj(gsubtreed_test_definitions)
         ))