1
2
3
4
5
6 """
7 Logging module.
8
9 Five levels of log information are defined.
10 These are, in order of decreasing verbosity: log, debug, info, warning, error.
11
12 This module provides a Loggable class for objects, as well as various
13 convenience methods for logging in general, and for logging with Twisted
14 and failures in particular.
15
16 Maintainer: U{Thomas Vander Stichele <thomas at apestaart dot org>}
17 """
18
19 import errno
20 import sys
21 import os
22 import fnmatch
23 import time
24 import types
25 import traceback
26
27
28 _DEBUG = "*:1"
29
30 _ENV_VAR_NAME = None
31
32 _PACKAGE_SCRUB_LIST = []
33
34
35 _categories = {}
36
37
38 _log_handlers = []
39 _log_handlers_limited = []
40
41 _initialized = False
42
43 _stdout = None
44 _stderr = None
45 _old_hup_handler = None
46
47
48
49 (ERROR,
50 WARN,
51 INFO,
52 DEBUG,
53 LOG) = range(1, 6)
54
55 COLORS = {ERROR: 'RED',
56 WARN: 'YELLOW',
57 INFO: 'GREEN',
58 DEBUG: 'BLUE',
59 LOG: 'CYAN'
60 }
61
62 _FORMATTED_LEVELS = []
63
65 """
66 Return the name of a log level.
67 """
68 assert isinstance(level, int) and level > 0 and level < 6, \
69 "Bad debug level"
70 return ('ERROR', 'WARN', 'INFO', 'DEBUG', 'LOG')[level - 1]
71
76
78 """
79 Register a given category in the debug system.
80 A level will be assigned to it based on previous calls to setDebug.
81 """
82
83
84 global _DEBUG
85 global _levels
86 global _categories
87
88 level = 0
89 chunks = _DEBUG.split(',')
90 for chunk in chunks:
91 if not chunk:
92 continue
93 if ':' in chunk:
94 spec, value = chunk.split(':')
95 else:
96 spec = '*'
97 value = chunk
98
99
100
101 if category in fnmatch.filter((category,), spec):
102
103 if not value:
104 continue
105 try:
106 level = int(value)
107 except ValueError:
108 level = 5
109
110 _categories[category] = level
111
113 """
114 @param category: string
115
116 Get the debug level at which this category is being logged, adding it
117 if it wasn't registered yet.
118 """
119 global _categories
120 if not _categories.has_key(category):
121 registerCategory(category)
122 return _categories[category]
123
142
144 """Fetches the current log settings.
145 The returned object can be sent to setLogSettings to restore the
146 returned settings
147 @returns: the current settings
148 """
149 return (_DEBUG,
150 _categories,
151 _log_handlers,
152 _log_handlers_limited)
153
161
163 '''
164 Scrub the filename to a relative path for all packages in our scrub list.
165 '''
166 global _PACKAGE_SCRUB_LIST
167 for package in _PACKAGE_SCRUB_LIST:
168 i = filename.rfind(package)
169 if i > -1:
170 return filename[i:]
171
172 return filename
173
175 """
176 Return the filename and line number for the given location.
177
178 If where is a negative integer, look for the code entry in the current
179 stack that is the given number of frames above this module.
180 If where is a function, look for the code entry of the function.
181
182 @param where: how many frames to go back up, or function
183 @type where: int (negative) or function
184
185 @return: tuple of (file, line)
186 @rtype: tuple of (str, int)
187 """
188 co = None
189 lineno = None
190
191 if isinstance(where, types.FunctionType):
192 co = where.func_code
193 lineno = co.co_firstlineno
194 elif isinstance(where, types.MethodType):
195 co = where.im_func.func_code
196 lineno = co.co_firstlineno
197 else:
198 stackFrame = sys._getframe()
199 while stackFrame:
200 co = stackFrame.f_code
201 if not co.co_filename.endswith('log.py'):
202
203 while where < -1:
204 stackFrame = stackFrame.f_back
205 where += 1
206 co = stackFrame.f_code
207 lineno = stackFrame.f_lineno
208 break
209 stackFrame = stackFrame.f_back
210
211 if not co:
212 return "<unknown file>", 0
213
214 return scrubFilename(co.co_filename), lineno
215
217 """
218 Ellipsize the representation of the given object.
219 """
220 r = repr(o)
221 if len(r) < 800:
222 return r
223
224 r = r[:60] + ' ... ' + r[-15:]
225 return r
226
245
246 -def doLog(level, object, category, format, args, where=-1,
247 filePath=None, line=None):
248 """
249 @param where: what to log file and line number for;
250 -1 for one frame above log.py; -2 and down for higher up;
251 a function for a (future) code object
252 @type where: int or callable
253 @param filePath: file to show the message as coming from, if caller
254 knows best
255 @type filePath: str
256 @param line: line to show the message as coming from, if caller
257 knows best
258 @type line: int
259
260 @return: dict of calculated variables, if they needed calculating.
261 currently contains file and line; this prevents us from
262 doing this work in the caller when it isn't needed because
263 of the debug level
264 """
265 ret = {}
266
267 if args:
268 message = format % args
269 else:
270 message = format
271
272
273 if _log_handlers:
274 if filePath is None and line is None:
275 (filePath, line) = getFileLine(where=where)
276 ret['filePath'] = filePath
277 ret['line'] = line
278 for handler in _log_handlers:
279 try:
280 handler(level, object, category, file, line, message)
281 except TypeError, e:
282 raise SystemError, "handler %r raised a TypeError: %s" % (
283 handler, getExceptionMessage(e))
284
285 if level > getCategoryLevel(category):
286 return ret
287
288 for handler in _log_handlers_limited:
289
290
291 if filePath is None and line is None:
292 (filePath, line) = getFileLine(where=where)
293 ret['filePath'] = filePath
294 ret['line'] = line
295 try:
296 handler(level, object, category, filePath, line, message)
297 except TypeError:
298 raise SystemError, "handler %r raised a TypeError" % handler
299
300 return ret
301
303 """
304 Log a fatal error message in the given category.
305 This will also raise a L{SystemExit}.
306 """
307 doLog(ERROR, object, cat, format, args)
308
309
310
311
312 if args:
313 raise SystemExit(format % args)
314 else:
315 raise SystemExit(format)
316
318 """
319 Log a warning message in the given category.
320 This is used for non-fatal problems.
321 """
322 doLog(WARN, object, cat, format, args)
323
325 """
326 Log an informational message in the given category.
327 """
328 doLog(INFO, object, cat, format, args)
329
331 """
332 Log a debug message in the given category.
333 """
334 doLog(DEBUG, object, cat, format, args)
335
337 """
338 Log a log message. Used for debugging recurring events.
339 """
340 doLog(LOG, object, cat, format, args)
341
343 """Write to a file object, ignoring errors.
344 """
345 try:
346 if args:
347 file.write(format % args)
348 else:
349 file.write(format)
350 except IOError, e:
351 if e.errno == errno.EPIPE:
352
353
354 os._exit(os.EX_OSERR)
355
356
358 """
359 A log handler that writes to stderr.
360
361 @type level: string
362 @type object: string (or None)
363 @type category: string
364 @type message: string
365 """
366
367 o = ""
368 if object:
369 o = '"' + object + '"'
370
371 where = "(%s:%d)" % (file, line)
372
373
374
375 safeprintf(sys.stderr, '%s [%5d] %-32s %-17s %-15s ',
376 getFormattedLevelName(level), os.getpid(), o, category,
377 time.strftime("%b %d %H:%M:%S"))
378 safeprintf(sys.stderr, '%-4s %s %s\n', "", message, where)
379
380 sys.stderr.flush()
381
406
407
408
409
410 -def init(envVarName, enableColorOutput=False):
435
448
450 """
451 Returns the currently active DEBUG string.
452 @rtype: str
453 """
454 global _DEBUG
455 return _DEBUG
456
458 """
459 Set the package names to scrub from filenames.
460 Filenames from these paths in log messages will be scrubbed to their
461 relative file path instead of the full absolute path.
462
463 @type packages: list of str
464 """
465 global _PACKAGE_SCRUB_LIST
466 _PACKAGE_SCRUB_LIST = packages
467
477
479 """
480 Add a custom log handler.
481
482 @param func: a function object with prototype (level, object, category,
483 message) where level is either ERROR, WARN, INFO, DEBUG, or
484 LOG, and the rest of the arguments are strings or None. Use
485 getLevelName(level) to get a printable name for the log level.
486 @type func: a callable function
487
488 @raises TypeError: if func is not a callable
489 """
490
491 if not callable(func):
492 raise TypeError, "func must be callable"
493
494 if func not in _log_handlers:
495 _log_handlers.append(func)
496
498 """
499 Add a custom log handler.
500
501 @param func: a function object with prototype (level, object, category,
502 message) where level is either ERROR, WARN, INFO, DEBUG, or
503 LOG, and the rest of the arguments are strings or None. Use
504 getLevelName(level) to get a printable name for the log level.
505 @type func: a callable function
506
507 @raises TypeError: TypeError if func is not a callable
508 """
509 if not callable(func):
510 raise TypeError, "func must be callable"
511
512 if func not in _log_handlers_limited:
513 _log_handlers_limited.append(func)
514
516 """
517 Remove a registered log handler.
518
519 @param func: a function object with prototype (level, object, category,
520 message) where level is either ERROR, WARN, INFO, DEBUG, or
521 LOG, and the rest of the arguments are strings or None. Use
522 getLevelName(level) to get a printable name for the log level.
523 @type func: a callable function
524
525 @raises ValueError: if func is not registered
526 """
527 _log_handlers.remove(func)
528
529
531 """
532 Remove a registered limited log handler.
533
534 @param func: a function object with prototype (level, object, category,
535 message) where level is either ERROR, WARN, INFO, DEBUG, or
536 LOG, and the rest of the arguments are strings or None. Use
537 getLevelName(level) to get a printable name for the log level.
538 @type func: a callable function
539
540 @raises ValueError: if func is not registered
541 """
542 _log_handlers_limited.remove(func)
543
544
545 -def error(cat, format, *args):
547
550
551 -def info(cat, format, *args):
553
554 -def debug(cat, format, *args):
556
557 -def log(cat, format, *args):
559
560
562 """
563 Return a short message based on an exception, useful for debugging.
564 Tries to find where the exception was triggered.
565 """
566 stack = traceback.extract_tb(sys.exc_info()[2])
567 if filename:
568 stack = [f for f in stack if f[0].find(filename) > -1]
569
570 (filename, line, func, text) = stack[frame]
571 filename = scrubFilename(filename)
572 exc = exception.__class__.__name__
573 msg = ""
574
575
576 if str(exception):
577 msg = ": %s" % str(exception)
578 return "exception %(exc)s at %(filename)s:%(line)s: %(func)s()%(msg)s" \
579 % locals()
580
582 """
583 Reopens the stdout and stderr output files, as set by
584 L{outputToFiles}.
585 """
586 if not _stdout and not _stderr:
587 debug('log', 'told to reopen log files, but log files not set')
588 return
589
590 def reopen(name, fileno, *args):
591 oldmask = os.umask(0026)
592 try:
593 f = open(name, 'a+', *args)
594 finally:
595 os.umask(oldmask)
596
597 os.dup2(f.fileno(), fileno)
598
599 if _stdout:
600 reopen(_stdout, sys.stdout.fileno())
601
602 if _stderr:
603 reopen(_stderr, sys.stderr.fileno(), 0)
604 debug('log', 'opened log %r', _stderr)
605
607 """
608 Redirect stdout and stderr to named files.
609
610 Records the file names so that a future call to reopenOutputFiles()
611 can open the same files. Installs a SIGHUP handler that will reopen
612 the output files.
613
614 Note that stderr is opened unbuffered, so if it shares a file with
615 stdout then interleaved output may not appear in the order that you
616 expect.
617 """
618 global _stdout, _stderr, _old_hup_handler
619 _stdout, _stderr = stdout, stderr
620 reopenOutputFiles()
621
622 def sighup(signum, frame):
623 info('log', "Received SIGHUP, reopening logs")
624 reopenOutputFiles()
625 if _old_hup_handler:
626 info('log', "Calling old SIGHUP hander")
627 _old_hup_handler(signum, frame)
628
629 debug('log', 'installing SIGHUP handler')
630 import signal
631 handler = signal.signal(signal.SIGHUP, sighup)
632 if handler == signal.SIG_DFL or handler == signal.SIG_IGN:
633 _old_hup_handler = None
634 else:
635 _old_hup_handler = handler
636
637
638
640 """
641 Base class for objects that want to be able to log messages with
642 different level of severity. The levels are, in order from least
643 to most: log, debug, info, warning, error.
644
645 @cvar logCategory: Implementors can provide a category to log their
646 messages under.
647 """
648
649 logCategory = 'default'
650
657
664
665 - def info(self, *args):
671
678
679 - def log(self, *args):
685
686 - def doLog(self, level, where, format, *args, **kwargs):
687 """
688 Log a message at the given level, with the possibility of going
689 higher up in the stack.
690
691 @param level: log level
692 @type level: int
693 @param where: how many frames to go back from the last log frame;
694 or a function (to log for a future call)
695 @type where: int (negative), or function
696
697 @param kwargs: a dict of pre-calculated values from a previous
698 doLog call
699
700 @return: a dict of calculated variables, to be reused in a
701 call to doLog that should show the same location
702 @rtype: dict
703 """
704 if _canShortcutLogging(self.logCategory, level):
705 return {}
706 args = self.logFunction(*args)
707 return doLog(level, self.logObjectName(), self.logCategory,
708 format, args, where=where, **kwargs)
709
726
728 """Overridable log function. Default just returns passed message."""
729 return args
730
732 """Overridable object name function."""
733
734 for name in ['logName', 'name']:
735 if hasattr(self, name):
736 return getattr(self, name)
737
738 return None
739
740
741
742
743 _initializedTwisted = False
744
745
746 __theTwistedLogObserver = None
747
756
757
758
760 """
761 Return a short message based on L{twisted.python.failure.Failure}.
762 Tries to find where the exception was triggered.
763 """
764 exc = str(failure.type)
765 msg = failure.getErrorMessage()
766 if len(failure.frames) == 0:
767 return "failure %(exc)s: %(msg)s" % locals()
768
769 (func, filename, line, some, other) = failure.frames[-1]
770 filename = scrubFilename(filename)
771 return "failure %(exc)s at %(filename)s:%(line)s: %(func)s(): %(msg)s" \
772 % locals()
773
775 """
776 Log a warning about a Failure. Useful as an errback handler:
777 d.addErrback(warningFailure)
778
779 @param swallow: whether to swallow the failure or not
780 @type swallow: bool
781 """
782 warning('', getFailureMessage(failure))
783 if not swallow:
784 return failure
785
787 """
788 Integrate twisted's logger with our logger.
789
790 This is done in a separate method because calling this imports and sets
791 up a reactor. Since we want basic logging working before choosing a
792 reactor, we need to separate these.
793 """
794 global _initializedTwisted
795
796 if _initializedTwisted:
797 return
798
799 debug('log', 'Integrating twisted logger')
800
801
802 from twisted.python import log as tlog
803
804
805
806 from twisted.spread import pb
807
808
809
810 observer = _getTheTwistedLogObserver()
811 observer.ignoreErrors([pb.Error,])
812 tlog.startLoggingWithObserver(observer.emit, False)
813
814 _initializedTwisted = True
815
816
817
818
820 """
821 Twisted log observer that integrates with our logging.
822 """
823 logCategory = "logobserver"
824
826 self._ignoreErrors = []
827
828 - def emit(self, eventDict):
829 method = log
830 edm = eventDict['message']
831 if not edm:
832 if eventDict['isError'] and eventDict.has_key('failure'):
833 f = eventDict['failure']
834 for failureType in self._ignoreErrors:
835 r = f.check(failureType)
836 if r:
837 self.debug("Failure of type %r, ignoring" % failureType)
838 return
839
840 self.log("Failure %r" % f)
841
842 method = debug
843 msg = "A twisted traceback occurred."
844 if getCategoryLevel("twisted") < WARN:
845 msg += " Run with debug level >= 2 to see the traceback."
846
847 warning('twisted', msg)
848 text = f.getTraceback()
849 safeprintf(sys.stderr, "\nTwisted traceback:\n")
850 safeprintf(sys.stderr, text + '\n')
851 elif eventDict.has_key('format'):
852 text = eventDict['format'] % eventDict
853 else:
854
855 return
856 else:
857 text = ' '.join(map(str, edm))
858
859 fmtDict = { 'system': eventDict['system'],
860 'text': text.replace("\n", "\n\t")
861 }
862 msgStr = " [%(system)s] %(text)s\n" % fmtDict
863
864
865 method('twisted', msgStr)
866
868 for failureType in types:
869 self._ignoreErrors.append(failureType)
870
872 self._ignoreErrors = []
873