Launchpad itself

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

  1. generate-ppa-logging
  2. Merge into devel
Proposed by Jonathan Lange
Status: Merged
Approved by: j.c.sackett
Approved revision: no longer in the source branch.
Merged at revision: 15370
Proposed branch: lp:~jml/launchpad/generate-ppa-logging
Merge into: lp:launchpad
Diff against target: 921 lines (+236/-202)
13 files modified
database/schema/upgrade.py (+3/-7)
lib/lp/app/browser/tales.py (+3/-9)
lib/lp/archivepublisher/scripts/generate_ppa_htaccess.py (+90/-52)
lib/lp/archivepublisher/tests/test_generate_ppa_htaccess.py (+79/-129)
lib/lp/bugs/doc/sourceforge-remote-products.txt (+1/-0)
lib/lp/registry/doc/teammembership.txt (+1/-0)
lib/lp/services/looptuner.py (+0/-4)
lib/lp/services/osutils.py (+6/-0)
lib/lp/services/scripts/base.py (+11/-0)
lib/lp/services/tests/test_osutils.py (+13/-0)
lib/lp/services/tests/test_utils.py (+16/-1)
lib/lp/services/utils.py (+12/-0)
lib/lp/translations/doc/poexport-request.txt (+1/-0)
To merge this branch: bzr merge lp:~jml/launchpad/generate-ppa-logging
Reviewer Review Type Date Requested Status
j.c.sackett (community) Approve
Jelmer Vernooij (community) code Approve
Review via email: mp+108040@code.launchpad.net

Commit message

Instrument generate_ppa_htaccess.

Description of the change

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.

To post a comment you must log in.
Revision history for this message
Jelmer Vernooij (jelmer) :
review: Approve (code)
Revision history for this message
Jonathan Lange (jml) wrote :

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

