Merge lp:~jml/launchpad/generate-ppa-logging into lp:launchpad

[Jonathan Lange]

Instrument generate_ppa_htaccess.

Turns out that generate_ppa_htaccess is a blocking step in the process of buying software. We need it to be as fast as possible, and so we need to instrument it to see where its slow.

Along the way, I've done some cleanups to code. In an effort to reduce the line count damage, I may have gone a bit overboard in cramming changes into this diff. Sorry.

Here's a summary:

 * Add a debug log to all cronscripts to say how long they spent running
 * Add a method to get the last activity of a cronscript
 * Add total_seconds helper to get the number of seconds in a timedelta
   * Use this helper in lots of places
 * Add write_file helper to write out a file. Just use this helper in these tests.
 * Rename deactivateTokens to deactivateInvalidTokens, split its implementation into something that figures out what the tokens are, and something that deactivates arbitrary tokens
 * Rename getNewTokensSinceLastRun to getNewTokens
 * Change the 'getNew*' methods in generate_ppa_htaccess to take a 'since' time
 * Change both 'getNew*' methods to use the same damn since time
 * Calculate the correct since time once, and test that directly, deleting other indirect tests
 * Use matchers and helpers in the tests where possible
 * General test cleanup
 * Lots of instrumentation

Adds 31 lines of code.

[Jelmer Vernooij (jelmer)]

review: Approve (code)

[Jonathan Lange (jml)]

FWIW, the tests and set up methods for test_generate_ppa_htaccess ought to be broken up into little pieces.

[j.c.sackett (jcsackett)]

Jonathan--

This looks good. I have two quibbles about comments in the code below, but that's all.

> === modified file 'lib/lp/services/tests/test_utils.py'
> --- lib/lp/services/tests/test_utils.py 2011-12-19 23:38:16 +0000
> +++ lib/lp/services/tests/test_utils.py 2012-05-31 12:14:21 +0000
> @@ -384,3 +388,14 @@
> """Values are obfuscated recursively."""
> obfuscated = obfuscate_structure({'foo': (['<email address hidden>'],)})
> self.assertEqual({'foo': [['<email address hidden>']]}, obfuscated)
> +
> +
> +class TestTotalSeconds(TestCase):
> +
> + # Remove this when Python 2.6 support is dropped. Replace calls with
> + # timedelta.total_seconds.
> +
> + def test_total_seconds(self):
> + # Numbers are arbitrary.
> + duration = timedelta(days=3, seconds=45, microseconds=16)
> + self.assertEqual(3 * 24 * 3600 + 45.000016, total_seconds(duration))

Could you make the comment in this test an XXX comment? It marginally
increases the chances other people will notice this and kill it appropriately.

> === modified file 'lib/lp/services/utils.py'
> --- lib/lp/services/utils.py 2012-05-24 20:25:54 +0000
> +++ lib/lp/services/utils.py 2012-05-31 12:14:21 +0000
> @@ -26,6 +26,7 @@
> 'save_bz2_pickle',
> 'synchronize',
> 'text_delta',
> + 'total_seconds',
> 'traceback_info',
> 'utc_now',
> 'value_string',
> @@ -383,3 +384,15 @@
> for key, value in o.iteritems())
> else:
> return o
> +
> +
> +def total_seconds(duration):
> + """The number of total seconds in a timedelta.
> +
> + In Python 2.7, spell this as duration.total_seconds(). Only needed for
> + Python 2.6 or earlier.
> + """
> + return (
> + (duration.microseconds +
> + (duration.seconds + duration.days * 24 * 3600) * 1e6)
> + / 1e6)

This should probably have a similar XXX comment.

I believe I mentioned the LoC tool in IRC; as you mentioned, this is part of a broader arc of work--if that's going to end up reducing LoC, fantastic. If not, you still have that credit I mentioned, so either way this should be fine as regards our LoC limits.

Thanks!

review: Approve

=== modified file 'database/schema/upgrade.py'
--- database/schema/upgrade.py	2012-01-04 13:07:46 +0000
+++ database/schema/upgrade.py	2012-06-06 13:49:20 +0000
@@ -33,6 +33,7 @@
     logger,
     logger_options,
     )
+from lp.services.utils import total_seconds
 import replication.helpers
 
 
