Merge lp:~lifeless/launchpad/lognamer into lp:launchpad
- lognamer
- Merge into devel
Status: | Merged |
---|---|
Approved by: | Curtis Hovey |
Approved revision: | no longer in the source branch. |
Merged at revision: | 11101 |
Proposed branch: | lp:~lifeless/launchpad/lognamer |
Merge into: | lp:launchpad |
Diff against target: |
1076 lines (+432/-269) 11 files modified
lib/canonical/launchpad/pagetests/standalone/xx-request-expired.txt (+2/-2) lib/canonical/launchpad/pagetests/standalone/xx-soft-timeout.txt (+2/-2) lib/canonical/launchpad/scripts/ftests/test_oops_prune.py (+5/-3) lib/canonical/launchpad/scripts/oops.py (+4/-2) lib/canonical/launchpad/webapp/errorlog.py (+40/-131) lib/canonical/launchpad/webapp/tests/test_errorlog.py (+42/-129) lib/lp/services/job/tests/test_runner.py (+1/-0) lib/lp/services/log/__init__.py (+11/-0) lib/lp/services/log/tests/__init__.py (+4/-0) lib/lp/services/log/tests/test_uniquefileallocator.py (+139/-0) lib/lp/services/log/uniquefileallocator.py (+182/-0) |
To merge this branch: | bzr merge lp:~lifeless/launchpad/lognamer |
Related bugs: |
Reviewer | Review Type | Date Requested | Status |
---|---|---|---|
Curtis Hovey (community) | code | Approve | |
Review via email: mp+28574@code.launchpad.net |
Commit message
Factor out new lp.services.
Description of the change
Factor out a new canonical.
This new module takes care of allocating and finding log files on disk, without
worrying about serialisation, deciding what should be in them etc.
The result is a more focused ErrorReportingU
be reused for other tasks that also want to be able to write log-like files to
unique names on disk.
I don't know if this is entirely enough to reuse this with no other glue changes, but it looks pretty good to me. And looking at the ERU I can see what it does more easily.
Robert Collins (lifeless) wrote : | # |
Thanks for the review.
On Wed, Jun 30, 2010 at 7:55 AM, Curtis Hovey
<email address hidden> wrote:
> Review: Needs Information
> Hi Rob.
>
> Thanks for extracting this logic. I have a few comments and I am confused
> by a test change.
Cool :)
>> === added file 'lib/canonical/
>> --- lib/canonical/
>> +++ lib/canonical/
>
> webapp is deprecated. I think this would be better located at
> lib/lp/
Some similar things that might want to use this:
log / dump / debug / trace / audit
This is infrastructure for them, its about uniquely managing a set of
files on disk, in date and lexical ascending order.
So perhaps
logger/
>> +class LogNamer:
>> + """Assign unique file names to logs being written from an app/script.
>> +
>> + LogNamer causes logs written from one process to be uniquely named. It is not
>> + safe for use in multiple processes with the same output root - each process
>> + must have a unique output root.
>> + """
>
> I see trailing whitespace. Wrap the doc at 78 characters.
Sorry, editor isn't set to hunt out trailing whitespace, will fix and rewrap.
>> + def getFilename(self, log_serial, time):
>> + """Get the filename for a given log serial and time."""
>> + log_subtype = self._log_infix()
>> + output_dir = self.output_
>
> Avoid end comments. This looks like a comment rather than an XXX to denote
> tech-debt.
Ok. Gary just reminded me that you have a policy of needing a bug for
XXX, should I file one ?
>> + def newId(self, now=None):
>> + """Returns an (id, filename) pair for use by the caller.
>> +
>> + The ID is composed of a short string to identify the Launchpad instance
>> + followed by an ID that is unique for the day.
>> +
>> + The filename is composed of the zero padded second in the day
>> + followed by the ID. This ensures that reports are in date order when
>> + sorted lexically.
>> + """
>> + if now is not None:
>> + now = now.astimezone(UTC)
>> + else:
>> + now = datetime.
>> + # We look up the error directory before allocating a new ID,
>> + # because if the day has changed, errordir() will reset the ID
>> + # counter to zero.
>> + self.output_
>> + self._lock.
>> + try:
>> + self._last_serial += 1
>> + newid = self._last_serial
>> + finally:
>> + self._lock.
>> + subtype = self._log_infix()
>> + day_number = (now - epoch).days + 1
>> + log_id = '%s-%d%s%d' % (self._log_type, day_number, subtype, newid)
>> + filename = self.getFilenam
>> + return log_id, filename
>
> I am confused. The only changes I see in this method is prefix => infix,
> yet I can see you changed the the last test for this method to verify
> an error wa...
Robert Collins (lifeless) wrote : | # |
I think I've done what you asked, I chose a name that made sense to me
- please have a look at the incremental diff and let me know what you
think:
=== modified file 'lib/canonical/
--- lib/canonical/
+++ lib/canonical/
@@ -38,7 +38,7 @@
soft_
from canonical.
IErrorReport, IErrorReportEvent, IErrorReportReq
-from canonical.
+from lp.services.
from canonical.
UTC = pytz.utc
@@ -253,8 +253,8 @@
if section_name is None:
- # Start a new LogNamer to activate the new configuration.
- self.log_namer = LogNamer(
+ # Start a new UniqueFileAllocator to activate the new configuration.
+ self.log_namer = UniqueFileAlloc
=== modified file 'lib/canonical/
--- lib/canonical/
01:17:40 +0000
+++ lib/canonical/
00:25:56 +0000
@@ -37,8 +37,8 @@
_is_sensitive)
from canonical.
NoReferrer
-from canonical.
from lazr.restful.
+from lp.services.
from lp.services.osutils import remove_tree
from lp.testing import TestCase
@@ -230,9 +230,9 @@
- def test_creates_
+ def test_sets_
utility = ErrorReportingU
- self.assertIsIn
+ self.assertIsIn
def test_configure(
"""Test ErrorReportingU
=== added directory 'lib/lp/
=== added file 'lib/lp/
--- lib/lp/
+++ lib/lp/
@@ -0,0 +1,11 @@
+# Copyright 2010 Canonical Ltd. This software is licensed under the
+# GNU Affero General Public License version 3 (see the file LICENSE).
+
+"""lp.services.log provides log-like facilities.
+
+Consider putting infrastructure that is used for getting logs or diagnostics
+out of Launchpad and onto some external store in here.
+
+Because this part of lp.services, packages in this namespace can only use
+general LAZR or library functionality.
+"""
=== added directory 'lib/lp/
=== added file 'lib/lp/
--- lib/lp/
Curtis Hovey (sinzui) wrote : | # |
Thanks for the refactoring and explaining my confusion.
Preview Diff
1 | === modified file 'lib/canonical/launchpad/pagetests/standalone/xx-request-expired.txt' |
2 | --- lib/canonical/launchpad/pagetests/standalone/xx-request-expired.txt 2008-03-14 04:18:41 +0000 |
3 | +++ lib/canonical/launchpad/pagetests/standalone/xx-request-expired.txt 2010-07-05 19:27:28 +0000 |
4 | @@ -9,7 +9,7 @@ |
5 | >>> from textwrap import dedent |
6 | >>> from canonical.config import config |
7 | >>> from canonical.launchpad.webapp.errorlog import globalErrorUtility |
8 | - >>> old_lastid = globalErrorUtility.lastid |
9 | + >>> old_lastid = globalErrorUtility.getLastOopsReport().id |
10 | >>> test_data = dedent(""" |
11 | ... [database] |
12 | ... db_statement_timeout: 1 |
13 | @@ -29,7 +29,7 @@ |
14 | |
15 | We can now see that an error was logged since lastid has changed: |
16 | |
17 | - >>> old_lastid != globalErrorUtility.lastid |
18 | + >>> old_lastid != globalErrorUtility.getLastOopsReport().id |
19 | True |
20 | |
21 | Let's reset the config value we changed: |
22 | |
23 | === modified file 'lib/canonical/launchpad/pagetests/standalone/xx-soft-timeout.txt' |
24 | --- lib/canonical/launchpad/pagetests/standalone/xx-soft-timeout.txt 2008-03-14 04:18:41 +0000 |
25 | +++ lib/canonical/launchpad/pagetests/standalone/xx-soft-timeout.txt 2010-07-05 19:27:28 +0000 |
26 | @@ -41,7 +41,7 @@ |
27 | |
28 | >>> from textwrap import dedent |
29 | >>> from canonical.launchpad.webapp.errorlog import globalErrorUtility |
30 | - >>> old_lastid = globalErrorUtility.lastid |
31 | + >>> old_lastid = globalErrorUtility.getLastOopsReport().id |
32 | >>> test_data = (dedent(""" |
33 | ... [database] |
34 | ... soft_request_timeout: 1 |
35 | @@ -58,7 +58,7 @@ |
36 | |
37 | We can now see that an error was logged since lastid has changed: |
38 | |
39 | - >>> old_lastid != globalErrorUtility.lastid |
40 | + >>> old_lastid != globalErrorUtility.getLastOopsReport().id |
41 | True |
42 | |
43 | Since the page rendered correctly, we assume it's a soft timeout error, |
44 | |
45 | === modified file 'lib/canonical/launchpad/scripts/ftests/test_oops_prune.py' |
46 | --- lib/canonical/launchpad/scripts/ftests/test_oops_prune.py 2010-03-19 09:13:46 +0000 |
47 | +++ lib/canonical/launchpad/scripts/ftests/test_oops_prune.py 2010-07-05 19:27:28 +0000 |
48 | @@ -26,7 +26,7 @@ |
49 | referenced_oops, old_oops_files, unwanted_oops_files, |
50 | path_to_oopsid, prune_empty_oops_directories |
51 | ) |
52 | -from canonical.launchpad.webapp import errorlog |
53 | +from lp.services.log import uniquefileallocator |
54 | |
55 | class TestOopsPrune(unittest.TestCase): |
56 | layer = LaunchpadZopelessLayer |
57 | @@ -37,9 +37,11 @@ |
58 | # whole path rather than the path's basename. |
59 | self.oops_dir = tempfile.mkdtemp('.directory.with.dots') |
60 | |
61 | + # TODO: This should be in the errorlog tests, and calling into errorlog |
62 | + # methods. |
63 | # Create some fake OOPS files |
64 | self.today = datetime.now(tz=UTC) |
65 | - self.ages_ago = errorlog.epoch + timedelta(days=1) |
66 | + self.ages_ago = uniquefileallocator.epoch + timedelta(days=1) |
67 | self.awhile_ago = self.ages_ago + timedelta(days=1) |
68 | |
69 | for some_date in [self.today, self.ages_ago, self.awhile_ago]: |
70 | @@ -185,7 +187,7 @@ |
71 | found_oops_files.add( |
72 | path_to_oopsid(os.path.join(dirpath,filename)) |
73 | ) |
74 | - today_day_count = (self.today - errorlog.epoch).days + 1 |
75 | + today_day_count = (self.today - uniquefileallocator.epoch).days + 1 |
76 | self.failUnlessEqual( |
77 | found_oops_files, |
78 | set([ |
79 | |
80 | === modified file 'lib/canonical/launchpad/scripts/oops.py' |
81 | --- lib/canonical/launchpad/scripts/oops.py 2010-05-16 23:56:51 +0000 |
82 | +++ lib/canonical/launchpad/scripts/oops.py 2010-07-05 19:27:28 +0000 |
83 | @@ -19,9 +19,9 @@ |
84 | from pytz import utc |
85 | |
86 | from canonical.database.sqlbase import cursor |
87 | -from canonical.launchpad.webapp import errorlog |
88 | from canonical.launchpad.webapp.dbpolicy import SlaveOnlyDatabasePolicy |
89 | from lp.app.browser.stringformatter import FormattersAPI |
90 | +from lp.services.log import uniquefileallocator |
91 | |
92 | def referenced_oops(): |
93 | '''Return a set of OOPS codes that are referenced somewhere in the |
94 | @@ -77,7 +77,9 @@ |
95 | match = re.search('^(\d\d\d\d)-(\d\d+)-(\d\d+)$', date_str) |
96 | year, month, day = (int(bit) for bit in match.groups()) |
97 | oops_id = os.path.basename(path).split('.')[1] |
98 | - day = (datetime(year, month, day, tzinfo=utc) - errorlog.epoch).days + 1 |
99 | + # Should be making API calls not directly calculating. |
100 | + day = (datetime(year, month, day, tzinfo=utc) - \ |
101 | + uniquefileallocator.epoch).days + 1 |
102 | return '%d%s' % (day, oops_id) |
103 | |
104 | |
105 | |
106 | === modified file 'lib/canonical/launchpad/webapp/errorlog.py' |
107 | --- lib/canonical/launchpad/webapp/errorlog.py 2010-05-15 17:43:59 +0000 |
108 | +++ lib/canonical/launchpad/webapp/errorlog.py 2010-07-05 19:27:28 +0000 |
109 | @@ -38,16 +38,13 @@ |
110 | soft_timeout_expired) |
111 | from canonical.launchpad.webapp.interfaces import ( |
112 | IErrorReport, IErrorReportEvent, IErrorReportRequest) |
113 | +from lp.services.log.uniquefileallocator import UniqueFileAllocator |
114 | from canonical.launchpad.webapp.opstats import OpStats |
115 | |
116 | UTC = pytz.utc |
117 | |
118 | LAZR_OOPS_USER_REQUESTED_KEY = 'lazr.oops.user_requested' |
119 | |
120 | -# the section of the OOPS ID before the instance identifier is the |
121 | -# days since the epoch, which is defined as the start of 2006. |
122 | -epoch = datetime.datetime(2006, 01, 01, 00, 00, 00, tzinfo=UTC) |
123 | - |
124 | # Restrict the rate at which errors are sent to the Zope event Log |
125 | # (this does not affect generation of error reports). |
126 | _rate_restrict_pool = {} |
127 | @@ -242,75 +239,50 @@ |
128 | _ignored_exceptions_for_unauthenticated_users = set(['Unauthorized']) |
129 | _default_config_section = 'error_reports' |
130 | |
131 | - lasterrordir = None |
132 | - lastid = 0 |
133 | - |
134 | def __init__(self): |
135 | - self.lastid_lock = threading.Lock() |
136 | self.configure() |
137 | self._oops_messages = {} |
138 | self._oops_message_key_iter = ( |
139 | index for index, _ignored in enumerate(repeat(None))) |
140 | |
141 | def configure(self, section_name=None): |
142 | - """Configure the utility using the named section form the config. |
143 | + """Configure the utility using the named section from the config. |
144 | |
145 | The 'error_reports' section is used if section_name is None. |
146 | """ |
147 | if section_name is None: |
148 | section_name = self._default_config_section |
149 | - self.oops_prefix = config[section_name].oops_prefix |
150 | - self.error_dir = config[section_name].error_dir |
151 | self.copy_to_zlog = config[section_name].copy_to_zlog |
152 | - self.prefix = self.oops_prefix |
153 | + # Start a new UniqueFileAllocator to activate the new configuration. |
154 | + self.log_namer = UniqueFileAllocator( |
155 | + output_root=config[section_name].error_dir, |
156 | + log_type="OOPS", |
157 | + log_subtype=config[section_name].oops_prefix, |
158 | + ) |
159 | |
160 | def setOopsToken(self, token): |
161 | - """Append a string to the oops prefix. |
162 | - |
163 | - :param token: a string to append to a oops_prefix. |
164 | - Scripts that run multiple processes can append a string to |
165 | - the oops_prefix to create a unique identifier for each |
166 | - process. |
167 | - """ |
168 | - self.prefix = self.oops_prefix + token |
169 | - |
170 | - def _findLastOopsIdFilename(self, directory): |
171 | - """Find details of the last OOPS reported in the given directory. |
172 | - |
173 | - This function only considers OOPSes with the currently |
174 | - configured oops_prefix. |
175 | - |
176 | - :return: a tuple (oops_id, oops_filename), which will be (0, |
177 | - None) if no OOPS is found. |
178 | - """ |
179 | - prefix = self.prefix |
180 | - lastid = 0 |
181 | - lastfilename = None |
182 | - for filename in os.listdir(directory): |
183 | - oopsid = filename.rsplit('.', 1)[1] |
184 | - if not oopsid.startswith(prefix): |
185 | - continue |
186 | - oopsid = oopsid[len(prefix):] |
187 | - if oopsid.isdigit() and int(oopsid) > lastid: |
188 | - lastid = int(oopsid) |
189 | - lastfilename = filename |
190 | - return lastid, lastfilename |
191 | - |
192 | - def _findLastOopsId(self, directory): |
193 | - """Find the last error number used by this Launchpad instance. |
194 | - |
195 | - The purpose of this function is to not repeat sequence numbers |
196 | - if the Launchpad instance is restarted. |
197 | - |
198 | - This method is not thread safe, and only intended to be called |
199 | - from the constructor. |
200 | - """ |
201 | - return self._findLastOopsIdFilename(directory)[0] |
202 | + return self.log_namer.setToken(token) |
203 | + |
204 | + @property |
205 | + def oops_prefix(self): |
206 | + """Get the current effective oops prefix. |
207 | + |
208 | + This is the log subtype + anything set via setOopsToken. |
209 | + """ |
210 | + return self.log_namer.get_log_infix() |
211 | |
212 | def getOopsReport(self, time): |
213 | """Return the contents of the OOPS report logged at 'time'.""" |
214 | - oops_filename = self.getOopsFilename( |
215 | - self._findLastOopsId(self.errordir(time)), time) |
216 | + # How this works - get a serial that was logging in the dir |
217 | + # that logs for time are logged in. |
218 | + serial_from_time = self.log_namer._findHighestSerial( |
219 | + self.log_namer.output_dir(time)) |
220 | + # Calculate a filename which combines this most recent serial, |
221 | + # the current log_namer naming rules and the exact timestamp. |
222 | + oops_filename = self.log_namer.getFilename(serial_from_time, time) |
223 | + # Note that if there were no logs written, or if there were two |
224 | + # oops that matched the time window of directory on disk, this |
225 | + # call can raise an IOError. |
226 | oops_report = open(oops_filename, 'r') |
227 | try: |
228 | return ErrorReport.read(oops_report) |
229 | @@ -330,85 +302,21 @@ |
230 | Returns None if no OOPS is found. |
231 | """ |
232 | now = datetime.datetime.now(UTC) |
233 | - directory = self.errordir(now) |
234 | - oopsid, filename = self._findLastOopsIdFilename(directory) |
235 | + # Check today |
236 | + oopsid, filename = self.log_namer._findHighestSerialFilename(time=now) |
237 | if filename is None: |
238 | - directory = self.errordir(now - datetime.timedelta(days=1)) |
239 | - oopsid, filename = self._findLastOopsIdFilename(directory) |
240 | + # Check yesterday |
241 | + yesterday = now - datetime.timedelta(days=1) |
242 | + oopsid, filename = self.log_namer._findHighestSerialFilename( |
243 | + time=yesterday) |
244 | if filename is None: |
245 | return None |
246 | - oops_report = open(os.path.join(directory, filename), 'r') |
247 | + oops_report = open(filename, 'r') |
248 | try: |
249 | return ErrorReport.read(oops_report) |
250 | finally: |
251 | oops_report.close() |
252 | |
253 | - def errordir(self, now=None): |
254 | - """Find the directory to write error reports to. |
255 | - |
256 | - Error reports are written to subdirectories containing the |
257 | - date of the error. |
258 | - """ |
259 | - if now is not None: |
260 | - now = now.astimezone(UTC) |
261 | - else: |
262 | - now = datetime.datetime.now(UTC) |
263 | - date = now.strftime('%Y-%m-%d') |
264 | - errordir = os.path.join(self.error_dir, date) |
265 | - if errordir != self.lasterrordir: |
266 | - self.lastid_lock.acquire() |
267 | - try: |
268 | - self.lasterrordir = errordir |
269 | - # make sure the directory exists |
270 | - try: |
271 | - os.makedirs(errordir) |
272 | - except OSError, e: |
273 | - if e.errno != errno.EEXIST: |
274 | - raise |
275 | - self.lastid = self._findLastOopsId(errordir) |
276 | - finally: |
277 | - self.lastid_lock.release() |
278 | - return errordir |
279 | - |
280 | - def getOopsFilename(self, oops_id, time): |
281 | - """Get the filename for a given OOPS id and time.""" |
282 | - oops_prefix = self.prefix |
283 | - error_dir = self.errordir(time) |
284 | - second_in_day = time.hour * 3600 + time.minute * 60 + time.second |
285 | - return os.path.join( |
286 | - error_dir, '%05d.%s%s' % (second_in_day, oops_prefix, oops_id)) |
287 | - |
288 | - def newOopsId(self, now=None): |
289 | - """Returns an (oopsid, filename) pair for the next Oops ID |
290 | - |
291 | - The Oops ID is composed of a short string to identify the |
292 | - Launchpad instance followed by an ID that is unique for the |
293 | - day. |
294 | - |
295 | - The filename is composed of the zero padded second in the day |
296 | - followed by the Oops ID. This ensures that error reports are |
297 | - in date order when sorted lexically. |
298 | - """ |
299 | - if now is not None: |
300 | - now = now.astimezone(UTC) |
301 | - else: |
302 | - now = datetime.datetime.now(UTC) |
303 | - # We look up the error directory before allocating a new ID, |
304 | - # because if the day has changed, errordir() will reset the ID |
305 | - # counter to zero. |
306 | - self.errordir(now) |
307 | - self.lastid_lock.acquire() |
308 | - try: |
309 | - self.lastid += 1 |
310 | - newid = self.lastid |
311 | - finally: |
312 | - self.lastid_lock.release() |
313 | - oops_prefix = self.prefix |
314 | - day_number = (now - epoch).days + 1 |
315 | - oops = 'OOPS-%d%s%d' % (day_number, oops_prefix, newid) |
316 | - filename = self.getOopsFilename(newid, now) |
317 | - return oops, filename |
318 | - |
319 | def raising(self, info, request=None, now=None): |
320 | """See IErrorReportingUtility.raising() |
321 | |
322 | @@ -423,8 +331,7 @@ |
323 | entry = self._makeErrorReport(info, request, now, informational) |
324 | if entry is None: |
325 | return |
326 | - # As a side-effect, _makeErrorReport updates self.lastid. |
327 | - filename = self.getOopsFilename(self.lastid, entry.time) |
328 | + filename = entry._filename |
329 | entry.write(open(filename, 'wb')) |
330 | if request: |
331 | request.oopsid = entry.id |
332 | @@ -439,7 +346,6 @@ |
333 | informational=False): |
334 | """Return an ErrorReport for the supplied data. |
335 | |
336 | - As a side-effect, self.lastid is updated to the integer oops id. |
337 | :param info: Output of sys.exc_info() |
338 | :param request: The IErrorReportRequest which provides context to the |
339 | info. |
340 | @@ -534,11 +440,14 @@ |
341 | for (start, end, database_id, statement) |
342 | in get_request_statements()) |
343 | |
344 | - oopsid, filename = self.newOopsId(now) |
345 | - return ErrorReport(oopsid, strtype, strv, now, pageid, tb_text, |
346 | + oopsid, filename = self.log_namer.newId(now) |
347 | + |
348 | + result = ErrorReport(oopsid, strtype, strv, now, pageid, tb_text, |
349 | username, strurl, duration, |
350 | req_vars, statements, |
351 | informational) |
352 | + result._filename = filename |
353 | + return result |
354 | |
355 | def handling(self, info, request=None, now=None): |
356 | """Flag ErrorReport as informational only. |
357 | |
358 | === modified file 'lib/canonical/launchpad/webapp/tests/test_errorlog.py' |
359 | --- lib/canonical/launchpad/webapp/tests/test_errorlog.py 2010-05-04 13:22:15 +0000 |
360 | +++ lib/canonical/launchpad/webapp/tests/test_errorlog.py 2010-07-05 19:27:28 +0000 |
361 | @@ -18,6 +18,7 @@ |
362 | import unittest |
363 | |
364 | import pytz |
365 | +import testtools |
366 | |
367 | from zope.app.publication.tests.test_zopepublication import ( |
368 | UnauthenticatedPrincipal) |
369 | @@ -37,6 +38,7 @@ |
370 | from canonical.launchpad.webapp.interfaces import ( |
371 | NoReferrerError, TranslationUnavailable) |
372 | from lazr.restful.declarations import webservice_error |
373 | +from lp.services.log.uniquefileallocator import UniqueFileAllocator |
374 | from lp.services.osutils import remove_tree |
375 | from lp.testing import TestCase |
376 | |
377 | @@ -48,10 +50,11 @@ |
378 | """Used to test handling of exceptions in OOPS reports.""" |
379 | |
380 | |
381 | -class TestErrorReport(unittest.TestCase): |
382 | +class TestErrorReport(testtools.TestCase): |
383 | |
384 | def tearDown(self): |
385 | reset_logging() |
386 | + super(TestErrorReport, self).tearDown() |
387 | |
388 | def test___init__(self): |
389 | """Test ErrorReport.__init__()""" |
390 | @@ -208,8 +211,9 @@ |
391 | self.assertEqual(entry.db_statements[1], (5, 10, None, 'SELECT 2')) |
392 | |
393 | |
394 | -class TestErrorReportingUtility(unittest.TestCase): |
395 | +class TestErrorReportingUtility(testtools.TestCase): |
396 | def setUp(self): |
397 | + super(TestErrorReportingUtility, self).setUp() |
398 | # ErrorReportingUtility reads the global config to get the |
399 | # current error directory. |
400 | test_data = dedent(""" |
401 | @@ -224,138 +228,51 @@ |
402 | shutil.rmtree(config.error_reports.error_dir, ignore_errors=True) |
403 | config.pop('test_data') |
404 | reset_logging() |
405 | + super(TestErrorReportingUtility, self).tearDown() |
406 | + |
407 | + def test_sets_log_namer_to_a_UniqueFileAllocator(self): |
408 | + utility = ErrorReportingUtility() |
409 | + self.assertIsInstance(utility.log_namer, UniqueFileAllocator) |
410 | |
411 | def test_configure(self): |
412 | """Test ErrorReportingUtility.setConfigSection().""" |
413 | utility = ErrorReportingUtility() |
414 | # The ErrorReportingUtility uses the config.error_reports section |
415 | # by default. |
416 | - self.assertEqual(config.error_reports.oops_prefix, utility.prefix) |
417 | - self.assertEqual(config.error_reports.error_dir, utility.error_dir) |
418 | + self.assertEqual(config.error_reports.oops_prefix, |
419 | + utility.oops_prefix) |
420 | + self.assertEqual(config.error_reports.error_dir, |
421 | + utility.log_namer._output_root) |
422 | self.assertEqual( |
423 | config.error_reports.copy_to_zlog, utility.copy_to_zlog) |
424 | # Some external processes may use another config section to |
425 | # provide the error log configuration. |
426 | utility.configure(section_name='branchscanner') |
427 | - self.assertEqual(config.branchscanner.oops_prefix, utility.prefix) |
428 | - self.assertEqual(config.branchscanner.error_dir, utility.error_dir) |
429 | + self.assertEqual(config.branchscanner.oops_prefix, |
430 | + utility.oops_prefix) |
431 | + self.assertEqual(config.branchscanner.error_dir, |
432 | + utility.log_namer._output_root) |
433 | self.assertEqual( |
434 | config.branchscanner.copy_to_zlog, utility.copy_to_zlog) |
435 | |
436 | # The default error section can be restored. |
437 | utility.configure() |
438 | - self.assertEqual(config.error_reports.oops_prefix, utility.prefix) |
439 | - self.assertEqual(config.error_reports.error_dir, utility.error_dir) |
440 | + self.assertEqual(config.error_reports.oops_prefix, |
441 | + utility.oops_prefix) |
442 | + self.assertEqual(config.error_reports.error_dir, |
443 | + utility.log_namer._output_root) |
444 | self.assertEqual( |
445 | config.error_reports.copy_to_zlog, utility.copy_to_zlog) |
446 | |
447 | def test_setOopsToken(self): |
448 | """Test ErrorReportingUtility.setOopsToken().""" |
449 | utility = ErrorReportingUtility() |
450 | - default_prefix = config.error_reports.oops_prefix |
451 | - self.assertEqual('T', default_prefix) |
452 | - self.assertEqual('T', utility.prefix) |
453 | - |
454 | - # Some scripts will append a string token to the prefix. |
455 | - utility.setOopsToken('CW') |
456 | - self.assertEqual('TCW', utility.prefix) |
457 | - |
458 | + utility.setOopsToken('foo') |
459 | + self.assertEqual('Tfoo', utility.oops_prefix) |
460 | # Some scripts run multiple processes and append a string number |
461 | # to the prefix. |
462 | utility.setOopsToken('1') |
463 | - self.assertEqual('T1', utility.prefix) |
464 | - |
465 | - def test_newOopsId(self): |
466 | - """Test ErrorReportingUtility.newOopsId()""" |
467 | - utility = ErrorReportingUtility() |
468 | - |
469 | - errordir = config.error_reports.error_dir |
470 | - |
471 | - # first oops of the day |
472 | - now = datetime.datetime(2006, 04, 01, 00, 30, 00, tzinfo=UTC) |
473 | - oopsid, filename = utility.newOopsId(now) |
474 | - self.assertEqual(oopsid, 'OOPS-91T1') |
475 | - self.assertEqual(filename, |
476 | - os.path.join(errordir, '2006-04-01/01800.T1')) |
477 | - self.assertEqual(utility.lastid, 1) |
478 | - self.assertEqual( |
479 | - utility.lasterrordir, os.path.join(errordir, '2006-04-01')) |
480 | - |
481 | - # second oops of the day |
482 | - now = datetime.datetime(2006, 04, 01, 12, 00, 00, tzinfo=UTC) |
483 | - oopsid, filename = utility.newOopsId(now) |
484 | - self.assertEqual(oopsid, 'OOPS-91T2') |
485 | - self.assertEqual(filename, |
486 | - os.path.join(errordir, '2006-04-01/43200.T2')) |
487 | - self.assertEqual(utility.lastid, 2) |
488 | - self.assertEqual( |
489 | - utility.lasterrordir, os.path.join(errordir, '2006-04-01')) |
490 | - |
491 | - # first oops of following day |
492 | - now = datetime.datetime(2006, 04, 02, 00, 30, 00, tzinfo=UTC) |
493 | - oopsid, filename = utility.newOopsId(now) |
494 | - self.assertEqual(oopsid, 'OOPS-92T1') |
495 | - self.assertEqual(filename, |
496 | - os.path.join(errordir, '2006-04-02/01800.T1')) |
497 | - self.assertEqual(utility.lastid, 1) |
498 | - self.assertEqual( |
499 | - utility.lasterrordir, os.path.join(errordir, '2006-04-02')) |
500 | - |
501 | - # The oops_prefix honours setOopsToken(). |
502 | - utility.setOopsToken('XXX') |
503 | - oopsid, filename = utility.newOopsId(now) |
504 | - self.assertEqual(oopsid, 'OOPS-92TXXX2') |
505 | - |
506 | - # Another oops with a native datetime. |
507 | - now = datetime.datetime(2006, 04, 02, 00, 30, 00) |
508 | - self.assertRaises(ValueError, utility.newOopsId, now) |
509 | - |
510 | - def test_changeErrorDir(self): |
511 | - """Test changing the error dir using the global config.""" |
512 | - utility = ErrorReportingUtility() |
513 | - errordir = utility.error_dir |
514 | - |
515 | - # First an oops in the original error directory. |
516 | - now = datetime.datetime(2006, 04, 01, 00, 30, 00, tzinfo=UTC) |
517 | - oopsid, filename = utility.newOopsId(now) |
518 | - self.assertEqual(utility.lastid, 1) |
519 | - self.assertEqual( |
520 | - utility.lasterrordir, os.path.join(errordir, '2006-04-01')) |
521 | - |
522 | - # ErrorReportingUtility uses the error_dir attribute to |
523 | - # get the current error directory. |
524 | - new_errordir = tempfile.mkdtemp() |
525 | - utility.error_dir = new_errordir |
526 | - |
527 | - # Now an oops on the same day, in the new directory. |
528 | - now = datetime.datetime(2006, 04, 01, 12, 00, 00, tzinfo=UTC) |
529 | - oopsid, filename = utility.newOopsId(now) |
530 | - |
531 | - # Since it's a new directory, with no previous oops reports, the |
532 | - # id is 1 again, rather than 2. |
533 | - self.assertEqual(oopsid, 'OOPS-91T1') |
534 | - self.assertEqual(utility.lastid, 1) |
535 | - self.assertEqual( |
536 | - utility.lasterrordir, os.path.join(new_errordir, '2006-04-01')) |
537 | - |
538 | - shutil.rmtree(new_errordir, ignore_errors=True) |
539 | - |
540 | - def test_findLastOopsId(self): |
541 | - """Test ErrorReportingUtility._findLastOopsId()""" |
542 | - utility = ErrorReportingUtility() |
543 | - |
544 | - self.assertEqual(config.error_reports.oops_prefix, 'T') |
545 | - |
546 | - errordir = utility.errordir() |
547 | - # write some files |
548 | - open(os.path.join(errordir, '12343.T1'), 'w').close() |
549 | - open(os.path.join(errordir, '12342.T2'), 'w').close() |
550 | - open(os.path.join(errordir, '12345.T3'), 'w').close() |
551 | - open(os.path.join(errordir, '1234567.T0010'), 'w').close() |
552 | - open(os.path.join(errordir, '12346.A42'), 'w').close() |
553 | - open(os.path.join(errordir, '12346.B100'), 'w').close() |
554 | - |
555 | - self.assertEqual(utility._findLastOopsId(errordir), 10) |
556 | + self.assertEqual('T1', utility.oops_prefix) |
557 | |
558 | def test_raising(self): |
559 | """Test ErrorReportingUtility.raising() with no request""" |
560 | @@ -367,7 +284,7 @@ |
561 | except ArbitraryException: |
562 | utility.raising(sys.exc_info(), now=now) |
563 | |
564 | - errorfile = os.path.join(utility.errordir(now), '01800.T1') |
565 | + errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1') |
566 | self.assertTrue(os.path.exists(errorfile)) |
567 | lines = open(errorfile, 'r').readlines() |
568 | |
569 | @@ -421,7 +338,7 @@ |
570 | except ArbitraryException: |
571 | utility.raising(sys.exc_info(), request, now=now) |
572 | |
573 | - errorfile = os.path.join(utility.errordir(now), '01800.T1') |
574 | + errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1') |
575 | self.assertTrue(os.path.exists(errorfile)) |
576 | lines = open(errorfile, 'r').readlines() |
577 | |
578 | @@ -483,7 +400,7 @@ |
579 | raise ArbitraryException('xyz\nabc') |
580 | except ArbitraryException: |
581 | utility.raising(sys.exc_info(), request, now=now) |
582 | - errorfile = os.path.join(utility.errordir(now), '01800.T1') |
583 | + errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1') |
584 | self.assertTrue(os.path.exists(errorfile)) |
585 | lines = open(errorfile, 'r').readlines() |
586 | self.assertEqual(lines[16], 'xmlrpc args=(1, 2)\n') |
587 | @@ -538,7 +455,7 @@ |
588 | ('name1', 'value3')], URL='https://launchpad.net/example') |
589 | utility.raising(sys.exc_info(), request, now=now) |
590 | |
591 | - errorfile = os.path.join(utility.errordir(now), '01800.T1') |
592 | + errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1') |
593 | self.assertTrue(os.path.exists(errorfile)) |
594 | lines = open(errorfile, 'r').readlines() |
595 | |
596 | @@ -591,7 +508,7 @@ |
597 | utility.raising(sys.exc_info(), now=now) |
598 | log.uninstall() |
599 | |
600 | - errorfile = os.path.join(utility.errordir(now), '01800.T1') |
601 | + errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1') |
602 | self.assertTrue(os.path.exists(errorfile)) |
603 | lines = open(errorfile, 'r').readlines() |
604 | |
605 | @@ -634,7 +551,7 @@ |
606 | raise Unauthorized('xyz') |
607 | except Unauthorized: |
608 | utility.raising(sys.exc_info(), now=now) |
609 | - errorfile = os.path.join(utility.errordir(now), '01800.T1') |
610 | + errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1') |
611 | self.failUnless(os.path.exists(errorfile)) |
612 | |
613 | def test_raising_unauthorized_without_principal(self): |
614 | @@ -647,7 +564,7 @@ |
615 | raise Unauthorized('xyz') |
616 | except Unauthorized: |
617 | utility.raising(sys.exc_info(), request, now=now) |
618 | - errorfile = os.path.join(utility.errordir(now), '01800.T1') |
619 | + errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1') |
620 | self.failUnless(os.path.exists(errorfile)) |
621 | |
622 | def test_raising_unauthorized_with_unauthenticated_principal(self): |
623 | @@ -660,7 +577,7 @@ |
624 | raise Unauthorized('xyz') |
625 | except Unauthorized: |
626 | utility.raising(sys.exc_info(), request, now=now) |
627 | - errorfile = os.path.join(utility.errordir(now), '01800.T1') |
628 | + errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1') |
629 | self.failIf(os.path.exists(errorfile)) |
630 | |
631 | def test_raising_unauthorized_with_authenticated_principal(self): |
632 | @@ -673,7 +590,7 @@ |
633 | raise Unauthorized('xyz') |
634 | except Unauthorized: |
635 | utility.raising(sys.exc_info(), request, now=now) |
636 | - errorfile = os.path.join(utility.errordir(now), '01800.T1') |
637 | + errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1') |
638 | self.failUnless(os.path.exists(errorfile)) |
639 | |
640 | def test_raising_translation_unavailable(self): |
641 | @@ -691,7 +608,7 @@ |
642 | except TranslationUnavailable: |
643 | utility.raising(sys.exc_info(), now=now) |
644 | |
645 | - errorfile = os.path.join(utility.errordir(now), '01800.T1') |
646 | + errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1') |
647 | self.assertFalse(os.path.exists(errorfile)) |
648 | |
649 | def test_raising_no_referrer_error(self): |
650 | @@ -709,7 +626,7 @@ |
651 | except NoReferrerError: |
652 | utility.raising(sys.exc_info(), now=now) |
653 | |
654 | - errorfile = os.path.join(utility.errordir(now), '01800.T1') |
655 | + errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1') |
656 | self.assertFalse(os.path.exists(errorfile)) |
657 | |
658 | def test_raising_with_string_as_traceback(self): |
659 | @@ -729,7 +646,7 @@ |
660 | exc_tb = traceback.format_exc() |
661 | |
662 | utility.raising((exc_type, exc_value, exc_tb), now=now) |
663 | - errorfile = os.path.join(utility.errordir(now), '01800.T1') |
664 | + errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1') |
665 | |
666 | self.assertTrue(os.path.exists(errorfile)) |
667 | lines = open(errorfile, 'r').readlines() |
668 | @@ -767,7 +684,7 @@ |
669 | except ArbitraryException: |
670 | utility.handling(sys.exc_info(), now=now) |
671 | |
672 | - errorfile = os.path.join(utility.errordir(now), '01800.T1') |
673 | + errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1') |
674 | self.assertTrue(os.path.exists(errorfile)) |
675 | lines = open(errorfile, 'r').readlines() |
676 | |
677 | @@ -842,7 +759,7 @@ |
678 | oops.req_vars) |
679 | |
680 | |
681 | -class TestSensitiveRequestVariables(unittest.TestCase): |
682 | +class TestSensitiveRequestVariables(testtools.TestCase): |
683 | """Test request variables that should not end up in the stored OOPS. |
684 | |
685 | The _is_sensitive() method will return True for any variable name that |
686 | @@ -904,10 +821,10 @@ |
687 | TestCase.setUp(self) |
688 | self.logger = logging.getLogger(self.factory.getUniqueString()) |
689 | self.error_utility = ErrorReportingUtility() |
690 | - self.error_utility.error_dir = tempfile.mkdtemp() |
691 | + self.error_utility.log_namer._output_root = tempfile.mkdtemp() |
692 | self.logger.addHandler( |
693 | OopsLoggingHandler(error_utility=self.error_utility)) |
694 | - self.addCleanup(remove_tree, self.error_utility.error_dir) |
695 | + self.addCleanup(remove_tree, self.error_utility.log_namer._output_root) |
696 | |
697 | def test_exception_records_oops(self): |
698 | # When OopsLoggingHandler is a handler for a logger, any exceptions |
699 | @@ -935,7 +852,3 @@ |
700 | |
701 | def test_suite(): |
702 | return unittest.TestLoader().loadTestsFromName(__name__) |
703 | - |
704 | - |
705 | -if __name__ == '__main__': |
706 | - unittest.main(defaultTest='test_suite') |
707 | |
708 | === modified file 'lib/lp/services/job/tests/test_runner.py' |
709 | --- lib/lp/services/job/tests/test_runner.py 2010-05-03 02:37:30 +0000 |
710 | +++ lib/lp/services/job/tests/test_runner.py 2010-07-05 19:27:28 +0000 |
711 | @@ -406,6 +406,7 @@ |
712 | def runFromSource(cls, source, dbuser, logger): |
713 | expected_config = errorlog.ErrorReportingUtility() |
714 | expected_config.configure('merge_proposal_jobs') |
715 | + # Check that the unique oops token was applied. |
716 | self.assertEqual( |
717 | errorlog.globalErrorUtility.oops_prefix, |
718 | expected_config.oops_prefix) |
719 | |
720 | === added directory 'lib/lp/services/log' |
721 | === added file 'lib/lp/services/log/__init__.py' |
722 | --- lib/lp/services/log/__init__.py 1970-01-01 00:00:00 +0000 |
723 | +++ lib/lp/services/log/__init__.py 2010-07-05 19:27:28 +0000 |
724 | @@ -0,0 +1,11 @@ |
725 | +# Copyright 2010 Canonical Ltd. This software is licensed under the |
726 | +# GNU Affero General Public License version 3 (see the file LICENSE). |
727 | + |
728 | +"""lp.services.log provides log-like facilities. |
729 | + |
730 | +Consider putting infrastructure that is used for getting logs or diagnostics |
731 | +out of Launchpad and onto some external store in here. |
732 | + |
733 | +Because this part of lp.services, packages in this namespace can only use |
734 | +general LAZR or library functionality. |
735 | +""" |
736 | |
737 | === added directory 'lib/lp/services/log/tests' |
738 | === added file 'lib/lp/services/log/tests/__init__.py' |
739 | --- lib/lp/services/log/tests/__init__.py 1970-01-01 00:00:00 +0000 |
740 | +++ lib/lp/services/log/tests/__init__.py 2010-07-05 19:27:28 +0000 |
741 | @@ -0,0 +1,4 @@ |
742 | +# Copyright 2010 Canonical Ltd. This software is licensed under the |
743 | +# GNU Affero General Public License version 3 (see the file LICENSE). |
744 | + |
745 | +"""Tests for lp.services.log.""" |
746 | |
747 | === added file 'lib/lp/services/log/tests/test_uniquefileallocator.py' |
748 | --- lib/lp/services/log/tests/test_uniquefileallocator.py 1970-01-01 00:00:00 +0000 |
749 | +++ lib/lp/services/log/tests/test_uniquefileallocator.py 2010-07-05 19:27:28 +0000 |
750 | @@ -0,0 +1,139 @@ |
751 | +# Copyright 2010 Canonical Ltd. This software is licensed under the |
752 | +# GNU Affero General Public License version 3 (see the file LICENSE). |
753 | + |
754 | +"""Tests for the unique log naming facility.""" |
755 | + |
756 | +from __future__ import with_statement |
757 | +__metaclass__ = type |
758 | + |
759 | +import datetime |
760 | +import os |
761 | +import shutil |
762 | +import tempfile |
763 | +import unittest |
764 | + |
765 | +import pytz |
766 | +import testtools |
767 | + |
768 | +from lp.services.log.uniquefileallocator import UniqueFileAllocator |
769 | + |
770 | + |
771 | +UTC = pytz.timezone('UTC') |
772 | + |
773 | + |
774 | +class TestUniqueFileAllocator(testtools.TestCase): |
775 | + |
776 | + def setUp(self): |
777 | + super(TestUniqueFileAllocator, self).setUp() |
778 | + tempdir = tempfile.mkdtemp() |
779 | + self._tempdir = tempdir |
780 | + self.addCleanup(shutil.rmtree, tempdir, ignore_errors=True) |
781 | + |
782 | + def test_setToken(self): |
783 | + namer = UniqueFileAllocator("/any-old/path/", 'OOPS', 'T') |
784 | + self.assertEqual('T', namer.get_log_infix()) |
785 | + |
786 | + # Some scripts will append a string token to the prefix. |
787 | + namer.setToken('CW') |
788 | + self.assertEqual('TCW', namer.get_log_infix()) |
789 | + |
790 | + # Some scripts run multiple processes and append a string number |
791 | + # to the prefix. |
792 | + namer.setToken('1') |
793 | + self.assertEqual('T1', namer.get_log_infix()) |
794 | + |
795 | + def assertUniqueFileAllocator(self, namer, now, expected_id, |
796 | + expected_last_id, expected_suffix, expected_lastdir): |
797 | + logid, filename = namer.newId(now) |
798 | + self.assertEqual(logid, expected_id) |
799 | + self.assertEqual(filename, |
800 | + os.path.join(namer._output_root, expected_suffix)) |
801 | + self.assertEqual(namer._last_serial, expected_last_id) |
802 | + self.assertEqual(namer._last_output_dir, |
803 | + os.path.join(namer._output_root, expected_lastdir)) |
804 | + |
805 | + def test_newId(self): |
806 | + # TODO: This should return an id, fileobj instead of a file name, to |
807 | + # reduce races with threads that are slow to use what they asked for, |
808 | + # when combined with configuration changes causing disk scans. That |
809 | + # would also permit using a completely stubbed out file system, |
810 | + # reducing IO in tests that use UniqueFileAllocator (such as all the |
811 | + # pagetests in Launchpad. At that point an interface to obtain a |
812 | + # factory of UniqueFileAllocator's would be useful to parameterise the |
813 | + # entire test suite. |
814 | + namer = UniqueFileAllocator(self._tempdir, 'OOPS', 'T') |
815 | + # first name of the day |
816 | + self.assertUniqueFileAllocator(namer, |
817 | + datetime.datetime(2006, 04, 01, 00, 30, 00, tzinfo=UTC), |
818 | + 'OOPS-91T1', 1, '2006-04-01/01800.T1', '2006-04-01') |
819 | + # second name of the day |
820 | + self.assertUniqueFileAllocator(namer, |
821 | + datetime.datetime(2006, 04, 01, 12, 00, 00, tzinfo=UTC), |
822 | + 'OOPS-91T2', 2, '2006-04-01/43200.T2', '2006-04-01') |
823 | + |
824 | + # first name of the following day sets a new dir and the id starts |
825 | + # over. |
826 | + self.assertUniqueFileAllocator(namer, |
827 | + datetime.datetime(2006, 04, 02, 00, 30, 00, tzinfo=UTC), |
828 | + 'OOPS-92T1', 1, '2006-04-02/01800.T1', '2006-04-02') |
829 | + |
830 | + # Setting a token inserts the token into the filename. |
831 | + namer.setToken('YYY') |
832 | + logid, filename = namer.newId( |
833 | + datetime.datetime(2006, 04, 02, 00, 30, 00, tzinfo=UTC)) |
834 | + self.assertEqual(logid, 'OOPS-92TYYY2') |
835 | + |
836 | + # Setting a type controls the log id: |
837 | + namer.setToken('') |
838 | + namer._log_type = "PROFILE" |
839 | + logid, filename = namer.newId( |
840 | + datetime.datetime(2006, 04, 02, 00, 30, 00, tzinfo=UTC)) |
841 | + self.assertEqual(logid, 'PROFILE-92T3') |
842 | + |
843 | + # Native timestamps are not permitted - UTC only. |
844 | + now = datetime.datetime(2006, 04, 02, 00, 30, 00) |
845 | + self.assertRaises(ValueError, namer.newId, now) |
846 | + |
847 | + def test_changeErrorDir(self): |
848 | + """Test changing the log output dur.""" |
849 | + namer = UniqueFileAllocator(self._tempdir, 'OOPS', 'T') |
850 | + |
851 | + # First an id in the original error directory. |
852 | + self.assertUniqueFileAllocator(namer, |
853 | + datetime.datetime(2006, 04, 01, 00, 30, 00, tzinfo=UTC), |
854 | + 'OOPS-91T1', 1, '2006-04-01/01800.T1', '2006-04-01') |
855 | + |
856 | + # UniqueFileAllocator uses the _output_root attribute to get the current output |
857 | + # directory. |
858 | + new_output_dir = tempfile.mkdtemp() |
859 | + self.addCleanup(shutil.rmtree, new_output_dir, ignore_errors=True) |
860 | + namer._output_root = new_output_dir |
861 | + |
862 | + # Now an id on the same day, in the new directory. |
863 | + now = datetime.datetime(2006, 04, 01, 12, 00, 00, tzinfo=UTC) |
864 | + log_id, filename = namer.newId(now) |
865 | + |
866 | + # Since it's a new directory, with no previous logs, the id is 1 again, |
867 | + # rather than 2. |
868 | + self.assertEqual(log_id, 'OOPS-91T1') |
869 | + self.assertEqual(namer._last_serial, 1) |
870 | + self.assertEqual(namer._last_output_dir, |
871 | + os.path.join(new_output_dir, '2006-04-01')) |
872 | + |
873 | + def test_findHighestSerial(self): |
874 | + namer = UniqueFileAllocator(self._tempdir, "OOPS", "T") |
875 | + # Creates the dir using now as the timestamp. |
876 | + output_dir = namer.output_dir() |
877 | + # write some files, in non-serial order. |
878 | + open(os.path.join(output_dir, '12343.T1'), 'w').close() |
879 | + open(os.path.join(output_dir, '12342.T2'), 'w').close() |
880 | + open(os.path.join(output_dir, '12345.T3'), 'w').close() |
881 | + open(os.path.join(output_dir, '1234567.T0010'), 'w').close() |
882 | + open(os.path.join(output_dir, '12346.A42'), 'w').close() |
883 | + open(os.path.join(output_dir, '12346.B100'), 'w').close() |
884 | + # The namer should figure out the right highest serial. |
885 | + self.assertEqual(namer._findHighestSerial(output_dir), 10) |
886 | + |
887 | + |
888 | +def test_suite(): |
889 | + return unittest.TestLoader().loadTestsFromName(__name__) |
890 | |
891 | === added file 'lib/lp/services/log/uniquefileallocator.py' |
892 | --- lib/lp/services/log/uniquefileallocator.py 1970-01-01 00:00:00 +0000 |
893 | +++ lib/lp/services/log/uniquefileallocator.py 2010-07-05 19:27:28 +0000 |
894 | @@ -0,0 +1,182 @@ |
895 | +# Copyright 2010 Canonical Ltd. This software is licensed under the |
896 | +# GNU Affero General Public License version 3 (see the file LICENSE). |
897 | + |
898 | +"""Create uniquely named log files on disk.""" |
899 | + |
900 | + |
901 | +__all__ = ['UniqueFileAllocator'] |
902 | + |
903 | +__metaclass__ = type |
904 | + |
905 | + |
906 | +import datetime |
907 | +import errno |
908 | +import os.path |
909 | +import threading |
910 | +import time |
911 | + |
912 | +import pytz |
913 | +UTC = pytz.utc |
914 | + |
915 | +# the section of the ID before the instance identifier is the |
916 | +# days since the epoch, which is defined as the start of 2006. |
917 | +epoch = datetime.datetime(2006, 01, 01, 00, 00, 00, tzinfo=UTC) |
918 | + |
919 | + |
920 | +class UniqueFileAllocator: |
921 | + """Assign unique file names to logs being written from an app/script. |
922 | + |
923 | + UniqueFileAllocator causes logs written from one process to be uniquely |
924 | + named. It is not safe for use in multiple processes with the same output |
925 | + root - each process must have a unique output root. |
926 | + """ |
927 | + |
928 | + def __init__(self, output_root, log_type, log_subtype): |
929 | + """Create a UniqueFileAllocator. |
930 | + |
931 | + :param output_root: The root directory that logs should be placed in. |
932 | + :param log_type: A string to use as a prefix in the ID assigned to new |
933 | + logs. For instance, "OOPS". |
934 | + :param log_subtype: A string to insert in the generate log filenames |
935 | + between the day number and the serial. For instance "T" for |
936 | + "Testing". |
937 | + """ |
938 | + self._lock = threading.Lock() |
939 | + self._output_root = output_root |
940 | + self._last_serial = 0 |
941 | + self._last_output_dir = None |
942 | + self._log_type = log_type |
943 | + self._log_subtype = log_subtype |
944 | + self._log_token = "" |
945 | + |
946 | + def _findHighestSerialFilename(self, directory=None, time=None): |
947 | + """Find details of the last log present in the given directory. |
948 | + |
949 | + This function only considers logs with the currently |
950 | + configured log_subtype. |
951 | + |
952 | + One of directory, time must be supplied. |
953 | + |
954 | + :param directory: Look in this directory. |
955 | + :param time: Look in the directory that a log written at this time |
956 | + would have been written to. If supplied, supercedes directory. |
957 | + :return: a tuple (log_serial, log_filename), which will be (0, |
958 | + None) if no logs are found. log_filename is a usable path, not |
959 | + simply the basename. |
960 | + """ |
961 | + if directory is None: |
962 | + directory = self.output_dir(time) |
963 | + prefix = self.get_log_infix() |
964 | + lastid = 0 |
965 | + lastfilename = None |
966 | + for filename in os.listdir(directory): |
967 | + logid = filename.rsplit('.', 1)[1] |
968 | + if not logid.startswith(prefix): |
969 | + continue |
970 | + logid = logid[len(prefix):] |
971 | + if logid.isdigit() and (lastid is None or int(logid) > lastid): |
972 | + lastid = int(logid) |
973 | + lastfilename = filename |
974 | + if lastfilename is not None: |
975 | + lastfilename = os.path.join(directory, lastfilename) |
976 | + return lastid, lastfilename |
977 | + |
978 | + def _findHighestSerial(self, directory): |
979 | + """Find the last serial actually applied to disk in directory. |
980 | + |
981 | + The purpose of this function is to not repeat sequence numbers |
982 | + if the logging application is restarted. |
983 | + |
984 | + This method is not thread safe, and only intended to be called |
985 | + from the constructor (but it is called from other places in integration |
986 | + tests). |
987 | + """ |
988 | + return self._findHighestSerialFilename(directory)[0] |
989 | + |
990 | + def getFilename(self, log_serial, time): |
991 | + """Get the filename for a given log serial and time.""" |
992 | + log_subtype = self.get_log_infix() |
993 | + # TODO: Calling output_dir causes a global lock to be taken and a |
994 | + # directory scan, which is bad for performance. It would be better |
995 | + # to have a split out 'directory name for time' function which the |
996 | + # 'want to use this directory now' function can call. |
997 | + output_dir = self.output_dir(time) |
998 | + second_in_day = time.hour * 3600 + time.minute * 60 + time.second |
999 | + return os.path.join( |
1000 | + output_dir, '%05d.%s%s' % (second_in_day, log_subtype, log_serial)) |
1001 | + |
1002 | + def get_log_infix(self): |
1003 | + """Return the current log infix to use in ids and file names.""" |
1004 | + return self._log_subtype + self._log_token |
1005 | + |
1006 | + def newId(self, now=None): |
1007 | + """Returns an (id, filename) pair for use by the caller. |
1008 | + |
1009 | + The ID is composed of a short string to identify the Launchpad instance |
1010 | + followed by an ID that is unique for the day. |
1011 | + |
1012 | + The filename is composed of the zero padded second in the day |
1013 | + followed by the ID. This ensures that reports are in date order when |
1014 | + sorted lexically. |
1015 | + """ |
1016 | + if now is not None: |
1017 | + now = now.astimezone(UTC) |
1018 | + else: |
1019 | + now = datetime.datetime.now(UTC) |
1020 | + # We look up the error directory before allocating a new ID, |
1021 | + # because if the day has changed, errordir() will reset the ID |
1022 | + # counter to zero. |
1023 | + self.output_dir(now) |
1024 | + self._lock.acquire() |
1025 | + try: |
1026 | + self._last_serial += 1 |
1027 | + newid = self._last_serial |
1028 | + finally: |
1029 | + self._lock.release() |
1030 | + subtype = self.get_log_infix() |
1031 | + day_number = (now - epoch).days + 1 |
1032 | + log_id = '%s-%d%s%d' % (self._log_type, day_number, subtype, newid) |
1033 | + filename = self.getFilename(newid, now) |
1034 | + return log_id, filename |
1035 | + |
1036 | + def output_dir(self, now=None): |
1037 | + """Find or make the directory to allocate log names in. |
1038 | + |
1039 | + Log names are assigned within subdirectories containing the date the |
1040 | + assignment happened. |
1041 | + """ |
1042 | + if now is not None: |
1043 | + now = now.astimezone(UTC) |
1044 | + else: |
1045 | + now = datetime.datetime.now(UTC) |
1046 | + date = now.strftime('%Y-%m-%d') |
1047 | + result = os.path.join(self._output_root, date) |
1048 | + if result != self._last_output_dir: |
1049 | + self._lock.acquire() |
1050 | + try: |
1051 | + self._last_output_dir = result |
1052 | + # make sure the directory exists |
1053 | + try: |
1054 | + os.makedirs(result) |
1055 | + except OSError, e: |
1056 | + if e.errno != errno.EEXIST: |
1057 | + raise |
1058 | + # TODO: Note that only one process can do this safely: its not |
1059 | + # cross-process safe, and also not entirely threadsafe: another |
1060 | + # thread that has a new log and hasn't written it could then |
1061 | + # use that serial number. We should either make it really safe, |
1062 | + # or remove the contention entirely and log uniquely per thread |
1063 | + # of execution. |
1064 | + self._last_serial = self._findHighestSerial(result) |
1065 | + finally: |
1066 | + self._lock.release() |
1067 | + return result |
1068 | + |
1069 | + def setToken(self, token): |
1070 | + """Append a string to the log subtype in filenames and log ids. |
1071 | + |
1072 | + :param token: a string to append.. |
1073 | + Scripts that run multiple processes can use this to create a unique |
1074 | + identifier for each process. |
1075 | + """ |
1076 | + self._log_token = token |
Hi Rob.
Thanks for extracting this logic. I have a few comments and I am confused
by a test change.
> === added file 'lib/canonical/ launchpad/ webapp/ lognamer. py' launchpad/ webapp/ lognamer. py 1970-01-01 00:00:00 +0000 launchpad/ webapp/ lognamer. py 2010-06-27 06:41:28 +0000
> --- lib/canonical/
> +++ lib/canonical/
webapp is deprecated. I think this would be better located at services/ logger/ lognamer. py, maybe logger is too broad.
lib/lp/
...
> +class LogNamer:
> + """Assign unique file names to logs being written from an app/script.
> +
> + LogNamer causes logs written from one process to be uniquely named. It is not
> + safe for use in multiple processes with the same output root - each process
> + must have a unique output root.
> + """
I see trailing whitespace. Wrap the doc at 78 characters.
...
> + def getFilename(self, log_serial, time): dir(time) #XXX locks and scans, bad.
> + """Get the filename for a given log serial and time."""
> + log_subtype = self._log_infix()
> + output_dir = self.output_
Avoid end comments. This looks like a comment rather than an XXX to denote
tech-debt.
...
> + def newId(self, now=None): datetime. now(UTC) dir(now) acquire( ) release( ) e(newid, now)
> + """Returns an (id, filename) pair for use by the caller.
> +
> + The ID is composed of a short string to identify the Launchpad instance
> + followed by an ID that is unique for the day.
> +
> + The filename is composed of the zero padded second in the day
> + followed by the ID. This ensures that reports are in date order when
> + sorted lexically.
> + """
> + if now is not None:
> + now = now.astimezone(UTC)
> + else:
> + now = datetime.
> + # We look up the error directory before allocating a new ID,
> + # because if the day has changed, errordir() will reset the ID
> + # counter to zero.
> + self.output_
> + self._lock.
> + try:
> + self._last_serial += 1
> + newid = self._last_serial
> + finally:
> + self._lock.
> + subtype = self._log_infix()
> + day_number = (now - epoch).days + 1
> + log_id = '%s-%d%s%d' % (self._log_type, day_number, subtype, newid)
> + filename = self.getFilenam
> + return log_id, filename
I am confused. The only changes I see in this method is prefix => infix,
yet I can see you changed the the last test for this method to verify
an error was raised.
Was the test wrong? Am I reading ``now.astimezon e(UTC)` ` wrong?
...
> === added file 'lib/canonical/ launchpad/ webapp/ tests/test_ lognamer. py' launchpad/ webapp/ tests/test_ lognamer. py 1970-01-01 00:00:00 +0000 launchpad/ webapp/ tests/test_ lognamer. py 2010-06-27 06:41:28 +0000 datetime( 2006, 04, 02, 00, 30, 00) es(ValueError, namer.newId, now)
> --- lib/canonical/
> +++ lib/canonical/
> ...
>
> + # Native timestamps are not permitted - UTC only.
> + now = datetime.
> + self.assertRais