Merge lp:~jcsackett/charmworld/better-latency-round-2 into lp:charmworld

[j.c.sackett]

Undoes the rollback for the better latency work, with a fix for the expiring credentials.

This undoes the rollback in r 443 of the better latency work originally done in
r 422.

The majority of the changes were explained and approved in an earlier MP[1].

charmworld/jobs/review.py
-------------------------
The reinstated call to login_with is updated to use consumer_name as a
parameter; this ensures that LP sees the same, already authorized consumer when
the request occurs in dev, staging, or production.

As before, the credentials file will have to be set on the staging and
production instances by setting the lp_credentials parameter on the charm, via
juju set. IS docs on wiki.canonical.com and the deploy script for staging will
both be updated with this information after this branch is QAed.

[1]: https://code.launchpad.net/~jcsackett/charmworld/better-latency-refactor/+merge/191615

[Aaron Bentley (abentley)]

Looks good to me.

review: Approve

[Juju Gui Bot (juju-gui-bot)]

FAILED: Autolanding.
More details in the following jenkins job:
http://162.213.35.27:8080/job/charmworld-autoland-lxc/81/
Executed test runs:

review: Needs Fixing (continuous-integration)

[j.c.sackett (jcsackett)]

Looks like it just failed on the npm step, possible network error? Trying again.

[Juju Gui Bot (juju-gui-bot)]

review: Approve (continuous-integration)

=== modified file '.bzrignore'
--- .bzrignore	2013-10-17 15:58:13 +0000
+++ .bzrignore	2013-11-13 16:15:48 +0000
@@ -29,3 +29,4 @@
 supervisord.log
 supervisord.pid
 _run
+charmbot_credentials.txt
 
=== modified file 'charmworld/jobs/review.py'
--- charmworld/jobs/review.py	2013-11-05 18:40:38 +0000
+++ charmworld/jobs/review.py	2013-11-13 16:15:48 +0000
@@ -38,10 +38,21 @@
     # older than the window that is still open. Right now this is probably the
     # more performant way to go about it, but that's going to change as the
     # data outside of our window gets larger.
+    try:
+        lp_credentials = get_ini()['lp_credentials_file']
+    except KeyError:
+        lp_credentials = None
     with Timer() as timer:
-        lp = Launchpad.login_anonymously('charm-tools',
-                                         'production',
-                                         version='devel')
+        if lp_credentials:
+            lp = Launchpad.login_with(application_name='charm-tools',
+                                      service_root='production',
+                                      version='devel',
+                                      consumer_name='charmworld',
+                                      credentials_file=lp_credentials)
+        else:
+            lp = Launchpad.login_anonymously('charm-tools',
+                                             'production',
+                                             version='devel')
 
         # Entity roots for items of interests
         charm = lp.distributions['charms']
@@ -50,13 +61,13 @@
 
     log.debug("lp login time %0.2f", timer.duration())
 
+    branch_filter = "Show only Bugs with linked Branches"
     with Timer() as timer:
         bugs = charm.searchTasks(
             tags=['new-formula', 'new-charm'],
-            tags_combinator="Any")
-        # Best practice  dictates that charmers be subscribed to all bugs
-        # and merge proposals for official source package branches.
-        charmers_bugs = charmers.searchTasks()
+            tags_combinator="Any",
+            linked_branches=branch_filter)
+        charmers_bugs = charmers.searchTasks(linked_branches=branch_filter)
         proposals = charmers.getRequestedReviews()
         contributor_proposals = charm_contributors.getRequestedReviews()
 
@@ -69,27 +80,67 @@
             itertools.chain(proposals, contributor_proposals, doc_proposals))
 
 
