Launchpad itself

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

lognamer
Merge into devel

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
Related bugs:	Link a bug report

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.

Revision history for this message

Curtis Hovey (sinzui) wrote on 2010-06-29:

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)

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 on 2010-06-29:

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...

Thanks for the review.

On Wed, Jun 30, 2010 at 7:55 AM, Curtis Hovey
<curtis.hovey@canonical.com> 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 was raised.

> Was the test wrong? Am I reading ``now.astimezone(UTC)`` wrong?

I think you are misreading:
the old test was:
-        # Another oops with a native datetime.
-        now = datetime.datetime(2006, 04, 02, 00, 30, 00)
-        self.assertRaises(ValueError, utility.newOopsId, now)

The new test:
+        # Native timestamps are not permitted - UTC only.
+        now = datetime.datetime(2006, 04, 02, 00, 30, 00)
+        self.assertRaises(ValueError, namer.newId, now)

I think it should be rephrased though, to say 'timestamps that cannot
be coerced into UTC are not accepted' - that would avoid confusing
people I hope.

Thanks,
Rob

Revision history for this message

Robert Collins (lifeless) wrote on 2010-06-30:

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...

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/__init__.py	1970-01-01 00:00:00 +0000
+++ lib/lp/services/log/tests/__init__.py	2010-06-30 00:25:56 +0000
@@ -0,0 +1,4 @@
+# Copyright 2010 Canonical Ltd.  This software is licensed under the
+# GNU Affero General Public License version 3 (see the file LICENSE).
+
+"""Tests for lp.services.log."""

=== renamed file
'lib/canonical/launchpad/webapp/tests/test_lognamer.py' =>
'lib/lp/services/log/tests/test_uniquefileallocator.py'
--- lib/canonical/launchpad/webapp/tests/test_lognamer.py	2010-06-27
01:17:40 +0000
+++ lib/lp/services/log/tests/test_uniquefileallocator.py	2010-06-30
00:25:56 +0000
@@ -15,22 +15,22 @@
 import pytz
 import testtools

-from canonical.launchpad.webapp.lognamer import LogNamer
+from lp.services.log.uniquefileallocator import UniqueFileAllocator

UTC = pytz.timezone('UTC')

-class TestLogNamer(testtools.TestCase):
+class TestUniqueFileAllocator(testtools.TestCase):

def setUp(self):
-        super(TestLogNamer, self).setUp()
+        super(TestUniqueFileAllocator, self).setUp()
         tempdir = tempfile.mkdtemp()
         self._tempdir = tempdir
         self.addCleanup(shutil.rmtree, tempdir, ignore_errors=True)

def test_setToken(self):
-        namer = LogNamer("/any-old/path/", 'OOPS', 'T')
+        namer = UniqueFileAllocator("/any-old/path/", 'OOPS', 'T')
         self.assertEqual('T', namer._log_infix())

# Some scripts will append a string token to the prefix.
@@ -42,8 +42,8 @@
         namer.setToken('1')
         self.assertEqual('T1', namer._log_infix())

