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 _FORMATTED_LEVELS = []
62 _LEVEL_NAMES = ['ERROR', 'WARN', 'INFO', 'DEBUG', 'LOG']
63
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
77
79 """
80 Return a list with the level names
81 @return: A list with the level names
82 @rtype: list of str
83 """
84 return _LEVEL_NAMES
85
86
88 """
89 Return the integer value of the levelName.
90 @param levelName: The string value of the level name
91 @type levelName: str
92 @return: The value of the level name we are interested in.
93 @rtype: int
94 """
95 assert isinstance(levelName, str) and levelName in getLevelNames(), \
96 "Bad debug level name"
97 return getLevelNames().index(levelName)+1
98
99
104
105
107 """
108 Register a given category in the debug system.
109 A level will be assigned to it based on previous calls to setDebug.
110 """
111
112
113 global _DEBUG
114 global _levels
115 global _categories
116
117 level = 0
118 chunks = _DEBUG.split(',')
119 for chunk in chunks:
120 if not chunk:
121 continue
122 if ':' in chunk:
123 spec, value = chunk.split(':')
124 else:
125 spec = '*'
126 value = chunk
127
128
129
130 if category in fnmatch.filter((category, ), spec):
131
132 if not value:
133 continue
134 try:
135 level = int(value)
136 except ValueError:
137 level = 5
138
139 _categories[category] = level
140
141
143 """
144 @param category: string
145
146 Get the debug level at which this category is being logged, adding it
147 if it wasn't registered yet.
148 """
149 global _categories
150 if not category in _categories:
151 registerCategory(category)
152 return _categories[category]
153
154
173
174
176 """Fetches the current log settings.
177 The returned object can be sent to setLogSettings to restore the
178 returned settings
179 @returns: the current settings
180 """
181 return (_DEBUG,
182 _categories,
183 _log_handlers,
184 _log_handlers_limited)
185
186
194
195
207
208
210 """
211 Return the filename and line number for the given location.
212
213 If where is a negative integer, look for the code entry in the current
214 stack that is the given number of frames above this module.
215 If where is a function, look for the code entry of the function.
216
217 @param where: how many frames to go back up, or function
218 @type where: int (negative) or function
219
220 @return: tuple of (file, line)
221 @rtype: tuple of (str, int)
222 """
223 co = None
224 lineno = None
225
226 if isinstance(where, types.FunctionType):
227 co = where.func_code
228 lineno = co.co_firstlineno
229 elif isinstance(where, types.MethodType):
230 co = where.im_func.func_code
231 lineno = co.co_firstlineno
232 else:
233 stackFrame = sys._getframe()
234 while stackFrame:
235 co = stackFrame.f_code
236 if not co.co_filename.endswith('log.py'):
237
238 while where < -1:
239 stackFrame = stackFrame.f_back
240 where += 1
241 co = stackFrame.f_code
242 lineno = stackFrame.f_lineno
243 break
244 stackFrame = stackFrame.f_back
245
246 if not co:
247 return "<unknown file>", 0
248
249 return scrubFilename(co.co_filename), lineno
250
251
253 """
254 Ellipsize the representation of the given object.
255 """
256 r = repr(o)
257 if len(r) < 800:
258 return r
259
260 r = r[:60] + ' ... ' + r[-15:]
261 return r
262
263
282
283
284 -def doLog(level, object, category, format, args, where=-1,
285 filePath=None, line=None):
286 """
287 @param where: what to log file and line number for;
288 -1 for one frame above log.py; -2 and down for higher up;
289 a function for a (future) code object
290 @type where: int or callable
291 @param filePath: file to show the message as coming from, if caller
292 knows best
293 @type filePath: str
294 @param line: line to show the message as coming from, if caller
295 knows best
296 @type line: int
297
298 @return: dict of calculated variables, if they needed calculating.
299 currently contains file and line; this prevents us from
300 doing this work in the caller when it isn't needed because
301 of the debug level
302 """
303 ret = {}
304
305 if args:
306 message = format % args
307 else:
308 message = format
309
310
311 if _log_handlers:
312 if filePath is None and line is None:
313 (filePath, line) = getFileLine(where=where)
314 ret['filePath'] = filePath
315 ret['line'] = line
316 for handler in _log_handlers:
317 try:
318 handler(level, object, category, file, line, message)
319 except TypeError, e:
320 raise SystemError("handler %r raised a TypeError: %s" % (
321 handler, getExceptionMessage(e)))
322
323 if level > getCategoryLevel(category):
324 return ret
325
326 if _log_handlers_limited:
327 if filePath is None and line is None:
328 (filePath, line) = getFileLine(where=where)
329 ret['filePath'] = filePath
330 ret['line'] = line
331 for handler in _log_handlers_limited:
332
333
334 try:
335 handler(level, object, category, filePath, line, message)
336 except TypeError:
337 raise SystemError("handler %r raised a TypeError" % handler)
338
339 return ret
340
341
343 """
344 Log a fatal error message in the given category.
345 This will also raise a L{SystemExit}.
346 """
347 doLog(ERROR, object, cat, format, args)
348
349
350
351
352 if args:
353 raise SystemExit(format % args)
354 else:
355 raise SystemExit(format)
356
357
359 """
360 Log a warning message in the given category.
361 This is used for non-fatal problems.
362 """
363 doLog(WARN, object, cat, format, args)
364
365
367 """
368 Log an informational message in the given category.
369 """
370 doLog(INFO, object, cat, format, args)
371
372
374 """
375 Log a debug message in the given category.
376 """
377 doLog(DEBUG, object, cat, format, args)
378
379
381 """
382 Log a log message. Used for debugging recurring events.
383 """
384 doLog(LOG, object, cat, format, args)
385
386
388 """Write to a file object, ignoring errors.
389 """
390 try:
391 if args:
392 file.write(format % args)
393 else:
394 file.write(format)
395 except IOError, e:
396 if e.errno == errno.EPIPE:
397
398
399 os._exit(os.EX_OSERR)
400
401
402
404 """
405 A log handler that writes to stderr.
406
407 @type level: string
408 @type object: string (or None)
409 @type category: string
410 @type message: string
411 """
412
413 o = ""
414 if object:
415 o = '"' + object + '"'
416
417 where = "(%s:%d)" % (file, line)
418
419
420
421 safeprintf(sys.stderr, '%s [%5d] %-32s %-17s %-15s ',
422 getFormattedLevelName(level), os.getpid(), o, category,
423 time.strftime("%b %d %H:%M:%S"))
424 safeprintf(sys.stderr, '%-4s %s %s\n', "", message, where)
425
426 sys.stderr.flush()
427
428
452
453
454
455
456
457
458 -def init(envVarName, enableColorOutput=False):
483
484
497
498
500 """
501 Returns the currently active DEBUG string.
502 @rtype: str
503 """
504 global _DEBUG
505 return _DEBUG
506
507
509 """
510 Set the package names to scrub from filenames.
511 Filenames from these paths in log messages will be scrubbed to their
512 relative file path instead of the full absolute path.
513
514 @type packages: list of str
515 """
516 global _PACKAGE_SCRUB_LIST
517 _PACKAGE_SCRUB_LIST = packages
518
519
529
530
532 """
533 Add a custom log handler.
534
535 @param func: a function object with prototype (level, object, category,
536 message) where level is either ERROR, WARN, INFO, DEBUG, or
537 LOG, and the rest of the arguments are strings or None. Use
538 getLevelName(level) to get a printable name for the log level.
539 @type func: a callable function
540
541 @raises TypeError: if func is not a callable
542 """
543
544 if not callable(func):
545 raise TypeError("func must be callable")
546
547 if func not in _log_handlers:
548 _log_handlers.append(func)
549
550
552 """
553 Add a custom log handler.
554
555 @param func: a function object with prototype (level, object, category,
556 message) where level is either ERROR, WARN, INFO, DEBUG, or
557 LOG, and the rest of the arguments are strings or None. Use
558 getLevelName(level) to get a printable name for the log level.
559 @type func: a callable function
560
561 @raises TypeError: TypeError if func is not a callable
562 """
563 if not callable(func):
564 raise TypeError("func must be callable")
565
566 if func not in _log_handlers_limited:
567 _log_handlers_limited.append(func)
568
569
571 """
572 Remove a registered log handler.
573
574 @param func: a function object with prototype (level, object, category,
575 message) where level is either ERROR, WARN, INFO, DEBUG, or
576 LOG, and the rest of the arguments are strings or None. Use
577 getLevelName(level) to get a printable name for the log level.
578 @type func: a callable function
579
580 @raises ValueError: if func is not registered
581 """
582 _log_handlers.remove(func)
583
584
586 """
587 Remove a registered limited log handler.
588
589 @param func: a function object with prototype (level, object, category,
590 message) where level is either ERROR, WARN, INFO, DEBUG, or
591 LOG, and the rest of the arguments are strings or None. Use
592 getLevelName(level) to get a printable name for the log level.
593 @type func: a callable function
594
595 @raises ValueError: if func is not registered
596 """
597 _log_handlers_limited.remove(func)
598
599
600
601
602 -def error(cat, format, *args):
604
605
608
609
610 -def info(cat, format, *args):
612
613
614 -def debug(cat, format, *args):
616
617
618 -def log(cat, format, *args):
620
621
622
623
625 """
626 Return a short message based on an exception, useful for debugging.
627 Tries to find where the exception was triggered.
628 """
629 stack = traceback.extract_tb(sys.exc_info()[2])
630 if filename:
631 stack = [f for f in stack if f[0].find(filename) > -1]
632
633 (filename, line, func, text) = stack[frame]
634 filename = scrubFilename(filename)
635 exc = exception.__class__.__name__
636 msg = ""
637
638
639 if str(exception):
640 msg = ": %s" % str(exception)
641 return "exception %(exc)s at %(filename)s:%(line)s: %(func)s()%(msg)s" \
642 % locals()
643
644
646 """
647 Reopens the stdout and stderr output files, as set by
648 L{outputToFiles}.
649 """
650 if not _stdout and not _stderr:
651 debug('log', 'told to reopen log files, but log files not set')
652 return
653
654 def reopen(name, fileno, *args):
655 oldmask = os.umask(0026)
656 try:
657 f = open(name, 'a+', *args)
658 finally:
659 os.umask(oldmask)
660
661 os.dup2(f.fileno(), fileno)
662
663 if _stdout:
664 reopen(_stdout, sys.stdout.fileno())
665
666 if _stderr:
667 reopen(_stderr, sys.stderr.fileno(), 0)
668 debug('log', 'opened log %r', _stderr)
669
670
672 """
673 Redirect stdout and stderr to named files.
674
675 Records the file names so that a future call to reopenOutputFiles()
676 can open the same files. Installs a SIGHUP handler that will reopen
677 the output files.
678
679 Note that stderr is opened unbuffered, so if it shares a file with
680 stdout then interleaved output may not appear in the order that you
681 expect.
682 """
683 global _stdout, _stderr, _old_hup_handler
684 _stdout, _stderr = stdout, stderr
685 reopenOutputFiles()
686
687 def sighup(signum, frame):
688 info('log', "Received SIGHUP, reopening logs")
689 reopenOutputFiles()
690 if _old_hup_handler:
691 info('log', "Calling old SIGHUP hander")
692 _old_hup_handler(signum, frame)
693
694 try:
695 import signal
696 except ImportError:
697 debug('log', 'POSIX signals not supported, unable to install'
698 ' SIGHUP handler')
699 else:
700 debug('log', 'installing SIGHUP handler')
701 handler = signal.signal(signal.SIGHUP, sighup)
702 if handler == signal.SIG_DFL or handler == signal.SIG_IGN:
703 _old_hup_handler = None
704 else:
705 _old_hup_handler = handler
706
707
708
709
710
712 """
713 Base class for objects that want to be able to log messages with
714 different level of severity. The levels are, in order from least
715 to most: log, debug, info, warning, error.
716
717 @cvar logCategory: Implementors can provide a category to log their
718 messages under.
719 """
720
721 logCategory = 'default'
722
724 """
725 Sets a marker that written to the logs. Setting this
726 marker to multiple elements at a time helps debugging.
727 @param marker: A string write to the log.
728 @type marker: str
729 @param level: The log level. It can be log.WARN, log.INFO,
730 log.DEBUG, log.ERROR or log.LOG.
731 @type level: int
732 """
733
734 if level == ERROR:
735 self.error('%s', marker)
736
737 doLog(level, self.logObjectName(), self.logCategory, '%s', marker)
738
745
752
753 - def info(self, *args):
759
766
767 - def log(self, *args):
773
774 - def doLog(self, level, where, format, *args, **kwargs):
775 """
776 Log a message at the given level, with the possibility of going
777 higher up in the stack.
778
779 @param level: log level
780 @type level: int
781 @param where: how many frames to go back from the last log frame;
782 or a function (to log for a future call)
783 @type where: int (negative), or function
784
785 @param kwargs: a dict of pre-calculated values from a previous
786 doLog call
787
788 @return: a dict of calculated variables, to be reused in a
789 call to doLog that should show the same location
790 @rtype: dict
791 """
792 if _canShortcutLogging(self.logCategory, level):
793 return {}
794 args = self.logFunction(*args)
795 return doLog(level, self.logObjectName(), self.logCategory,
796 format, args, where=where, **kwargs)
797
814
816 """Overridable log function. Default just returns passed message."""
817 return args
818
820 """Overridable object name function."""
821
822 for name in ['logName', 'name']:
823 if hasattr(self, name):
824 return getattr(self, name)
825
826 return None
827
828
829
830
831 _initializedTwisted = False
832
833
834 __theTwistedLogObserver = None
835
836
845
846
847
848
849
851 """
852 Return a short message based on L{twisted.python.failure.Failure}.
853 Tries to find where the exception was triggered.
854 """
855 exc = str(failure.type)
856 msg = failure.getErrorMessage()
857 if len(failure.frames) == 0:
858 return "failure %(exc)s: %(msg)s" % locals()
859
860 (func, filename, line, some, other) = failure.frames[-1]
861 filename = scrubFilename(filename)
862 return "failure %(exc)s at %(filename)s:%(line)s: %(func)s(): %(msg)s" \
863 % locals()
864
865
867 """
868 Log a warning about a Failure. Useful as an errback handler:
869 d.addErrback(warningFailure)
870
871 @param swallow: whether to swallow the failure or not
872 @type swallow: bool
873 """
874 warning('', getFailureMessage(failure))
875 if not swallow:
876 return failure
877
878
908
909
910
911
912
913
915 """
916 Twisted log observer that integrates with our logging.
917 """
918 logCategory = "logobserver"
919
921 self._ignoreErrors = []
922
923 - def emit(self, eventDict):
924 method = log
925 edm = eventDict['message']
926 if not edm:
927 if eventDict['isError'] and 'failure' in eventDict:
928 f = eventDict['failure']
929 for failureType in self._ignoreErrors:
930 r = f.check(failureType)
931 if r:
932 self.debug("Failure of type %r, ignoring" %
933 failureType)
934 return
935
936 self.log("Failure %r" % f)
937
938 method = debug
939 msg = "A twisted traceback occurred."
940 if getCategoryLevel("twisted") < WARN:
941 msg += " Run with debug level >= 2 to see the traceback."
942
943 warning('twisted', msg)
944 text = f.getTraceback()
945 safeprintf(sys.stderr, "\nTwisted traceback:\n")
946 safeprintf(sys.stderr, text + '\n')
947 elif 'format' in eventDict:
948 text = eventDict['format'] % eventDict
949 else:
950
951 return
952 else:
953 text = ' '.join(map(str, edm))
954
955 msgStr = " [%(system)s] %(text)s\n" % {
956 'system': eventDict['system'],
957 'text': text.replace("\n", "\n\t")}
958
959
960 method('twisted', msgStr)
961
963 for failureType in types:
964 self._ignoreErrors.append(failureType)
965
967 self._ignoreErrors = []
968