+def calculate_proposal_latency(proposal, now):
+    if proposal.date_reviewed:
+        latency = (
+            proposal.date_reviewed - proposal.date_review_requested)
+    else:
+        # `now` has been calculated in UTC, and LP returns UTC TZ
+        # datetimes. We can safely remove the TZ, letting us get the
+        latency = (
+            now - proposal.date_review_requested.replace(tzinfo=None))
+    return latency.total_seconds()
+
+
+def calculate_task_latency(task, now):
+    link_entries = [e for e in task.bug.activity.entries if
+                    e['whatchanged'] == 'branch linked']
+    if len(link_entries) == 1:
+        start_date = link_entries[0]['datechanged']
+        start_date = datetime.datetime.strptime(
+            start_date.split('.')[0], '%Y-%m-%dT%H:%M:%S')
+    elif len(link_entries) > 1:
+        #Filter down to links associated with the currently linked branches
+        linked_branches = task.bug.linked_branches
+        branch_names = [link.branch.display_name for link in linked_branches]
+        current_entries = [e for e in link_entries if
+                           e['newvalue'] in branch_names]
+        if current_entries != []:
+            start_date = current_entries[0]['datechanged']
+            start_date = datetime.datetime.strptime(
+                start_date.split('.')[0], '%Y-%m-%dT%H:%M:%S')
+        else:
+            # At some point, the name of the branch changed, so we can't find
+            # the event when it was added. This happens rarely, so we just
+            # abandon stats for this task.
+            return
+    elif link_entries == []:
+        # We have no entries, probably b/c the lp step failed to login with
+        # authentication.
+        return
+
+    if task.date_fix_committed:
+        end_date = task.date_fix_committed.replace(tzinfo=None)
+    else:
+        end_date = now
+    latency = end_date - start_date
+    return latency.total_seconds()
+
+
 def update_review_queue(db, tasks, proposals, log):
     '''Updates the review queue information.'''
+    now = datetime.datetime.utcnow()
+    window = now - datetime.timedelta(days=180)  # 6 month window for latency
     bug_statuses = [
         'New', 'Confirmed', 'Triaged', 'In Progress', 'Fix Committed']
-    proposal_statuses = ['Needs review', 'Needs fixing', 'Needs information']
-    now = datetime.datetime.utcnow()
-    window = now - datetime.timedelta(days=180)  # 6 month window for latency
-
     r_queue = []
     latencies = []
     for task in tasks:
         if (task.date_created.replace(tzinfo=None) >= window or
             task.status in bug_statuses):
-            if task.date_confirmed:
-                latency = task.date_confirmed - task.date_created
-            else:
-                # Now has been calculated in UTC, and LP returns UTC TZ
-                # datetimes. We can safely remove the TZ, letting us get the
-                # timedelta.
-                latency = now - task.date_created.replace(tzinfo=None)
-            latencies.append(latency.total_seconds())
+            latency = calculate_task_latency(task, now)
+            if latency:
+                latencies.append(latency)
 
         if task.status in bug_statuses:
             entry = {
@@ -102,19 +153,13 @@
             }
             r_queue.append(entry)
 
+    proposal_statuses = [
+        'Needs review', 'Needs fixing', 'Needs information']
     for proposal in proposals:
         if (proposal.date_created.replace(tzinfo=None) >= window or
             proposal.queue_status in proposal_statuses):
-            if proposal.date_reviewed:
-                latency = (
-                    proposal.date_reviewed - proposal.date_review_requested)
-            else:
-                # Now has been calculated in UTC, and LP returns UTC TZ
-                # datetimes. We can safely remove the TZ, letting us get the
-                latency = (
-                    now - proposal.date_review_requested.replace(tzinfo=None))
-            latencies.append(latency.total_seconds())
-
+            latency = calculate_proposal_latency(proposal, now)
+            latencies.append(latency)
         if proposal.queue_status in proposal_statuses:
             parts = proposal.target_branch_link.rsplit('/', 3)
             if parts[-1] == "trunk":