@@ -112,11 +113,6 @@
     """)
 
 
-def to_seconds(td):
-    """Convert a timedelta to seconds."""
-    return td.days * (24 * 60 * 60) + td.seconds + td.microseconds / 1000000.0
-
-
 def report_patch_times(con, todays_patches):
     """Report how long it took to apply the given patches."""
     cur = con.cursor()
@@ -135,7 +131,7 @@
     for major, minor, patch, start_time, db_time in cur.fetchall():
         if (major, minor, patch) in todays_patches:
             continue
-        db_time = to_seconds(db_time)
+        db_time = total_seconds(db_time)
         start_time = start_time.strftime('%Y-%m-%d')
         log.info(
             "%d-%02d-%d applied %s in %0.1f seconds"
@@ -157,7 +153,7 @@
             continue
         log.info(
             "%d-%02d-%d applied just now in %0.1f seconds",
-            major, minor, patch, to_seconds(db_time))
+            major, minor, patch, total_seconds(db_time))
 
 
 def apply_patches_normal(con):

=== modified file 'lib/lp/app/browser/tales.py'
--- lib/lp/app/browser/tales.py	2012-06-05 00:42:31 +0000
+++ lib/lp/app/browser/tales.py	2012-06-06 13:49:20 +0000
@@ -71,6 +71,7 @@
 from lp.registry.interfaces.person import IPerson
 from lp.registry.interfaces.product import IProduct
 from lp.registry.interfaces.projectgroup import IProjectGroup
+from lp.services.utils import total_seconds
 from lp.services.webapp import (
     canonical_url,
     urlappend,
@@ -2307,11 +2308,7 @@
         # a useful name. It's also unlikely that these numbers will be
         # changed.
 
-        # Calculate the total number of seconds in the duration,
-        # including the decimal part.
-        seconds = self._duration.days * (3600 * 24)
-        seconds += self._duration.seconds
-        seconds += (float(self._duration.microseconds) / 10 ** 6)
+        seconds = total_seconds(self._duration)
 
         # First we'll try to calculate an approximate number of
         # seconds up to a minute. We'll start by defining a sorted
@@ -2410,10 +2407,7 @@
         return "%d weeks" % weeks
 
     def millisecondduration(self):
-        return str(
-            (self._duration.days * 24 * 3600
-             + self._duration.seconds * 1000
-             + self._duration.microseconds // 1000)) + 'ms'
+        return '%sms' % (total_seconds(self._duration) * 1000,)
 
 
 class LinkFormatterAPI(ObjectFormatterAPI):

=== modified file 'lib/lp/archivepublisher/scripts/generate_ppa_htaccess.py'
--- lib/lp/archivepublisher/scripts/generate_ppa_htaccess.py	2012-05-30 17:05:21 +0000
+++ lib/lp/archivepublisher/scripts/generate_ppa_htaccess.py	2012-06-06 13:49:20 +0000
@@ -14,7 +14,6 @@
 import tempfile
 
 import pytz
-from zope.component import getUtility
 
 from lp.archivepublisher.config import getPubConfig
 from lp.archivepublisher.htaccess import (
@@ -32,7 +31,7 @@
     simple_sendmail,
     )
 from lp.services.scripts.base import LaunchpadCronScript
-from lp.services.scripts.interfaces.scriptactivity import IScriptActivitySet
+from lp.services.utils import total_seconds
 from lp.services.webapp import canonical_url
 from lp.soyuz.enums import (
     ArchiveStatus,
@@ -159,16 +158,12 @@
 
         simple_sendmail(from_address, to_address, subject, body, headers)
 
-    def deactivateTokens(self, send_email=False):
-        """Deactivate tokens as necessary.
-
-        If a subscriber no longer has an active token for the PPA, we
-        deactivate it.
-
-        :param send_email: Whether to send a cancellation email to the owner
-            of the token.  This defaults to False to speed up the test
-            suite.
-        :return: the set of ppas affected by token deactivations.
+    def _getInvalidTokens(self):
+        """Return all invalid tokens.
+
+        A token is invalid if it is active and the token owner is *not* a
+        subscriber to the archive that the token is for. The subscription can
+        be either direct or through a team.
         """
         # First we grab all the active tokens for which there is a
         # matching current archive subscription for a team of which the
@@ -187,19 +182,44 @@
         all_active_tokens = store.find(
             ArchiveAuthToken,
             ArchiveAuthToken.date_deactivated == None)
-        invalid_tokens = all_active_tokens.difference(valid_tokens)
-
-        # We note the ppas affected by these token deactivations so that
-        # we can later update their htpasswd files.
+
+        return all_active_tokens.difference(valid_tokens)
+
+    def deactivateTokens(self, tokens, send_email=False):
+        """Deactivate the given tokens.
+
+        :return: A set of PPAs affected by the deactivations.
+        """
         affected_ppas = set()
-        for token in invalid_tokens:
+        num_tokens = 0
+        for token in tokens:
             if send_email:
                 self.sendCancellationEmail(token)
+            # Deactivate tokens one at a time, as 'tokens' is the result of a
+            # set expression and storm does not allow setting on such things.
             token.deactivate()
             affected_ppas.add(token.archive)
-
+            num_tokens += 1
+        self.logger.debug(
+            "Deactivated %s tokens, %s PPAs affected"
+            % (num_tokens, len(affected_ppas)))
         return affected_ppas
 