-    def assertLogNamed(self, namer, now, expected_id, expected_last_id,
-        expected_suffix, expected_lastdir):
+    def assertUniqueFileAllocator(self, namer, now, expected_id,
+        expected_last_id, expected_suffix, expected_lastdir):
         logid, filename = namer.newId(now)
         self.assertEqual(logid, expected_id)
         self.assertEqual(filename,
@@ -57,29 +57,31 @@
         # reduce races with threads that are slow to use what they asked for,
         # when combined with configuration changes causing disk scans. That
         # would also permit using a completely stubbed out file system,
-        # reducing IO in tests that use LogNamer (such as all the pagetests in
-        # Launchpad.
-        namer = LogNamer(self._tempdir, 'OOPS', 'T')
+        # reducing IO in tests that use UniqueFileAllocator (such as all the
+        # pagetests in Launchpad. At that point an interface to obtain a
+        # factory of UniqueFileAllocator's would be useful to parameterise the
+        # entire test suite.
+        namer = UniqueFileAllocator(self._tempdir, 'OOPS', 'T')
         # first name of the day
-        self.assertLogNamed(namer,
+        self.assertUniqueFileAllocator(namer,
             datetime.datetime(2006, 04, 01, 00, 30, 00, tzinfo=UTC),
             'OOPS-91T1', 1, '2006-04-01/01800.T1', '2006-04-01')
         # second name of the day
-        self.assertLogNamed(namer,
+        self.assertUniqueFileAllocator(namer,
             datetime.datetime(2006, 04, 01, 12, 00, 00, tzinfo=UTC),
             'OOPS-91T2', 2, '2006-04-01/43200.T2', '2006-04-01')

# first name of the following day sets a new dir and the id starts
         # over.
-        self.assertLogNamed(namer,
+        self.assertUniqueFileAllocator(namer,
             datetime.datetime(2006, 04, 02, 00, 30, 00, tzinfo=UTC),
             'OOPS-92T1', 1, '2006-04-02/01800.T1', '2006-04-02')

# Setting a token inserts the token into the filename.
-        namer.setToken('XXX')
+        namer.setToken('YYY')
         logid, filename = namer.newId(
             datetime.datetime(2006, 04, 02, 00, 30, 00, tzinfo=UTC))
-        self.assertEqual(logid, 'OOPS-92TXXX2')
+        self.assertEqual(logid, 'OOPS-92TYYY2')

# Setting a type controls the log id:
         namer.setToken('')
@@ -94,14 +96,14 @@

def test_changeErrorDir(self):
         """Test changing the log output dur."""
-        namer = LogNamer(self._tempdir, 'OOPS', 'T')
+        namer = UniqueFileAllocator(self._tempdir, 'OOPS', 'T')

# First an id in the original error directory.
-        self.assertLogNamed(namer,
+        self.assertUniqueFileAllocator(namer,
             datetime.datetime(2006, 04, 01, 00, 30, 00, tzinfo=UTC),
             'OOPS-91T1', 1, '2006-04-01/01800.T1', '2006-04-01')

-        # LogNamer uses the _output_root attribute to get the current output
+        # UniqueFileAllocator uses the _output_root attribute to get
the current output
         # directory.
         new_output_dir = tempfile.mkdtemp()
         self.addCleanup(shutil.rmtree, new_output_dir, ignore_errors=True)
@@ -119,7 +121,7 @@
             os.path.join(new_output_dir, '2006-04-01'))

def test_findHighestSerial(self):
-        namer = LogNamer(self._tempdir, "OOPS", "T")
+        namer = UniqueFileAllocator(self._tempdir, "OOPS", "T")
         # Creates the dir using now as the timestamp.
         output_dir = namer.output_dir()
         # write some files, in non-serial order.

=== renamed file 'lib/canonical/launchpad/webapp/lognamer.py' =>
'lib/lp/services/log/uniquefileallocator.py'
--- lib/canonical/launchpad/webapp/lognamer.py	2010-06-27 06:38:33 +0000
+++ lib/lp/services/log/uniquefileallocator.py	2010-06-30 00:25:56 +0000
@@ -4,7 +4,7 @@
 """Create uniquely named log files on disk."""

-__all__ = ['LogNamer']
+__all__ = ['UniqueFileAllocator']

__metaclass__ = type

@@ -18,21 +18,21 @@
 import pytz
 UTC = pytz.utc

-# the section of the Log ID before the instance identifier is the
+# the section of the ID before the instance identifier is the
 # days since the epoch, which is defined as the start of 2006.
 epoch = datetime.datetime(2006, 01, 01, 00, 00, 00, tzinfo=UTC)

-class LogNamer:
+class UniqueFileAllocator:
     """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.
+    UniqueFileAllocator 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.
     """

def __init__(self, output_root, log_type, log_subtype):
-        """Create a LogNamer.
+        """Create a UniqueFileAllocator.

:param output_root: The root directory that logs should be placed in.
         :param log_type: A string to use as a prefix in the ID assigned to new
@@ -96,7 +96,11 @@
     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.
+        # TODO: Calling output_dir causes a global lock to be taken and a
+        # directory scan, which is bad for performance. It would be better
+        # to have a split out 'directory name for time' function which the
+        # 'want to use this directory now' function can call.
+        output_dir = self.output_dir(time)
         second_in_day = time.hour * 3600 + time.minute * 60 + time.second
         return os.path.join(
             output_dir, '%05d.%s%s' % (second_in_day, log_subtype, log_serial))
@@ -157,10 +161,12 @@
                 except OSError, e:
                     if e.errno != errno.EEXIST:
                         raise
-                # XXX: Note that only one process can do this safely: its not
+                # TODO: Note that only one process can do this safely: its not
                 # cross-process safe, and also not entirely threadsafe: another
                 # thread that has a new log and hasn't written it could then
-                # use that serial number.
+                # use that serial number. We should either make it really safe,
+                # or remove the contention entirely and log uniquely per thread
+                # of execution.
                 self._last_serial = self._findHighestSerial(result)
             finally:
                 self._lock.release()

Revision history for this message

Curtis Hovey (sinzui) wrote on 2010-06-30:

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

Subscribers

People subscribed via source and target branches

to all changes:

Barki Mustapha

Celso Providelo

Christian Reis

Christy Awad

Colin Watson

Harpianto,ANDI

James Troup

John A Meinel

Kevin bush

Launchpad code reviewers

Launchpad code reviewers from Canonical

Matthew Tanner

Maximiliano Bertacchini

Oguz Ersoz

Robert Collins

Simon Brakhane

Ubuntu-BR DevOps

William Grant

alhawiti

api.ng

pedro cavazos

todaioan

wenjingwen

to status/vote changes:

Tzaddi

Tzaddi Belding

 === 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 @@
      >>> from textwrap import dedent
      >>> from canonical.config import config
      >>> from canonical.launchpad.webapp.errorlog import globalErrorUtility
--    >>> old_lastid = globalErrorUtility.lastid
++    >>> old_lastid = globalErrorUtility.getLastOopsReport().id
      >>> test_data = dedent("""
      ...     [database]
      ...     db_statement_timeout: 1
@@ -29,7 +29,7 @@
  We can now see that an error was logged since lastid has changed:
--    >>> old_lastid != globalErrorUtility.lastid
++    >>> old_lastid != globalErrorUtility.getLastOopsReport().id
      True
  Let's reset the config value we changed:
 === 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 @@
      >>> from textwrap import dedent
      >>> from canonical.launchpad.webapp.errorlog import globalErrorUtility
--    >>> old_lastid = globalErrorUtility.lastid
++    >>> old_lastid = globalErrorUtility.getLastOopsReport().id
      >>> test_data = (dedent("""
      ...     [database]
      ...     soft_request_timeout: 1
@@ -58,7 +58,7 @@
  We can now see that an error was logged since lastid has changed:
--    >>> old_lastid != globalErrorUtility.lastid
++    >>> old_lastid != globalErrorUtility.getLastOopsReport().id
      True
  Since the page rendered correctly, we assume it's a soft timeout error,
 === 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 @@
          referenced_oops, old_oops_files, unwanted_oops_files,
          path_to_oopsid, prune_empty_oops_directories
+         )
--from canonical.launchpad.webapp import errorlog
++from lp.services.log import uniquefileallocator
  class TestOopsPrune(unittest.TestCase):
      layer = LaunchpadZopelessLayer
@@ -37,9 +37,11 @@
          # whole path rather than the path's basename.
          self.oops_dir = tempfile.mkdtemp('.directory.with.dots')
++        # TODO: This should be in the errorlog tests, and calling into errorlog
++        # methods.
          # Create some fake OOPS files
          self.today = datetime.now(tz=UTC)
--        self.ages_ago = errorlog.epoch + timedelta(days=1)
++        self.ages_ago = uniquefileallocator.epoch + timedelta(days=1)
          self.awhile_ago = self.ages_ago + timedelta(days=1)
          for some_date in [self.today, self.ages_ago, self.awhile_ago]:
@@ -185,7 +187,7 @@
                  found_oops_files.add(
                          path_to_oopsid(os.path.join(dirpath,filename))
+                         )
--        today_day_count = (self.today - errorlog.epoch).days + 1
++        today_day_count = (self.today - uniquefileallocator.epoch).days + 1
          self.failUnlessEqual(
                  found_oops_files,
                  set([
 === 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 @@
  from pytz import utc
  from canonical.database.sqlbase import cursor
--from canonical.launchpad.webapp import errorlog
  from canonical.launchpad.webapp.dbpolicy import SlaveOnlyDatabasePolicy
  from lp.app.browser.stringformatter import FormattersAPI
++from lp.services.log import uniquefileallocator
  def referenced_oops():
      '''Return a set of OOPS codes that are referenced somewhere in the
@@ -77,7 +77,9 @@
      match = re.search('^(\d\d\d\d)-(\d\d+)-(\d\d+)$', date_str)
      year, month, day = (int(bit) for bit in match.groups())
      oops_id = os.path.basename(path).split('.')[1]
--    day = (datetime(year, month, day, tzinfo=utc) - errorlog.epoch).days + 1
++    # Should be making API calls not directly calculating.
++    day = (datetime(year, month, day, tzinfo=utc) - \
++        uniquefileallocator.epoch).days + 1
      return '%d%s' % (day, oops_id)
 === 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 @@
      soft_timeout_expired)
  from canonical.launchpad.webapp.interfaces import (
      IErrorReport, IErrorReportEvent, IErrorReportRequest)
++from lp.services.log.uniquefileallocator import UniqueFileAllocator
  from canonical.launchpad.webapp.opstats import OpStats
  UTC = pytz.utc
  LAZR_OOPS_USER_REQUESTED_KEY = 'lazr.oops.user_requested'
--# the section of the OOPS ID before the instance identifier is the
--# days since the epoch, which is defined as the start of 2006.
--epoch = datetime.datetime(2006, 01, 01, 00, 00, 00, tzinfo=UTC)
--
  # Restrict the rate at which errors are sent to the Zope event Log
  # (this does not affect generation of error reports).
  _rate_restrict_pool = {}
@@ -242,75 +239,50 @@
      _ignored_exceptions_for_unauthenticated_users = set(['Unauthorized'])
      _default_config_section = 'error_reports'
--    lasterrordir = None
--    lastid = 0
--
      def __init__(self):
--        self.lastid_lock = threading.Lock()
          self.configure()
          self._oops_messages = {}
          self._oops_message_key_iter = (
              index for index, _ignored in enumerate(repeat(None)))
      def configure(self, section_name=None):
--        """Configure the utility using the named section form the config.
++        """Configure the utility using the named section from the config.
          The 'error_reports' section is used if section_name is None.
          """
          if section_name is None:
              section_name = self._default_config_section
--        self.oops_prefix = config[section_name].oops_prefix
--        self.error_dir = config[section_name].error_dir
          self.copy_to_zlog = config[section_name].copy_to_zlog
--        self.prefix = self.oops_prefix
++        # 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,
++            )
      def setOopsToken(self, token):
--        """Append a string to the oops prefix.
--
--        :param token: a string to append to a oops_prefix.
--            Scripts that run multiple processes can append a string to
--            the oops_prefix to create a unique identifier for each
--            process.
--        """
--        self.prefix = self.oops_prefix + token
--
--    def _findLastOopsIdFilename(self, directory):
--        """Find details of the last OOPS reported in the given directory.
--
--        This function only considers OOPSes with the currently
--        configured oops_prefix.
--
--        :return: a tuple (oops_id, oops_filename), which will be (0,
--            None) if no OOPS is found.
--        """
--        prefix = self.prefix
--        lastid = 0
--        lastfilename = None
--        for filename in os.listdir(directory):
--            oopsid = filename.rsplit('.', 1)[1]
--            if not oopsid.startswith(prefix):
--                continue
--            oopsid = oopsid[len(prefix):]
--            if oopsid.isdigit() and int(oopsid) > lastid:
--                lastid = int(oopsid)
--                lastfilename = filename
--        return lastid, lastfilename
--
--    def _findLastOopsId(self, directory):
--        """Find the last error number used by this Launchpad instance.
--
--        The purpose of this function is to not repeat sequence numbers
--        if the Launchpad instance is restarted.
--
--        This method is not thread safe, and only intended to be called
--        from the constructor.
--        """
--        return self._findLastOopsIdFilename(directory)[0]
++        return self.log_namer.setToken(token)
++
++    @property
++    def oops_prefix(self):
++        """Get the current effective oops prefix.
++
++        This is the log subtype + anything set via setOopsToken.
++        """
++        return self.log_namer.get_log_infix()
      def getOopsReport(self, time):
          """Return the contents of the OOPS report logged at 'time'."""
--        oops_filename = self.getOopsFilename(
--            self._findLastOopsId(self.errordir(time)), time)
++        # How this works - get a serial that was logging in the dir
++        # that logs for time are logged in.
++        serial_from_time = self.log_namer._findHighestSerial(
++            self.log_namer.output_dir(time))
++        # Calculate a filename which combines this most recent serial,
++        # the current log_namer naming rules and the exact timestamp.
++        oops_filename = self.log_namer.getFilename(serial_from_time, time)
++        # Note that if there were no logs written, or if there were two
++        # oops that matched the time window of directory on disk, this
++        # call can raise an IOError.
          oops_report = open(oops_filename, 'r')
          try:
              return ErrorReport.read(oops_report)
@@ -330,85 +302,21 @@
          Returns None if no OOPS is found.
          """
          now = datetime.datetime.now(UTC)
--        directory = self.errordir(now)
--        oopsid, filename = self._findLastOopsIdFilename(directory)
++        # Check today
++        oopsid, filename = self.log_namer._findHighestSerialFilename(time=now)
          if filename is None:
--            directory = self.errordir(now - datetime.timedelta(days=1))
--            oopsid, filename = self._findLastOopsIdFilename(directory)
++            # Check yesterday
++            yesterday = now - datetime.timedelta(days=1)
++            oopsid, filename = self.log_namer._findHighestSerialFilename(
++                time=yesterday)
              if filename is None:
                  return None
--        oops_report = open(os.path.join(directory, filename), 'r')
++        oops_report = open(filename, 'r')
          try:
              return ErrorReport.read(oops_report)
          finally:
              oops_report.close()
--    def errordir(self, now=None):
--        """Find the directory to write error reports to.
--
--        Error reports are written to subdirectories containing the
--        date of the error.
--        """
--        if now is not None:
--            now = now.astimezone(UTC)
--        else:
--            now = datetime.datetime.now(UTC)
--        date = now.strftime('%Y-%m-%d')
--        errordir = os.path.join(self.error_dir, date)
--        if errordir != self.lasterrordir:
--            self.lastid_lock.acquire()
--            try:
--                self.lasterrordir = errordir
--                # make sure the directory exists
--                try:
--                    os.makedirs(errordir)
--                except OSError, e:
--                    if e.errno != errno.EEXIST:
--                        raise
--                self.lastid = self._findLastOopsId(errordir)
--            finally:
--                self.lastid_lock.release()
--        return errordir
--
--    def getOopsFilename(self, oops_id, time):
--        """Get the filename for a given OOPS id and time."""
--        oops_prefix = self.prefix
--        error_dir = self.errordir(time)
--        second_in_day = time.hour * 3600 + time.minute * 60 + time.second
--        return os.path.join(
--            error_dir, '%05d.%s%s' % (second_in_day, oops_prefix, oops_id))
--
--    def newOopsId(self, now=None):
--        """Returns an (oopsid, filename) pair for the next Oops ID
--
--        The Oops 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 Oops ID.  This ensures that error 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.errordir(now)
--        self.lastid_lock.acquire()
--        try:
--            self.lastid += 1
--            newid = self.lastid
--        finally:
--            self.lastid_lock.release()
--        oops_prefix = self.prefix
--        day_number = (now - epoch).days + 1
--        oops = 'OOPS-%d%s%d' % (day_number, oops_prefix, newid)
--        filename = self.getOopsFilename(newid, now)
--        return oops, filename
--
      def raising(self, info, request=None, now=None):
          """See IErrorReportingUtility.raising()
@@ -423,8 +331,7 @@
          entry = self._makeErrorReport(info, request, now, informational)
          if entry is None:
              return
--        # As a side-effect, _makeErrorReport updates self.lastid.
--        filename = self.getOopsFilename(self.lastid, entry.time)
++        filename = entry._filename
          entry.write(open(filename, 'wb'))
          if request:
              request.oopsid = entry.id
@@ -439,7 +346,6 @@
                           informational=False):
          """Return an ErrorReport for the supplied data.
--        As a side-effect, self.lastid is updated to the integer oops id.
          :param info: Output of sys.exc_info()
          :param request: The IErrorReportRequest which provides context to the
              info.
@@ -534,11 +440,14 @@
              for (start, end, database_id, statement)
                  in get_request_statements())
--        oopsid, filename = self.newOopsId(now)
--        return ErrorReport(oopsid, strtype, strv, now, pageid, tb_text,
++        oopsid, filename = self.log_namer.newId(now)
++
++        result = ErrorReport(oopsid, strtype, strv, now, pageid, tb_text,
                             username, strurl, duration,
                             req_vars, statements,
                             informational)
++        result._filename = filename
++        return result
      def handling(self, info, request=None, now=None):
          """Flag ErrorReport as informational only.
 === 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 @@
  import unittest
  import pytz
++import testtools
  from zope.app.publication.tests.test_zopepublication import (
      UnauthenticatedPrincipal)
@@ -37,6 +38,7 @@
  from canonical.launchpad.webapp.interfaces import (
      NoReferrerError, TranslationUnavailable)
  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
@@ -48,10 +50,11 @@
      """Used to test handling of exceptions in OOPS reports."""
--class TestErrorReport(unittest.TestCase):
++class TestErrorReport(testtools.TestCase):
      def tearDown(self):
          reset_logging()
++        super(TestErrorReport, self).tearDown()
      def test___init__(self):
          """Test ErrorReport.__init__()"""
@@ -208,8 +211,9 @@
          self.assertEqual(entry.db_statements[1], (5, 10, None, 'SELECT 2'))
--class TestErrorReportingUtility(unittest.TestCase):
++class TestErrorReportingUtility(testtools.TestCase):
      def setUp(self):
++        super(TestErrorReportingUtility, self).setUp()
          # ErrorReportingUtility reads the global config to get the
          # current error directory.
          test_data = dedent("""
@@ -224,138 +228,51 @@
          shutil.rmtree(config.error_reports.error_dir, ignore_errors=True)
          config.pop('test_data')
          reset_logging()
++        super(TestErrorReportingUtility, self).tearDown()
++
++    def test_sets_log_namer_to_a_UniqueFileAllocator(self):
++        utility = ErrorReportingUtility()
++        self.assertIsInstance(utility.log_namer, UniqueFileAllocator)
      def test_configure(self):
          """Test ErrorReportingUtility.setConfigSection()."""
          utility = ErrorReportingUtility()
          # The ErrorReportingUtility uses the config.error_reports section
          # by default.
--        self.assertEqual(config.error_reports.oops_prefix, utility.prefix)
--        self.assertEqual(config.error_reports.error_dir, utility.error_dir)
++        self.assertEqual(config.error_reports.oops_prefix,
++            utility.oops_prefix)
++        self.assertEqual(config.error_reports.error_dir,
++            utility.log_namer._output_root)
          self.assertEqual(
              config.error_reports.copy_to_zlog, utility.copy_to_zlog)
          # Some external processes may use another config section to
          # provide the error log configuration.
          utility.configure(section_name='branchscanner')
--        self.assertEqual(config.branchscanner.oops_prefix, utility.prefix)
--        self.assertEqual(config.branchscanner.error_dir, utility.error_dir)
++        self.assertEqual(config.branchscanner.oops_prefix,
++            utility.oops_prefix)
++        self.assertEqual(config.branchscanner.error_dir,
++            utility.log_namer._output_root)
          self.assertEqual(
              config.branchscanner.copy_to_zlog, utility.copy_to_zlog)
          # The default error section can be restored.
          utility.configure()
--        self.assertEqual(config.error_reports.oops_prefix, utility.prefix)
--        self.assertEqual(config.error_reports.error_dir, utility.error_dir)
++        self.assertEqual(config.error_reports.oops_prefix,
++            utility.oops_prefix)
++        self.assertEqual(config.error_reports.error_dir,
++            utility.log_namer._output_root)
          self.assertEqual(
              config.error_reports.copy_to_zlog, utility.copy_to_zlog)
      def test_setOopsToken(self):
          """Test ErrorReportingUtility.setOopsToken()."""
          utility = ErrorReportingUtility()
--        default_prefix = config.error_reports.oops_prefix
--        self.assertEqual('T', default_prefix)
--        self.assertEqual('T', utility.prefix)
--
--        # Some scripts will append a string token to the prefix.
--        utility.setOopsToken('CW')
--        self.assertEqual('TCW', utility.prefix)
--
++        utility.setOopsToken('foo')
++        self.assertEqual('Tfoo', utility.oops_prefix)
          # Some scripts run multiple processes and append a string number
          # to the prefix.
          utility.setOopsToken('1')
--        self.assertEqual('T1', utility.prefix)
--
--    def test_newOopsId(self):
--        """Test ErrorReportingUtility.newOopsId()"""
--        utility = ErrorReportingUtility()
--
--        errordir = config.error_reports.error_dir
--
--        # first oops of the day
--        now = datetime.datetime(2006, 04, 01, 00, 30, 00, tzinfo=UTC)
--        oopsid, filename = utility.newOopsId(now)
--        self.assertEqual(oopsid, 'OOPS-91T1')
--        self.assertEqual(filename,
--                         os.path.join(errordir, '2006-04-01/01800.T1'))
--        self.assertEqual(utility.lastid, 1)
--        self.assertEqual(
--            utility.lasterrordir, os.path.join(errordir, '2006-04-01'))
--
--        # second oops of the day
--        now = datetime.datetime(2006, 04, 01, 12, 00, 00, tzinfo=UTC)
--        oopsid, filename = utility.newOopsId(now)
--        self.assertEqual(oopsid, 'OOPS-91T2')
--        self.assertEqual(filename,
--                         os.path.join(errordir, '2006-04-01/43200.T2'))
--        self.assertEqual(utility.lastid, 2)
--        self.assertEqual(
--            utility.lasterrordir, os.path.join(errordir, '2006-04-01'))
--
--        # first oops of following day
--        now = datetime.datetime(2006, 04, 02, 00, 30, 00, tzinfo=UTC)
--        oopsid, filename = utility.newOopsId(now)
--        self.assertEqual(oopsid, 'OOPS-92T1')
--        self.assertEqual(filename,
--                         os.path.join(errordir, '2006-04-02/01800.T1'))
--        self.assertEqual(utility.lastid, 1)
--        self.assertEqual(
--            utility.lasterrordir, os.path.join(errordir, '2006-04-02'))
--
--        # The oops_prefix honours setOopsToken().
--        utility.setOopsToken('XXX')
--        oopsid, filename = utility.newOopsId(now)
--        self.assertEqual(oopsid, 'OOPS-92TXXX2')
--
--        # Another oops with a native datetime.
--        now = datetime.datetime(2006, 04, 02, 00, 30, 00)
--        self.assertRaises(ValueError, utility.newOopsId, now)
--
--    def test_changeErrorDir(self):
--        """Test changing the error dir using the global config."""
--        utility = ErrorReportingUtility()
--        errordir = utility.error_dir
--
--        # First an oops in the original error directory.
--        now = datetime.datetime(2006, 04, 01, 00, 30, 00, tzinfo=UTC)
--        oopsid, filename = utility.newOopsId(now)
--        self.assertEqual(utility.lastid, 1)
--        self.assertEqual(
--            utility.lasterrordir, os.path.join(errordir, '2006-04-01'))
--
--        # ErrorReportingUtility uses the error_dir attribute to
--        # get the current error directory.
--        new_errordir = tempfile.mkdtemp()
--        utility.error_dir = new_errordir
--
--        # Now an oops on the same day, in the new directory.
--        now = datetime.datetime(2006, 04, 01, 12, 00, 00, tzinfo=UTC)
--        oopsid, filename = utility.newOopsId(now)
--
--        # Since it's a new directory, with no previous oops reports, the
--        # id is 1 again, rather than 2.
--        self.assertEqual(oopsid, 'OOPS-91T1')
--        self.assertEqual(utility.lastid, 1)
--        self.assertEqual(
--            utility.lasterrordir, os.path.join(new_errordir, '2006-04-01'))
--
--        shutil.rmtree(new_errordir, ignore_errors=True)
--
--    def test_findLastOopsId(self):
--        """Test ErrorReportingUtility._findLastOopsId()"""
--        utility = ErrorReportingUtility()
--
--        self.assertEqual(config.error_reports.oops_prefix, 'T')
--
--        errordir = utility.errordir()
--        # write some files
--        open(os.path.join(errordir, '12343.T1'), 'w').close()
--        open(os.path.join(errordir, '12342.T2'), 'w').close()
--        open(os.path.join(errordir, '12345.T3'), 'w').close()
--        open(os.path.join(errordir, '1234567.T0010'), 'w').close()
--        open(os.path.join(errordir, '12346.A42'), 'w').close()
--        open(os.path.join(errordir, '12346.B100'), 'w').close()
--
--        self.assertEqual(utility._findLastOopsId(errordir), 10)
++        self.assertEqual('T1', utility.oops_prefix)
      def test_raising(self):
          """Test ErrorReportingUtility.raising() with no request"""
@@ -367,7 +284,7 @@
          except ArbitraryException:
              utility.raising(sys.exc_info(), now=now)
--        errorfile = os.path.join(utility.errordir(now), '01800.T1')
++        errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1')
          self.assertTrue(os.path.exists(errorfile))
          lines = open(errorfile, 'r').readlines()
@@ -421,7 +338,7 @@
          except ArbitraryException:
              utility.raising(sys.exc_info(), request, now=now)
--        errorfile = os.path.join(utility.errordir(now), '01800.T1')
++        errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1')
          self.assertTrue(os.path.exists(errorfile))
          lines = open(errorfile, 'r').readlines()
@@ -483,7 +400,7 @@
              raise ArbitraryException('xyz\nabc')
          except ArbitraryException:
              utility.raising(sys.exc_info(), request, now=now)
--        errorfile = os.path.join(utility.errordir(now), '01800.T1')
++        errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1')
          self.assertTrue(os.path.exists(errorfile))
          lines = open(errorfile, 'r').readlines()
          self.assertEqual(lines[16], 'xmlrpc args=(1, 2)\n')
@@ -538,7 +455,7 @@
                  ('name1', 'value3')], URL='https://launchpad.net/example')
              utility.raising(sys.exc_info(), request, now=now)
--        errorfile = os.path.join(utility.errordir(now), '01800.T1')
++        errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1')
          self.assertTrue(os.path.exists(errorfile))
          lines = open(errorfile, 'r').readlines()
@@ -591,7 +508,7 @@
              utility.raising(sys.exc_info(), now=now)
          log.uninstall()
--        errorfile = os.path.join(utility.errordir(now), '01800.T1')
++        errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1')
          self.assertTrue(os.path.exists(errorfile))
          lines = open(errorfile, 'r').readlines()
@@ -634,7 +551,7 @@
              raise Unauthorized('xyz')
          except Unauthorized:
              utility.raising(sys.exc_info(), now=now)
--        errorfile = os.path.join(utility.errordir(now), '01800.T1')
++        errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1')
          self.failUnless(os.path.exists(errorfile))
      def test_raising_unauthorized_without_principal(self):
@@ -647,7 +564,7 @@
              raise Unauthorized('xyz')
          except Unauthorized:
              utility.raising(sys.exc_info(), request, now=now)
--        errorfile = os.path.join(utility.errordir(now), '01800.T1')
++        errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1')
          self.failUnless(os.path.exists(errorfile))
      def test_raising_unauthorized_with_unauthenticated_principal(self):
@@ -660,7 +577,7 @@
              raise Unauthorized('xyz')
          except Unauthorized:
              utility.raising(sys.exc_info(), request, now=now)
--        errorfile = os.path.join(utility.errordir(now), '01800.T1')
++        errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1')
          self.failIf(os.path.exists(errorfile))
      def test_raising_unauthorized_with_authenticated_principal(self):
@@ -673,7 +590,7 @@
              raise Unauthorized('xyz')
          except Unauthorized:
              utility.raising(sys.exc_info(), request, now=now)
--        errorfile = os.path.join(utility.errordir(now), '01800.T1')
++        errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1')
          self.failUnless(os.path.exists(errorfile))
      def test_raising_translation_unavailable(self):
@@ -691,7 +608,7 @@
          except TranslationUnavailable:
              utility.raising(sys.exc_info(), now=now)
--        errorfile = os.path.join(utility.errordir(now), '01800.T1')
++        errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1')
          self.assertFalse(os.path.exists(errorfile))
      def test_raising_no_referrer_error(self):
@@ -709,7 +626,7 @@
          except NoReferrerError:
              utility.raising(sys.exc_info(), now=now)
--        errorfile = os.path.join(utility.errordir(now), '01800.T1')
++        errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1')
          self.assertFalse(os.path.exists(errorfile))
      def test_raising_with_string_as_traceback(self):
@@ -729,7 +646,7 @@
              exc_tb = traceback.format_exc()
          utility.raising((exc_type, exc_value, exc_tb), now=now)
--        errorfile = os.path.join(utility.errordir(now), '01800.T1')
++        errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1')
          self.assertTrue(os.path.exists(errorfile))
          lines = open(errorfile, 'r').readlines()
@@ -767,7 +684,7 @@
          except ArbitraryException:
              utility.handling(sys.exc_info(), now=now)
--        errorfile = os.path.join(utility.errordir(now), '01800.T1')
++        errorfile = os.path.join(utility.log_namer.output_dir(now), '01800.T1')
          self.assertTrue(os.path.exists(errorfile))
          lines = open(errorfile, 'r').readlines()
@@ -842,7 +759,7 @@
                      oops.req_vars)
--class TestSensitiveRequestVariables(unittest.TestCase):
++class TestSensitiveRequestVariables(testtools.TestCase):
      """Test request variables that should not end up in the stored OOPS.
      The _is_sensitive() method will return True for any variable name that
@@ -904,10 +821,10 @@
          TestCase.setUp(self)
          self.logger = logging.getLogger(self.factory.getUniqueString())
          self.error_utility = ErrorReportingUtility()
--        self.error_utility.error_dir = tempfile.mkdtemp()
++        self.error_utility.log_namer._output_root = tempfile.mkdtemp()
          self.logger.addHandler(
              OopsLoggingHandler(error_utility=self.error_utility))
--        self.addCleanup(remove_tree, self.error_utility.error_dir)
++        self.addCleanup(remove_tree, self.error_utility.log_namer._output_root)
      def test_exception_records_oops(self):
          # When OopsLoggingHandler is a handler for a logger, any exceptions
@@ -935,7 +852,3 @@
  def test_suite():
      return unittest.TestLoader().loadTestsFromName(__name__)
--
--
--if __name__ == '__main__':
--    unittest.main(defaultTest='test_suite')
 === 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 @@
              def runFromSource(cls, source, dbuser, logger):
                  expected_config = errorlog.ErrorReportingUtility()
                  expected_config.configure('merge_proposal_jobs')
++                # Check that the unique oops token was applied.
                  self.assertEqual(
                      errorlog.globalErrorUtility.oops_prefix,
                      expected_config.oops_prefix)
 === 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 @@
++# 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/__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 @@
++# Copyright 2010 Canonical Ltd.  This software is licensed under the
++# GNU Affero General Public License version 3 (see the file LICENSE).
++
++"""Tests for lp.services.log."""
 === 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 @@
++# Copyright 2010 Canonical Ltd.  This software is licensed under the
++# GNU Affero General Public License version 3 (see the file LICENSE).
++
++"""Tests for the unique log naming facility."""
++
++from __future__ import with_statement
++__metaclass__ = type
++
++import datetime
++import os
++import shutil
++import tempfile
++import unittest
++
++import pytz
++import testtools
++
++from lp.services.log.uniquefileallocator import UniqueFileAllocator
++
++
++UTC = pytz.timezone('UTC')
++
++
++class TestUniqueFileAllocator(testtools.TestCase):
++
++    def setUp(self):
++        super(TestUniqueFileAllocator, self).setUp()
++        tempdir = tempfile.mkdtemp()
++        self._tempdir = tempdir
++        self.addCleanup(shutil.rmtree, tempdir, ignore_errors=True)
++
++    def test_setToken(self):
++        namer = UniqueFileAllocator("/any-old/path/", 'OOPS', 'T')
++        self.assertEqual('T', namer.get_log_infix())
++
++        # Some scripts will append a string token to the prefix.
++        namer.setToken('CW')
++        self.assertEqual('TCW', namer.get_log_infix())
++
++        # Some scripts run multiple processes and append a string number
++        # to the prefix.
++        namer.setToken('1')
++        self.assertEqual('T1', namer.get_log_infix())
++
++    def assertUniqueFileAllocator(self, namer, now, expected_id,
++        expected_last_id, expected_suffix, expected_lastdir):
++        logid, filename = namer.newId(now)
++        self.assertEqual(logid, expected_id)
++        self.assertEqual(filename,
++            os.path.join(namer._output_root, expected_suffix))
++        self.assertEqual(namer._last_serial, expected_last_id)
++        self.assertEqual(namer._last_output_dir,
++            os.path.join(namer._output_root, expected_lastdir))
++
++    def test_newId(self):
++        # TODO: This should return an id, fileobj instead of a file name, to
++        # reduce races with threads that are slow to use what they asked for,
++        # when combined with configuration changes causing disk scans. That
++        # would also permit using a completely stubbed out file system,
++        # reducing IO in tests that use UniqueFileAllocator (such as all the
++        # pagetests in Launchpad. At that point an interface to obtain a
++        # factory of UniqueFileAllocator's would be useful to parameterise the
++        # entire test suite.
++        namer = UniqueFileAllocator(self._tempdir, 'OOPS', 'T')
++        # first name of the day
++        self.assertUniqueFileAllocator(namer,
++            datetime.datetime(2006, 04, 01, 00, 30, 00, tzinfo=UTC),
++            'OOPS-91T1', 1, '2006-04-01/01800.T1', '2006-04-01')
++        # second name of the day
++        self.assertUniqueFileAllocator(namer,
++            datetime.datetime(2006, 04, 01, 12, 00, 00, tzinfo=UTC),
++            'OOPS-91T2', 2, '2006-04-01/43200.T2', '2006-04-01')
++
++        # first name of the following day sets a new dir and the id starts
++        # over.
++        self.assertUniqueFileAllocator(namer,
++            datetime.datetime(2006, 04, 02, 00, 30, 00, tzinfo=UTC),
++            'OOPS-92T1', 1, '2006-04-02/01800.T1', '2006-04-02')
++
++        # Setting a token inserts the token into the filename.
++        namer.setToken('YYY')
++        logid, filename = namer.newId(
++            datetime.datetime(2006, 04, 02, 00, 30, 00, tzinfo=UTC))
++        self.assertEqual(logid, 'OOPS-92TYYY2')
++
++        # Setting a type controls the log id:
++        namer.setToken('')
++        namer._log_type = "PROFILE"
++        logid, filename = namer.newId(
++            datetime.datetime(2006, 04, 02, 00, 30, 00, tzinfo=UTC))
++        self.assertEqual(logid, 'PROFILE-92T3')
++
++        # Native timestamps are not permitted - UTC only.
++        now = datetime.datetime(2006, 04, 02, 00, 30, 00)
++        self.assertRaises(ValueError, namer.newId, now)
++
++    def test_changeErrorDir(self):
++        """Test changing the log output dur."""
++        namer = UniqueFileAllocator(self._tempdir, 'OOPS', 'T')
++
++        # First an id in the original error directory.
++        self.assertUniqueFileAllocator(namer,
++            datetime.datetime(2006, 04, 01, 00, 30, 00, tzinfo=UTC),
++            'OOPS-91T1', 1, '2006-04-01/01800.T1', '2006-04-01')
++
++        # UniqueFileAllocator uses the _output_root attribute to get the current output
++        # directory.
++        new_output_dir = tempfile.mkdtemp()
++        self.addCleanup(shutil.rmtree, new_output_dir, ignore_errors=True)
++        namer._output_root = new_output_dir
++
++        # Now an id on the same day, in the new directory.
++        now = datetime.datetime(2006, 04, 01, 12, 00, 00, tzinfo=UTC)
++        log_id, filename = namer.newId(now)
++
++        # Since it's a new directory, with no previous logs, the id is 1 again,
++        # rather than 2.
++        self.assertEqual(log_id, 'OOPS-91T1')
++        self.assertEqual(namer._last_serial, 1)
++        self.assertEqual(namer._last_output_dir,
++            os.path.join(new_output_dir, '2006-04-01'))
++
++    def test_findHighestSerial(self):
++        namer = UniqueFileAllocator(self._tempdir, "OOPS", "T")
++        # Creates the dir using now as the timestamp.
++        output_dir = namer.output_dir()
++        # write some files, in non-serial order.
++        open(os.path.join(output_dir, '12343.T1'), 'w').close()
++        open(os.path.join(output_dir, '12342.T2'), 'w').close()
++        open(os.path.join(output_dir, '12345.T3'), 'w').close()
++        open(os.path.join(output_dir, '1234567.T0010'), 'w').close()
++        open(os.path.join(output_dir, '12346.A42'), 'w').close()
++        open(os.path.join(output_dir, '12346.B100'), 'w').close()
++        # The namer should figure out the right highest serial.
++        self.assertEqual(namer._findHighestSerial(output_dir), 10)
++
++
++def test_suite():
++    return unittest.TestLoader().loadTestsFromName(__name__)
 === 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 @@
++# Copyright 2010 Canonical Ltd.  This software is licensed under the
++# GNU Affero General Public License version 3 (see the file LICENSE).
++
++"""Create uniquely named log files on disk."""
++
++
++__all__ = ['UniqueFileAllocator']
++
++__metaclass__ = type
++
++
++import datetime
++import errno
++import os.path
++import threading
++import time
++
++import pytz
++UTC = pytz.utc
++
++# the section of the ID before the instance identifier is the
++# days since the epoch, which is defined as the start of 2006.
++epoch = datetime.datetime(2006, 01, 01, 00, 00, 00, tzinfo=UTC)
++
++
++class UniqueFileAllocator:
++    """Assign unique file names to logs being written from an app/script.
++
++    UniqueFileAllocator 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.
++    """
++
++    def __init__(self, output_root, log_type, log_subtype):
++        """Create a UniqueFileAllocator.
++
++        :param output_root: The root directory that logs should be placed in.
++        :param log_type: A string to use as a prefix in the ID assigned to new
++            logs. For instance, "OOPS".
++        :param log_subtype: A string to insert in the generate log filenames
++            between the day number and the serial. For instance "T" for
++            "Testing".
++        """
++        self._lock = threading.Lock()
++        self._output_root = output_root
++        self._last_serial = 0
++        self._last_output_dir = None
++        self._log_type = log_type
++        self._log_subtype = log_subtype
++        self._log_token = ""
++
++    def _findHighestSerialFilename(self, directory=None, time=None):
++        """Find details of the last log present in the given directory.
++
++        This function only considers logs with the currently
++        configured log_subtype.
++
++        One of directory, time must be supplied.
++
++        :param directory: Look in this directory.
++        :param time: Look in the directory that a log written at this time
++            would have been written to. If supplied, supercedes directory.
++        :return: a tuple (log_serial, log_filename), which will be (0,
++            None) if no logs are found. log_filename is a usable path, not
++            simply the basename.
++        """
++        if directory is None:
++            directory = self.output_dir(time)
++        prefix = self.get_log_infix()
++        lastid = 0
++        lastfilename = None
++        for filename in os.listdir(directory):
++            logid = filename.rsplit('.', 1)[1]
++            if not logid.startswith(prefix):
++                continue
++            logid = logid[len(prefix):]
++            if logid.isdigit() and (lastid is None or int(logid) > lastid):
++                lastid = int(logid)
++                lastfilename = filename
++        if lastfilename is not None:
++            lastfilename = os.path.join(directory, lastfilename)
++        return lastid, lastfilename
++
++    def _findHighestSerial(self, directory):
++        """Find the last serial actually applied to disk in directory.
++
++        The purpose of this function is to not repeat sequence numbers
++        if the logging application is restarted.
++
++        This method is not thread safe, and only intended to be called
++        from the constructor (but it is called from other places in integration
++        tests).
++        """
++        return self._findHighestSerialFilename(directory)[0]
++
++    def getFilename(self, log_serial, time):
++        """Get the filename for a given log serial and time."""
++        log_subtype = self.get_log_infix()
++        # TODO: Calling output_dir causes a global lock to be taken and a
++        # directory scan, which is bad for performance. It would be better
++        # to have a split out 'directory name for time' function which the
++        # 'want to use this directory now' function can call.
++        output_dir = self.output_dir(time)
++        second_in_day = time.hour * 3600 + time.minute * 60 + time.second
++        return os.path.join(
++            output_dir, '%05d.%s%s' % (second_in_day, log_subtype, log_serial))
++
++    def get_log_infix(self):
++        """Return the current log infix to use in ids and file names."""
++        return self._log_subtype + self._log_token
++
++    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.get_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
++
++    def output_dir(self, now=None):
++        """Find or make the directory to allocate log names in.
++
++        Log names are assigned within subdirectories containing the date the
++        assignment happened.
++        """
++        if now is not None:
++            now = now.astimezone(UTC)
++        else:
++            now = datetime.datetime.now(UTC)
++        date = now.strftime('%Y-%m-%d')
++        result = os.path.join(self._output_root, date)
++        if result != self._last_output_dir:
++            self._lock.acquire()
++            try:
++                self._last_output_dir = result
++                # make sure the directory exists
++                try:
++                    os.makedirs(result)
++                except OSError, e:
++                    if e.errno != errno.EEXIST:
++                        raise
++                # TODO: Note that only one process can do this safely: its not
++                # cross-process safe, and also not entirely threadsafe: another
++                # thread that has a new log and hasn't written it could then
++                # use that serial number. We should either make it really safe,
++                # or remove the contention entirely and log uniquely per thread
++                # of execution.
++                self._last_serial = self._findHighestSerial(result)
++            finally:
++                self._lock.release()
++        return result
++
++    def setToken(self, token):
++        """Append a string to the log subtype in filenames and log ids.
++
++        :param token: a string to append..
++            Scripts that run multiple processes can use this to create a unique
++            identifier for each process.
++        """
++        self._log_token = token