@@ -131,7 +176,6 @@
 
             entry = {
                 'type': 'proposal',
-                'latency': latency.total_seconds(),
                 'date_modified': last_modified,
                 'date_created': proposal.date_created,
                 'summary': "Merge for %s from %s" % (target, origin),
 
=== modified file 'charmworld/jobs/tests/test_review.py'
--- charmworld/jobs/tests/test_review.py	2013-11-05 18:40:38 +0000
+++ charmworld/jobs/tests/test_review.py	2013-11-13 16:15:48 +0000
@@ -3,7 +3,13 @@
 import datetime
 import logging
 
-from charmworld.jobs.review import update_review_queue
+import mock
+
+from charmworld.jobs.review import (
+    calculate_proposal_latency,
+    calculate_task_latency,
+    update_review_queue,
+)
 from charmworld.testing import MongoTestBase
 
 
@@ -12,45 +18,45 @@
 TWO_DAYS = NOW - datetime.timedelta(2)
 
 
-class MockBug:
-    date_last_updated = NOW
-
-
-class MockTask:
-
-    def __init__(self, confirmed=False):
-        self.date_created = TWO_DAYS
-        self.title = u'Bug #0 in a collection: "A bug task"'
-        self.web_link = "http://example.com"
-        self.bug = MockBug()
-        if confirmed:
-            self.status = "Confirmed"
-            self.date_confirmed = YESTERDAY
-        else:
-            self.date_confirmed = None
-            self.status = "New"
-
-
-class MockCommentCollection:
-    total_size = 0
-
-
-class MockProposal:
-
-    def __init__(self, reviewed=False):
-        base = 'https://api.launchpad.net/devel/'
-        self.target_branch_link = base + '~charmers/charms/precise/foo/trunk'
-        self.source_branch_link = base + '~bar/charms/precise/foo/fnord'
-        self.all_comments = MockCommentCollection()
-        self.date_review_requested = TWO_DAYS
-        self.date_created = TWO_DAYS
-        self.web_link = 'http://example.com'
-        if reviewed:
-            self.date_reviewed = YESTERDAY
-            self.queue_status = "Approved"
-        else:
-            self.date_reviewed = None
-            self.queue_status = "Needs review"
+def get_mock_task(confirmed=False, entries=[], linked_branches=[]):
+    if confirmed:
+        status = "Confirmed"
+        date_fix_committed = YESTERDAY
+    else:
+        date_fix_committed = None
+        status = "New"
+    return mock.Mock(
+        status=status,
+        date_fix_committed=date_fix_committed,
+        date_created=TWO_DAYS,
+        title=u'Bug #0 in a collection: "A bug task"',
+        web_link="http://example.com",
+        bug=mock.Mock(
+            date_last_updated=NOW,
+            linked_branches=linked_branches,
+            activity=mock.Mock(entries=entries)
+        ),
+    )
+
+
+def get_mock_proposal(reviewed=False):
+    base = 'https://api.launchpad.net/devel/'
+    if reviewed:
+        date_reviewed = YESTERDAY
+        queue_status = "Approved"
+    else:
+        date_reviewed = None
+        queue_status = "Needs review"
+    return mock.Mock(
+        target_branch_link=base + '~charmers/charms/precise/foo/trunk',
+        source_branch_link=base + '~bar/charms/precise/foo/fnord',
+        all_comments=mock.Mock(total_size=0),
+        date_review_requested=TWO_DAYS,
+        date_created=TWO_DAYS,
+        web_link='http://example.com',
+        date_reviewed=date_reviewed,
+        queue_status=queue_status,
+    )
 
 
 class ReviewTest(MongoTestBase):
@@ -63,7 +69,7 @@
 
     def test_review_handles_bugs(self):
         log = logging.getLogger('foo')
-        update_review_queue(self.db, [MockTask()], [], log)
+        update_review_queue(self.db, [get_mock_task()], [], log)
         self.assertEqual(1, self.db.review_queue.count())
         item = self.db.review_queue.find_one()
         self.assertEqual(NOW.date(), item['date_modified'].date())
@@ -74,7 +80,7 @@
 
     def test_review_handles_proposals(self):
         log = logging.getLogger('foo')
-        update_review_queue(self.db, [], [MockProposal()], log)
+        update_review_queue(self.db, [], [get_mock_proposal()], log)
         self.assertEqual(1, self.db.review_queue.count())
         item = self.db.review_queue.find_one()
         self.assertEqual(TWO_DAYS.date(), item['date_modified'].date())
@@ -84,10 +90,65 @@
         self.assertEqual('http://example.com', item['item'])
         self.assertEqual('Needs review', item['status'])
 
-    def test_review_calculates_latency(self):
+    def test_calculate_task_latency_with_two_valid_links(self):
+        linked_branches = [
+            mock.Mock(branch=mock.Mock(display_name='lp:~foo/bar/bjorn')),
+            mock.Mock(branch=mock.Mock(display_name='lp:~foo/bar/baz'))
+        ]
+        two_days = datetime.datetime.strftime(
+            TWO_DAYS, '%Y-%m-%dT%H:%M:%S')
+        yesterday = datetime.datetime.strftime(
+            YESTERDAY, '%Y-%m-%dT%H:%M:%S')
+        entries = [
+            {'whatchanged': 'branch linked',
+             'newvalue': 'lp:~foo/bar/baz',
+             'datechanged': two_days},
+            {'whatchanged': 'branch linked',
+             'newvalue': 'lp:~foo/bar/bjorn',
+             'datechanged': yesterday}]
+        latency = calculate_task_latency(
+            get_mock_task(
+                True, entries=entries, linked_branches=linked_branches), NOW)
+        self.assertEqual(60 * 60 * 24, int(latency))
+
+    def test_calculate_task_latency_bug_with_one_valid_link(self):
+        linked_branches = [
+            mock.Mock(branch=mock.Mock(display_name='lp:~foo/bar/bjorn'))
+        ]
+        two_days = datetime.datetime.strftime(
+            TWO_DAYS, '%Y-%m-%dT%H:%M:%S')
+        yesterday = datetime.datetime.strftime(
+            YESTERDAY, '%Y-%m-%dT%H:%M:%S')
+        entries = [
+            {'whatchanged': 'branch linked',
+             'newvalue': 'lp:~foo/bar/baz',
+             'datechanged': yesterday},
+            {'whatchanged': 'branch linked',
+             'newvalue': 'lp:~foo/bar/bjorn',
+             'datechanged': two_days}]
+        latency = calculate_task_latency(
+            get_mock_task(
+                True, entries=entries, linked_branches=linked_branches), NOW)
+        self.assertEqual(60 * 60 * 24, int(latency))
+
+    def test_calculate_task_latency_bug_with_one_link(self):
+        date_changed = datetime.datetime.strftime(
+            TWO_DAYS, '%Y-%m-%dT%H:%M:%S')
+        entries = [{'whatchanged': 'branch linked',
+                    'newvalue': 'lp:~foo/bar/baz',
+                    'datechanged': date_changed}]
+        latency = calculate_task_latency(
+            get_mock_task(True, entries=entries), NOW)
+        self.assertEqual(60 * 60 * 24, int(latency))
+
+    def test_calculate_proposal_latency(self):
+        latency = calculate_proposal_latency(get_mock_proposal(True), NOW)
+        self.assertEqual(60 * 60 * 24, int(latency))
+
+    def test_review_job_saves_latency(self):
         log = logging.getLogger('foo')
         self.assertEqual(0, self.db.review_queue_latency.count())
-        update_review_queue(self.db, [], [MockProposal(True)], log)
+        update_review_queue(self.db, [], [get_mock_proposal(True)], log)
         self.assertEqual(1, self.db.review_queue_latency.count())
         item = self.db.review_queue_latency.find_one()
         self.assertEqual(NOW.date(), item['date'].date())
@@ -96,14 +157,14 @@
         self.assertEqual(1, datetime.timedelta(seconds=item['min']).days)
 
     def test_review_discards_closed_bugs(self):
-        tasks = [MockTask(), MockTask()]
+        tasks = [get_mock_task(), get_mock_task()]
         tasks[0].status = 'Fix released'
         log = logging.getLogger('foo')
         update_review_queue(self.db, tasks, [], log)
         self.assertEqual(1, self.db.review_queue.count())
 
     def test_review_discards_approved_proposals(self):
-        proposals = [MockProposal(), MockProposal()]
+        proposals = [get_mock_proposal(), get_mock_proposal()]
         proposals[0].queue_status = 'Approved'
         log = logging.getLogger('foo')
         update_review_queue(self.db, [], proposals, log)