+    def deactivateInvalidTokens(self, send_email=False):
+        """Deactivate tokens as necessary.
+
+        If an active token for a PPA no longer has any subscribers,
+        we deactivate the token.
+
+        :param send_email: Whether to send a cancellation email to the owner
+            of the token.  This defaults to False to speed up the test
+            suite.
+        :return: the set of ppas affected by token deactivations so that we
+            can later update their htpasswd files.
+        """
+        invalid_tokens = self._getInvalidTokens()
+        return self.deactivateTokens(invalid_tokens, send_email=send_email)
+
     def expireSubscriptions(self):
         """Expire subscriptions as necessary.
 
@@ -223,44 +243,40 @@
             self.logger.info(
                 "Expired subscriptions: %s" % ", ".join(subscription_names))
 
-    def getNewTokensSinceLastRun(self):
-        """Return result set of new tokens created since the last run."""
+    def getTimeToSyncFrom(self):
+        """Return the time we'll synchronize from.
+
+        Any new PPAs or tokens created since this time will be used to
+        generate passwords.
+        """
+        # NTP is running on our servers and therefore we can assume
+        # only minimal skew, we include a fudge-factor of 1s so that
+        # even the minimal skew cannot demonstrate bug 627608.
+        last_activity = self.get_last_activity()
+        if not last_activity:
+            return
+        return last_activity.date_started - timedelta(seconds=1)
+
+    def getNewTokens(self, since=None):
+        """Return result set of new tokens created since the given time."""
         store = IStore(ArchiveAuthToken)
-        # If we don't know when we last ran, we include all active
-        # tokens by default.
-        last_success = getUtility(IScriptActivitySet).getLastActivity(
-            'generate-ppa-htaccess')
         extra_expr = []
-        if last_success:
-            # NTP is running on our servers and therefore we can assume
-            # only minimal skew, we include a fudge-factor of 1s so that
-            # even the minimal skew cannot demonstrate bug 627608.
-            last_script_start_with_skew = last_success.date_started - (
-                timedelta(seconds=1))
-            extra_expr = [
-                ArchiveAuthToken.date_created >= last_script_start_with_skew]
-
+        if since:
+            extra_expr = [ArchiveAuthToken.date_created >= since]
         new_ppa_tokens = store.find(
             ArchiveAuthToken,
             ArchiveAuthToken.date_deactivated == None,
             *extra_expr)
-
         return new_ppa_tokens
 
-    def getNewPrivatePPAs(self):
+    def getNewPrivatePPAs(self, since=None):
         """Return the recently created private PPAs."""
         # Avoid circular import.
         from lp.soyuz.model.archive import Archive
         store = IStore(Archive)
-        # If we don't know when we last ran, we include all active
-        # tokens by default.
-        last_success = getUtility(IScriptActivitySet).getLastActivity(
-            'generate-ppa-htaccess')
         extra_expr = []
-        if last_success:
-            extra_expr = [
-                Archive.date_created >= last_success.date_completed]
-
+        if since:
+            extra_expr = [Archive.date_created >= since]
         return store.find(
             Archive, Archive._private == True, *extra_expr)
 
@@ -268,16 +284,34 @@
         """Script entry point."""
         self.logger.info('Starting the PPA .htaccess generation')
         self.expireSubscriptions()
-        affected_ppas = self.deactivateTokens(send_email=True)
+        affected_ppas = self.deactivateInvalidTokens(send_email=True)
+        current_ppa_count = len(affected_ppas)
+        self.logger.debug(
+            '%s PPAs with deactivated tokens' % current_ppa_count)
+
+        last_success = self.getTimeToSyncFrom()
 
         # In addition to the ppas that are affected by deactivated
         # tokens, we also want to include any ppas that have tokens
         # created since the last time we ran.
-        for token in self.getNewTokensSinceLastRun():
+        num_tokens = 0
+        for token in self.getNewTokens(since=last_success):
             affected_ppas.add(token.archive)
-
-        affected_ppas.update(self.getNewPrivatePPAs())
-
+            num_tokens += 1
+
+        new_ppa_count = len(affected_ppas)
+        self.logger.debug(
+            "%s new tokens since last run, %s PPAs affected"
+            % (num_tokens, new_ppa_count - current_ppa_count))
+        current_ppa_count = new_ppa_count
+
+        affected_ppas.update(self.getNewPrivatePPAs(since=last_success))
+        new_ppa_count = len(affected_ppas)
+        self.logger.debug(
+            "%s new private PPAs since last run"
+            % (new_ppa_count - current_ppa_count))
+
+        self.logger.debug('%s PPAs require updating' % new_ppa_count)
         for ppa in affected_ppas:
             # If this PPA is blacklisted, do not touch it's htaccess/pwd
             # files.
@@ -285,23 +319,27 @@
                 ppa.owner.name, [])
             if ppa.name in blacklisted_ppa_names_for_owner:
                 self.logger.info(
-                    "Skipping htacess updates for blacklisted PPA "
+                    "Skipping htaccess updates for blacklisted PPA "
                     " '%s' owned by %s.",
                         ppa.name,
                         ppa.owner.displayname)
                 continue
             elif ppa.status == ArchiveStatus.DELETED or ppa.enabled is False:
                 self.logger.info(
-                    "Skipping htacess updates for deleted or disabled PPA "
+                    "Skipping htaccess updates for deleted or disabled PPA "
                     " '%s' owned by %s.",
                         ppa.name,
                         ppa.owner.displayname)
                 continue
 
             self.ensureHtaccess(ppa)
+            htpasswd_write_start = datetime.now()
             temp_htpasswd = self.generateHtpasswd(ppa)
-            if not self.replaceUpdatedHtpasswd(ppa, temp_htpasswd):
-                os.remove(temp_htpasswd)
+            self.replaceUpdatedHtpasswd(ppa, temp_htpasswd)
+            htpasswd_write_duration = datetime.now() - htpasswd_write_start
+            self.logger.debug(
+                "Wrote htpasswd for '%s': %ss"
+                % (ppa.name, total_seconds(htpasswd_write_duration)))
 
         if self.options.no_deactivation or self.options.dryrun:
             self.logger.info('Dry run, so not committing transaction.')

=== modified file 'lib/lp/archivepublisher/tests/test_generate_ppa_htaccess.py'
--- lib/lp/archivepublisher/tests/test_generate_ppa_htaccess.py	2012-05-30 17:05:21 +0000
+++ lib/lp/archivepublisher/tests/test_generate_ppa_htaccess.py	2012-06-06 13:49:20 +0000
@@ -14,6 +14,12 @@
 import tempfile
 
 import pytz
+from testtools.matchers import (
+    AllMatch,
+    FileContains,
+    FileExists,
+    Not,
+    )
 import transaction
 from zope.component import getUtility
 from zope.security.proxy import removeSecurityProxy
@@ -29,6 +35,11 @@
 from lp.services.log.logger import BufferLogger
 from lp.services.mail import stub
 from lp.services.scripts.interfaces.scriptactivity import IScriptActivitySet
+from lp.services.osutils import (
+    ensure_directory_exists,
+    remove_if_exists,
+    write_file,
+    )
 from lp.soyuz.enums import (
     ArchiveStatus,
     ArchiveSubscriberStatus,
@@ -48,6 +59,8 @@
     layer = LaunchpadZopelessLayer
     dbuser = config.generateppahtaccess.dbuser
 
+    SCRIPT_NAME = 'test tokens'
+
     def setUp(self):
         super(TestPPAHtaccessTokenGeneration, self).setUp()
         self.owner = self.factory.makePerson(
@@ -64,7 +77,7 @@
         """Return a HtaccessTokenGenerator instance."""
         if test_args is None:
             test_args = []
-        script = HtaccessTokenGenerator("test tokens", test_args=test_args)
+        script = HtaccessTokenGenerator(self.SCRIPT_NAME, test_args=test_args)
         script.logger = BufferLogger()
         script.txn = self.layer.txn
         switch_dbuser(self.dbuser)
@@ -90,13 +103,10 @@
         pub_config = getPubConfig(self.ppa)
 
         filename = os.path.join(pub_config.htaccessroot, ".htaccess")
-        if os.path.isfile(filename):
-            os.remove(filename)
+        remove_if_exists(filename)
         script = self.getScript()
         script.ensureHtaccess(self.ppa)
-        self.assertTrue(
-            os.path.isfile(filename),
-            "%s is not present when it should be" % filename)
+        self.addCleanup(remove_if_exists, filename)
 
         contents = [
             "",
@@ -104,29 +114,24 @@
             "AuthName           \"Token Required\"",
             "AuthUserFile       %s/.htpasswd" % pub_config.htaccessroot,
             "Require            valid-user",
+            "",
             ]
-
-        file = open(filename, "r")
-        file_contents = file.read().splitlines()
-        file.close()
-        os.remove(filename)
-
-        self.assertEqual(contents, file_contents)
+        self.assertThat(filename, FileContains('\n'.join(contents)))
 
     def testGenerateHtpasswd(self):
         """Given some `ArchiveAuthToken`s, test generating htpasswd."""
         # Make some subscriptions and tokens.
-        name12 = getUtility(IPersonSet).getByName("name12")
-        name16 = getUtility(IPersonSet).getByName("name16")
-        self.ppa.newSubscription(name12, self.ppa.owner)
-        self.ppa.newSubscription(name16, self.ppa.owner)
         tokens = []
-        tokens.append(self.ppa.newAuthToken(name12))
-        tokens.append(self.ppa.newAuthToken(name16))
+        for name in ['name12', 'name16']:
+            person = getUtility(IPersonSet).getByName(name)
+            self.ppa.newSubscription(person, self.ppa.owner)
+            tokens.append(self.ppa.newAuthToken(person))
+        token_usernames = [token.person.name for token in tokens]
 
         # Generate the passwd file.
         script = self.getScript()
         filename = script.generateHtpasswd(self.ppa)
+        self.addCleanup(remove_if_exists, filename)
 
         # It should be a temp file in the same directory as the intended
         # target file when it's renamed, so that os.rename() won't
@@ -136,32 +141,19 @@
             pub_config.htaccessroot, os.path.dirname(filename))
 
         # Read it back in.
-        file = open(filename, "r")
-        file_contents = file.read().splitlines()
-
-        # The first line should be the buildd_secret.
-        [user, password] = file_contents[0].split(":", 1)
-        self.assertEqual(user, "buildd")
+        file_contents = [
+            line.strip().split(':', 1) for line in open(filename, 'r')]
+
+        # First entry is buildd secret, rest are from tokens.
+        usernames = list(zip(*file_contents)[0])
+        self.assertEqual(['buildd'] + token_usernames, usernames)
+
         # We can re-encrypt the buildd_secret and it should match the
         # one in the .htpasswd file.
+        password = file_contents[0][1]
         encrypted_secret = crypt.crypt(self.ppa.buildd_secret, password)
         self.assertEqual(encrypted_secret, password)
 
-        # Finally, there should be two more lines in the file, one for
-        # each of the tokens generated above.
-        self.assertEqual(len(file_contents), 3)
-        [user1, password1] = file_contents[1].split(":", 1)
-        [user2, password2] = file_contents[2].split(":", 1)
-        self.assertEqual(user1, "name12")
-        self.assertEqual(user2, "name16")
-
-        # For the names to appear in the order above, the dabatase IDs
-        # for the tokens have to be in that order.  (To ensure a
-        # consistent ordering)
-        self.assertTrue(tokens[0].id < tokens[1].id)
-
-        os.remove(filename)
-
     def testReplaceUpdatedHtpasswd(self):
         """Test that the htpasswd file is only replaced if it changes."""
         FILE_CONTENT = "Kneel before Zod!"
@@ -171,11 +163,8 @@
         filename = os.path.join(pub_config.htaccessroot, ".htpasswd")
 
         # Write out a dummy .htpasswd
-        if not os.path.exists(pub_config.htaccessroot):
-            os.makedirs(pub_config.htaccessroot)
-        file = open(filename, "w")
-        file.write(FILE_CONTENT)
-        file.close()
+        ensure_directory_exists(pub_config.htaccessroot)
+        write_file(filename, FILE_CONTENT)
 
         # Write the same contents in a temp file.
         fd, temp_filename = tempfile.mkstemp(dir=pub_config.htaccessroot)
@@ -189,9 +178,7 @@
             script.replaceUpdatedHtpasswd(self.ppa, temp_filename))
 
         # Writing a different .htpasswd should see it get replaced.
-        file = open(filename, "w")
-        file.write("Come to me, son of Jor-El!")
-        file.close()
+        write_file(filename, "Come to me, son of Jor-El!")
 
         self.assertTrue(
             script.replaceUpdatedHtpasswd(self.ppa, temp_filename))
@@ -269,7 +256,7 @@
 
         # Initially, nothing is eligible for deactivation.
         script = self.getScript()
-        script.deactivateTokens()
+        script.deactivateInvalidTokens()
         for person in tokens:
             self.assertNotDeactivated(tokens[person])
 
@@ -280,7 +267,7 @@
         # Clear out emails generated when leaving a team.
         pop_notifications()
 
-        script.deactivateTokens(send_email=True)
+        script.deactivateInvalidTokens(send_email=True)
         self.assertDeactivated(tokens[team1_person])
         del tokens[team1_person]
         for person in tokens:
@@ -298,7 +285,7 @@
             promiscuous_person.leave(team1)
         # Clear out emails generated when leaving a team.
         pop_notifications()
-        script.deactivateTokens(send_email=True)
+        script.deactivateInvalidTokens(send_email=True)
         self.assertNotDeactivated(tokens[promiscuous_person])
         for person in tokens:
             self.assertNotDeactivated(tokens[person])
@@ -317,7 +304,7 @@
             parent_team.setMembershipData(
                 team2, TeamMembershipStatus.DEACTIVATED, name12)
             self.assertFalse(team2.inTeam(parent_team))
-        script.deactivateTokens()
+        script.deactivateInvalidTokens()
         for person in persons2:
             self.assertDeactivated(tokens[person])
 
@@ -348,10 +335,8 @@
         pub_config = getPubConfig(self.ppa)
         htaccess = os.path.join(pub_config.htaccessroot, ".htaccess")
         htpasswd = os.path.join(pub_config.htaccessroot, ".htpasswd")
-        if os.path.isfile(htaccess):
-            os.remove(htaccess)
-        if os.path.isfile(htpasswd):
-            os.remove(htpasswd)
+        remove_if_exists(htaccess)
+        remove_if_exists(htpasswd)
         return htaccess, htpasswd
 
     def testSubscriptionExpiry(self):
@@ -384,8 +369,7 @@
         self.assertEqual(
             return_code, 0, "Got a bad return code of %s\nOutput:\n%s" %
                 (return_code, stderr))
-        self.assertTrue(os.path.isfile(htaccess))
-        self.assertTrue(os.path.isfile(htpasswd))
+        self.assertThat([htaccess, htpasswd], AllMatch(FileExists()))
         os.remove(htaccess)
         os.remove(htpasswd)
 
@@ -407,8 +391,7 @@
         script.main()
 
         # Assert no files were written.
-        self.assertFalse(os.path.isfile(htaccess))
-        self.assertFalse(os.path.isfile(htpasswd))
+        self.assertThat([htaccess, htpasswd], AllMatch(Not(FileExists())))
 
         # Assert that the cancelled subscription did not cause the token
         # to get deactivated.
@@ -441,10 +424,8 @@
         # The tokens will still be deactivated, and subscriptions expired.
         self.assertDeactivated(tokens[0])
         self.assertEqual(subs[0].status, ArchiveSubscriberStatus.EXPIRED)
-
         # But the htaccess is not touched.
-        self.assertFalse(os.path.isfile(htaccess))
-        self.assertFalse(os.path.isfile(htpasswd))
+        self.assertThat([htaccess, htpasswd], AllMatch(Not(FileExists())))
 
     def testSkippingOfDisabledPPAs(self):
         """Test that the htaccess for disabled PPAs are not touched."""
@@ -464,8 +445,7 @@
         script.main()
 
         # The htaccess and htpasswd files should not be generated.
-        self.assertFalse(os.path.isfile(htaccess))
-        self.assertFalse(os.path.isfile(htpasswd))
+        self.assertThat([htaccess, htpasswd], AllMatch(Not(FileExists())))
 
     def testSkippingOfDeletedPPAs(self):
         """Test that the htaccess for deleted PPAs are not touched."""
@@ -484,8 +464,7 @@
         script.main()
 
         # The htaccess and htpasswd files should not be generated.
-        self.assertFalse(os.path.isfile(htaccess))
-        self.assertFalse(os.path.isfile(htpasswd))
+        self.assertThat([htaccess, htpasswd], AllMatch(Not(FileExists())))
 
     def testSendingCancellationEmail(self):
         """Test that when a token is deactivated, its user gets an email.
