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 _LEVEL_NAMES = ['ERROR', 'WARN', 'INFO', 'DEBUG', 'LOG']
64
66 """
67 Return the name of a log level.
68 @param level: The level we want to know the name
69 @type level: int
70 @return: The name of the level
71 @rtype: str
72 """
73 assert isinstance(level, int) and level > 0 and level < 6, \
74 TypeError("Bad debug level")
75 return getLevelNames()[level - 1]
76
78 """
79 Return a list with the level names
80 @return: A list with the level names
81 @rtype: list of str
82 """
83 return _LEVEL_NAMES
84
86 """
87 Return the integer value of the levelName.
88 @param levelName: The string value of the level name
89 @type levelName: str
90 @return: The value of the level name we are interested in.
91 @rtype: int
92 """
93 assert isinstance(levelName, str) and levelName in getLevelNames(), \
94 "Bad debug level name"
95 return getLevelNames().index(levelName)+1
96
101
103 """
104 Register a given category in the debug system.
105 A level will be assigned to it based on previous calls to setDebug.
106 """
107
108
109 global _DEBUG
110 global _levels
111 global _categories
112
113 level = 0
114 chunks = _DEBUG.split(',')
115 for chunk in chunks:
116 if not chunk:
117 continue
118 if ':' in chunk:
119 spec, value = chunk.split(':')
120 else:
121 spec = '*'
122 value = chunk
123
124
125
126 if category in fnmatch.filter((category,), spec):
127
128 if not value:
129 continue
130 try:
131 level = int(value)
132 except ValueError:
133 level = 5
134
135 _categories[category] = level
136
138 """
139 @param category: string
140
141 Get the debug level at which this category is being logged, adding it
142 if it wasn't registered yet.
143 """
144 global _categories
145 if not _categories.has_key(category):
146 registerCategory(category)
147 return _categories[category]
148
167
169 """Fetches the current log settings.
170 The returned object can be sent to setLogSettings to restore the
171 returned settings
172 @returns: the current settings
173 """
174 return (_DEBUG,
175 _categories,
176 _log_handlers,
177 _log_handlers_limited)
178
186
198
200 """
201 Return the filename and line number for the given location.
202
203 If where is a negative integer, look for the code entry in the current
204 stack that is the given number of frames above this module.
205 If where is a function, look for the code entry of the function.
206
207 @param where: how many frames to go back up, or function
208 @type where: int (negative) or function
209
210 @return: tuple of (file, line)
211 @rtype: tuple of (str, int)
212 """
213 co = None
214 lineno = None
215
216 if isinstance(where, types.FunctionType):
217 co = where.func_code
218 lineno = co.co_firstlineno
219 elif isinstance(where, types.MethodType):
220 co = where.im_func.func_code
221 lineno = co.co_firstlineno
222 else:
223 stackFrame = sys._getframe()
224 while stackFrame:
225 co = stackFrame.f_code
226 if not co.co_filename.endswith('log.py'):
227
228 while where < -1:
229 stackFrame = stackFrame.f_back
230 where += 1
231 co = stackFrame.f_code
232 lineno = stackFrame.f_lineno
233 break
234 stackFrame = stackFrame.f_back
235
236 if not co:
237 return "<unknown file>", 0
238
239 return scrubFilename(co.co_filename), lineno
240
242 """
243 Ellipsize the representation of the given object.
244 """
245 r = repr(o)
246 if len(r) < 800:
247 return r
248
249 r = r[:60] + ' ... ' + r[-15:]
250 return r
251
270
271 -def doLog(level, object, category, format, args, where=-1,
272 filePath=None, line=None):
273 """
274 @param where: what to log file and line number for;
275 -1 for one frame above log.py; -2 and down for higher up;
276 a function for a (future) code object
277 @type where: int or callable
278 @param filePath: file to show the message as coming from, if caller
279 knows best
280 @type filePath: str
281 @param line: line to show the message as coming from, if caller
282 knows best
283 @type line: int
284
285 @return: dict of calculated variables, if they needed calculating.
286 currently contains file and line; this prevents us from
287 doing this work in the caller when it isn't needed because
288 of the debug level
289 """
290 ret = {}
291
292 if args:
293 message = format % args
294 else:
295 message = format
296
297
298 if _log_handlers:
299 if filePath is None and line is None:
300 (filePath, line) = getFileLine(where=where)
301 ret['filePath'] = filePath
302 ret['line'] = line
303 for handler in _log_handlers:
304 try:
305 handler(level, object, category, file, line, message)
306 except TypeError, e:
307 raise SystemError, "handler %r raised a TypeError: %s" % (
308 handler, getExceptionMessage(e))
309
310 if level > getCategoryLevel(category):
311 return ret
312
313 if _log_handlers_limited:
314 if filePath is None and line is None:
315 (filePath, line) = getFileLine(where=where)
316 ret['filePath'] = filePath
317 ret['line'] = line
318 for handler in _log_handlers_limited:
319
320
321 try:
322 handler(level, object, category, filePath, line, message)
323 except TypeError:
324 raise SystemError, "handler %r raised a TypeError" % handler
325
326 return ret
327
329 """
330 Log a fatal error message in the given category.
331 This will also raise a L{SystemExit}.
332 """
333 doLog(ERROR, object, cat, format, args)
334
335
336
337
338 if args:
339 raise SystemExit(format % args)
340 else:
341 raise SystemExit(format)
342
344 """
345 Log a warning message in the given category.
346 This is used for non-fatal problems.
347 """
348 doLog(WARN, object, cat, format, args)
349
351 """
352 Log an informational message in the given category.
353 """
354 doLog(INFO, object, cat, format, args)
355
357 """
358 Log a debug message in the given category.
359 """
360 doLog(DEBUG, object, cat, format, args)
361
363 """
364 Log a log message. Used for debugging recurring events.
365 """
366 doLog(LOG, object, cat, format, args)
367
369 """Write to a file object, ignoring errors.
370 """
371 try:
372 if args:
373 file.write(format % args)
374 else:
375 file.write(format)
376 except IOError, e:
377 if e.errno == errno.EPIPE:
378
379
380 os._exit(os.EX_OSERR)
381
382
384 """
385 A log handler that writes to stderr.
386
387 @type level: string
388 @type object: string (or None)
389 @type category: string
390 @type message: string
391 """
392
393 o = ""
394 if object:
395 o = '"' + object + '"'
396
397 where = "(%s:%d)" % (file, line)
398
399
400
401 safeprintf(sys.stderr, '%s [%5d] %-32s %-17s %-15s ',
402 getFormattedLevelName(level), os.getpid(), o, category,
403 time.strftime("%b %d %H:%M:%S"))
404 safeprintf(sys.stderr, '%-4s %s %s\n', "", message, where)
405
406 sys.stderr.flush()
407
431
432
433
434
435 -def init(envVarName, enableColorOutput=False):
460
473
475 """
476 Returns the currently active DEBUG string.
477 @rtype: str
478 """
479 global _DEBUG
480 return _DEBUG
481
483 """
484 Set the package names to scrub from filenames.
485 Filenames from these paths in log messages will be scrubbed to their
486 relative file path instead of the full absolute path.
487
488 @type packages: list of str
489 """
490 global _PACKAGE_SCRUB_LIST
491 _PACKAGE_SCRUB_LIST = packages
492
502
504 """
505 Add a custom log handler.
506
507 @param func: a function object with prototype (level, object, category,
508 message) where level is either ERROR, WARN, INFO, DEBUG, or
509 LOG, and the rest of the arguments are strings or None. Use
510 getLevelName(level) to get a printable name for the log level.
511 @type func: a callable function
512
513 @raises TypeError: if func is not a callable
514 """
515
516 if not callable(func):
517 raise TypeError, "func must be callable"
518
519 if func not in _log_handlers:
520 _log_handlers.append(func)
521
523 """
524 Add a custom log handler.
525
526 @param func: a function object with prototype (level, object, category,
527 message) where level is either ERROR, WARN, INFO, DEBUG, or
528 LOG, and the rest of the arguments are strings or None. Use
529 getLevelName(level) to get a printable name for the log level.
530 @type func: a callable function
531
532 @raises TypeError: TypeError if func is not a callable
533 """
534 if not callable(func):
535 raise TypeError, "func must be callable"
536
537 if func not in _log_handlers_limited:
538 _log_handlers_limited.append(func)
539
541 """
542 Remove a registered log handler.
543
544 @param func: a function object with prototype (level, object, category,
545 message) where level is either ERROR, WARN, INFO, DEBUG, or
546 LOG, and the rest of the arguments are strings or None. Use
547 getLevelName(level) to get a printable name for the log level.
548 @type func: a callable function
549
550 @raises ValueError: if func is not registered
551 """
552 _log_handlers.remove(func)
553
554
556 """
557 Remove a registered limited log handler.
558
559 @param func: a function object with prototype (level, object, category,
560 message) where level is either ERROR, WARN, INFO, DEBUG, or
561 LOG, and the rest of the arguments are strings or None. Use
562 getLevelName(level) to get a printable name for the log level.
563 @type func: a callable function
564
565 @raises ValueError: if func is not registered
566 """
567 _log_handlers_limited.remove(func)
568
569
570 -def error(cat, format, *args):
572
575
576 -def info(cat, format, *args):
578
579 -def debug(cat, format, *args):
581
582 -def log(cat, format, *args):
584
585
587 """
588 Return a short message based on an exception, useful for debugging.
589 Tries to find where the exception was triggered.
590 """
591 stack = traceback.extract_tb(sys.exc_info()[2])
592 if filename:
593 stack = [f for f in stack if f[0].find(filename) > -1]
594
595 (filename, line, func, text) = stack[frame]
596 filename = scrubFilename(filename)
597 exc = exception.__class__.__name__
598 msg = ""
599
600
601 if str(exception):
602 msg = ": %s" % str(exception)
603 return "exception %(exc)s at %(filename)s:%(line)s: %(func)s()%(msg)s" \
604 % locals()
605
607 """
608 Reopens the stdout and stderr output files, as set by
609 L{outputToFiles}.
610 """
611 if not _stdout and not _stderr:
612 debug('log', 'told to reopen log files, but log files not set')
613 return
614
615 def reopen(name, fileno, *args):
616 oldmask = os.umask(0026)
617 try:
618 f = open(name, 'a+', *args)
619 finally:
620 os.umask(oldmask)
621
622 os.dup2(f.fileno(), fileno)
623
624 if _stdout:
625 reopen(_stdout, sys.stdout.fileno())
626
627 if _stderr:
628 reopen(_stderr, sys.stderr.fileno(), 0)
629 debug('log', 'opened log %r', _stderr)
630
632 """
633 Redirect stdout and stderr to named files.
634
635 Records the file names so that a future call to reopenOutputFiles()
636 can open the same files. Installs a SIGHUP handler that will reopen
637 the output files.
638
639 Note that stderr is opened unbuffered, so if it shares a file with
640 stdout then interleaved output may not appear in the order that you
641 expect.
642 """
643 global _stdout, _stderr, _old_hup_handler
644 _stdout, _stderr = stdout, stderr
645 reopenOutputFiles()
646
647 def sighup(signum, frame):
648 info('log', "Received SIGHUP, reopening logs")
649 reopenOutputFiles()
650 if _old_hup_handler:
651 info('log', "Calling old SIGHUP hander")
652 _old_hup_handler(signum, frame)
653
654 debug('log', 'installing SIGHUP handler')
655 import signal
656 handler = signal.signal(signal.SIGHUP, sighup)
657 if handler == signal.SIG_DFL or handler == signal.SIG_IGN:
658 _old_hup_handler = None
659 else:
660 _old_hup_handler = handler
661
662
663
665 """
666 Base class for objects that want to be able to log messages with
667 different level of severity. The levels are, in order from least
668 to most: log, debug, info, warning, error.
669
670 @cvar logCategory: Implementors can provide a category to log their
671 messages under.
672 """
673
674 logCategory = 'default'
675
677 """
678 Sets a marker that written to the logs. Setting this
679 marker to multiple elements at a time helps debugging.
680 @param marker: A string write to the log.
681 @type marker: str
682 @param level: The log level. It can be log.WARN, log.INFO,
683 log.DEBUG, log.ERROR or log.LOG.
684 @type level: int
685 """
686 logHandlers = {WARN:self.warning, INFO:self.info, DEBUG: self.debug,
687 ERROR: self.error, LOG:self.log}
688 logHandler = logHandlers.get(level)
689 if logHandler:
690 logHandler('%s', marker)
691
698
705
706 - def info(self, *args):
712
719
720 - def log(self, *args):
726
727 - def doLog(self, level, where, format, *args, **kwargs):
728 """
729 Log a message at the given level, with the possibility of going
730 higher up in the stack.
731
732 @param level: log level
733 @type level: int
734 @param where: how many frames to go back from the last log frame;
735 or a function (to log for a future call)
736 @type where: int (negative), or function
737
738 @param kwargs: a dict of pre-calculated values from a previous
739 doLog call
740
741 @return: a dict of calculated variables, to be reused in a
742 call to doLog that should show the same location
743 @rtype: dict
744 """
745 if _canShortcutLogging(self.logCategory, level):
746 return {}
747 args = self.logFunction(*args)
748 return doLog(level, self.logObjectName(), self.logCategory,
749 format, args, where=where, **kwargs)
750
767
769 """Overridable log function. Default just returns passed message."""
770 return args
771
773 """Overridable object name function."""
774
775 for name in ['logName', 'name']:
776 if hasattr(self, name):
777 return getattr(self, name)
778
779 return None
780
781
782
783
784 _initializedTwisted = False
785
786
787 __theTwistedLogObserver = None
788
797
798
799
801 """
802 Return a short message based on L{twisted.python.failure.Failure}.
803 Tries to find where the exception was triggered.
804 """
805 exc = str(failure.type)
806 msg = failure.getErrorMessage()
807 if len(failure.frames) == 0:
808 return "failure %(exc)s: %(msg)s" % locals()
809
810 (func, filename, line, some, other) = failure.frames[-1]
811 filename = scrubFilename(filename)
812 return "failure %(exc)s at %(filename)s:%(line)s: %(func)s(): %(msg)s" \
813 % locals()
814
816 """
817 Log a warning about a Failure. Useful as an errback handler:
818 d.addErrback(warningFailure)
819
820 @param swallow: whether to swallow the failure or not
821 @type swallow: bool
822 """
823 warning('', getFailureMessage(failure))
824 if not swallow:
825 return failure
826
856
857
858
859
861 """
862 Twisted log observer that integrates with our logging.
863 """
864 logCategory = "logobserver"
865
867 self._ignoreErrors = []
868
869 - def emit(self, eventDict):
870 method = log
871 edm = eventDict['message']
872 if not edm:
873 if eventDict['isError'] and eventDict.has_key('failure'):
874 f = eventDict['failure']
875 for failureType in self._ignoreErrors:
876 r = f.check(failureType)
877 if r:
878 self.debug("Failure of type %r, ignoring" % failureType)
879 return
880
881 self.log("Failure %r" % f)
882
883 method = debug
884 msg = "A twisted traceback occurred."
885 if getCategoryLevel("twisted") < WARN:
886 msg += " Run with debug level >= 2 to see the traceback."
887
888 warning('twisted', msg)
889 text = f.getTraceback()
890 safeprintf(sys.stderr, "\nTwisted traceback:\n")
891 safeprintf(sys.stderr, text + '\n')
892 elif eventDict.has_key('format'):
893 text = eventDict['format'] % eventDict
894 else:
895
896 return
897 else:
898 text = ' '.join(map(str, edm))
899
900 fmtDict = { 'system': eventDict['system'],
901 'text': text.replace("\n", "\n\t")
902 }
903 msgStr = " [%(system)s] %(text)s\n" % fmtDict
904
905
906 method('twisted', msgStr)
907
909 for failureType in types:
910 self._ignoreErrors.append(failureType)
911
913 self._ignoreErrors = []
914