Merge lp:~dpb/latch-test/dont-be-so-verbose into lp:latch-test

[David Britton]

- Don't treat failed LP reads the same as an empty set read
- Don't post such big latch messages, people can just click the results link that latch sticks in there.

- Refactored code to make the failed read from launchpad actionable
- Stop posting full text of failure to MP
- Added test cases for refactored code (mostly overlap with existing ones)

Please feel free to flame me for testing what could be done better, mocking, etc. I didn't want to spend too much time here, but wanted to make a good change at the same time.

[🤖 Landscape Builder (landscape-builder)]

Command: make test
Result: Success
Revno: 13
Branch: lp:~davidpbritton/latch-test/dont-be-so-verbose
Jenkins: https://ci.lscape.net/job/latch-test/2272/

review: Approve (test results)

[Free Ekanayaka (free.ekanayaka)]

Thanks for pushing an MP for this David, looks like a good change to me.

Re testing, yes, my recommendation is to avoid mocks, but since these tests already make use of them, it seems out of scope to fix that here, so +1

Unrelated comment, but it seems to me that it's not possible (or it would be very awkward) to save artifacts generated by latch-test, because of this code in test_cli:

        with temporary_directory() as temp_dir:
            environment.initialize(temp_dir)
            result = environment.execute_test()

which essentially purge everything after tests have run. Would it be possible to add support for specifying an artifacts directory path inside the temporary directory that will moved or copied to the working directory before purging everything? This way we can attach more state information about failed tests using Jenkins artifacts (something that is now pressing because of some flaky integration tests).

review: Approve

[Alberto Donato (ack)]

Looks good, +1

A few minor comments inline.

review: Approve

[David Britton (dpb)]

Added bug for free's comment: https://launchpad.net/bugs/1493373

Addressed all of alberto's in this branch.

[🤖 Landscape Builder (landscape-builder)]

There are additional revisions which have not been approved in review. Please seek review and approval of these new revisions.

[🤖 Landscape Builder (landscape-builder)]

No approved revision specified.

=== modified file 'latch.py'
--- latch.py	2015-04-23 18:43:19 +0000
+++ latch.py	2015-09-08 14:29:55 +0000
@@ -12,11 +12,20 @@
 import sys
 import tempfile
 
+
 log = logging.getLogger(__name__)
 
 
+class LaunchpadFetchError(Exception):
+    """Error fetching collection from Launchpad."""
+
+
 def fetch_collection(lp, collection):
-    """Fetch a launchpad collection with proper batch awareness."""
+    """Fetch a launchpad collection with proper batch awareness.
+
+    @param collection: Collection to read.
+    raises LaunchpadFetchError if any errors come from lp.
+    """
     try:
         if collection.total_size > 0:
             for entry in collection.entries:
@@ -25,16 +34,16 @@
                 collection = collection.next_collection
                 for entry in collection.entries:
                     yield lp.load(entry["self_link"])
-    except Exception:
+    except Exception as e:
         log.exception("Error retrieving collection")
-
-
-def format_test_result(result, always_output=False):
+        raise LaunchpadFetchError(str(e))
+
+
+def format_test_result(result, show_output=False):
     """
     Format test results for printing/appending to an MP.
 
-    @param always_output True=always append, False=append
-           only on error
+    @param show_output True=show, False=hide (default)
     """
     string = u"Command: %(command)s\n" \
         u"Result: %(status)s\n" \
@@ -42,7 +51,7 @@
         u"Branch: %(branch)s" % result
     if 'BUILD_URL' in os.environ:
         string += u"\nJenkins: %s" % os.environ["BUILD_URL"]
-    if always_output or result["status"] == u"Fail":
+    if show_output:
         string += u"\n-------------------------------------------\n"
         string += u"%s" % result["output"]
     return string
@@ -239,32 +248,53 @@
             log.debug("-> Would be adding result: %s to %s" % (
                 result['status'], self.lp_candidate.web_link))
 
+    def _get_revision_from_comment(self, comment):
+        """Given a comment on an MP, return the revision it tested.
+        0 will be returned if the comment does not apply."""
+        revision_tested = 0
+        if self.lp.me != comment.author:
+            return 0
+        m = re.search("Revno: (.*)", comment.message_body[:1024])
+        if m is None:
+            log.warning("comment (%s) from %s missing revno, skipping" % (
+                comment.self_link, self.lp.me))
+            return 0
+        stored_revision = m.group(1).strip()
+        try:
+            revision_tested = int(stored_revision)
+        except ValueError:
+            log.warning("comment (%s) revno parse error, skipping" % (
+                comment.self_link))
+            return 0
+        return revision_tested
+
     def are_test_results_stale(self):
         """
         Evaluate candidate to determine if latest results are stale.  Return
         boolean evaluation.  Each result is checked for the stored revision
         number and compared to the source_branch revno.
+        Error conditions are counted as not stale so as not to trigger
+        retests over and over.
         """
         revision_tested = 0
         log.debug(
             "-> current revno: r%s" % (
                 self.lp_candidate.source_branch.revision_count))