@@ -555,6 +534,20 @@
         self.assertEqual(
             num_emails, 0, "Expected 0 emails, got %s" % num_emails)
 
+    def test_getTimeToSyncFrom(self):
+        # Sync from 1s before previous start to catch anything made during the
+        # last script run, and to handle NTP clock skew.
+        now = datetime.now(pytz.UTC)
+        script_start_time = now - timedelta(seconds=2)
+        script_end_time = now
+
+        getUtility(IScriptActivitySet).recordSuccess(
+            self.SCRIPT_NAME, script_start_time, script_end_time)
+        script = self.getScript()
+        self.assertEqual(
+            script_start_time - timedelta(seconds=1),
+            script.getTimeToSyncFrom())
+
     def test_getNewPrivatePPAs_no_previous_run(self):
         # All private PPAs are returned if there was no previous run.
         # This happens even if they have no tokens.
@@ -568,93 +561,51 @@
     def test_getNewPrivatePPAs_only_those_since_last_run(self):
         # Only private PPAs created since the last run are returned.
         # This happens even if they have no tokens.
-
-        now = datetime.now(pytz.UTC)
-        getUtility(IScriptActivitySet).recordSuccess(
-            'generate-ppa-htaccess', now, now - timedelta(minutes=3))
-        removeSecurityProxy(self.ppa).date_created = (
-            now - timedelta(minutes=4))
+        last_start = datetime.now(pytz.UTC) - timedelta(seconds=90)
+        before_last_start = last_start - timedelta(seconds=30)
+        removeSecurityProxy(self.ppa).date_created = before_last_start
 
         # Create a new PPA that should show up.
         new_ppa = self.factory.makeArchive(private=True)
 
         script = self.getScript()