Revision history for this message
j.c.sackett (jcsackett) wrote :

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

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'database/schema/upgrade.py'
2--- database/schema/upgrade.py 2012-01-04 13:07:46 +0000
3+++ database/schema/upgrade.py 2012-06-06 13:49:20 +0000
4@@ -33,6 +33,7 @@
5 logger,
6 logger_options,
7 )
8+from lp.services.utils import total_seconds
9 import replication.helpers
10
11
12@@ -112,11 +113,6 @@
13 """)
14
15
16-def to_seconds(td):
17- """Convert a timedelta to seconds."""
18- return td.days * (24 * 60 * 60) + td.seconds + td.microseconds / 1000000.0
19-
20-
21 def report_patch_times(con, todays_patches):
22 """Report how long it took to apply the given patches."""
23 cur = con.cursor()
24@@ -135,7 +131,7 @@
25 for major, minor, patch, start_time, db_time in cur.fetchall():
26 if (major, minor, patch) in todays_patches:
27 continue
28- db_time = to_seconds(db_time)
29+ db_time = total_seconds(db_time)
30 start_time = start_time.strftime('%Y-%m-%d')
31 log.info(
32 "%d-%02d-%d applied %s in %0.1f seconds"
33@@ -157,7 +153,7 @@
34 continue
35 log.info(
36 "%d-%02d-%d applied just now in %0.1f seconds",
37- major, minor, patch, to_seconds(db_time))
38+ major, minor, patch, total_seconds(db_time))
39
40
41 def apply_patches_normal(con):
42
43=== modified file 'lib/lp/app/browser/tales.py'
44--- lib/lp/app/browser/tales.py 2012-06-05 00:42:31 +0000
45+++ lib/lp/app/browser/tales.py 2012-06-06 13:49:20 +0000
46@@ -71,6 +71,7 @@
47 from lp.registry.interfaces.person import IPerson
48 from lp.registry.interfaces.product import IProduct
49 from lp.registry.interfaces.projectgroup import IProjectGroup
50+from lp.services.utils import total_seconds
51 from lp.services.webapp import (
52 canonical_url,
53 urlappend,
54@@ -2307,11 +2308,7 @@
55 # a useful name. It's also unlikely that these numbers will be
56 # changed.
57
58- # Calculate the total number of seconds in the duration,
59- # including the decimal part.
60- seconds = self._duration.days * (3600 * 24)
61- seconds += self._duration.seconds
62- seconds += (float(self._duration.microseconds) / 10 ** 6)
63+ seconds = total_seconds(self._duration)
64
65 # First we'll try to calculate an approximate number of
66 # seconds up to a minute. We'll start by defining a sorted
67@@ -2410,10 +2407,7 @@
68 return "%d weeks" % weeks
69
70 def millisecondduration(self):
71- return str(
72- (self._duration.days * 24 * 3600
73- + self._duration.seconds * 1000
74- + self._duration.microseconds // 1000)) + 'ms'
75+ return '%sms' % (total_seconds(self._duration) * 1000,)
76
77
78 class LinkFormatterAPI(ObjectFormatterAPI):
79
80=== modified file 'lib/lp/archivepublisher/scripts/generate_ppa_htaccess.py'
81--- lib/lp/archivepublisher/scripts/generate_ppa_htaccess.py 2012-05-30 17:05:21 +0000
82+++ lib/lp/archivepublisher/scripts/generate_ppa_htaccess.py 2012-06-06 13:49:20 +0000
83@@ -14,7 +14,6 @@
84 import tempfile
85
86 import pytz
87-from zope.component import getUtility
88
89 from lp.archivepublisher.config import getPubConfig
90 from lp.archivepublisher.htaccess import (
91@@ -32,7 +31,7 @@
92 simple_sendmail,
93 )
94 from lp.services.scripts.base import LaunchpadCronScript
95-from lp.services.scripts.interfaces.scriptactivity import IScriptActivitySet
96+from lp.services.utils import total_seconds
97 from lp.services.webapp import canonical_url
98 from lp.soyuz.enums import (
99 ArchiveStatus,
100@@ -159,16 +158,12 @@
101
102 simple_sendmail(from_address, to_address, subject, body, headers)
103
104- def deactivateTokens(self, send_email=False):
105- """Deactivate tokens as necessary.
106-
107- If a subscriber no longer has an active token for the PPA, we
108- deactivate it.
109-
110- :param send_email: Whether to send a cancellation email to the owner
111- of the token. This defaults to False to speed up the test
112- suite.
113- :return: the set of ppas affected by token deactivations.
114+ def _getInvalidTokens(self):
115+ """Return all invalid tokens.
116+
117+ A token is invalid if it is active and the token owner is *not* a
118+ subscriber to the archive that the token is for. The subscription can
119+ be either direct or through a team.
120 """
121 # First we grab all the active tokens for which there is a
122 # matching current archive subscription for a team of which the
123@@ -187,19 +182,44 @@
124 all_active_tokens = store.find(
125 ArchiveAuthToken,
126 ArchiveAuthToken.date_deactivated == None)
127- invalid_tokens = all_active_tokens.difference(valid_tokens)
128-
129- # We note the ppas affected by these token deactivations so that
130- # we can later update their htpasswd files.
131+
132+ return all_active_tokens.difference(valid_tokens)
133+
134+ def deactivateTokens(self, tokens, send_email=False):
135+ """Deactivate the given tokens.
136+
137+ :return: A set of PPAs affected by the deactivations.
138+ """
139 affected_ppas = set()
140- for token in invalid_tokens:
141+ num_tokens = 0
142+ for token in tokens:
143 if send_email:
144 self.sendCancellationEmail(token)
145+ # Deactivate tokens one at a time, as 'tokens' is the result of a
146+ # set expression and storm does not allow setting on such things.
147 token.deactivate()
148 affected_ppas.add(token.archive)
149-
150+ num_tokens += 1
151+ self.logger.debug(
152+ "Deactivated %s tokens, %s PPAs affected"
153+ % (num_tokens, len(affected_ppas)))
154 return affected_ppas
155
156+ def deactivateInvalidTokens(self, send_email=False):
157+ """Deactivate tokens as necessary.
158+
159+ If an active token for a PPA no longer has any subscribers,
160+ we deactivate the token.
161+
162+ :param send_email: Whether to send a cancellation email to the owner
163+ of the token. This defaults to False to speed up the test
164+ suite.
165+ :return: the set of ppas affected by token deactivations so that we
166+ can later update their htpasswd files.
167+ """
168+ invalid_tokens = self._getInvalidTokens()
169+ return self.deactivateTokens(invalid_tokens, send_email=send_email)
170+
171 def expireSubscriptions(self):
172 """Expire subscriptions as necessary.
173
174@@ -223,44 +243,40 @@
175 self.logger.info(
176 "Expired subscriptions: %s" % ", ".join(subscription_names))
177
178- def getNewTokensSinceLastRun(self):
179- """Return result set of new tokens created since the last run."""
180+ def getTimeToSyncFrom(self):
181+ """Return the time we'll synchronize from.
182+
183+ Any new PPAs or tokens created since this time will be used to
184+ generate passwords.
185+ """
186+ # NTP is running on our servers and therefore we can assume
187+ # only minimal skew, we include a fudge-factor of 1s so that
188+ # even the minimal skew cannot demonstrate bug 627608.
189+ last_activity = self.get_last_activity()
190+ if not last_activity:
191+ return
192+ return last_activity.date_started - timedelta(seconds=1)
193+
194+ def getNewTokens(self, since=None):
195+ """Return result set of new tokens created since the given time."""
196 store = IStore(ArchiveAuthToken)
197- # If we don't know when we last ran, we include all active
198- # tokens by default.
199- last_success = getUtility(IScriptActivitySet).getLastActivity(
200- 'generate-ppa-htaccess')
201 extra_expr = []
202- if last_success:
203- # NTP is running on our servers and therefore we can assume
204- # only minimal skew, we include a fudge-factor of 1s so that
205- # even the minimal skew cannot demonstrate bug 627608.
206- last_script_start_with_skew = last_success.date_started - (
207- timedelta(seconds=1))
208- extra_expr = [
209- ArchiveAuthToken.date_created >= last_script_start_with_skew]
210-
211+ if since:
212+ extra_expr = [ArchiveAuthToken.date_created >= since]
213 new_ppa_tokens = store.find(
214 ArchiveAuthToken,
215 ArchiveAuthToken.date_deactivated == None,
216 *extra_expr)
217-
218 return new_ppa_tokens
219
220- def getNewPrivatePPAs(self):
221+ def getNewPrivatePPAs(self, since=None):
222 """Return the recently created private PPAs."""
223 # Avoid circular import.
224 from lp.soyuz.model.archive import Archive
225 store = IStore(Archive)
226- # If we don't know when we last ran, we include all active
227- # tokens by default.
228- last_success = getUtility(IScriptActivitySet).getLastActivity(
229- 'generate-ppa-htaccess')
230 extra_expr = []
231- if last_success:
232- extra_expr = [
233- Archive.date_created >= last_success.date_completed]
234-
235+ if since:
236+ extra_expr = [Archive.date_created >= since]
237 return store.find(
238 Archive, Archive._private == True, *extra_expr)
239
240@@ -268,16 +284,34 @@
241 """Script entry point."""
242 self.logger.info('Starting the PPA .htaccess generation')
243 self.expireSubscriptions()
244- affected_ppas = self.deactivateTokens(send_email=True)
245+ affected_ppas = self.deactivateInvalidTokens(send_email=True)
246+ current_ppa_count = len(affected_ppas)
247+ self.logger.debug(
248+ '%s PPAs with deactivated tokens' % current_ppa_count)
249+
250+ last_success = self.getTimeToSyncFrom()
251
252 # In addition to the ppas that are affected by deactivated
253 # tokens, we also want to include any ppas that have tokens
254 # created since the last time we ran.
255- for token in self.getNewTokensSinceLastRun():
256+ num_tokens = 0
257+ for token in self.getNewTokens(since=last_success):
258 affected_ppas.add(token.archive)
259-
260- affected_ppas.update(self.getNewPrivatePPAs())
261-
262+ num_tokens += 1
263+
264+ new_ppa_count = len(affected_ppas)
265+ self.logger.debug(
266+ "%s new tokens since last run, %s PPAs affected"
267+ % (num_tokens, new_ppa_count - current_ppa_count))
268+ current_ppa_count = new_ppa_count
269+
270+ affected_ppas.update(self.getNewPrivatePPAs(since=last_success))
271+ new_ppa_count = len(affected_ppas)
272+ self.logger.debug(
273+ "%s new private PPAs since last run"
274+ % (new_ppa_count - current_ppa_count))
275+
276+ self.logger.debug('%s PPAs require updating' % new_ppa_count)
277 for ppa in affected_ppas:
278 # If this PPA is blacklisted, do not touch it's htaccess/pwd
279 # files.
280@@ -285,23 +319,27 @@
281 ppa.owner.name, [])
282 if ppa.name in blacklisted_ppa_names_for_owner:
283 self.logger.info(
284- "Skipping htacess updates for blacklisted PPA "
285+ "Skipping htaccess updates for blacklisted PPA "
286 " '%s' owned by %s.",
287 ppa.name,
288 ppa.owner.displayname)
289 continue
290 elif ppa.status == ArchiveStatus.DELETED or ppa.enabled is False:
291 self.logger.info(
292- "Skipping htacess updates for deleted or disabled PPA "
293+ "Skipping htaccess updates for deleted or disabled PPA "
294 " '%s' owned by %s.",
295 ppa.name,
296 ppa.owner.displayname)
297 continue
298
299 self.ensureHtaccess(ppa)
300+ htpasswd_write_start = datetime.now()
301 temp_htpasswd = self.generateHtpasswd(ppa)
302- if not self.replaceUpdatedHtpasswd(ppa, temp_htpasswd):
303- os.remove(temp_htpasswd)
304+ self.replaceUpdatedHtpasswd(ppa, temp_htpasswd)
305+ htpasswd_write_duration = datetime.now() - htpasswd_write_start
306+ self.logger.debug(
307+ "Wrote htpasswd for '%s': %ss"
308+ % (ppa.name, total_seconds(htpasswd_write_duration)))
309
310 if self.options.no_deactivation or self.options.dryrun:
311 self.logger.info('Dry run, so not committing transaction.')
312
313=== modified file 'lib/lp/archivepublisher/tests/test_generate_ppa_htaccess.py'
314--- lib/lp/archivepublisher/tests/test_generate_ppa_htaccess.py 2012-05-30 17:05:21 +0000
315+++ lib/lp/archivepublisher/tests/test_generate_ppa_htaccess.py 2012-06-06 13:49:20 +0000
316@@ -14,6 +14,12 @@
317 import tempfile
318
319 import pytz
320+from testtools.matchers import (
321+ AllMatch,
322+ FileContains,
323+ FileExists,
324+ Not,
325+ )
326 import transaction
327 from zope.component import getUtility
328 from zope.security.proxy import removeSecurityProxy
329@@ -29,6 +35,11 @@
330 from lp.services.log.logger import BufferLogger
331 from lp.services.mail import stub
332 from lp.services.scripts.interfaces.scriptactivity import IScriptActivitySet
333+from lp.services.osutils import (
334+ ensure_directory_exists,
335+ remove_if_exists,
336+ write_file,
337+ )
338 from lp.soyuz.enums import (
339 ArchiveStatus,
340 ArchiveSubscriberStatus,
341@@ -48,6 +59,8 @@
342 layer = LaunchpadZopelessLayer
343 dbuser = config.generateppahtaccess.dbuser
344
345+ SCRIPT_NAME = 'test tokens'
346+
347 def setUp(self):
348 super(TestPPAHtaccessTokenGeneration, self).setUp()
349 self.owner = self.factory.makePerson(
350@@ -64,7 +77,7 @@
351 """Return a HtaccessTokenGenerator instance."""
352 if test_args is None:
353 test_args = []
354- script = HtaccessTokenGenerator("test tokens", test_args=test_args)
355+ script = HtaccessTokenGenerator(self.SCRIPT_NAME, test_args=test_args)
356 script.logger = BufferLogger()
357 script.txn = self.layer.txn
358 switch_dbuser(self.dbuser)
359@@ -90,13 +103,10 @@
360 pub_config = getPubConfig(self.ppa)
361
362 filename = os.path.join(pub_config.htaccessroot, ".htaccess")
363- if os.path.isfile(filename):
364- os.remove(filename)
365+ remove_if_exists(filename)
366 script = self.getScript()
367 script.ensureHtaccess(self.ppa)
368- self.assertTrue(
369- os.path.isfile(filename),
370- "%s is not present when it should be" % filename)
371+ self.addCleanup(remove_if_exists, filename)
372
373 contents = [
374 "",
375@@ -104,29 +114,24 @@
376 "AuthName \"Token Required\"",
377 "AuthUserFile %s/.htpasswd" % pub_config.htaccessroot,
378 "Require valid-user",
379+ "",
380 ]
381-
382- file = open(filename, "r")
383- file_contents = file.read().splitlines()
384- file.close()
385- os.remove(filename)
386-
387- self.assertEqual(contents, file_contents)
388+ self.assertThat(filename, FileContains('\n'.join(contents)))
389
390 def testGenerateHtpasswd(self):
391 """Given some `ArchiveAuthToken`s, test generating htpasswd."""
392 # Make some subscriptions and tokens.
393- name12 = getUtility(IPersonSet).getByName("name12")
394- name16 = getUtility(IPersonSet).getByName("name16")
395- self.ppa.newSubscription(name12, self.ppa.owner)
396- self.ppa.newSubscription(name16, self.ppa.owner)
397 tokens = []
398- tokens.append(self.ppa.newAuthToken(name12))
399- tokens.append(self.ppa.newAuthToken(name16))
400+ for name in ['name12', 'name16']:
401+ person = getUtility(IPersonSet).getByName(name)
402+ self.ppa.newSubscription(person, self.ppa.owner)
403+ tokens.append(self.ppa.newAuthToken(person))
404+ token_usernames = [token.person.name for token in tokens]
405
406 # Generate the passwd file.
407 script = self.getScript()
408 filename = script.generateHtpasswd(self.ppa)
409+ self.addCleanup(remove_if_exists, filename)
410
411 # It should be a temp file in the same directory as the intended
412 # target file when it's renamed, so that os.rename() won't
413@@ -136,32 +141,19 @@
414 pub_config.htaccessroot, os.path.dirname(filename))
415
416 # Read it back in.
417- file = open(filename, "r")
418- file_contents = file.read().splitlines()
419-
420- # The first line should be the buildd_secret.
421- [user, password] = file_contents[0].split(":", 1)
422- self.assertEqual(user, "buildd")
423+ file_contents = [
424+ line.strip().split(':', 1) for line in open(filename, 'r')]
425+
426+ # First entry is buildd secret, rest are from tokens.
427+ usernames = list(zip(*file_contents)[0])
428+ self.assertEqual(['buildd'] + token_usernames, usernames)
429+
430 # We can re-encrypt the buildd_secret and it should match the
431 # one in the .htpasswd file.
432+ password = file_contents[0][1]
433 encrypted_secret = crypt.crypt(self.ppa.buildd_secret, password)
434 self.assertEqual(encrypted_secret, password)
435
436- # Finally, there should be two more lines in the file, one for
437- # each of the tokens generated above.
438- self.assertEqual(len(file_contents), 3)
439- [user1, password1] = file_contents[1].split(":", 1)
440- [user2, password2] = file_contents[2].split(":", 1)
441- self.assertEqual(user1, "name12")
442- self.assertEqual(user2, "name16")
443-
444- # For the names to appear in the order above, the dabatase IDs
445- # for the tokens have to be in that order. (To ensure a
446- # consistent ordering)
447- self.assertTrue(tokens[0].id < tokens[1].id)
448-
449- os.remove(filename)
450-
451 def testReplaceUpdatedHtpasswd(self):
452 """Test that the htpasswd file is only replaced if it changes."""
453 FILE_CONTENT = "Kneel before Zod!"
454@@ -171,11 +163,8 @@
455 filename = os.path.join(pub_config.htaccessroot, ".htpasswd")
456
457 # Write out a dummy .htpasswd
458- if not os.path.exists(pub_config.htaccessroot):
459- os.makedirs(pub_config.htaccessroot)
460- file = open(filename, "w")
461- file.write(FILE_CONTENT)
462- file.close()
463+ ensure_directory_exists(pub_config.htaccessroot)
464+ write_file(filename, FILE_CONTENT)
465
466 # Write the same contents in a temp file.
467 fd, temp_filename = tempfile.mkstemp(dir=pub_config.htaccessroot)
468@@ -189,9 +178,7 @@
469 script.replaceUpdatedHtpasswd(self.ppa, temp_filename))
470
471 # Writing a different .htpasswd should see it get replaced.
472- file = open(filename, "w")
473- file.write("Come to me, son of Jor-El!")
474- file.close()
475+ write_file(filename, "Come to me, son of Jor-El!")
476
477 self.assertTrue(
478 script.replaceUpdatedHtpasswd(self.ppa, temp_filename))
479@@ -269,7 +256,7 @@
480
481 # Initially, nothing is eligible for deactivation.
482 script = self.getScript()
483- script.deactivateTokens()
484+ script.deactivateInvalidTokens()
485 for person in tokens:
486 self.assertNotDeactivated(tokens[person])
487
488@@ -280,7 +267,7 @@
489 # Clear out emails generated when leaving a team.
490 pop_notifications()
491
492- script.deactivateTokens(send_email=True)
493+ script.deactivateInvalidTokens(send_email=True)
494 self.assertDeactivated(tokens[team1_person])
495 del tokens[team1_person]
496 for person in tokens:
497@@ -298,7 +285,7 @@
498 promiscuous_person.leave(team1)
499 # Clear out emails generated when leaving a team.
500 pop_notifications()
501- script.deactivateTokens(send_email=True)
502+ script.deactivateInvalidTokens(send_email=True)
503 self.assertNotDeactivated(tokens[promiscuous_person])
504 for person in tokens:
505 self.assertNotDeactivated(tokens[person])
506@@ -317,7 +304,7 @@
507 parent_team.setMembershipData(
508 team2, TeamMembershipStatus.DEACTIVATED, name12)
509 self.assertFalse(team2.inTeam(parent_team))
510- script.deactivateTokens()
511+ script.deactivateInvalidTokens()
512 for person in persons2:
513 self.assertDeactivated(tokens[person])
514
515@@ -348,10 +335,8 @@
516 pub_config = getPubConfig(self.ppa)
517 htaccess = os.path.join(pub_config.htaccessroot, ".htaccess")
518 htpasswd = os.path.join(pub_config.htaccessroot, ".htpasswd")
519- if os.path.isfile(htaccess):
520- os.remove(htaccess)
521- if os.path.isfile(htpasswd):
522- os.remove(htpasswd)
523+ remove_if_exists(htaccess)
524+ remove_if_exists(htpasswd)
525 return htaccess, htpasswd
526
527 def testSubscriptionExpiry(self):
528@@ -384,8 +369,7 @@
529 self.assertEqual(
530 return_code, 0, "Got a bad return code of %s\nOutput:\n%s" %
531 (return_code, stderr))
532- self.assertTrue(os.path.isfile(htaccess))
533- self.assertTrue(os.path.isfile(htpasswd))
534+ self.assertThat([htaccess, htpasswd], AllMatch(FileExists()))
535 os.remove(htaccess)
536 os.remove(htpasswd)
537
538@@ -407,8 +391,7 @@
539 script.main()
540
541 # Assert no files were written.
542- self.assertFalse(os.path.isfile(htaccess))
543- self.assertFalse(os.path.isfile(htpasswd))
544+ self.assertThat([htaccess, htpasswd], AllMatch(Not(FileExists())))
545
546 # Assert that the cancelled subscription did not cause the token
547 # to get deactivated.
548@@ -441,10 +424,8 @@
549 # The tokens will still be deactivated, and subscriptions expired.
550 self.assertDeactivated(tokens[0])
551 self.assertEqual(subs[0].status, ArchiveSubscriberStatus.EXPIRED)
552-
553 # But the htaccess is not touched.
554- self.assertFalse(os.path.isfile(htaccess))
555- self.assertFalse(os.path.isfile(htpasswd))
556+ self.assertThat([htaccess, htpasswd], AllMatch(Not(FileExists())))
557
558 def testSkippingOfDisabledPPAs(self):
559 """Test that the htaccess for disabled PPAs are not touched."""
560@@ -464,8 +445,7 @@
561 script.main()
562
563 # The htaccess and htpasswd files should not be generated.
564- self.assertFalse(os.path.isfile(htaccess))
565- self.assertFalse(os.path.isfile(htpasswd))
566+ self.assertThat([htaccess, htpasswd], AllMatch(Not(FileExists())))
567
568 def testSkippingOfDeletedPPAs(self):
569 """Test that the htaccess for deleted PPAs are not touched."""
570@@ -484,8 +464,7 @@
571 script.main()
572
573 # The htaccess and htpasswd files should not be generated.
574- self.assertFalse(os.path.isfile(htaccess))
575- self.assertFalse(os.path.isfile(htpasswd))
576+ self.assertThat([htaccess, htpasswd], AllMatch(Not(FileExists())))
577
578 def testSendingCancellationEmail(self):
579 """Test that when a token is deactivated, its user gets an email.
580@@ -555,6 +534,20 @@
581 self.assertEqual(
582 num_emails, 0, "Expected 0 emails, got %s" % num_emails)
583
584+ def test_getTimeToSyncFrom(self):
585+ # Sync from 1s before previous start to catch anything made during the
586+ # last script run, and to handle NTP clock skew.
587+ now = datetime.now(pytz.UTC)
588+ script_start_time = now - timedelta(seconds=2)
589+ script_end_time = now
590+
591+ getUtility(IScriptActivitySet).recordSuccess(
592+ self.SCRIPT_NAME, script_start_time, script_end_time)
593+ script = self.getScript()
594+ self.assertEqual(
595+ script_start_time - timedelta(seconds=1),
596+ script.getTimeToSyncFrom())
597+
598 def test_getNewPrivatePPAs_no_previous_run(self):
599 # All private PPAs are returned if there was no previous run.
600 # This happens even if they have no tokens.
601@@ -568,93 +561,51 @@
602 def test_getNewPrivatePPAs_only_those_since_last_run(self):
603 # Only private PPAs created since the last run are returned.
604 # This happens even if they have no tokens.
605-
606- now = datetime.now(pytz.UTC)
607- getUtility(IScriptActivitySet).recordSuccess(
608- 'generate-ppa-htaccess', now, now - timedelta(minutes=3))
609- removeSecurityProxy(self.ppa).date_created = (
610- now - timedelta(minutes=4))
611+ last_start = datetime.now(pytz.UTC) - timedelta(seconds=90)
612+ before_last_start = last_start - timedelta(seconds=30)
613+ removeSecurityProxy(self.ppa).date_created = before_last_start
614
615 # Create a new PPA that should show up.
616 new_ppa = self.factory.makeArchive(private=True)
617
618 script = self.getScript()
619- self.assertContentEqual([new_ppa], script.getNewPrivatePPAs())
620+ new_ppas = script.getNewPrivatePPAs(since=last_start)
621+ self.assertContentEqual([new_ppa], new_ppas)
622
623- def test_getNewTokensSinceLastRun_no_previous_run(self):
624+ def test_getNewTokens_no_previous_run(self):
625 """All valid tokens returned if there is no record of previous run."""
626 tokens = self.setupDummyTokens()[1]
627
628 # If there is no record of the script running previously, all
629 # valid tokens are returned.
630 script = self.getScript()
631- self.assertContentEqual(tokens, script.getNewTokensSinceLastRun())
632+ self.assertContentEqual(tokens, script.getNewTokens())
633
634- def test_getNewTokensSinceLastRun_only_those_since_last_run(self):
635+ def test_getNewTokens_only_those_since_last_run(self):
636 """Only tokens created since the last run are returned."""
637- now = datetime.now(pytz.UTC)
638- script_start_time = now - timedelta(seconds=2)
639- script_end_time = now
640- before_previous_start = script_start_time - timedelta(seconds=30)
641+ last_start = datetime.now(pytz.UTC) - timedelta(seconds=90)
642+ before_last_start = last_start - timedelta(seconds=30)
643
644- getUtility(IScriptActivitySet).recordSuccess(
645- 'generate-ppa-htaccess', date_started=script_start_time,
646- date_completed=script_end_time)
647 tokens = self.setupDummyTokens()[1]
648 # This token will not be included.
649- removeSecurityProxy(tokens[0]).date_created = before_previous_start
650-
651- script = self.getScript()
652- self.assertContentEqual(tokens[1:], script.getNewTokensSinceLastRun())
653-
654- def test_getNewTokensSinceLastRun_includes_tokens_during_last_run(self):
655- """Tokens created during the last ppa run will be included."""
656- now = datetime.now(pytz.UTC)
657- script_start_time = now - timedelta(seconds=2)
658- script_end_time = now
659- in_between = now - timedelta(seconds=1)
660-
661- getUtility(IScriptActivitySet).recordSuccess(
662- 'generate-ppa-htaccess', script_start_time, script_end_time)
663- tokens = self.setupDummyTokens()[1]
664- # This token will be included because it's been created during
665- # the previous script run.
666- removeSecurityProxy(tokens[0]).date_created = in_between
667-
668- script = self.getScript()
669- self.assertContentEqual(tokens, script.getNewTokensSinceLastRun())
670-
671- def test_getNewTokensSinceLastRun_handles_ntp_skew(self):
672- """An ntp-skew of up to one second will not affect the results."""
673- now = datetime.now(pytz.UTC)
674- script_start_time = now - timedelta(seconds=2)
675- script_end_time = now
676- earliest_with_ntp_skew = script_start_time - timedelta(
677- milliseconds=500)
678-
679- tokens = self.setupDummyTokens()[1]
680- getUtility(IScriptActivitySet).recordSuccess(
681- 'generate-ppa-htaccess', date_started=script_start_time,
682- date_completed=script_end_time)
683- # This token will still be included in the results.
684- removeSecurityProxy(tokens[0]).date_created = earliest_with_ntp_skew
685-
686- script = self.getScript()
687- self.assertContentEqual(tokens, script.getNewTokensSinceLastRun())
688-
689- def test_getNewTokensSinceLastRun_only_active_tokens(self):
690+ removeSecurityProxy(tokens[0]).date_created = before_last_start
691+
692+ script = self.getScript()
693+ new_tokens = script.getNewTokens(since=last_start)
694+ self.assertContentEqual(tokens[1:], new_tokens)
695+
696+ def test_getNewTokens_only_active_tokens(self):
697 """Only active tokens are returned."""
698 tokens = self.setupDummyTokens()[1]
699 tokens[0].deactivate()
700
701 script = self.getScript()
702- self.assertContentEqual(tokens[1:], script.getNewTokensSinceLastRun())
703+ self.assertContentEqual(tokens[1:], script.getNewTokens())
704
705 def test_processes_PPAs_without_subscription(self):
706 # A .htaccess file is written for Private PPAs even if they don't have
707 # any subscriptions.
708 htaccess, htpasswd = self.ensureNoFiles()
709-
710 transaction.commit()
711
712 # Call the script and check that we have a .htaccess and a
713@@ -663,7 +614,6 @@
714 self.assertEqual(
715 return_code, 0, "Got a bad return code of %s\nOutput:\n%s" %
716 (return_code, stderr))
717- self.assertTrue(os.path.isfile(htaccess))
718- self.assertTrue(os.path.isfile(htpasswd))
719+ self.assertThat([htaccess, htpasswd], AllMatch(FileExists()))
720 os.remove(htaccess)
721 os.remove(htpasswd)
722
723=== modified file 'lib/lp/bugs/doc/sourceforge-remote-products.txt'
724--- lib/lp/bugs/doc/sourceforge-remote-products.txt 2011-12-28 17:03:06 +0000
725+++ lib/lp/bugs/doc/sourceforge-remote-products.txt 2012-06-06 13:49:20 +0000
726@@ -122,4 +122,5 @@
727 DEBUG ...
728 INFO No Products to update.
729 INFO Time for this run: ... seconds.
730+ DEBUG updateremoteproduct ran in ...s (excl. load & lock)
731 DEBUG Removing lock file:...
732
733=== modified file 'lib/lp/registry/doc/teammembership.txt'
734--- lib/lp/registry/doc/teammembership.txt 2012-04-10 14:01:17 +0000
735+++ lib/lp/registry/doc/teammembership.txt 2012-06-06 13:49:20 +0000
736@@ -697,6 +697,7 @@
737 DEBUG ...
738 DEBUG Sent warning email to name16 in launchpad-buildd-admins team.
739 DEBUG Sent warning email to name12 in landscape-developers team.
740+ DEBUG flag-expired-memberships ran in ...s (excl. load & lock)
741 DEBUG Removing lock file: ...launchpad-flag-expired-memberships.lock
742 >>> process.returncode
743 0
744
745=== modified file 'lib/lp/services/looptuner.py'
746--- lib/lp/services/looptuner.py 2012-01-06 11:50:43 +0000
747+++ lib/lp/services/looptuner.py 2012-06-06 13:49:20 +0000
748@@ -258,10 +258,6 @@
749 time.sleep(seconds)
750
751
752-def timedelta_to_seconds(td):
753- return 24 * 60 * td.days + td.seconds
754-
755-
756 class DBLoopTuner(LoopTuner):
757 """A LoopTuner that plays well with PostgreSQL and replication.
758
759
760=== modified file 'lib/lp/services/osutils.py'
761--- lib/lp/services/osutils.py 2011-06-24 11:10:43 +0000
762+++ lib/lp/services/osutils.py 2012-06-06 13:49:20 +0000
763@@ -204,3 +204,9 @@
764 except OSError, e:
765 if e.errno != errno.ENOENT:
766 raise
767+
768+
769+def write_file(path, content):
770+ f = open(path, 'w')
771+ f.write(content)
772+ f.close()
773
774=== modified file 'lib/lp/services/scripts/base.py'
775--- lib/lp/services/scripts/base.py 2012-01-06 11:08:30 +0000
776+++ lib/lp/services/scripts/base.py 2012-06-06 13:49:20 +0000
777@@ -47,6 +47,7 @@
778 from lp.services.mail.sendmail import set_immediate_mail_delivery
779 from lp.services.scripts.interfaces.scriptactivity import IScriptActivitySet
780 from lp.services.scripts.logger import OopsHandler
781+from lp.services.utils import total_seconds
782 from lp.services.webapp.errorlog import globalErrorUtility
783 from lp.services.webapp.interaction import (
784 ANONYMOUS,
785@@ -414,6 +415,10 @@
786 # overriding the name property.
787 logging.getLogger().addHandler(OopsHandler(self.name))
788
789+ def get_last_activity(self):
790+ """Return the last activity, if any."""
791+ return getUtility(IScriptActivitySet).getLastActivity(self.name)
792+
793 @log_unhandled_exception_and_exit
794 def record_activity(self, date_started, date_completed):
795 """Record the successful completion of the script."""
796@@ -424,6 +429,12 @@
797 date_started=date_started,
798 date_completed=date_completed)
799 self.txn.commit()
800+ # date_started is recorded *after* the lock is acquired and we've
801+ # initialized Zope components and the database. Thus this time is
802+ # only for the script proper, rather than total execution time.
803+ seconds_taken = total_seconds(date_completed - date_started)
804+ self.logger.debug(
805+ "%s ran in %ss (excl. load & lock)" % (self.name, seconds_taken))
806
807
808 @contextmanager
809
810=== modified file 'lib/lp/services/tests/test_osutils.py'
811--- lib/lp/services/tests/test_osutils.py 2011-08-12 11:37:08 +0000
812+++ lib/lp/services/tests/test_osutils.py 2012-06-06 13:49:20 +0000
813@@ -10,11 +10,14 @@
814 import socket
815 import tempfile
816
817+from testtools.matchers import FileContains
818+
819 from lp.services.osutils import (
820 ensure_directory_exists,
821 open_for_writing,
822 remove_tree,
823 until_no_eintr,
824+ write_file,
825 )
826 from lp.testing import TestCase
827
828@@ -95,6 +98,16 @@
829 self.assertEqual("Hello world!\n", open(filename).read())
830
831
832+class TestWriteFile(TestCase):
833+
834+ def test_write_file(self):
835+ directory = self.makeTemporaryDirectory()
836+ filename = os.path.join(directory, 'filename')
837+ content = self.getUniqueString()
838+ write_file(filename, content)
839+ self.assertThat(filename, FileContains(content))
840+
841+
842 class TestUntilNoEINTR(TestCase):
843 """Tests for until_no_eintr."""
844
845
846=== modified file 'lib/lp/services/tests/test_utils.py'
847--- lib/lp/services/tests/test_utils.py 2011-12-19 23:38:16 +0000
848+++ lib/lp/services/tests/test_utils.py 2012-06-06 13:49:20 +0000
849@@ -6,7 +6,10 @@
850 __metaclass__ = type
851
852 from contextlib import contextmanager
853-from datetime import datetime
854+from datetime import (
855+ datetime,
856+ timedelta,
857+ )
858 import hashlib
859 import itertools
860 import os
861@@ -34,6 +37,7 @@
862 obfuscate_structure,
863 run_capturing_output,
864 save_bz2_pickle,
865+ total_seconds,
866 traceback_info,
867 utc_now,
868 )
869@@ -384,3 +388,14 @@
870 """Values are obfuscated recursively."""
871 obfuscated = obfuscate_structure({'foo': (['a@example.com'],)})
872 self.assertEqual({'foo': [['<email address hidden>']]}, obfuscated)
873+
874+
875+class TestTotalSeconds(TestCase):
876+
877+ # XXX: JonathanLange 2012-05-31: Remove this when Python 2.6 support is
878+ # dropped. Replace calls with timedelta.total_seconds.
879+
880+ def test_total_seconds(self):
881+ # Numbers are arbitrary.
882+ duration = timedelta(days=3, seconds=45, microseconds=16)
883+ self.assertEqual(3 * 24 * 3600 + 45.000016, total_seconds(duration))
884
885=== modified file 'lib/lp/services/utils.py'
886--- lib/lp/services/utils.py 2012-05-24 20:25:54 +0000
887+++ lib/lp/services/utils.py 2012-06-06 13:49:20 +0000
888@@ -26,6 +26,7 @@
889 'save_bz2_pickle',
890 'synchronize',
891 'text_delta',
892+ 'total_seconds',
893 'traceback_info',
894 'utc_now',
895 'value_string',
896@@ -383,3 +384,14 @@
897 for key, value in o.iteritems())
898 else:
899 return o
900+
901+
902+def total_seconds(duration):
903+ """The number of total seconds in a timedelta.
904+ """
905+ # XXX: JonathanLange 2012-05-12: In Python 2.7, spell this as
906+ # duration.total_seconds(). Only needed for Python 2.6 or earlier.
907+ return (
908+ (duration.microseconds +
909+ (duration.seconds + duration.days * 24 * 3600) * 1e6)
910+ / 1e6)
911
912=== modified file 'lib/lp/translations/doc/poexport-request.txt'
913--- lib/lp/translations/doc/poexport-request.txt 2011-12-23 23:44:59 +0000
914+++ lib/lp/translations/doc/poexport-request.txt 2012-06-06 13:49:20 +0000
915@@ -263,6 +263,7 @@
916 DEBUG Exporting objects for Happy Downloader, related to template
917 alsa-utils in alsa-utils trunk
918 INFO Stored file at http://.../launchpad-export.tar.gz
919+ DEBUG rosetta-export-queue ran in ...s (excl. load & lock)
920 DEBUG Removing lock file: /var/lock/launchpad-rosetta-export-queue.lock
921 <BLANKLINE>
922