Ensure logging is checked by most tests

Make sure to test that log messages are being emitted and captured
correctly across a larger number of tests to catch issues in tests
incorrectly polluting the setup of the logging capturing across other
test cases exposed by a recent patch.

Where tests are executed in separate threads it is possible for a
mistake in one thread, thrashing the logging capture to go unnoticed
unless other tests being executed in the same thread are checking for
correct log output. This can result in random failures as the test
execution order is dependent on PYTHONHASHSEED.

This change ensures that most tests being executed perform a positive
assertion for content to appear in the logged output, at one of the
standard log levels (as opposed to the custom one) to ensure that
logging is being captured correctly by the test framework.

Change-Id: I903478d6f3cb3f25dd7e2410c78155eca6a7d780
Related-Patch: https://review.openstack.org/387426

git_upstream/commands/import.py

@@ -134,6 +134,8 @@ class ImportCommand(LogDedentMixin, GitUpstreamCommand):
 
     def execute(self):
 
+        self.log.info("Starting execution of import command")
+
         import_upstream = ImportUpstream(
             branch=self.args.branch,
             upstream=self.args.real_upstream_branch,

git_upstream/tests/commands/import/test_import.py

@@ -64,6 +64,9 @@ class TestImportCommand(TestWithScenarios, BaseTestCase):
         self.assertThat(self.logger.output,
                         Not(Contains("Successfully rebased and updated")))
 
+        self.assertThat(self.logger.output,
+                        Contains("Starting execution of import command"))
+
         # perform sanity checks on results
         self._check_tree_state()
 

git_upstream/tests/searchers/test_searchers.py

@@ -18,6 +18,7 @@ from pprint import pformat
 
 from testscenarios import TestWithScenarios
 from testtools.content import text_content
+from testtools import matchers
 
 from git_upstream.lib.searchers import UpstreamMergeBaseSearcher
 from git_upstream.tests.base import BaseTestCase
@@ -50,6 +51,11 @@ class TestUpstreamMergeBaseSearcher(TestWithScenarios, BaseTestCase):
 
         searcher = UpstreamMergeBaseSearcher(branch=self.branches['head'][0],
                                              patterns=pattern, repo=self.repo)
+
         self.assertEqual(
             self.gittree._commits_from_nodes(reversed(self.expected_changes)),
             searcher.list(self.branches['upstream'][0]))
+
+        self.assertThat(self.logger.output,
+                        matchers.Contains("Searching for most recent merge "
+                                          "base with upstream branches"))

git_upstream/tests/strategies/test_strategies.py

@@ -20,6 +20,7 @@ from pprint import pformat
 
 from testscenarios import TestWithScenarios
 from testtools.content import text_content
+from testtools import matchers
 
 from git_upstream.tests.base import BaseTestCase
 from git_upstream.tests.base import get_scenarios
@@ -56,3 +57,7 @@ class TestStrategies(TestWithScenarios, BaseTestCase):
         self.assertEqual(
             self.gittree._commits_from_nodes(self.expected_changes),
             [c for c in strategy.filtered_iter()])
+
+        self.assertThat(self.logger.output,
+                        matchers.Contains("Searching for most recent merge "
+                                          "base with upstream branches"))