-        self.assertContentEqual([new_ppa], script.getNewPrivatePPAs())
+        new_ppas = script.getNewPrivatePPAs(since=last_start)
+        self.assertContentEqual([new_ppa], new_ppas)
 
-    def test_getNewTokensSinceLastRun_no_previous_run(self):
+    def test_getNewTokens_no_previous_run(self):
         """All valid tokens returned if there is no record of previous run."""
         tokens = self.setupDummyTokens()[1]
 
         # If there is no record of the script running previously, all
         # valid tokens are returned.
         script = self.getScript()
-        self.assertContentEqual(tokens, script.getNewTokensSinceLastRun())
+        self.assertContentEqual(tokens, script.getNewTokens())
 
-    def test_getNewTokensSinceLastRun_only_those_since_last_run(self):
+    def test_getNewTokens_only_those_since_last_run(self):
         """Only tokens created since the last run are returned."""
-        now = datetime.now(pytz.UTC)
-        script_start_time = now - timedelta(seconds=2)
-        script_end_time = now
-        before_previous_start = script_start_time - timedelta(seconds=30)
+        last_start = datetime.now(pytz.UTC) - timedelta(seconds=90)
+        before_last_start = last_start - timedelta(seconds=30)
 
-        getUtility(IScriptActivitySet).recordSuccess(
-            'generate-ppa-htaccess', date_started=script_start_time,
-            date_completed=script_end_time)
         tokens = self.setupDummyTokens()[1]
         # This token will not be included.