-        for comment in fetch_collection(self.lp,
-                                        self.lp_candidate.all_comments):
-            if self.lp.me != comment.author:
-                continue
-            m = re.search("Revno: (.*)", comment.message_body[:1024])
-            if m is None:
-                log.warning("comment (%s) from %s missing revno, skipping" % (
-                    comment.self_link, self.lp.me))
-                continue
-            stored_revision = m.group(1).strip()
-            try:
-                revision_tested = max(revision_tested, int(stored_revision))
-            except ValueError:
-                log.warning("comment (%s) revno parse error, skipping" % (
-                    comment.self_link))
-                continue
+
+        revision_tested = 0
+        try:
+            # Since comments are always in chronological order, we can
+            # stop after we hit a match going backward
+            for comment in reversed(fetch_collection(
+                    self.lp, self.lp_candidate.all_comments)):
+                revision_tested = self._get_revision_from_comment(comment)
+                if revision_tested > 0:
+                    break
+        except LaunchpadFetchError:
+            log.exception("Error fetching comments from Launchpad on %s" % (
+                self.lp_candidate.web_link))
+            log.warning("Skipping candidate: %s")
+            return False
 
         if revision_tested == 0:
             log.debug("-> results are stale, tested_revision == 0")

=== modified file 'test_latch.py'
--- test_latch.py	2015-04-23 16:01:38 +0000
+++ test_latch.py	2015-09-08 14:29:55 +0000
@@ -3,19 +3,45 @@
 import latch
 import unittest
 from mock import MagicMock, patch
+import logging
+from logging.handlers import BufferingHandler
 import os
-import random
 from subprocess import PIPE, STDOUT, check_call, CalledProcessError
 
 OUTPUT = u"output ✈"
 MULTILINE_OUTPUT = u"multiline\noutput ✈"
 
+FAKE_ME = MagicMock()
+FAKE_ME.name = "fake-user"
+
 
 def fetch_collection(self, collection):
     """Return collection directly."""
     return collection
 
 
+def get_fake_comment(body=None, revno=1, author_name=FAKE_ME.name):
+    """Return a fake comment.
+    @param body: If set, put this in the body, otherwise, formulate the body
+                 as a latch comment with a Revno:
+    @param revno: revision number
+    @param author_name: author name
+    """
+    fake_comment = MagicMock()
+    if author_name == FAKE_ME.name:
+        fake_author = FAKE_ME
+    else:
+        fake_author = MagicMock()
+        fake_author.name = author_name
+    fake_comment.author = fake_author
+
+    if body is None:
+        fake_comment.message_body = "Revno: %s" % revno
+    else:
+        fake_comment.message_body = body
+    return fake_comment
+
+
 def add_results(candidate, revision, author):
     """
     Add fake test results to a candidate, one for each revision in
@@ -23,7 +49,6 @@
     """
     candidate.all_comments = []
     revisions = range(1, revision + 1)
-    random.shuffle(revisions)
     for revno in revisions:
         comment = MagicMock()
         comment.message_body = "Revno: %s" % revno
@@ -89,17 +114,61 @@
     return (source, target)
 
 
+def raises_launchpad_fetch_error(*args):
+    raise latch.LaunchpadFetchError("This is an Error.")
+
+
 # For all tests, bypass fetch_collection and just return raw data
 latch.fetch_collection = fetch_collection
 
 
+class TestLogHandler(BufferingHandler):
+    """LogHandler so unit tests can inspect logs written."""
+
+    def __init__(self):
+        super(TestLogHandler, self).__init__(0)
+        self.buffer = ()
+
+    def shouldFlush(self):
+        return False
+
+    def emit(self, record):
+        self.buffer += (record.levelname, record.msg),
+        self.buffer += ("ALL", record.msg),
+
+
+class LoggedTest(unittest.TestCase):
+    """Testing class that can track emitted logs"""
+
+    def setUp(self):
+        super(LoggedTest, self).setUp()
+        self.handler = TestLogHandler()
+        self.logger = logging.getLogger(latch.__name__)
+        self.logger.addHandler(self.handler)
+
+    def tearDown(self):
+        self.logger.removeHandler(self.handler)
+        self.handler.close()
+
+    def assertInLogs(self, message, level="ALL"):
+        """Assert that a message is logged.  Substrings are OK.
+
+        Optionally restict search to a log level of INFO, WARNING and ERROR.
+        """
+        for log_level, log_message in self.handler.buffer:
+            if level == log_level:
+                if message in log_message:
+                    return
+        raise AssertionError("String '%s' not found in %s" % (
+            message, self.handler.buffer))
+
+
 class LatchTest(unittest.TestCase):
 
     def setUp(self):
         self.latch = latch.Latch()
         self.latch.lp = MagicMock()
