Launchpad itself

Merge lp:~jpds/launchpad/fix_489363 into lp:launchpad

  1. fix_489363
  2. Merge into devel
Proposed by Jonathan Davies
Status: Merged
Approved by: Jeroen T. Vermeulen
Approved revision: not available
Merged at revision: 10088
Proposed branch: lp:~jpds/launchpad/fix_489363
Merge into: lp:launchpad
Diff against target: 164 lines (+57/-9)
2 files modified
lib/lp/registry/scripts/distributionmirror_prober.py (+27/-8)
lib/lp/registry/tests/test_distributionmirror_prober.py (+30/-1)
To merge this branch: bzr merge lp:~jpds/launchpad/fix_489363
Reviewer Review Type Date Requested Status
Jeroen T. Vermeulen (community) code Approve
Review via email: mp+16531@code.launchpad.net

Commit message

Added timestamps to our mirror logs and added tests to ensure that we are logging text properly.

To post a comment you must log in.
Revision history for this message
Jonathan Davies (jpds) wrote :

= Summary =

Mirror prober logs should have timestamps in them (preferably in UTC) so that it's easier to debug when a mirror got probed, so that some mirror administrators do not get confused by old logs (see bug #474214 for an example).

This branches adds timestamps to our mirror logs and adds tests to ensure that we are logging what we should be logging.

Revision history for this message
Jeroen T. Vermeulen (jtv) wrote :

We went through a lot of back-and-forth on IRC, but now I think it's in fine shape.

The main thing I fought for was to inject a fake timestamp into the test, so that it has an exact, predictable text to match for. A separate test then verifies that this isn't hiding a failure in composing the human-readable text for the log message.

I understand LoggingMixin now has the appropriate docstrings. With that, r=me.

Jeroen

review: Approve
Revision history for this message
Jeroen T. Vermeulen (jtv) wrote :

Giving this an approval vote of type "code" so you can "ec2 land" it.