-        removeSecurityProxy(tokens[0]).date_created = before_previous_start
-
-        script = self.getScript()
-        self.assertContentEqual(tokens[1:], script.getNewTokensSinceLastRun())
-
-    def test_getNewTokensSinceLastRun_includes_tokens_during_last_run(self):
-        """Tokens created during the last ppa run will be included."""
-        now = datetime.now(pytz.UTC)
-        script_start_time = now - timedelta(seconds=2)
-        script_end_time = now
-        in_between = now - timedelta(seconds=1)
-
-        getUtility(IScriptActivitySet).recordSuccess(
-            'generate-ppa-htaccess', script_start_time, script_end_time)
-        tokens = self.setupDummyTokens()[1]
-        # This token will be included because it's been created during
-        # the previous script run.
-        removeSecurityProxy(tokens[0]).date_created = in_between
-
-        script = self.getScript()
-        self.assertContentEqual(tokens, script.getNewTokensSinceLastRun())
-
-    def test_getNewTokensSinceLastRun_handles_ntp_skew(self):
-        """An ntp-skew of up to one second will not affect the results."""
-        now = datetime.now(pytz.UTC)
-        script_start_time = now - timedelta(seconds=2)
-        script_end_time = now
-        earliest_with_ntp_skew = script_start_time - timedelta(
-            milliseconds=500)
-
-        tokens = self.setupDummyTokens()[1]
-        getUtility(IScriptActivitySet).recordSuccess(
-            'generate-ppa-htaccess', date_started=script_start_time,
-            date_completed=script_end_time)
-        # This token will still be included in the results.
-        removeSecurityProxy(tokens[0]).date_created = earliest_with_ntp_skew
-
-        script = self.getScript()
-        self.assertContentEqual(tokens, script.getNewTokensSinceLastRun())
-
-    def test_getNewTokensSinceLastRun_only_active_tokens(self):
+        removeSecurityProxy(tokens[0]).date_created = before_last_start
+
+        script = self.getScript()
+        new_tokens = script.getNewTokens(since=last_start)
+        self.assertContentEqual(tokens[1:], new_tokens)
+
+    def test_getNewTokens_only_active_tokens(self):
         """Only active tokens are returned."""
         tokens = self.setupDummyTokens()[1]
         tokens[0].deactivate()
 
         script = self.getScript()
