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
1=== modified file 'lib/lp/registry/scripts/distributionmirror_prober.py'
2--- lib/lp/registry/scripts/distributionmirror_prober.py 2009-10-26 18:40:04 +0000
3+++ lib/lp/registry/scripts/distributionmirror_prober.py 2009-12-23 16:57:17 +0000
4@@ -8,6 +8,8 @@
5 import urllib2
6 import urlparse
7
8+from datetime import datetime
9+
10 from zope.component import getUtility
11
12 from twisted.internet import defer, protocol, reactor
13@@ -48,6 +50,23 @@
14 # start connecting.
15 OVERALL_REQUESTS = 100
16
17+__metaclass__ = type
18+
19+
20+class LoggingMixin:
21+ """Common logging class for archive and releases mirror messages."""
22+
23+ def _getTime(self):
24+ """Return the current UTC time."""
25+ return datetime.utcnow()
26+
27+ def logMessage(self, message):
28+ """Append a UTC timestamp to the message returned by the mirror
29+ prober.
30+ """
31+ timestamp = datetime.ctime(self._getTime())
32+ self.log_file.write(timestamp + ": " + message)
33+
34
35 class RequestManager:
36
37@@ -373,7 +392,7 @@
38 "URLs: %s" % self.url)
39
40
41-class ArchiveMirrorProberCallbacks(object):
42+class ArchiveMirrorProberCallbacks(LoggingMixin):
43
44 expected_failures = (BadResponseCode, ProberTimeout, ConnectionSkipped)
45
46@@ -407,7 +426,7 @@
47 % (self.mirror_class_name,
48 self._getSeriesPocketAndComponentDescription(), self.url,
49 failure.getErrorMessage()))
50- self.log_file.write(msg)
51+ self.logMessage(msg)
52 failure.trap(*self.expected_failures)
53
54 def ensureMirrorSeries(self, http_status):
55@@ -421,7 +440,7 @@
56 mirror = self.ensureMethod(
57 self.series, self.pocket, self.component)
58
59- self.log_file.write(msg)
60+ self.logMessage(msg)
61 return mirror
62
63 def updateMirrorFreshness(self, arch_or_source_mirror):
64@@ -477,7 +496,7 @@
65 '%s.\n' % (url, self.mirror_class_name,
66 self._getSeriesPocketAndComponentDescription(),
67 freshness.title))
68- self.log_file.write(msg)
69+ self.logMessage(msg)
70 arch_or_source_mirror.freshness = freshness
71
72 def _getSeriesPocketAndComponentDescription(self):
73@@ -502,7 +521,7 @@
74 % (failure.getErrorMessage(), url,
75 self._getSeriesPocketAndComponentDescription()))
76 if failure.check(*self.expected_failures) is not None:
77- self.log_file.write(msg)
78+ self.logMessage(msg)
79 else:
80 # This is not an error we expect from an HTTP server, so we log it
81 # using the cronscript's logger and wait for kiko to complain
82@@ -512,7 +531,7 @@
83 return None
84
85
86-class MirrorCDImageProberCallbacks(object):
87+class MirrorCDImageProberCallbacks(LoggingMixin):
88
89 expected_failures = (BadResponseCode, ProberTimeout, ConnectionSkipped)
90
91@@ -547,13 +566,13 @@
92
93 mirror = self.mirror.ensureMirrorCDImageSeries(
94 self.distroseries, self.flavour)
95- self.log_file.write(
96+ self.logMessage(
97 "Found all ISO images for series %s and flavour %s.\n"
98 % (self.distroseries.title, self.flavour))
99 return mirror
100
101 def logMissingURL(self, failure, url):
102- self.log_file.write(
103+ self.logMessage(
104 "Failed %s: %s\n" % (url, failure.getErrorMessage()))
105 return failure
106
107
108=== modified file 'lib/lp/registry/tests/test_distributionmirror_prober.py'
109--- lib/lp/registry/tests/test_distributionmirror_prober.py 2009-10-26 18:40:04 +0000
110+++ lib/lp/registry/tests/test_distributionmirror_prober.py 2009-12-23 16:57:17 +0000
111@@ -8,9 +8,11 @@
112 __metaclass__ = type
113
114
115+from datetime import datetime
116 import httplib
117 import logging
118 import os
119+import re
120 from StringIO import StringIO
121 import unittest
122
123@@ -36,7 +38,8 @@
124 RedirectAwareProberProtocol, probe_archive_mirror, probe_cdimage_mirror,
125 should_skip_host, PER_HOST_REQUESTS, MIN_REQUEST_TIMEOUT_RATIO,
126 MIN_REQUESTS_TO_CONSIDER_RATIO, _build_request_for_cdimage_file_list,
127- restore_http_proxy, MultiLock, OVERALL_REQUESTS, RequestManager)
128+ restore_http_proxy, MultiLock, OVERALL_REQUESTS, RequestManager,
129+ LoggingMixin)
130 from lp.registry.tests.distributionmirror_http_server import (
131 DistributionMirrorTestHTTPServer)
132 from canonical.testing import LaunchpadZopelessLayer, TwistedLayer
133@@ -794,5 +797,31 @@
134 self.failUnlessEqual(request.headers['Cache-control'], 'no-cache')
135
136
137+class TestLoggingMixin(unittest.TestCase):
138+
139+ def _fake_gettime(self):
140+ # Fake the current time.
141+ fake_time = datetime(2004, 10, 20, 12, 00, 00, 000000)
142+ return fake_time
143+
144+ def test_logMessage_output(self):
145+ logger = LoggingMixin()
146+ logger.log_file = StringIO()
147+ logger._getTime = self._fake_gettime
148+ logger.logMessage("Ubuntu Warty Released")
149+ logger.log_file.seek(0)
150+ message = logger.log_file.read()
151+ self.failUnlessEqual('Wed Oct 20 12:00:00 2004: Ubuntu Warty Released',
152+ message)
153+
154+ def test_logMessage_integration(self):
155+ logger = LoggingMixin()
156+ logger.log_file = StringIO()
157+ logger.logMessage("Probing...")
158+ logger.log_file.seek(0)
159+ message = logger.log_file.read()
160+ self.assertNotEqual(None, message)
161+
162+
163 def test_suite():
164 return unittest.TestLoader().loadTestsFromName(__name__)