Merge lp:~lifeless/launchpad/lognamer into lp:launchpad

Proposed by Robert Collins on 2010-06-27
Status: Merged
Approved by: Curtis Hovey on 2010-06-30
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
Reviewer Review Type Date Requested Status
Curtis Hovey (community) code 2010-06-27 Approve on 2010-06-30
Review via email: mp+28574@code.launchpad.net

Commit message

Factor out new lp.services.log.uniquefileallocator module from the file naming component of errorlog.

Description of the change

  Factor out a new canonical.launchpad.webapp.lognamer module from errorlog.
  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 ErrorReportingUtility and a new helper that can
  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.

To post a comment you must log in.
Curtis Hovey (sinzui) wrote :

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'
> --- lib/canonical/launchpad/webapp/lognamer.py 1970-01-01 00:00:00 +0000
> +++ lib/canonical/launchpad/webapp/lognamer.py 2010-06-27 06:41:28 +0000

webapp is deprecated. I think this would be better located at
lib/lp/services/logger/lognamer.py, maybe logger is too broad.

...

> +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):
> + """Get the filename for a given log serial and time."""
> + log_subtype = self._log_infix()
> + output_dir = self.output_dir(time) #XXX locks and scans, bad.

Avoid end comments. This looks like a comment rather than an XXX to denote
tech-debt.

...

> + 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.datetime.now(UTC)
> + # 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_dir(now)
> + self._lock.acquire()
> + try:
> + self._last_serial += 1
> + newid = self._last_serial
> + finally:
> + self._lock.release()
> + 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.getFilename(newid, now)
> + 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.astimezone(UTC)`` wrong?

...

> === added file 'lib/canonical/launchpad/webapp/tests/test_lognamer.py'
> --- lib/canonical/launchpad/webapp/tests/test_lognamer.py 1970-01-01 00:00:00 +0000
> +++ lib/canonical/launchpad/webapp/tests/test_lognamer.py 2010-06-27 06:41:28 +0000
> ...
>
> + # Native timestamps are not permitted - UTC only.
> + now = datetime.datetime(2006, 04, 02, 00, 30, 00)
> + self.assertRaises(ValueError, namer.newId, now)

review: Needs Information
Robert Collins (lifeless) wrote :
Download full text (3.8 KiB)

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/launchpad/webapp/lognamer.py'
>> --- lib/canonical/launchpad/webapp/lognamer.py        1970-01-01 00:00:00 +0000
>> +++ lib/canonical/launchpad/webapp/lognamer.py        2010-06-27 06:41:28 +0000
>
> webapp is deprecated. I think this would be better located at
> lib/lp/services/logger/lognamer.py, maybe logger is too broad.

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/filemanager.py namemanager / namer / controller /

>> +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_dir(time) #XXX locks and scans, bad.
>
> 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.datetime.now(UTC)
>> +        # 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_dir(now)
>> +        self._lock.acquire()
>> +        try:
>> +            self._last_serial += 1
>> +            newid = self._last_serial
>> +        finally:
>> +            self._lock.release()
>> +        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.getFilename(newid, now)
>> +        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...

Read more...

Robert Collins (lifeless) wrote :
Download full text (11.1 KiB)

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/launchpad/webapp/errorlog.py'
--- lib/canonical/launchpad/webapp/errorlog.py 2010-06-27 01:17:40 +0000
+++ lib/canonical/launchpad/webapp/errorlog.py 2010-06-30 00:25:56 +0000
@@ -38,7 +38,7 @@
     soft_timeout_expired)
 from canonical.launchpad.webapp.interfaces import (
     IErrorReport, IErrorReportEvent, IErrorReportRequest)
-from canonical.launchpad.webapp.lognamer import LogNamer
+from lp.services.log.uniquefileallocator import UniqueFileAllocator
 from canonical.launchpad.webapp.opstats import OpStats

 UTC = pytz.utc
@@ -253,8 +253,8 @@
         if section_name is None:
             section_name = self._default_config_section
         self.copy_to_zlog = config[section_name].copy_to_zlog
- # 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 = UniqueFileAllocator(
             output_root=config[section_name].error_dir,
             log_type="OOPS",
             log_subtype=config[section_name].oops_prefix,

=== modified file 'lib/canonical/launchpad/webapp/tests/test_errorlog.py'
--- lib/canonical/launchpad/webapp/tests/test_errorlog.py 2010-06-27
01:17:40 +0000
+++ lib/canonical/launchpad/webapp/tests/test_errorlog.py 2010-06-30
00:25:56 +0000
@@ -37,8 +37,8 @@
     _is_sensitive)
 from canonical.launchpad.webapp.interfaces import (
     NoReferrerError, TranslationUnavailable)
-from canonical.launchpad.webapp.lognamer import LogNamer
 from lazr.restful.declarations import webservice_error
+from lp.services.log.uniquefileallocator import UniqueFileAllocator
 from lp.services.osutils import remove_tree
 from lp.testing import TestCase

@@ -230,9 +230,9 @@
         reset_logging()
         super(TestErrorReportingUtility, self).tearDown()

- def test_creates_LogNamer(self):
+ def test_sets_log_namer_to_a_UniqueFileAllocator(self):
         utility = ErrorReportingUtility()
- self.assertIsInstance(utility.log_namer, LogNamer)
+ self.assertIsInstance(utility.log_namer, UniqueFileAllocator)

     def test_configure(self):
         """Test ErrorReportingUtility.setConfigSection()."""

=== added directory 'lib/lp/services/log'
=== added file 'lib/lp/services/log/__init__.py'
--- lib/lp/services/log/__init__.py 1970-01-01 00:00:00 +0000
+++ lib/lp/services/log/__init__.py 2010-06-30 00:25:56 +0000
@@ -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/services/log/tests'
=== added file 'lib/lp/services/log/tests/__init__.py'
--- lib/lp/services/log/tests/__ini...

Curtis Hovey (sinzui) wrote :

Thanks for the refactoring and explaining my confusion.

review: Approve (code)

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
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