-        self.assertContentEqual(tokens[1:], script.getNewTokensSinceLastRun())
+        self.assertContentEqual(tokens[1:], script.getNewTokens())
 
     def test_processes_PPAs_without_subscription(self):
         # A .htaccess file is written for Private PPAs even if they don't have
         # any subscriptions.
         htaccess, htpasswd = self.ensureNoFiles()
-
         transaction.commit()
 
         # Call the script and check that we have a .htaccess and a
@@ -663,7 +614,6 @@
         self.assertEqual(
             return_code, 0, "Got a bad return code of %s\nOutput:\n%s" %
                 (return_code, stderr))
-        self.assertTrue(os.path.isfile(htaccess))
-        self.assertTrue(os.path.isfile(htpasswd))
+        self.assertThat([htaccess, htpasswd], AllMatch(FileExists()))
         os.remove(htaccess)
         os.remove(htpasswd)

=== modified file 'lib/lp/bugs/doc/sourceforge-remote-products.txt'
--- lib/lp/bugs/doc/sourceforge-remote-products.txt	2011-12-28 17:03:06 +0000
+++ lib/lp/bugs/doc/sourceforge-remote-products.txt	2012-06-06 13:49:20 +0000
@@ -122,4 +122,5 @@
     DEBUG   ...
     INFO    No Products to update.
     INFO    Time for this run: ... seconds.
+    DEBUG   updateremoteproduct ran in ...s (excl. load & lock)
     DEBUG   Removing lock file:...

=== modified file 'lib/lp/registry/doc/teammembership.txt'
--- lib/lp/registry/doc/teammembership.txt	2012-04-10 14:01:17 +0000
+++ lib/lp/registry/doc/teammembership.txt	2012-06-06 13:49:20 +0000
@@ -697,6 +697,7 @@
     DEBUG   ...
     DEBUG   Sent warning email to name16 in launchpad-buildd-admins team.
     DEBUG   Sent warning email to name12 in landscape-developers team.
+    DEBUG   flag-expired-memberships ran in ...s (excl. load & lock)
     DEBUG   Removing lock file: ...launchpad-flag-expired-memberships.lock
     >>> process.returncode
     0

=== modified file 'lib/lp/services/looptuner.py'
--- lib/lp/services/looptuner.py	2012-01-06 11:50:43 +0000
+++ lib/lp/services/looptuner.py	2012-06-06 13:49:20 +0000
@@ -258,10 +258,6 @@
             time.sleep(seconds)
 
 
