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