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

Proposed by Robert Collins
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
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.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.
Revision history for this message
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
Revision history for this message
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...

Revision history for this message
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...

Revision history for this message
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
=== modified file 'lib/canonical/launchpad/pagetests/standalone/xx-request-expired.txt'
--- lib/canonical/launchpad/pagetests/standalone/xx-request-expired.txt 2008-03-14 04:18:41 +0000
+++ lib/canonical/launchpad/pagetests/standalone/xx-request-expired.txt 2010-07-05 19:27:28 +0000
@@ -9,7 +9,7 @@
9 >>> from textwrap import dedent9 >>> from textwrap import dedent
10 >>> from canonical.config import config10 >>> from canonical.config import config
11 >>> from canonical.launchpad.webapp.errorlog import globalErrorUtility11 >>> from canonical.launchpad.webapp.errorlog import globalErrorUtility
12 >>> old_lastid = globalErrorUtility.lastid12 >>> old_lastid = globalErrorUtility.getLastOopsReport().id
13 >>> test_data = dedent("""13 >>> test_data = dedent("""
14 ... [database]14 ... [database]
15 ... db_statement_timeout: 115 ... db_statement_timeout: 1
@@ -29,7 +29,7 @@
2929
30We can now see that an error was logged since lastid has changed:30We can now see that an error was logged since lastid has changed:
3131
32 >>> old_lastid != globalErrorUtility.lastid32 >>> old_lastid != globalErrorUtility.getLastOopsReport().id
33 True33 True
3434
35Let's reset the config value we changed:35Let's reset the config value we changed:
3636
=== modified file 'lib/canonical/launchpad/pagetests/standalone/xx-soft-timeout.txt'
--- lib/canonical/launchpad/pagetests/standalone/xx-soft-timeout.txt 2008-03-14 04:18:41 +0000
+++ lib/canonical/launchpad/pagetests/standalone/xx-soft-timeout.txt 2010-07-05 19:27:28 +0000
@@ -41,7 +41,7 @@
4141
42 >>> from textwrap import dedent42 >>> from textwrap import dedent
43 >>> from canonical.launchpad.webapp.errorlog import globalErrorUtility43 >>> from canonical.launchpad.webapp.errorlog import globalErrorUtility
44 >>> old_lastid = globalErrorUtility.lastid44 >>> old_lastid = globalErrorUtility.getLastOopsReport().id
45 >>> test_data = (dedent("""45 >>> test_data = (dedent("""
46 ... [database]46 ... [database]
47 ... soft_request_timeout: 147 ... soft_request_timeout: 1
@@ -58,7 +58,7 @@
5858
59We can now see that an error was logged since lastid has changed:59We can now see that an error was logged since lastid has changed:
6060
61 >>> old_lastid != globalErrorUtility.lastid61 >>> old_lastid != globalErrorUtility.getLastOopsReport().id
62 True62 True
6363
64Since the page rendered correctly, we assume it's a soft timeout error,64Since the page rendered correctly, we assume it's a soft timeout error,
6565
=== modified file 'lib/canonical/launchpad/scripts/ftests/test_oops_prune.py'
--- lib/canonical/launchpad/scripts/ftests/test_oops_prune.py 2010-03-19 09:13:46 +0000
+++ lib/canonical/launchpad/scripts/ftests/test_oops_prune.py 2010-07-05 19:27:28 +0000
@@ -26,7 +26,7 @@
26 referenced_oops, old_oops_files, unwanted_oops_files,26 referenced_oops, old_oops_files, unwanted_oops_files,
27 path_to_oopsid, prune_empty_oops_directories27 path_to_oopsid, prune_empty_oops_directories
28 )28 )
29from canonical.launchpad.webapp import errorlog29from lp.services.log import uniquefileallocator
3030
31class TestOopsPrune(unittest.TestCase):31class TestOopsPrune(unittest.TestCase):
32 layer = LaunchpadZopelessLayer32 layer = LaunchpadZopelessLayer
@@ -37,9 +37,11 @@
37 # whole path rather than the path's basename.37 # whole path rather than the path's basename.
38 self.oops_dir = tempfile.mkdtemp('.directory.with.dots')38 self.oops_dir = tempfile.mkdtemp('.directory.with.dots')
3939
40 # TODO: This should be in the errorlog tests, and calling into errorlog
41 # methods.
40 # Create some fake OOPS files42 # Create some fake OOPS files
41 self.today = datetime.now(tz=UTC)43 self.today = datetime.now(tz=UTC)
42 self.ages_ago = errorlog.epoch + timedelta(days=1)44 self.ages_ago = uniquefileallocator.epoch + timedelta(days=1)
43 self.awhile_ago = self.ages_ago + timedelta(days=1)45 self.awhile_ago = self.ages_ago + timedelta(days=1)
4446
45 for some_date in [self.today, self.ages_ago, self.awhile_ago]:47 for some_date in [self.today, self.ages_ago, self.awhile_ago]:
@@ -185,7 +187,7 @@
185 found_oops_files.add(187 found_oops_files.add(
186 path_to_oopsid(os.path.join(dirpath,filename))188 path_to_oopsid(os.path.join(dirpath,filename))
187 )189 )
188 today_day_count = (self.today - errorlog.epoch).days + 1190 today_day_count = (self.today - uniquefileallocator.epoch).days + 1
189 self.failUnlessEqual(191 self.failUnlessEqual(
190 found_oops_files,192 found_oops_files,
191 set([193 set([
192194
=== modified file 'lib/canonical/launchpad/scripts/oops.py'
--- lib/canonical/launchpad/scripts/oops.py 2010-05-16 23:56:51 +0000
+++ lib/canonical/launchpad/scripts/oops.py 2010-07-05 19:27:28 +0000
@@ -19,9 +19,9 @@
19from pytz import utc19from pytz import utc
2020
21from canonical.database.sqlbase import cursor21from canonical.database.sqlbase import cursor
22from canonical.launchpad.webapp import errorlog
23from canonical.launchpad.webapp.dbpolicy import SlaveOnlyDatabasePolicy22from canonical.launchpad.webapp.dbpolicy import SlaveOnlyDatabasePolicy
24from lp.app.browser.stringformatter import FormattersAPI23from lp.app.browser.stringformatter import FormattersAPI
24from lp.services.log import uniquefileallocator
2525
26def referenced_oops():26def referenced_oops():
27 '''Return a set of OOPS codes that are referenced somewhere in the27 '''Return a set of OOPS codes that are referenced somewhere in the
@@ -77,7 +77,9 @@
77 match = re.search('^(\d\d\d\d)-(\d\d+)-(\d\d+)$', date_str)77 match = re.search('^(\d\d\d\d)-(\d\d+)-(\d\d+)$', date_str)
78 year, month, day = (int(bit) for bit in match.groups())78 year, month, day = (int(bit) for bit in match.groups())
79 oops_id = os.path.basename(path).split('.')[1]79 oops_id = os.path.basename(path).split('.')[1]
80 day = (datetime(year, month, day, tzinfo=utc) - errorlog.epoch).days + 180 # Should be making API calls not directly calculating.
81 day = (datetime(year, month, day, tzinfo=utc) - \
82 uniquefileallocator.epoch).days + 1
81 return '%d%s' % (day, oops_id)83 return '%d%s' % (day, oops_id)
8284
8385
8486
=== modified file 'lib/canonical/launchpad/webapp/errorlog.py'
--- lib/canonical/launchpad/webapp/errorlog.py 2010-05-15 17:43:59 +0000
+++ lib/canonical/launchpad/webapp/errorlog.py 2010-07-05 19:27:28 +0000
@@ -38,16 +38,13 @@
38 soft_timeout_expired)38 soft_timeout_expired)
39from canonical.launchpad.webapp.interfaces import (39from canonical.launchpad.webapp.interfaces import (
40 IErrorReport, IErrorReportEvent, IErrorReportRequest)40 IErrorReport, IErrorReportEvent, IErrorReportRequest)
41from lp.services.log.uniquefileallocator import UniqueFileAllocator
41from canonical.launchpad.webapp.opstats import OpStats42from canonical.launchpad.webapp.opstats import OpStats
4243
43UTC = pytz.utc44UTC = pytz.utc
4445
45LAZR_OOPS_USER_REQUESTED_KEY = 'lazr.oops.user_requested'46LAZR_OOPS_USER_REQUESTED_KEY = 'lazr.oops.user_requested'
4647
47# the section of the OOPS ID before the instance identifier is the
48# days since the epoch, which is defined as the start of 2006.
49epoch = datetime.datetime(2006, 01, 01, 00, 00, 00, tzinfo=UTC)
50
51# Restrict the rate at which errors are sent to the Zope event Log48# Restrict the rate at which errors are sent to the Zope event Log
52# (this does not affect generation of error reports).49# (this does not affect generation of error reports).
53_rate_restrict_pool = {}50_rate_restrict_pool = {}
@@ -242,75 +239,50 @@
242 _ignored_exceptions_for_unauthenticated_users = set(['Unauthorized'])239 _ignored_exceptions_for_unauthenticated_users = set(['Unauthorized'])
243 _default_config_section = 'error_reports'240 _default_config_section = 'error_reports'
244241
245 lasterrordir = None
246 lastid = 0
247
248 def __init__(self):242 def __init__(self):
249 self.lastid_lock = threading.Lock()
250 self.configure()243 self.configure()
251 self._oops_messages = {}244 self._oops_messages = {}
252 self._oops_message_key_iter = (245 self._oops_message_key_iter = (
253 index for index, _ignored in enumerate(repeat(None)))246 index for index, _ignored in enumerate(repeat(None)))
254247
255 def configure(self, section_name=None):248 def configure(self, section_name=None):
256 """Configure the utility using the named section form the config.249 """Configure the utility using the named section from the config.
257250
258 The 'error_reports' section is used if section_name is None.251 The 'error_reports' section is used if section_name is None.
259 """252 """
260 if section_name is None:253 if section_name is None:
261 section_name = self._default_config_section254 section_name = self._default_config_section
262 self.oops_prefix = config[section_name].oops_prefix
263 self.error_dir = config[section_name].error_dir
264 self.copy_to_zlog = config[section_name].copy_to_zlog255 self.copy_to_zlog = config[section_name].copy_to_zlog
265 self.prefix = self.oops_prefix256 # Start a new UniqueFileAllocator to activate the new configuration.
257 self.log_namer = UniqueFileAllocator(
258 output_root=config[section_name].error_dir,
259 log_type="OOPS",
260 log_subtype=config[section_name].oops_prefix,
261 )
266262
267 def setOopsToken(self, token):263 def setOopsToken(self, token):
268 """Append a string to the oops prefix.264 return self.log_namer.setToken(token)
269265
270 :param token: a string to append to a oops_prefix.266 @property
271 Scripts that run multiple processes can append a string to267 def oops_prefix(self):
272 the oops_prefix to create a unique identifier for each268 """Get the current effective oops prefix.
273 process.269
274 """270 This is the log subtype + anything set via setOopsToken.
275 self.prefix = self.oops_prefix + token271 """
276272 return self.log_namer.get_log_infix()
277 def _findLastOopsIdFilename(self, directory):
278 """Find details of the last OOPS reported in the given directory.
279
280 This function only considers OOPSes with the currently
281 configured oops_prefix.
282
283 :return: a tuple (oops_id, oops_filename), which will be (0,
284 None) if no OOPS is found.
285 """
286 prefix = self.prefix
287 lastid = 0
288 lastfilename = None
289 for filename in os.listdir(directory):
290 oopsid = filename.rsplit('.', 1)[1]
291 if not oopsid.startswith(prefix):
292 continue
293 oopsid = oopsid[len(prefix):]
294 if oopsid.isdigit() and int(oopsid) > lastid:
295 lastid = int(oopsid)
296 lastfilename = filename
297 return lastid, lastfilename
298
299 def _findLastOopsId(self, directory):
300 """Find the last error number used by this Launchpad instance.
301
302 The purpose of this function is to not repeat sequence numbers
303 if the Launchpad instance is restarted.
304
305 This method is not thread safe, and only intended to be called
306 from the constructor.
307 """
308 return self._findLastOopsIdFilename(directory)[0]
309273
310 def getOopsReport(self, time):274 def getOopsReport(self, time):
311 """Return the contents of the OOPS report logged at 'time'."""275 """Return the contents of the OOPS report logged at 'time'."""
312 oops_filename = self.getOopsFilename(276 # How this works - get a serial that was logging in the dir
313 self._findLastOopsId(self.errordir(time)), time)277 # that logs for time are logged in.
278 serial_from_time = self.log_namer._findHighestSerial(
279 self.log_namer.output_dir(time))
280 # Calculate a filename which combines this most recent serial,
281 # the current log_namer naming rules and the exact timestamp.
282 oops_filename = self.log_namer.getFilename(serial_from_time, time)
283 # Note that if there were no logs written, or if there were two
284 # oops that matched the time window of directory on disk, this
285 # call can raise an IOError.
314 oops_report = open(oops_filename, 'r')286 oops_report = open(oops_filename, 'r')
315 try:287 try:
316 return ErrorReport.read(oops_report)288 return ErrorReport.read(oops_report)
@@ -330,85 +302,21 @@
330 Returns None if no OOPS is found.302 Returns None if no OOPS is found.
331 """303 """
332 now = datetime.datetime.now(UTC)304 now = datetime.datetime.now(UTC)
333 directory = self.errordir(now)305 # Check today
334 oopsid, filename = self._findLastOopsIdFilename(directory)306 oopsid, filename = self.log_namer._findHighestSerialFilename(time=now)
335 if filename is None:307 if filename is None:
336 directory = self.errordir(now - datetime.timedelta(days=1))308 # Check yesterday
337 oopsid, filename = self._findLastOopsIdFilename(directory)309 yesterday = now - datetime.timedelta(days=1)
310 oopsid, filename = self.log_namer._findHighestSerialFilename(
311 time=yesterday)
338 if filename is None:312 if filename is None:
339 return None313 return None
340 oops_report = open(os.path.join(directory, filename), 'r')314 oops_report = open(filename, 'r')
341 try:315 try:
342 return ErrorReport.read(oops_report)316 return ErrorReport.read(oops_report)
343 finally:317 finally:
344 oops_report.close()318 oops_report.close()
345319
346 def errordir(self, now=None):
347 """Find the directory to write error reports to.
348
349 Error reports are written to subdirectories containing the
350 date of the error.
351 """
352 if now is not None:
353 now = now.astimezone(UTC)
354 else:
355 now = datetime.datetime.now(UTC)
356 date = now.strftime('%Y-%m-%d')
357 errordir = os.path.join(self.error_dir, date)
358 if errordir != self.lasterrordir:
359 self.lastid_lock.acquire()
360 try:
361 self.lasterrordir = errordir
362 # make sure the directory exists
363 try:
364 os.makedirs(errordir)
365 except OSError, e:
366 if e.errno != errno.EEXIST:
367 raise
368 self.lastid = self._findLastOopsId(errordir)
369 finally:
370 self.lastid_lock.release()
371 return errordir
372
373 def getOopsFilename(self, oops_id, time):
374 """Get the filename for a given OOPS id and time."""
375 oops_prefix = self.prefix
376 error_dir = self.errordir(time)
377 second_in_day = time.hour * 3600 + time.minute * 60 + time.second
378 return os.path.join(
379 error_dir, '%05d.%s%s' % (second_in_day, oops_prefix, oops_id))
380
381 def newOopsId(self, now=None):
382 """Returns an (oopsid, filename) pair for the next Oops ID
383
384 The Oops ID is composed of a short string to identify the
385 Launchpad instance followed by an ID that is unique for the
386 day.
387
388 The filename is composed of the zero padded second in the day
389 followed by the Oops ID. This ensures that error reports are
390 in date order when sorted lexically.
391 """
392 if now is not None:
393 now = now.astimezone(UTC)
394 else:
395 now = datetime.datetime.now(UTC)
396 # We look up the error directory before allocating a new ID,
397 # because if the day has changed, errordir() will reset the ID
398 # counter to zero.
399 self.errordir(now)
400 self.lastid_lock.acquire()
401 try:
402 self.lastid += 1
403 newid = self.lastid
404 finally:
405 self.lastid_lock.release()
406 oops_prefix = self.prefix
407 day_number = (now - epoch).days + 1
408 oops = 'OOPS-%d%s%d' % (day_number, oops_prefix, newid)
409 filename = self.getOopsFilename(newid, now)
410 return oops, filename
411
412 def raising(self, info, request=None, now=None):320 def raising(self, info, request=None, now=None):
413 """See IErrorReportingUtility.raising()321 """See IErrorReportingUtility.raising()
414322
@@ -423,8 +331,7 @@
423 entry = self._makeErrorReport(info, request, now, informational)331 entry = self._makeErrorReport(info, request, now, informational)
424 if entry is None:332 if entry is None:
425 return333 return
426 # As a side-effect, _makeErrorReport updates self.lastid.334 filename = entry._filename
427 filename = self.getOopsFilename(self.lastid, entry.time)
428 entry.write(open(filename, 'wb'))335 entry.write(open(filename, 'wb'))
429 if request:336 if request:
430 request.oopsid = entry.id337 request.oopsid = entry.id
@@ -439,7 +346,6 @@
439 informational=False):346 informational=False):
440 """Return an ErrorReport for the supplied data.347 """Return an ErrorReport for the supplied data.
441348
442 As a side-effect, self.lastid is updated to the integer oops id.
443 :param info: Output of sys.exc_info()349 :param info: Output of sys.exc_info()
444 :param request: The IErrorReportRequest which provides context to the350 :param request: The IErrorReportRequest which provides context to the
445 info.351 info.
@@ -534,11 +440,14 @@
534 for (start, end, database_id, statement)440 for (start, end, database_id, statement)
535 in get_request_statements())441 in get_request_statements())
536442
537 oopsid, filename = self.newOopsId(now)443 oopsid, filename = self.log_namer.newId(now)
538 return ErrorReport(oopsid, strtype, strv, now, pageid, tb_text,444
445 result = ErrorReport(oopsid, strtype, strv, now, pageid, tb_text,
539 username, strurl, duration,446 username, strurl, duration,
540 req_vars, statements,447 req_vars, statements,
541 informational)448 informational)
449 result._filename = filename
450 return result
542451
543 def handling(self, info, request=None, now=None):452 def handling(self, info, request=None, now=None):
544 """Flag ErrorReport as informational only.453 """Flag ErrorReport as informational only.
545454
=== modified file 'lib/canonical/launchpad/webapp/tests/test_errorlog.py'
--- lib/canonical/launchpad/webapp/tests/test_errorlog.py 2010-05-04 13:22:15 +0000
+++ lib/canonical/launchpad/webapp/tests/test_errorlog.py 2010-07-05 19:27:28 +0000
@@ -18,6 +18,7 @@
18import unittest18import unittest
1919
20import pytz20import pytz
21import testtools
2122
22from zope.app.publication.tests.test_zopepublication import (23from zope.app.publication.tests.test_zopepublication import (
23 UnauthenticatedPrincipal)24 UnauthenticatedPrincipal)
@@ -37,6 +38,7 @@
37from canonical.launchpad.webapp.interfaces import (38from canonical.launchpad.webapp.interfaces import (
38 NoReferrerError, TranslationUnavailable)39 NoReferrerError, TranslationUnavailable)
39from lazr.restful.declarations import webservice_error40from lazr.restful.declarations import webservice_error
41from lp.services.log.uniquefileallocator import UniqueFileAllocator
40from lp.services.osutils import remove_tree42from lp.services.osutils import remove_tree
41from lp.testing import TestCase43from lp.testing import TestCase
4244
@@ -48,10 +50,11 @@
48 """Used to test handling of exceptions in OOPS reports."""50 """Used to test handling of exceptions in OOPS reports."""
4951
5052
51class TestErrorReport(unittest.TestCase):53class TestErrorReport(testtools.TestCase):
5254
53 def tearDown(self):55 def tearDown(self):
54 reset_logging()56 reset_logging()
57 super(TestErrorReport, self).tearDown()
5558
56 def test___init__(self):59 def test___init__(self):
57 """Test ErrorReport.__init__()"""60 """Test ErrorReport.__init__()"""
@@ -208,8 +211,9 @@
208 self.assertEqual(entry.db_statements[1], (5, 10, None, 'SELECT 2'))211 self.assertEqual(entry.db_statements[1], (5, 10, None, 'SELECT 2'))
209212
210213
211class TestErrorReportingUtility(unittest.TestCase):214class TestErrorReportingUtility(testtools.TestCase):
212 def setUp(self):215 def setUp(self):
216 super(TestErrorReportingUtility, self).setUp()
213 # ErrorReportingUtility reads the global config to get the217 # ErrorReportingUtility reads the global config to get the
214 # current error directory.218 # current error directory.
215 test_data = dedent("""219 test_data = dedent("""
@@ -224,138 +228,51 @@
224 shutil.rmtree(config.error_reports.error_dir, ignore_errors=True)228 shutil.rmtree(config.error_reports.error_dir, ignore_errors=True)
225 config.pop('test_data')229 config.pop('test_data')
226 reset_logging()230 reset_logging()
231 super(TestErrorReportingUtility, self).tearDown()
232
233 def test_sets_log_namer_to_a_UniqueFileAllocator(self):
234 utility = ErrorReportingUtility()
235 self.assertIsInstance(utility.log_namer, UniqueFileAllocator)
227236
228 def test_configure(self):237 def test_configure(self):
229 """Test ErrorReportingUtility.setConfigSection()."""238 """Test ErrorReportingUtility.setConfigSection()."""
230 utility = ErrorReportingUtility()239 utility = ErrorReportingUtility()
231 # The ErrorReportingUtility uses the config.error_reports section240 # The ErrorReportingUtility uses the config.error_reports section
232 # by default.241 # by default.
233 self.assertEqual(config.error_reports.oops_prefix, utility.prefix)242 self.assertEqual(config.error_reports.oops_prefix,
234 self.assertEqual(config.error_reports.error_dir, utility.error_dir)243 utility.oops_prefix)
244 self.assertEqual(config.error_reports.error_dir,
245 utility.log_namer._output_root)
235 self.assertEqual(246 self.assertEqual(
236 config.error_reports.copy_to_zlog, utility.copy_to_zlog)247 config.error_reports.copy_to_zlog, utility.copy_to_zlog)
237 # Some external processes may use another config section to248 # Some external processes may use another config section to
238 # provide the error log configuration.249 # provide the error log configuration.
239 utility.configure(section_name='branchscanner')250 utility.configure(section_name='branchscanner')
240 self.assertEqual(config.branchscanner.oops_prefix, utility.prefix)251 self.assertEqual(config.branchscanner.oops_prefix,
241 self.assertEqual(config.branchscanner.error_dir, utility.error_dir)252 utility.oops_prefix)
253 self.assertEqual(config.branchscanner.error_dir,
254 utility.log_namer._output_root)
242 self.assertEqual(255 self.assertEqual(
243 config.branchscanner.copy_to_zlog, utility.copy_to_zlog)256 config.branchscanner.copy_to_zlog, utility.copy_to_zlog)
244257
245 # The default error section can be restored.258 # The default error section can be restored.
246 utility.configure()259 utility.configure()
247 self.assertEqual(config.error_reports.oops_prefix, utility.prefix)260 self.assertEqual(config.error_reports.oops_prefix,
248 self.assertEqual(config.error_reports.error_dir, utility.error_dir)261 utility.oops_prefix)
262 self.assertEqual(config.error_reports.error_dir,
263 utility.log_namer._output_root)
249 self.assertEqual(264 self.assertEqual(
250 config.error_reports.copy_to_zlog, utility.copy_to_zlog)265 config.error_reports.copy_to_zlog, utility.copy_to_zlog)
251266
252 def test_setOopsToken(self):267 def test_setOopsToken(self):
253 """Test ErrorReportingUtility.setOopsToken()."""268 """Test ErrorReportingUtility.setOopsToken()."""
254 utility = ErrorReportingUtility()269 utility = ErrorReportingUtility()
255 default_prefix = config.error_reports.oops_prefix270 utility.setOopsToken('foo')
256 self.assertEqual('T', default_prefix)271 self.assertEqual('Tfoo', utility.oops_prefix)
257 self.assertEqual('T', utility.prefix)
258
259 # Some scripts will append a string token to the prefix.
260 utility.setOopsToken('CW')
261 self.assertEqual('TCW', utility.prefix)
262
263 # Some scripts run multiple processes and append a string number272 # Some scripts run multiple processes and append a string number
264 # to the prefix.273 # to the prefix.
265 utility.setOopsToken('1')274 utility.setOopsToken('1')
266 self.assertEqual('T1', utility.prefix)275 self.assertEqual('T1', utility.oops_prefix)
267
268 def test_newOopsId(self):
269 """Test ErrorReportingUtility.newOopsId()"""
270 utility = ErrorReportingUtility()
271
272 errordir = config.error_reports.error_dir
273
274 # first oops of the day
275 now = datetime.datetime(2006, 04, 01, 00, 30, 00, tzinfo=UTC)
276 oopsid, filename = utility.newOopsId(now)
277 self.assertEqual(oopsid, 'OOPS-91T1')
278 self.assertEqual(filename,
279 os.path.join(errordir, '2006-04-01/01800.T1'))
280 self.assertEqual(utility.lastid, 1)
281 self.assertEqual(
282 utility.lasterrordir, os.path.join(errordir, '2006-04-01'))
283
284 # second oops of the day
285 now = datetime.datetime(2006, 04, 01, 12, 00, 00, tzinfo=UTC)
286 oopsid, filename = utility.newOopsId(now)
287 self.assertEqual(oopsid, 'OOPS-91T2')
288 self.assertEqual(filename,
289 os.path.join(errordir, '2006-04-01/43200.T2'))
290 self.assertEqual(utility.lastid, 2)
291 self.assertEqual(
292 utility.lasterrordir, os.path.join(errordir, '2006-04-01'))
293
294 # first oops of following day
295 now = datetime.datetime(2006, 04, 02, 00, 30, 00, tzinfo=UTC)
296 oopsid, filename = utility.newOopsId(now)
297 self.assertEqual(oopsid, 'OOPS-92T1')
298 self.assertEqual(filename,
299 os.path.join(errordir, '2006-04-02/01800.T1'))
300 self.assertEqual(utility.lastid, 1)
301 self.assertEqual(
302 utility.lasterrordir, os.path.join(errordir, '2006-04-02'))
303
304 # The oops_prefix honours setOopsToken().
305 utility.setOopsToken('XXX')
306 oopsid, filename = utility.newOopsId(now)
307 self.assertEqual(oopsid, 'OOPS-92TXXX2')
308
309 # Another oops with a native datetime.
310 now = datetime.datetime(2006, 04, 02, 00, 30, 00)
311 self.assertRaises(ValueError, utility.newOopsId, now)
312
313 def test_changeErrorDir(self):
314 """Test changing the error dir using the global config."""
315 utility = ErrorReportingUtility()
316 errordir = utility.error_dir
317
318 # First an oops in the original error directory.
319 now = datetime.datetime(2006, 04, 01, 00, 30, 00, tzinfo=UTC)
320 oopsid, filename = utility.newOopsId(now)
321 self.assertEqual(utility.lastid, 1)
322 self.assertEqual(
323 utility.lasterrordir, os.path.join(errordir, '2006-04-01'))
324
325 # ErrorReportingUtility uses the error_dir attribute to
326 # get the current error directory.
327 new_errordir = tempfile.mkdtemp()
328 utility.error_dir = new_errordir
329
330 # Now an oops on the same day, in the new directory.
331 now = datetime.datetime(2006, 04, 01, 12, 00, 00, tzinfo=UTC)
332 oopsid, filename = utility.newOopsId(now)
333
334 # Since it's a new directory, with no previous oops reports, the
335 # id is 1 again, rather than 2.
336 self.assertEqual(oopsid, 'OOPS-91T1')
337 self.assertEqual(utility.lastid, 1)
338 self.assertEqual(
339 utility.lasterrordir, os.path.join(new_errordir, '2006-04-01'))
340
341 shutil.rmtree(new_errordir, ignore_errors=True)
342
343 def test_findLastOopsId(self):
344 """Test ErrorReportingUtility._findLastOopsId()"""
345 utility = ErrorReportingUtility()
346
347 self.assertEqual(config.error_reports.oops_prefix, 'T')
348
349 errordir = utility.errordir()
350 # write some files
351 open(os.path.join(errordir, '12343.T1'), 'w').close()
352 open(os.path.join(errordir, '12342.T2'), 'w').close()
353 open(os.path.join(errordir, '12345.T3'), 'w').close()
354 open(os.path.join(errordir, '1234567.T0010'), 'w').close()
355 open(os.path.join(errordir, '12346.A42'), 'w').close()
356 open(os.path.join(errordir, '12346.B100'), 'w').close()
357
358 self.assertEqual(utility._findLastOopsId(errordir), 10)
359276
360 def test_raising(self):277 def test_raising(self):
361 """Test ErrorReportingUtility.raising() with no request"""278 """Test ErrorReportingUtility.raising() with no request"""
@@ -367,7 +284,7 @@
367 except ArbitraryException:284 except ArbitraryException:
368 utility.raising(sys.exc_info(), now=now)285 utility.raising(sys.exc_info(), now=now)
369286
370 errorfile = os.path.join(utility.errordir(now), '01800.T1')287 errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1')
371 self.assertTrue(os.path.exists(errorfile))288 self.assertTrue(os.path.exists(errorfile))
372 lines = open(errorfile, 'r').readlines()289 lines = open(errorfile, 'r').readlines()
373290
@@ -421,7 +338,7 @@
421 except ArbitraryException:338 except ArbitraryException:
422 utility.raising(sys.exc_info(), request, now=now)339 utility.raising(sys.exc_info(), request, now=now)
423340
424 errorfile = os.path.join(utility.errordir(now), '01800.T1')341 errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1')
425 self.assertTrue(os.path.exists(errorfile))342 self.assertTrue(os.path.exists(errorfile))
426 lines = open(errorfile, 'r').readlines()343 lines = open(errorfile, 'r').readlines()
427344
@@ -483,7 +400,7 @@
483 raise ArbitraryException('xyz\nabc')400 raise ArbitraryException('xyz\nabc')
484 except ArbitraryException:401 except ArbitraryException:
485 utility.raising(sys.exc_info(), request, now=now)402 utility.raising(sys.exc_info(), request, now=now)
486 errorfile = os.path.join(utility.errordir(now), '01800.T1')403 errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1')
487 self.assertTrue(os.path.exists(errorfile))404 self.assertTrue(os.path.exists(errorfile))
488 lines = open(errorfile, 'r').readlines()405 lines = open(errorfile, 'r').readlines()
489 self.assertEqual(lines[16], 'xmlrpc args=(1, 2)\n')406 self.assertEqual(lines[16], 'xmlrpc args=(1, 2)\n')
@@ -538,7 +455,7 @@
538 ('name1', 'value3')], URL='https://launchpad.net/example')455 ('name1', 'value3')], URL='https://launchpad.net/example')
539 utility.raising(sys.exc_info(), request, now=now)456 utility.raising(sys.exc_info(), request, now=now)
540457
541 errorfile = os.path.join(utility.errordir(now), '01800.T1')458 errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1')
542 self.assertTrue(os.path.exists(errorfile))459 self.assertTrue(os.path.exists(errorfile))
543 lines = open(errorfile, 'r').readlines()460 lines = open(errorfile, 'r').readlines()
544461
@@ -591,7 +508,7 @@
591 utility.raising(sys.exc_info(), now=now)508 utility.raising(sys.exc_info(), now=now)
592 log.uninstall()509 log.uninstall()
593510
594 errorfile = os.path.join(utility.errordir(now), '01800.T1')511 errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1')
595 self.assertTrue(os.path.exists(errorfile))512 self.assertTrue(os.path.exists(errorfile))
596 lines = open(errorfile, 'r').readlines()513 lines = open(errorfile, 'r').readlines()
597514
@@ -634,7 +551,7 @@
634 raise Unauthorized('xyz')551 raise Unauthorized('xyz')
635 except Unauthorized:552 except Unauthorized:
636 utility.raising(sys.exc_info(), now=now)553 utility.raising(sys.exc_info(), now=now)
637 errorfile = os.path.join(utility.errordir(now), '01800.T1')554 errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1')
638 self.failUnless(os.path.exists(errorfile))555 self.failUnless(os.path.exists(errorfile))
639556
640 def test_raising_unauthorized_without_principal(self):557 def test_raising_unauthorized_without_principal(self):
@@ -647,7 +564,7 @@
647 raise Unauthorized('xyz')564 raise Unauthorized('xyz')
648 except Unauthorized:565 except Unauthorized:
649 utility.raising(sys.exc_info(), request, now=now)566 utility.raising(sys.exc_info(), request, now=now)
650 errorfile = os.path.join(utility.errordir(now), '01800.T1')567 errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1')
651 self.failUnless(os.path.exists(errorfile))568 self.failUnless(os.path.exists(errorfile))
652569
653 def test_raising_unauthorized_with_unauthenticated_principal(self):570 def test_raising_unauthorized_with_unauthenticated_principal(self):
@@ -660,7 +577,7 @@
660 raise Unauthorized('xyz')577 raise Unauthorized('xyz')
661 except Unauthorized:578 except Unauthorized:
662 utility.raising(sys.exc_info(), request, now=now)579 utility.raising(sys.exc_info(), request, now=now)
663 errorfile = os.path.join(utility.errordir(now), '01800.T1')580 errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1')
664 self.failIf(os.path.exists(errorfile))581 self.failIf(os.path.exists(errorfile))
665582
666 def test_raising_unauthorized_with_authenticated_principal(self):583 def test_raising_unauthorized_with_authenticated_principal(self):
@@ -673,7 +590,7 @@
673 raise Unauthorized('xyz')590 raise Unauthorized('xyz')
674 except Unauthorized:591 except Unauthorized:
675 utility.raising(sys.exc_info(), request, now=now)592 utility.raising(sys.exc_info(), request, now=now)
676 errorfile = os.path.join(utility.errordir(now), '01800.T1')593 errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1')
677 self.failUnless(os.path.exists(errorfile))594 self.failUnless(os.path.exists(errorfile))
678595
679 def test_raising_translation_unavailable(self):596 def test_raising_translation_unavailable(self):
@@ -691,7 +608,7 @@
691 except TranslationUnavailable:608 except TranslationUnavailable:
692 utility.raising(sys.exc_info(), now=now)609 utility.raising(sys.exc_info(), now=now)
693610
694 errorfile = os.path.join(utility.errordir(now), '01800.T1')611 errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1')
695 self.assertFalse(os.path.exists(errorfile))612 self.assertFalse(os.path.exists(errorfile))
696613
697 def test_raising_no_referrer_error(self):614 def test_raising_no_referrer_error(self):
@@ -709,7 +626,7 @@
709 except NoReferrerError:626 except NoReferrerError:
710 utility.raising(sys.exc_info(), now=now)627 utility.raising(sys.exc_info(), now=now)
711628
712 errorfile = os.path.join(utility.errordir(now), '01800.T1')629 errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1')
713 self.assertFalse(os.path.exists(errorfile))630 self.assertFalse(os.path.exists(errorfile))
714631
715 def test_raising_with_string_as_traceback(self):632 def test_raising_with_string_as_traceback(self):
@@ -729,7 +646,7 @@
729 exc_tb = traceback.format_exc()646 exc_tb = traceback.format_exc()
730647
731 utility.raising((exc_type, exc_value, exc_tb), now=now)648 utility.raising((exc_type, exc_value, exc_tb), now=now)
732 errorfile = os.path.join(utility.errordir(now), '01800.T1')649 errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1')
733650
734 self.assertTrue(os.path.exists(errorfile))651 self.assertTrue(os.path.exists(errorfile))
735 lines = open(errorfile, 'r').readlines()652 lines = open(errorfile, 'r').readlines()
@@ -767,7 +684,7 @@
767 except ArbitraryException:684 except ArbitraryException:
768 utility.handling(sys.exc_info(), now=now)685 utility.handling(sys.exc_info(), now=now)
769686
770 errorfile = os.path.join(utility.errordir(now), '01800.T1')687 errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1')
771 self.assertTrue(os.path.exists(errorfile))688 self.assertTrue(os.path.exists(errorfile))
772 lines = open(errorfile, 'r').readlines()689 lines = open(errorfile, 'r').readlines()
773690
@@ -842,7 +759,7 @@
842 oops.req_vars)759 oops.req_vars)
843760
844761
845class TestSensitiveRequestVariables(unittest.TestCase):762class TestSensitiveRequestVariables(testtools.TestCase):
846 """Test request variables that should not end up in the stored OOPS.763 """Test request variables that should not end up in the stored OOPS.
847764
848 The _is_sensitive() method will return True for any variable name that765 The _is_sensitive() method will return True for any variable name that
@@ -904,10 +821,10 @@
904 TestCase.setUp(self)821 TestCase.setUp(self)
905 self.logger = logging.getLogger(self.factory.getUniqueString())822 self.logger = logging.getLogger(self.factory.getUniqueString())
906 self.error_utility = ErrorReportingUtility()823 self.error_utility = ErrorReportingUtility()
907 self.error_utility.error_dir = tempfile.mkdtemp()824 self.error_utility.log_namer._output_root = tempfile.mkdtemp()
908 self.logger.addHandler(825 self.logger.addHandler(
909 OopsLoggingHandler(error_utility=self.error_utility))826 OopsLoggingHandler(error_utility=self.error_utility))
910 self.addCleanup(remove_tree, self.error_utility.error_dir)827 self.addCleanup(remove_tree, self.error_utility.log_namer._output_root)
911828
912 def test_exception_records_oops(self):829 def test_exception_records_oops(self):
913 # When OopsLoggingHandler is a handler for a logger, any exceptions830 # When OopsLoggingHandler is a handler for a logger, any exceptions
@@ -935,7 +852,3 @@
935852
936def test_suite():853def test_suite():
937 return unittest.TestLoader().loadTestsFromName(__name__)854 return unittest.TestLoader().loadTestsFromName(__name__)
938
939
940if __name__ == '__main__':
941 unittest.main(defaultTest='test_suite')
942855
=== modified file 'lib/lp/services/job/tests/test_runner.py'
--- lib/lp/services/job/tests/test_runner.py 2010-05-03 02:37:30 +0000
+++ lib/lp/services/job/tests/test_runner.py 2010-07-05 19:27:28 +0000
@@ -406,6 +406,7 @@
406 def runFromSource(cls, source, dbuser, logger):406 def runFromSource(cls, source, dbuser, logger):
407 expected_config = errorlog.ErrorReportingUtility()407 expected_config = errorlog.ErrorReportingUtility()
408 expected_config.configure('merge_proposal_jobs')408 expected_config.configure('merge_proposal_jobs')
409 # Check that the unique oops token was applied.
409 self.assertEqual(410 self.assertEqual(
410 errorlog.globalErrorUtility.oops_prefix,411 errorlog.globalErrorUtility.oops_prefix,
411 expected_config.oops_prefix)412 expected_config.oops_prefix)
412413
=== 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-07-05 19:27:28 +0000
@@ -0,0 +1,11 @@
1# Copyright 2010 Canonical Ltd. This software is licensed under the
2# GNU Affero General Public License version 3 (see the file LICENSE).
3
4"""lp.services.log provides log-like facilities.
5
6Consider putting infrastructure that is used for getting logs or diagnostics
7out of Launchpad and onto some external store in here.
8
9Because this part of lp.services, packages in this namespace can only use
10general LAZR or library functionality.
11"""
012
=== added directory 'lib/lp/services/log/tests'
=== added file 'lib/lp/services/log/tests/__init__.py'
--- lib/lp/services/log/tests/__init__.py 1970-01-01 00:00:00 +0000
+++ lib/lp/services/log/tests/__init__.py 2010-07-05 19:27:28 +0000
@@ -0,0 +1,4 @@
1# Copyright 2010 Canonical Ltd. This software is licensed under the
2# GNU Affero General Public License version 3 (see the file LICENSE).
3
4"""Tests for lp.services.log."""
05
=== added file 'lib/lp/services/log/tests/test_uniquefileallocator.py'
--- lib/lp/services/log/tests/test_uniquefileallocator.py 1970-01-01 00:00:00 +0000
+++ lib/lp/services/log/tests/test_uniquefileallocator.py 2010-07-05 19:27:28 +0000
@@ -0,0 +1,139 @@
1# Copyright 2010 Canonical Ltd. This software is licensed under the
2# GNU Affero General Public License version 3 (see the file LICENSE).
3
4"""Tests for the unique log naming facility."""
5
6from __future__ import with_statement
7__metaclass__ = type
8
9import datetime
10import os
11import shutil
12import tempfile
13import unittest
14
15import pytz
16import testtools
17
18from lp.services.log.uniquefileallocator import UniqueFileAllocator
19
20
21UTC = pytz.timezone('UTC')
22
23
24class TestUniqueFileAllocator(testtools.TestCase):
25
26 def setUp(self):
27 super(TestUniqueFileAllocator, self).setUp()
28 tempdir = tempfile.mkdtemp()
29 self._tempdir = tempdir
30 self.addCleanup(shutil.rmtree, tempdir, ignore_errors=True)
31
32 def test_setToken(self):
33 namer = UniqueFileAllocator("/any-old/path/", 'OOPS', 'T')
34 self.assertEqual('T', namer.get_log_infix())
35
36 # Some scripts will append a string token to the prefix.
37 namer.setToken('CW')
38 self.assertEqual('TCW', namer.get_log_infix())
39
40 # Some scripts run multiple processes and append a string number
41 # to the prefix.
42 namer.setToken('1')
43 self.assertEqual('T1', namer.get_log_infix())
44
45 def assertUniqueFileAllocator(self, namer, now, expected_id,
46 expected_last_id, expected_suffix, expected_lastdir):
47 logid, filename = namer.newId(now)
48 self.assertEqual(logid, expected_id)
49 self.assertEqual(filename,
50 os.path.join(namer._output_root, expected_suffix))
51 self.assertEqual(namer._last_serial, expected_last_id)
52 self.assertEqual(namer._last_output_dir,
53 os.path.join(namer._output_root, expected_lastdir))
54
55 def test_newId(self):
56 # TODO: This should return an id, fileobj instead of a file name, to
57 # reduce races with threads that are slow to use what they asked for,
58 # when combined with configuration changes causing disk scans. That
59 # would also permit using a completely stubbed out file system,
60 # reducing IO in tests that use UniqueFileAllocator (such as all the
61 # pagetests in Launchpad. At that point an interface to obtain a
62 # factory of UniqueFileAllocator's would be useful to parameterise the
63 # entire test suite.
64 namer = UniqueFileAllocator(self._tempdir, 'OOPS', 'T')
65 # first name of the day
66 self.assertUniqueFileAllocator(namer,
67 datetime.datetime(2006, 04, 01, 00, 30, 00, tzinfo=UTC),
68 'OOPS-91T1', 1, '2006-04-01/01800.T1', '2006-04-01')
69 # second name of the day
70 self.assertUniqueFileAllocator(namer,
71 datetime.datetime(2006, 04, 01, 12, 00, 00, tzinfo=UTC),
72 'OOPS-91T2', 2, '2006-04-01/43200.T2', '2006-04-01')
73
74 # first name of the following day sets a new dir and the id starts
75 # over.
76 self.assertUniqueFileAllocator(namer,
77 datetime.datetime(2006, 04, 02, 00, 30, 00, tzinfo=UTC),
78 'OOPS-92T1', 1, '2006-04-02/01800.T1', '2006-04-02')
79
80 # Setting a token inserts the token into the filename.
81 namer.setToken('YYY')
82 logid, filename = namer.newId(
83 datetime.datetime(2006, 04, 02, 00, 30, 00, tzinfo=UTC))
84 self.assertEqual(logid, 'OOPS-92TYYY2')
85
86 # Setting a type controls the log id:
87 namer.setToken('')
88 namer._log_type = "PROFILE"
89 logid, filename = namer.newId(
90 datetime.datetime(2006, 04, 02, 00, 30, 00, tzinfo=UTC))
91 self.assertEqual(logid, 'PROFILE-92T3')
92
93 # Native timestamps are not permitted - UTC only.
94 now = datetime.datetime(2006, 04, 02, 00, 30, 00)
95 self.assertRaises(ValueError, namer.newId, now)
96
97 def test_changeErrorDir(self):
98 """Test changing the log output dur."""
99 namer = UniqueFileAllocator(self._tempdir, 'OOPS', 'T')
100
101 # First an id in the original error directory.
102 self.assertUniqueFileAllocator(namer,
103 datetime.datetime(2006, 04, 01, 00, 30, 00, tzinfo=UTC),
104 'OOPS-91T1', 1, '2006-04-01/01800.T1', '2006-04-01')
105
106 # UniqueFileAllocator uses the _output_root attribute to get the current output
107 # directory.
108 new_output_dir = tempfile.mkdtemp()
109 self.addCleanup(shutil.rmtree, new_output_dir, ignore_errors=True)
110 namer._output_root = new_output_dir
111
112 # Now an id on the same day, in the new directory.
113 now = datetime.datetime(2006, 04, 01, 12, 00, 00, tzinfo=UTC)
114 log_id, filename = namer.newId(now)
115
116 # Since it's a new directory, with no previous logs, the id is 1 again,
117 # rather than 2.
118 self.assertEqual(log_id, 'OOPS-91T1')
119 self.assertEqual(namer._last_serial, 1)
120 self.assertEqual(namer._last_output_dir,
121 os.path.join(new_output_dir, '2006-04-01'))
122
123 def test_findHighestSerial(self):
124 namer = UniqueFileAllocator(self._tempdir, "OOPS", "T")
125 # Creates the dir using now as the timestamp.
126 output_dir = namer.output_dir()
127 # write some files, in non-serial order.
128 open(os.path.join(output_dir, '12343.T1'), 'w').close()
129 open(os.path.join(output_dir, '12342.T2'), 'w').close()
130 open(os.path.join(output_dir, '12345.T3'), 'w').close()
131 open(os.path.join(output_dir, '1234567.T0010'), 'w').close()
132 open(os.path.join(output_dir, '12346.A42'), 'w').close()
133 open(os.path.join(output_dir, '12346.B100'), 'w').close()
134 # The namer should figure out the right highest serial.
135 self.assertEqual(namer._findHighestSerial(output_dir), 10)
136
137
138def test_suite():
139 return unittest.TestLoader().loadTestsFromName(__name__)
0140
=== added file 'lib/lp/services/log/uniquefileallocator.py'
--- lib/lp/services/log/uniquefileallocator.py 1970-01-01 00:00:00 +0000
+++ lib/lp/services/log/uniquefileallocator.py 2010-07-05 19:27:28 +0000
@@ -0,0 +1,182 @@
1# Copyright 2010 Canonical Ltd. This software is licensed under the
2# GNU Affero General Public License version 3 (see the file LICENSE).
3
4"""Create uniquely named log files on disk."""
5
6
7__all__ = ['UniqueFileAllocator']
8
9__metaclass__ = type
10
11
12import datetime
13import errno
14import os.path
15import threading
16import time
17
18import pytz
19UTC = pytz.utc
20
21# the section of the ID before the instance identifier is the
22# days since the epoch, which is defined as the start of 2006.
23epoch = datetime.datetime(2006, 01, 01, 00, 00, 00, tzinfo=UTC)
24
25
26class UniqueFileAllocator:
27 """Assign unique file names to logs being written from an app/script.
28
29 UniqueFileAllocator causes logs written from one process to be uniquely
30 named. It is not safe for use in multiple processes with the same output
31 root - each process must have a unique output root.
32 """
33
34 def __init__(self, output_root, log_type, log_subtype):
35 """Create a UniqueFileAllocator.
36
37 :param output_root: The root directory that logs should be placed in.
38 :param log_type: A string to use as a prefix in the ID assigned to new
39 logs. For instance, "OOPS".
40 :param log_subtype: A string to insert in the generate log filenames
41 between the day number and the serial. For instance "T" for
42 "Testing".
43 """
44 self._lock = threading.Lock()
45 self._output_root = output_root
46 self._last_serial = 0
47 self._last_output_dir = None
48 self._log_type = log_type
49 self._log_subtype = log_subtype
50 self._log_token = ""
51
52 def _findHighestSerialFilename(self, directory=None, time=None):
53 """Find details of the last log present in the given directory.
54
55 This function only considers logs with the currently
56 configured log_subtype.
57
58 One of directory, time must be supplied.
59
60 :param directory: Look in this directory.
61 :param time: Look in the directory that a log written at this time
62 would have been written to. If supplied, supercedes directory.
63 :return: a tuple (log_serial, log_filename), which will be (0,
64 None) if no logs are found. log_filename is a usable path, not
65 simply the basename.
66 """
67 if directory is None:
68 directory = self.output_dir(time)
69 prefix = self.get_log_infix()
70 lastid = 0
71 lastfilename = None
72 for filename in os.listdir(directory):
73 logid = filename.rsplit('.', 1)[1]
74 if not logid.startswith(prefix):
75 continue
76 logid = logid[len(prefix):]
77 if logid.isdigit() and (lastid is None or int(logid) > lastid):
78 lastid = int(logid)
79 lastfilename = filename
80 if lastfilename is not None:
81 lastfilename = os.path.join(directory, lastfilename)
82 return lastid, lastfilename
83
84 def _findHighestSerial(self, directory):
85 """Find the last serial actually applied to disk in directory.
86
87 The purpose of this function is to not repeat sequence numbers
88 if the logging application is restarted.
89
90 This method is not thread safe, and only intended to be called
91 from the constructor (but it is called from other places in integration
92 tests).
93 """
94 return self._findHighestSerialFilename(directory)[0]
95
96 def getFilename(self, log_serial, time):
97 """Get the filename for a given log serial and time."""
98 log_subtype = self.get_log_infix()
99 # TODO: Calling output_dir causes a global lock to be taken and a
100 # directory scan, which is bad for performance. It would be better
101 # to have a split out 'directory name for time' function which the
102 # 'want to use this directory now' function can call.
103 output_dir = self.output_dir(time)
104 second_in_day = time.hour * 3600 + time.minute * 60 + time.second
105 return os.path.join(
106 output_dir, '%05d.%s%s' % (second_in_day, log_subtype, log_serial))
107
108 def get_log_infix(self):
109 """Return the current log infix to use in ids and file names."""
110 return self._log_subtype + self._log_token
111
112 def newId(self, now=None):
113 """Returns an (id, filename) pair for use by the caller.
114
115 The ID is composed of a short string to identify the Launchpad instance
116 followed by an ID that is unique for the day.
117
118 The filename is composed of the zero padded second in the day
119 followed by the ID. This ensures that reports are in date order when
120 sorted lexically.
121 """
122 if now is not None:
123 now = now.astimezone(UTC)
124 else:
125 now = datetime.datetime.now(UTC)
126 # We look up the error directory before allocating a new ID,
127 # because if the day has changed, errordir() will reset the ID
128 # counter to zero.
129 self.output_dir(now)
130 self._lock.acquire()
131 try:
132 self._last_serial += 1
133 newid = self._last_serial
134 finally:
135 self._lock.release()
136 subtype = self.get_log_infix()
137 day_number = (now - epoch).days + 1
138 log_id = '%s-%d%s%d' % (self._log_type, day_number, subtype, newid)
139 filename = self.getFilename(newid, now)
140 return log_id, filename
141
142 def output_dir(self, now=None):
143 """Find or make the directory to allocate log names in.
144
145 Log names are assigned within subdirectories containing the date the
146 assignment happened.
147 """
148 if now is not None:
149 now = now.astimezone(UTC)
150 else:
151 now = datetime.datetime.now(UTC)
152 date = now.strftime('%Y-%m-%d')
153 result = os.path.join(self._output_root, date)
154 if result != self._last_output_dir:
155 self._lock.acquire()
156 try:
157 self._last_output_dir = result
158 # make sure the directory exists
159 try:
160 os.makedirs(result)
161 except OSError, e:
162 if e.errno != errno.EEXIST:
163 raise
164 # TODO: Note that only one process can do this safely: its not
165 # cross-process safe, and also not entirely threadsafe: another
166 # thread that has a new log and hasn't written it could then
167 # use that serial number. We should either make it really safe,
168 # or remove the contention entirely and log uniquely per thread
169 # of execution.
170 self._last_serial = self._findHighestSerial(result)
171 finally:
172 self._lock.release()
173 return result
174
175 def setToken(self, token):
176 """Append a string to the log subtype in filenames and log ids.
177
178 :param token: a string to append..
179 Scripts that run multiple processes can use this to create a unique
180 identifier for each process.
181 """
182 self._log_token = token