-def timedelta_to_seconds(td):
-    return 24 * 60 * td.days + td.seconds
-
-
 class DBLoopTuner(LoopTuner):
     """A LoopTuner that plays well with PostgreSQL and replication.
 

=== modified file 'lib/lp/services/osutils.py'
--- lib/lp/services/osutils.py	2011-06-24 11:10:43 +0000
+++ lib/lp/services/osutils.py	2012-06-06 13:49:20 +0000
@@ -204,3 +204,9 @@
     except OSError, e:
         if e.errno != errno.ENOENT:
             raise
+
+
+def write_file(path, content):
+    f = open(path, 'w')
+    f.write(content)
+    f.close()

=== modified file 'lib/lp/services/scripts/base.py'
--- lib/lp/services/scripts/base.py	2012-01-06 11:08:30 +0000
+++ lib/lp/services/scripts/base.py	2012-06-06 13:49:20 +0000
@@ -47,6 +47,7 @@
 from lp.services.mail.sendmail import set_immediate_mail_delivery
 from lp.services.scripts.interfaces.scriptactivity import IScriptActivitySet
 from lp.services.scripts.logger import OopsHandler
+from lp.services.utils import total_seconds
 from lp.services.webapp.errorlog import globalErrorUtility
 from lp.services.webapp.interaction import (
     ANONYMOUS,
@@ -414,6 +415,10 @@
         # overriding the name property.
         logging.getLogger().addHandler(OopsHandler(self.name))
 
+    def get_last_activity(self):
+        """Return the last activity, if any."""
+        return getUtility(IScriptActivitySet).getLastActivity(self.name)
+
     @log_unhandled_exception_and_exit
     def record_activity(self, date_started, date_completed):
         """Record the successful completion of the script."""
@@ -424,6 +429,12 @@
             date_started=date_started,
             date_completed=date_completed)
         self.txn.commit()
+        # date_started is recorded *after* the lock is acquired and we've
+        # initialized Zope components and the database.  Thus this time is
+        # only for the script proper, rather than total execution time.
+        seconds_taken = total_seconds(date_completed - date_started)
+        self.logger.debug(
+            "%s ran in %ss (excl. load & lock)" % (self.name, seconds_taken))
 
 
 @contextmanager

=== modified file 'lib/lp/services/tests/test_osutils.py'
--- lib/lp/services/tests/test_osutils.py	2011-08-12 11:37:08 +0000
+++ lib/lp/services/tests/test_osutils.py	2012-06-06 13:49:20 +0000
@@ -10,11 +10,14 @@
 import socket
 import tempfile
 
+from testtools.matchers import FileContains
+
 from lp.services.osutils import (
     ensure_directory_exists,
     open_for_writing,
     remove_tree,
     until_no_eintr,
+    write_file,
     )
 from lp.testing import TestCase
 
@@ -95,6 +98,16 @@
         self.assertEqual("Hello world!\n", open(filename).read())
 
 
+class TestWriteFile(TestCase):
+
+    def test_write_file(self):
+        directory = self.makeTemporaryDirectory()
+        filename = os.path.join(directory, 'filename')
+        content = self.getUniqueString()
+        write_file(filename, content)
+        self.assertThat(filename, FileContains(content))
+
+
 class TestUntilNoEINTR(TestCase):
     """Tests for until_no_eintr."""
 

=== modified file 'lib/lp/services/tests/test_utils.py'
--- lib/lp/services/tests/test_utils.py	2011-12-19 23:38:16 +0000
+++ lib/lp/services/tests/test_utils.py	2012-06-06 13:49:20 +0000
@@ -6,7 +6,10 @@
 __metaclass__ = type
 
 from contextlib import contextmanager
-from datetime import datetime
+from datetime import (
+    datetime,
+    timedelta,
+    )
 import hashlib
 import itertools
 import os
@@ -34,6 +37,7 @@
     obfuscate_structure,
     run_capturing_output,
     save_bz2_pickle,
+    total_seconds,
     traceback_info,
     utc_now,
     )
@@ -384,3 +388,14 @@
         """Values are obfuscated recursively."""
         obfuscated = obfuscate_structure({'foo': (['[e-mail]'],)})
         self.assertEqual({'foo': [['<email address hidden>']]}, obfuscated)
+
+
+class TestTotalSeconds(TestCase):
+
+    # XXX: JonathanLange 2012-05-31: Remove this when Python 2.6 support is
+    # dropped.  Replace calls with timedelta.total_seconds.
+
+    def test_total_seconds(self):
+        # Numbers are arbitrary.
+        duration = timedelta(days=3, seconds=45, microseconds=16)
+        self.assertEqual(3 * 24 * 3600 + 45.000016, total_seconds(duration))

=== modified file 'lib/lp/services/utils.py'
--- lib/lp/services/utils.py	2012-05-24 20:25:54 +0000
+++ lib/lp/services/utils.py	2012-06-06 13:49:20 +0000
@@ -26,6 +26,7 @@
     'save_bz2_pickle',
     'synchronize',
     'text_delta',
+    'total_seconds',
     'traceback_info',
     'utc_now',
     'value_string',
@@ -383,3 +384,14 @@
             for key, value in o.iteritems())
     else:
         return o
+
+
+def total_seconds(duration):
+    """The number of total seconds in a timedelta.
+    """
+    # XXX: JonathanLange 2012-05-12: In Python 2.7, spell this as
+    # duration.total_seconds().  Only needed for Python 2.6 or earlier.
+    return (
+        (duration.microseconds +
+         (duration.seconds + duration.days * 24 * 3600) * 1e6)
+        / 1e6)

=== modified file 'lib/lp/translations/doc/poexport-request.txt'
--- lib/lp/translations/doc/poexport-request.txt	2011-12-23 23:44:59 +0000
+++ lib/lp/translations/doc/poexport-request.txt	2012-06-06 13:49:20 +0000
@@ -263,6 +263,7 @@
     DEBUG   Exporting objects for Happy Downloader, related to template
     alsa-utils in alsa-utils trunk
     INFO    Stored file at http://.../launchpad-export.tar.gz
+    DEBUG   rosetta-export-queue ran in ...s (excl. load & lock)
     DEBUG   Removing lock file: /var/lock/launchpad-rosetta-export-queue.lock
     <BLANKLINE>