-        self.latch.lp.me = MagicMock()
-        self.latch.lp.me.name = "fake-user"
+        self.latch.lp.me = FAKE_ME
 
     def test_scan_branch_nothing(self):
         """Scan list of candidates, nothing should match."""
@@ -125,7 +194,7 @@
     def setUp(self):
         self.latch = latch.Latch()
         self.latch.lp = MagicMock()
-        self.latch.lp.me.name = "fake-user"
+        self.latch.lp.me = FAKE_ME
 
     def test__lookup_config(self):
         """section and key/value exist in config."""
@@ -157,14 +226,14 @@
             self.latch._lookup_config(config, candidate, "missing_key")
 
 
-class CandidateTest(unittest.TestCase):
+class CandidateTest(LoggedTest):
 
     def setUp(self):
+        super(CandidateTest, self).setUp()
         # Create a candidate object for testing, individual tests
         # will need to fill out the lp_candidate appropriately
         self.lp = MagicMock()
-        self.lp.me = MagicMock()
-        self.lp.me.name = "fake-user"
+        self.lp.me = FAKE_ME
         self.candidate = latch.Candidate(self.lp, MagicMock())
 
     def test_add_reviewer_readonly(self):
@@ -240,6 +309,43 @@
             "This is a test.")
         self.assertTrue(self.candidate.are_test_results_stale())
 
+    def test_are_test_results_stale_lp_error(self):
+        """Test results revno == source branch."""
+        self.candidate.lp_candidate.source_branch.revision_count = 1
+        add_results(self.candidate.lp_candidate, 1, self.lp.me)
+        old_fetch_collection = latch.fetch_collection
+        try:
+            latch.fetch_collection = raises_launchpad_fetch_error
+            self.assertFalse(
+                self.candidate.are_test_results_stale())
+            self.assertInLogs("Error fetching comments from Launchpad")
+            self.assertInLogs("Skipping candidate")
+        finally:
+            latch.fetch_collection = old_fetch_collection
+
+    def test_get_revision_from_comment(self):
+        """Test comment happy path, it's one of ours, and it has a revno."""
+        comment = get_fake_comment(revno=100)
+        self.assertEqual(
+            self.candidate._get_revision_from_comment(comment), 100)
+
+    def test_get_revision_from_comment_different_author(self):
+        """Test comment filter: comment not from self.lp.me returns 0."""
+        comment = get_fake_comment(author_name="someone-else")
+        self.assertEqual(self.candidate._get_revision_from_comment(comment), 0)
+
+    def test_get_revision_from_comment_no_revno(self):
+        """Test comment filter: revno missing from comment."""
+        comment = get_fake_comment(body="foobar")
+        self.assertEqual(self.candidate._get_revision_from_comment(comment), 0)
+        self.assertInLogs("missing revno, skipping")
+
+    def test_get_revision_from_comment_revno_parse_error(self):
+        """Test comment filter: revno not an int."""
+        comment = get_fake_comment(revno="foobar")
+        self.assertEqual(self.candidate._get_revision_from_comment(comment), 0)
+        self.assertInLogs("revno parse error, skipping")
+
     def test_add_result_readonly(self):
         """if readonly, should NOT try to create a comment."""
         result = {
@@ -293,25 +399,17 @@
 
     def test_format_test_result_force_include_output(self):
         """Passing result, output requested to appear."""
-        string = latch.format_test_result(self.result, always_output=True)
+        string = latch.format_test_result(self.result, show_output=True)
         self.assertIn(u"Result: Success", string)
         self.assertIn(MULTILINE_OUTPUT, string)
         self.assertNotIn(u"Jenkins:", string)
 
-    def test_format_test_result_include_output_with_failure(self):
-        """Failing result, output should appear."""
+    def test_format_test_result_with_failure_no_output(self):
+        """Failing result, output should not appear since not requested."""
         self.result["status"] = "Fail"
         string = latch.format_test_result(self.result)
         self.assertIn(u"Revno: 1234", string)
-        self.assertIn(MULTILINE_OUTPUT, string)
-        self.assertNotIn(u"Jenkins:", string)
-
-    def test_format_test_result_include_output_with_failure_and_request(self):
-        """Failing result, output should appear, even if requested."""
-        self.result["status"] = "Fail"
-        string = latch.format_test_result(self.result, always_output=True)
-        self.assertIn(u"Revno: 1234", string)
-        self.assertIn(MULTILINE_OUTPUT, string)
+        self.assertNotIn(MULTILINE_OUTPUT, string)
         self.assertNotIn(u"Jenkins:", string)
 
     def test_format_test_result_jenkins_build_url(self):
@@ -333,7 +431,7 @@
 class TestEnvironmentTest(unittest.TestCase):
     def setUp(self):
         self.lp = MagicMock()
-        self.lp.me.name = "fake-user"
+        self.lp.me = FAKE_ME
         self.environment = latch.TestEnvironment(
             latch.Candidate(self.lp, get_candidate(self.lp.me.name)),
             self.lp,