review: Approve (code)

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
=== modified file 'lib/lp/registry/scripts/distributionmirror_prober.py'
--- lib/lp/registry/scripts/distributionmirror_prober.py 2009-10-26 18:40:04 +0000
+++ lib/lp/registry/scripts/distributionmirror_prober.py 2009-12-23 16:57:17 +0000
@@ -8,6 +8,8 @@
8import urllib28import urllib2
9import urlparse9import urlparse
1010
11from datetime import datetime
12
11from zope.component import getUtility13from zope.component import getUtility
1214
13from twisted.internet import defer, protocol, reactor15from twisted.internet import defer, protocol, reactor
@@ -48,6 +50,23 @@
48# start connecting.50# start connecting.
49OVERALL_REQUESTS = 10051OVERALL_REQUESTS = 100
5052
53__metaclass__ = type
54
55
56class LoggingMixin:
57 """Common logging class for archive and releases mirror messages."""
58
59 def _getTime(self):
60 """Return the current UTC time."""
61 return datetime.utcnow()
62
63 def logMessage(self, message):
64 """Append a UTC timestamp to the message returned by the mirror
65 prober.
66 """
67 timestamp = datetime.ctime(self._getTime())
68 self.log_file.write(timestamp + ": " + message)
69
5170
52class RequestManager:71class RequestManager:
5372
@@ -373,7 +392,7 @@
373 "URLs: %s" % self.url)392 "URLs: %s" % self.url)
374393
375394
376class ArchiveMirrorProberCallbacks(object):395class ArchiveMirrorProberCallbacks(LoggingMixin):
377396
378 expected_failures = (BadResponseCode, ProberTimeout, ConnectionSkipped)397 expected_failures = (BadResponseCode, ProberTimeout, ConnectionSkipped)
379398
@@ -407,7 +426,7 @@
407 % (self.mirror_class_name,426 % (self.mirror_class_name,
408 self._getSeriesPocketAndComponentDescription(), self.url,427 self._getSeriesPocketAndComponentDescription(), self.url,
409 failure.getErrorMessage()))428 failure.getErrorMessage()))
410 self.log_file.write(msg)429 self.logMessage(msg)
411 failure.trap(*self.expected_failures)430 failure.trap(*self.expected_failures)
412431
413 def ensureMirrorSeries(self, http_status):432 def ensureMirrorSeries(self, http_status):
@@ -421,7 +440,7 @@
421 mirror = self.ensureMethod(440 mirror = self.ensureMethod(
422 self.series, self.pocket, self.component)441 self.series, self.pocket, self.component)
423442
424 self.log_file.write(msg)443 self.logMessage(msg)
425 return mirror444 return mirror
426445
427 def updateMirrorFreshness(self, arch_or_source_mirror):446 def updateMirrorFreshness(self, arch_or_source_mirror):
@@ -477,7 +496,7 @@
477 '%s.\n' % (url, self.mirror_class_name,496 '%s.\n' % (url, self.mirror_class_name,
478 self._getSeriesPocketAndComponentDescription(),497 self._getSeriesPocketAndComponentDescription(),
479 freshness.title))498 freshness.title))
480 self.log_file.write(msg)499 self.logMessage(msg)
481 arch_or_source_mirror.freshness = freshness500 arch_or_source_mirror.freshness = freshness
482501
483 def _getSeriesPocketAndComponentDescription(self):502 def _getSeriesPocketAndComponentDescription(self):
@@ -502,7 +521,7 @@
502 % (failure.getErrorMessage(), url,521 % (failure.getErrorMessage(), url,
503 self._getSeriesPocketAndComponentDescription()))522 self._getSeriesPocketAndComponentDescription()))
504 if failure.check(*self.expected_failures) is not None:523 if failure.check(*self.expected_failures) is not None:
505 self.log_file.write(msg)524 self.logMessage(msg)
506 else:525 else:
507 # This is not an error we expect from an HTTP server, so we log it526 # This is not an error we expect from an HTTP server, so we log it
508 # using the cronscript's logger and wait for kiko to complain527 # using the cronscript's logger and wait for kiko to complain
@@ -512,7 +531,7 @@
512 return None531 return None
513532
514533
515class MirrorCDImageProberCallbacks(object):534class MirrorCDImageProberCallbacks(LoggingMixin):
516535
517 expected_failures = (BadResponseCode, ProberTimeout, ConnectionSkipped)536 expected_failures = (BadResponseCode, ProberTimeout, ConnectionSkipped)
518537
@@ -547,13 +566,13 @@
547566
548 mirror = self.mirror.ensureMirrorCDImageSeries(567 mirror = self.mirror.ensureMirrorCDImageSeries(
549 self.distroseries, self.flavour)568 self.distroseries, self.flavour)
550 self.log_file.write(569 self.logMessage(
551 "Found all ISO images for series %s and flavour %s.\n"570 "Found all ISO images for series %s and flavour %s.\n"
552 % (self.distroseries.title, self.flavour))571 % (self.distroseries.title, self.flavour))
553 return mirror572 return mirror
554573
555 def logMissingURL(self, failure, url):574 def logMissingURL(self, failure, url):
556 self.log_file.write(575 self.logMessage(
557 "Failed %s: %s\n" % (url, failure.getErrorMessage()))576 "Failed %s: %s\n" % (url, failure.getErrorMessage()))
558 return failure577 return failure
559578
560579
=== modified file 'lib/lp/registry/tests/test_distributionmirror_prober.py'
--- lib/lp/registry/tests/test_distributionmirror_prober.py 2009-10-26 18:40:04 +0000
+++ lib/lp/registry/tests/test_distributionmirror_prober.py 2009-12-23 16:57:17 +0000
@@ -8,9 +8,11 @@
8__metaclass__ = type8__metaclass__ = type
99
1010
11from datetime import datetime
11import httplib12import httplib
12import logging13import logging
13import os14import os
15import re
14from StringIO import StringIO16from StringIO import StringIO
15import unittest17import unittest
1618
@@ -36,7 +38,8 @@
36 RedirectAwareProberProtocol, probe_archive_mirror, probe_cdimage_mirror,38 RedirectAwareProberProtocol, probe_archive_mirror, probe_cdimage_mirror,
37 should_skip_host, PER_HOST_REQUESTS, MIN_REQUEST_TIMEOUT_RATIO,39 should_skip_host, PER_HOST_REQUESTS, MIN_REQUEST_TIMEOUT_RATIO,
38 MIN_REQUESTS_TO_CONSIDER_RATIO, _build_request_for_cdimage_file_list,40 MIN_REQUESTS_TO_CONSIDER_RATIO, _build_request_for_cdimage_file_list,
39 restore_http_proxy, MultiLock, OVERALL_REQUESTS, RequestManager)41 restore_http_proxy, MultiLock, OVERALL_REQUESTS, RequestManager,
42 LoggingMixin)
40from lp.registry.tests.distributionmirror_http_server import (43from lp.registry.tests.distributionmirror_http_server import (
41 DistributionMirrorTestHTTPServer)44 DistributionMirrorTestHTTPServer)
42from canonical.testing import LaunchpadZopelessLayer, TwistedLayer45from canonical.testing import LaunchpadZopelessLayer, TwistedLayer
@@ -794,5 +797,31 @@
794 self.failUnlessEqual(request.headers['Cache-control'], 'no-cache')797 self.failUnlessEqual(request.headers['Cache-control'], 'no-cache')
795798
796799
800class TestLoggingMixin(unittest.TestCase):
801
802 def _fake_gettime(self):
803 # Fake the current time.
804 fake_time = datetime(2004, 10, 20, 12, 00, 00, 000000)
805 return fake_time
806
807 def test_logMessage_output(self):
808 logger = LoggingMixin()
809 logger.log_file = StringIO()
810 logger._getTime = self._fake_gettime
811 logger.logMessage("Ubuntu Warty Released")
812 logger.log_file.seek(0)
813 message = logger.log_file.read()
814 self.failUnlessEqual('Wed Oct 20 12:00:00 2004: Ubuntu Warty Released',
815 message)
816
817 def test_logMessage_integration(self):
818 logger = LoggingMixin()
819 logger.log_file = StringIO()
820 logger.logMessage("Probing...")
821 logger.log_file.seek(0)
822 message = logger.log_file.read()
823 self.assertNotEqual(None, message)
824
825
797def test_suite():826def test_suite():
798 return unittest.TestLoader().loadTestsFromName(__name__)827 return unittest.TestLoader().loadTestsFromName(__name__)