OLD | NEW |
| (Empty) |
1 # -*- test-case-name: twisted.test.test_log -*- | |
2 # Copyright (c) 2001-2007 Twisted Matrix Laboratories. | |
3 # See LICENSE for details. | |
4 | |
5 """ | |
6 Logging and metrics infrastructure. | |
7 """ | |
8 | |
9 from __future__ import division | |
10 | |
11 # System Imports | |
12 import sys | |
13 import time | |
14 import warnings | |
15 from datetime import datetime | |
16 import logging | |
17 | |
18 # Sibling Imports | |
19 from twisted.python import util, context, reflect | |
20 | |
21 class ILogContext: | |
22 """ | |
23 Actually, this interface is just a synoym for the dictionary interface, | |
24 but it serves as a key for the default information in a log. | |
25 | |
26 I do not inherit from Interface because the world is a cruel place. | |
27 """ | |
28 | |
29 context.setDefault(ILogContext, | |
30 {"isError": 0, | |
31 "system": "-"}) | |
32 | |
33 def callWithContext(ctx, func, *args, **kw): | |
34 newCtx = context.get(ILogContext).copy() | |
35 newCtx.update(ctx) | |
36 return context.call({ILogContext: newCtx}, func, *args, **kw) | |
37 | |
38 def callWithLogger(logger, func, *args, **kw): | |
39 """ | |
40 Utility method which wraps a function in a try:/except:, logs a failure if | |
41 one occurrs, and uses the system's logPrefix. | |
42 """ | |
43 try: | |
44 lp = logger.logPrefix() | |
45 except KeyboardInterrupt: | |
46 raise | |
47 except: | |
48 lp = '(buggy logPrefix method)' | |
49 err(system=lp) | |
50 try: | |
51 return callWithContext({"system": lp}, func, *args, **kw) | |
52 except KeyboardInterrupt: | |
53 raise | |
54 except: | |
55 err(system=lp) | |
56 | |
57 def showwarning(message, category, filename, lineno, file=None): | |
58 if file is None: | |
59 msg(warning=message, category=reflect.qual(category), filename=filename,
lineno=lineno, | |
60 format="%(filename)s:%(lineno)s: %(category)s: %(warning)s") | |
61 else: | |
62 _oldshowwarning(message, category, filename, lineno, file) | |
63 | |
64 _keepErrors = 0 | |
65 _keptErrors = [] | |
66 _ignoreErrors = [] | |
67 | |
68 def startKeepingErrors(): | |
69 """ | |
70 DEPRECATED in Twisted 2.5. | |
71 | |
72 Support function for testing frameworks. | |
73 | |
74 Start keeping errors in a buffer which can be retrieved (and emptied) with | |
75 flushErrors. | |
76 """ | |
77 warnings.warn("log.startKeepingErrors is deprecated since Twisted 2.5", | |
78 category=DeprecationWarning, stacklevel=2) | |
79 global _keepErrors | |
80 _keepErrors = 1 | |
81 | |
82 | |
83 def flushErrors(*errorTypes): | |
84 """ | |
85 DEPRECATED in Twisted 2.5. See L{TestCase.flushLoggedErrors}. | |
86 | |
87 Support function for testing frameworks. | |
88 | |
89 Return a list of errors that occurred since the last call to flushErrors(). | |
90 (This will return None unless startKeepingErrors has been called.) | |
91 """ | |
92 | |
93 warnings.warn("log.flushErrors is deprecated since Twisted 2.5. " | |
94 "If you need to flush errors from within a unittest, " | |
95 "use TestCase.flushLoggedErrors instead.", | |
96 category=DeprecationWarning, stacklevel=2) | |
97 return _flushErrors(*errorTypes) | |
98 | |
99 | |
100 def _flushErrors(*errorTypes): | |
101 """ | |
102 PRIVATE. DEPRECATED. DON'T USE. | |
103 """ | |
104 global _keptErrors | |
105 k = _keptErrors | |
106 _keptErrors = [] | |
107 if errorTypes: | |
108 for erk in k: | |
109 shouldReLog = 1 | |
110 for errT in errorTypes: | |
111 if erk.check(errT): | |
112 shouldReLog = 0 | |
113 if shouldReLog: | |
114 err(erk) | |
115 return k | |
116 | |
117 def ignoreErrors(*types): | |
118 """ | |
119 DEPRECATED | |
120 """ | |
121 warnings.warn("log.ignoreErrors is deprecated since Twisted 2.5", | |
122 category=DeprecationWarning, stacklevel=2) | |
123 _ignore(*types) | |
124 | |
125 def _ignore(*types): | |
126 """ | |
127 PRIVATE. DEPRECATED. DON'T USE. | |
128 """ | |
129 for type in types: | |
130 _ignoreErrors.append(type) | |
131 | |
132 def clearIgnores(): | |
133 """ | |
134 DEPRECATED | |
135 """ | |
136 warnings.warn("log.clearIgnores is deprecated since Twisted 2.5", | |
137 category=DeprecationWarning, stacklevel=2) | |
138 _clearIgnores() | |
139 | |
140 def _clearIgnores(): | |
141 """ | |
142 PRIVATE. DEPRECATED. DON'T USE. | |
143 """ | |
144 global _ignoreErrors | |
145 _ignoreErrors = [] | |
146 | |
147 | |
148 def err(_stuff=None, _why=None, **kw): | |
149 """ | |
150 Write a failure to the log. | |
151 """ | |
152 if _stuff is None: | |
153 _stuff = failure.Failure() | |
154 if isinstance(_stuff, failure.Failure): | |
155 if _keepErrors: | |
156 if _ignoreErrors: | |
157 keep = 0 | |
158 for err in _ignoreErrors: | |
159 r = _stuff.check(err) | |
160 if r: | |
161 keep = 0 | |
162 break | |
163 else: | |
164 keep = 1 | |
165 if keep: | |
166 _keptErrors.append(_stuff) | |
167 else: | |
168 _keptErrors.append(_stuff) | |
169 msg(failure=_stuff, why=_why, isError=1, **kw) | |
170 elif isinstance(_stuff, Exception): | |
171 msg(failure=failure.Failure(_stuff), why=_why, isError=1, **kw) | |
172 else: | |
173 msg(repr(_stuff), why=_why, isError=1, **kw) | |
174 | |
175 deferr = err | |
176 | |
177 | |
178 class Logger: | |
179 """ | |
180 This represents a class which may 'own' a log. Used by subclassing. | |
181 """ | |
182 def logPrefix(self): | |
183 """ | |
184 Override this method to insert custom logging behavior. Its | |
185 return value will be inserted in front of every line. It may | |
186 be called more times than the number of output lines. | |
187 """ | |
188 return '-' | |
189 | |
190 | |
191 class LogPublisher: | |
192 """ | |
193 Class for singleton log message publishing. | |
194 """ | |
195 | |
196 synchronized = ['msg'] | |
197 | |
198 def __init__(self): | |
199 self.observers = [] | |
200 | |
201 def addObserver(self, other): | |
202 """ | |
203 Add a new observer. | |
204 | |
205 Observers are callable objects that will be called with each new log | |
206 message (a dict). | |
207 """ | |
208 assert callable(other) | |
209 self.observers.append(other) | |
210 | |
211 def removeObserver(self, other): | |
212 """ | |
213 Remove an observer. | |
214 """ | |
215 self.observers.remove(other) | |
216 | |
217 def msg(self, *message, **kw): | |
218 """ | |
219 Log a new message. | |
220 | |
221 For example:: | |
222 | |
223 >>> log.msg('Hello, world.') | |
224 | |
225 In particular, you MUST avoid the forms:: | |
226 | |
227 >>> log.msg(u'Hello, world.') | |
228 >>> log.msg('Hello ', 'world.') | |
229 | |
230 These forms work (sometimes) by accident and will be disabled | |
231 entirely in the future. | |
232 """ | |
233 actualEventDict = (context.get(ILogContext) or {}).copy() | |
234 actualEventDict.update(kw) | |
235 actualEventDict['message'] = message | |
236 actualEventDict['time'] = time.time() | |
237 for i in xrange(len(self.observers) - 1, -1, -1): | |
238 try: | |
239 self.observers[i](actualEventDict) | |
240 except KeyboardInterrupt: | |
241 # Don't swallow keyboard interrupt! | |
242 raise | |
243 except UnicodeEncodeError: | |
244 raise | |
245 except: | |
246 o = self.observers.pop(i) | |
247 err(failure.Failure(), | |
248 "Log observer %s failed, removing from observer list." % (o,
)) | |
249 | |
250 | |
251 try: | |
252 theLogPublisher | |
253 except NameError: | |
254 theLogPublisher = LogPublisher() | |
255 addObserver = theLogPublisher.addObserver | |
256 removeObserver = theLogPublisher.removeObserver | |
257 msg = theLogPublisher.msg | |
258 | |
259 | |
260 def _safeFormat(fmtString, fmtDict): | |
261 """ | |
262 Try to format the string C{fmtString} using C{fmtDict} arguments, | |
263 swallowing all errors to always return a string. | |
264 """ | |
265 # There's a way we could make this if not safer at least more | |
266 # informative: perhaps some sort of str/repr wrapper objects | |
267 # could be wrapped around the things inside of C{fmtDict}. That way | |
268 # if the event dict contains an object with a bad __repr__, we | |
269 # can only cry about that individual object instead of the | |
270 # entire event dict. | |
271 try: | |
272 text = fmtString % fmtDict | |
273 except KeyboardInterrupt: | |
274 raise | |
275 except: | |
276 try: | |
277 text = ('Invalid format string or unformattable object in log messag
e: %r, %s' % (fmtString, fmtDict)) | |
278 except: | |
279 try: | |
280 text = 'UNFORMATTABLE OBJECT WRITTEN TO LOG with fmt %r, MESSAGE
LOST' % (fmtString,) | |
281 except: | |
282 text = 'PATHOLOGICAL ERROR IN BOTH FORMAT STRING AND MESSAGE DET
AILS, MESSAGE LOST' | |
283 return text | |
284 | |
285 | |
286 def textFromEventDict(eventDict): | |
287 """ | |
288 Extract text from an event dict passed to a log observer. If it cannot | |
289 handle the dict, it returns None. | |
290 | |
291 The possible keys of eventDict are: | |
292 - C{message}: by default, it holds the final text. It's required, but can | |
293 be empty if either C{isError} or C{format} is provided (the first | |
294 having the priority). | |
295 - C{isError}: boolean indicating the nature of the event. | |
296 - C{failure}: L{failure.Failure} instance, required if the event is an | |
297 error. | |
298 - C{why}: if defined, used as header of the traceback in case of errors. | |
299 - C{format}: string format used in place of C{message} to customize | |
300 the event. It uses all keys present in C{eventDict} to format | |
301 the text. | |
302 Other keys will be used when applying the C{format}, or ignored. | |
303 """ | |
304 edm = eventDict['message'] | |
305 if not edm: | |
306 if eventDict['isError'] and 'failure' in eventDict: | |
307 text = ((eventDict.get('why') or 'Unhandled Error') | |
308 + '\n' + eventDict['failure'].getTraceback()) | |
309 elif 'format' in eventDict: | |
310 text = _safeFormat(eventDict['format'], eventDict) | |
311 else: | |
312 # we don't know how to log this | |
313 return | |
314 else: | |
315 text = ' '.join(map(reflect.safe_str, edm)) | |
316 return text | |
317 | |
318 | |
319 class FileLogObserver: | |
320 """ | |
321 Log observer that writes to a file-like object. | |
322 | |
323 @type timeFormat: C{str} or C{NoneType} | |
324 @ivar timeFormat: If not C{None}, the format string passed to strftime(). | |
325 """ | |
326 timeFormat = None | |
327 | |
328 def __init__(self, f): | |
329 self.write = f.write | |
330 self.flush = f.flush | |
331 | |
332 def getTimezoneOffset(self, when): | |
333 """ | |
334 Return the current local timezone offset from UTC. | |
335 | |
336 @type when: C{int} | |
337 @param when: POSIX (ie, UTC) timestamp for which to find the offset. | |
338 | |
339 @rtype: C{int} | |
340 @return: The number of seconds offset from UTC. West is positive, | |
341 east is negative. | |
342 """ | |
343 offset = datetime.utcfromtimestamp(when) - datetime.fromtimestamp(when) | |
344 return offset.days * (60 * 60 * 24) + offset.seconds | |
345 | |
346 def formatTime(self, when): | |
347 """ | |
348 Format the given UTC value as a string representing that time in the | |
349 local timezone. | |
350 | |
351 By default it's formatted as a ISO8601-like string (ISO8601 date and | |
352 ISO8601 time separated by a space). It can be customized using the | |
353 C{timeFormat} attribute, which will be used as input for the underlying | |
354 C{time.strftime} call. | |
355 | |
356 @type when: C{int} | |
357 @param when: POSIX (ie, UTC) timestamp for which to find the offset. | |
358 | |
359 @rtype: C{str} | |
360 """ | |
361 if self.timeFormat is not None: | |
362 return time.strftime(self.timeFormat, time.localtime(when)) | |
363 | |
364 tzOffset = -self.getTimezoneOffset(when) | |
365 when = datetime.utcfromtimestamp(when + tzOffset) | |
366 tzHour = int(tzOffset / 60 / 60) | |
367 tzMin = int(tzOffset / 60 % 60) | |
368 return '%d-%02d-%02d %02d:%02d:%02d%+03d%02d' % ( | |
369 when.year, when.month, when.day, | |
370 when.hour, when.minute, when.second, | |
371 tzHour, tzMin) | |
372 | |
373 def emit(self, eventDict): | |
374 text = textFromEventDict(eventDict) | |
375 if text is None: | |
376 return | |
377 | |
378 timeStr = self.formatTime(eventDict['time']) | |
379 fmtDict = {'system': eventDict['system'], 'text': text.replace("\n", "\n
\t")} | |
380 msgStr = _safeFormat("[%(system)s] %(text)s\n", fmtDict) | |
381 | |
382 util.untilConcludes(self.write, timeStr + " " + msgStr) | |
383 util.untilConcludes(self.flush) # Hoorj! | |
384 | |
385 def start(self): | |
386 """ | |
387 Start observing log events. | |
388 """ | |
389 addObserver(self.emit) | |
390 | |
391 def stop(self): | |
392 """ | |
393 Stop observing log events. | |
394 """ | |
395 removeObserver(self.emit) | |
396 | |
397 | |
398 class PythonLoggingObserver(object): | |
399 """ | |
400 Output twisted messages to Python standard library L{logging} module. | |
401 | |
402 WARNING: specific logging configurations (example: network) can lead to | |
403 a blocking system. Nothing is done here to prevent that, so be sure to not | |
404 use this: code within Twisted, such as twisted.web, assumes that logging | |
405 does not block. | |
406 """ | |
407 | |
408 def __init__(self, loggerName="twisted"): | |
409 """ | |
410 @param loggerName: identifier used for getting logger. | |
411 @type loggerName: C{str} | |
412 """ | |
413 self.logger = logging.getLogger(loggerName) | |
414 | |
415 def emit(self, eventDict): | |
416 """ | |
417 Receive a twisted log entry, format it and bridge it to python. | |
418 | |
419 By default the logging level used is info; log.err produces error | |
420 level, and you can customize the level by using the C{logLevel} key:: | |
421 | |
422 >>> log.msg('debugging', logLevel=logging.DEBUG) | |
423 | |
424 """ | |
425 if 'logLevel' in eventDict: | |
426 level = eventDict['logLevel'] | |
427 elif eventDict['isError']: | |
428 level = logging.ERROR | |
429 else: | |
430 level = logging.INFO | |
431 text = textFromEventDict(eventDict) | |
432 if text is None: | |
433 return | |
434 self.logger.log(level, text) | |
435 | |
436 def start(self): | |
437 """ | |
438 Start observing log events. | |
439 """ | |
440 addObserver(self.emit) | |
441 | |
442 def stop(self): | |
443 """ | |
444 Stop observing log events. | |
445 """ | |
446 removeObserver(self.emit) | |
447 | |
448 | |
449 class StdioOnnaStick: | |
450 """ | |
451 Class that pretends to be stout/err. | |
452 """ | |
453 | |
454 closed = 0 | |
455 softspace = 0 | |
456 mode = 'wb' | |
457 name = '<stdio (log)>' | |
458 | |
459 def __init__(self, isError=0): | |
460 self.isError = isError | |
461 self.buf = '' | |
462 | |
463 def close(self): | |
464 pass | |
465 | |
466 def fileno(self): | |
467 return -1 | |
468 | |
469 def flush(self): | |
470 pass | |
471 | |
472 def read(self): | |
473 raise IOError("can't read from the log!") | |
474 | |
475 readline = read | |
476 readlines = read | |
477 seek = read | |
478 tell = read | |
479 | |
480 def write(self, data): | |
481 d = (self.buf + data).split('\n') | |
482 self.buf = d[-1] | |
483 messages = d[0:-1] | |
484 for message in messages: | |
485 msg(message, printed=1, isError=self.isError) | |
486 | |
487 def writelines(self, lines): | |
488 for line in lines: | |
489 msg(line, printed=1, isError=self.isError) | |
490 | |
491 | |
492 try: | |
493 _oldshowwarning | |
494 except NameError: | |
495 _oldshowwarning = None | |
496 | |
497 | |
498 def startLogging(file, *a, **kw): | |
499 """ | |
500 Initialize logging to a specified file. | |
501 """ | |
502 flo = FileLogObserver(file) | |
503 startLoggingWithObserver(flo.emit, *a, **kw) | |
504 | |
505 def startLoggingWithObserver(observer, setStdout=1): | |
506 """ | |
507 Initialize logging to a specified observer. If setStdout is true | |
508 (defaults to yes), also redirect sys.stdout and sys.stderr | |
509 to the specified file. | |
510 """ | |
511 global defaultObserver, _oldshowwarning | |
512 if not _oldshowwarning: | |
513 _oldshowwarning = warnings.showwarning | |
514 warnings.showwarning = showwarning | |
515 if defaultObserver: | |
516 defaultObserver.stop() | |
517 defaultObserver = None | |
518 addObserver(observer) | |
519 msg("Log opened.") | |
520 if setStdout: | |
521 sys.stdout = logfile | |
522 sys.stderr = logerr | |
523 | |
524 | |
525 class NullFile: | |
526 softspace = 0 | |
527 def read(self): pass | |
528 def write(self, bytes): pass | |
529 def flush(self): pass | |
530 def close(self): pass | |
531 | |
532 | |
533 def discardLogs(): | |
534 """ | |
535 Throw away all logs. | |
536 """ | |
537 global logfile | |
538 logfile = NullFile() | |
539 | |
540 | |
541 # Prevent logfile from being erased on reload. This only works in cpython. | |
542 try: | |
543 logfile | |
544 except NameError: | |
545 logfile = StdioOnnaStick(0) | |
546 logerr = StdioOnnaStick(1) | |
547 | |
548 | |
549 class DefaultObserver: | |
550 """ | |
551 Default observer. | |
552 | |
553 Will ignore all non-error messages and send error messages to sys.stderr. | |
554 Will be removed when startLogging() is called for the first time. | |
555 """ | |
556 | |
557 def _emit(self, eventDict): | |
558 if eventDict["isError"]: | |
559 if 'failure' in eventDict: | |
560 text = eventDict['failure'].getTraceback() | |
561 else: | |
562 text = " ".join([str(m) for m in eventDict["message"]]) + "\n" | |
563 sys.stderr.write(text) | |
564 sys.stderr.flush() | |
565 | |
566 def start(self): | |
567 addObserver(self._emit) | |
568 | |
569 def stop(self): | |
570 removeObserver(self._emit) | |
571 | |
572 | |
573 # Some more sibling imports, at the bottom and unqualified to avoid | |
574 # unresolvable circularity | |
575 import threadable, failure | |
576 threadable.synchronize(LogPublisher) | |
577 | |
578 | |
579 try: | |
580 defaultObserver | |
581 except NameError: | |
582 defaultObserver = DefaultObserver() | |
583 defaultObserver.start() | |
584 | |
OLD | NEW |