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. It is written such a way that it can be reused in
15 different projects to provide a controllable logging mechanism.
16
17 Maintainer: U{Thomas Vander Stichele <thomas at apestaart dot org>}
18 """
19
20 import errno
21 import sys
22 import os
23 import fnmatch
24 import time
25 import types
26 import logging
27 import traceback
28
29
30 _DEBUG = "*:1"
31
32 _ENV_VAR_NAME = None
33
34 _PACKAGE_SCRUB_LIST = []
35
36
37 _categories = {}
38
39
40 _log_handlers = []
41 _log_handlers_limited = []
42
43 _initialized = False
44
45 _stdout = None
46 _stderr = None
47 _old_hup_handler = None
48
49
50
51 (ERROR,
52 WARN,
53 INFO,
54 DEBUG,
55 LOG) = range(1, 6)
56
57 COLORS = {ERROR: 'RED',
58 WARN: 'YELLOW',
59 INFO: 'GREEN',
60 DEBUG: 'BLUE',
61 LOG: 'CYAN'}
62
63 _FORMATTED_LEVELS = []
64 _LEVEL_NAMES = ['ERROR', 'WARN', 'INFO', 'DEBUG', 'LOG']
65
66
68 """
69 Return the name of a log level.
70 @param level: The level we want to know the name
71 @type level: int
72 @return: The name of the level
73 @rtype: str
74 """
75 assert isinstance(level, int) and level > 0 and level < 6, \
76 TypeError("Bad debug level")
77 return getLevelNames()[level - 1]
78
79
81 """
82 Return a list with the level names
83 @return: A list with the level names
84 @rtype: list of str
85 """
86 return _LEVEL_NAMES
87
88
90 """
91 Return the integer value of the levelName.
92 @param levelName: The string value of the level name
93 @type levelName: str
94 @return: The value of the level name we are interested in.
95 @rtype: int
96 """
97 assert isinstance(levelName, str) and levelName in getLevelNames(), \
98 "Bad debug level name"
99 return getLevelNames().index(levelName)+1
100
101
106
107
109 """
110 Register a given category in the debug system.
111 A level will be assigned to it based on previous calls to setDebug.
112 """
113
114
115 global _DEBUG
116 global _levels
117 global _categories
118
119 level = 0
120 chunks = _DEBUG.split(',')
121 for chunk in chunks:
122 if not chunk:
123 continue
124 if ':' in chunk:
125 spec, value = chunk.split(':')
126 else:
127 spec = '*'
128 value = chunk
129
130
131
132 if category in fnmatch.filter((category, ), spec):
133
134 if not value:
135 continue
136 try:
137 level = int(value)
138 except ValueError:
139 level = 5
140
141 _categories[category] = level
142
143
145 """
146 @param category: string
147
148 Get the debug level at which this category is being logged, adding it
149 if it wasn't registered yet.
150 """
151 global _categories
152 if not category in _categories:
153 registerCategory(category)
154 return _categories[category]
155
156
175
176
178 """Fetches the current log settings.
179 The returned object can be sent to setLogSettings to restore the
180 returned settings
181 @returns: the current settings
182 """
183 return (_DEBUG,
184 _categories,
185 _log_handlers,
186 _log_handlers_limited)
187
188
196
197
209
210
212 """
213 Return the filename and line number for the given location.
214
215 If where is a negative integer, look for the code entry in the current
216 stack that is the given number of frames above this module.
217 If where is a function, look for the code entry of the function.
218
219 @param where: how many frames to go back up, or function
220 @type where: int (negative) or function
221
222 @param targetModule: continue going up the stack until that module is seen
223 @type targetModule: str or None
224
225 @return: tuple of (file, line)
226 @rtype: tuple of (str, int)
227 """
228 co = None
229 lineno = None
230
231 if isinstance(where, types.FunctionType):
232 co = where.func_code
233 lineno = co.co_firstlineno
234 elif isinstance(where, types.MethodType):
235 co = where.im_func.func_code
236 lineno = co.co_firstlineno
237 else:
238 stackFrame = sys._getframe()
239 while stackFrame:
240 co = stackFrame.f_code
241 if not co.co_filename.endswith('log.py'):
242
243 while where < -1:
244 stackFrame = stackFrame.f_back
245 where += 1
246 co = stackFrame.f_code
247 lineno = stackFrame.f_lineno
248 break
249 stackFrame = stackFrame.f_back
250
251 if not co:
252 return "<unknown file>", 0
253
254 if targetModule:
255 while stackFrame:
256 co = stackFrame.f_code
257 lineno = stackFrame.f_lineno
258 if targetModule in co.co_filename:
259 break
260 stackFrame = stackFrame.f_back
261
262 return scrubFilename(co.co_filename), lineno
263
264
266 """
267 Ellipsize the representation of the given object.
268 """
269 r = repr(o)
270 if len(r) < 800:
271 return r
272
273 r = r[:60] + ' ... ' + r[-15:]
274 return r
275
276
295
296
297 -def doLog(level, object, category, format, args, where=-1,
298 filePath=None, line=None):
299 """
300 @param where: what to log file and line number for;
301 -1 for one frame above log.py; -2 and down for higher up;
302 a function for a (future) code object
303 @type where: int or callable
304 @param filePath: file to show the message as coming from, if caller
305 knows best
306 @type filePath: str
307 @param line: line to show the message as coming from, if caller
308 knows best
309 @type line: int
310
311 @return: dict of calculated variables, if they needed calculating.
312 currently contains file and line; this prevents us from
313 doing this work in the caller when it isn't needed because
314 of the debug level
315 """
316 ret = {}
317
318 if args:
319 message = format % args
320 else:
321 message = format
322
323
324 if _log_handlers:
325 if filePath is None and line is None:
326 (filePath, line) = getFileLine(where=where)
327 ret['filePath'] = filePath
328 ret['line'] = line
329 for handler in _log_handlers:
330 try:
331 handler(level, object, category, file, line, message)
332 except TypeError, e:
333 raise SystemError("handler %r raised a TypeError: %s" % (
334 handler, getExceptionMessage(e)))
335
336 if level > getCategoryLevel(category):
337 return ret
338
339 if _log_handlers_limited:
340 if filePath is None and line is None:
341 (filePath, line) = getFileLine(where=where)
342 ret['filePath'] = filePath
343 ret['line'] = line
344 for handler in _log_handlers_limited:
345
346
347 try:
348 handler(level, object, category, filePath, line, message)
349 except TypeError:
350 raise SystemError("handler %r raised a TypeError" % handler)
351
352 return ret
353
354
356 """
357 Log a fatal error message in the given category.
358 This will also raise a L{SystemExit}.
359 """
360 doLog(ERROR, object, cat, format, args)
361
362
363
364
365 if args:
366 raise SystemExit(format % args)
367 else:
368 raise SystemExit(format)
369
370
372 """
373 Log a warning message in the given category.
374 This is used for non-fatal problems.
375 """
376 doLog(WARN, object, cat, format, args)
377
378
380 """
381 Log an informational message in the given category.
382 """
383 doLog(INFO, object, cat, format, args)
384
385
387 """
388 Log a debug message in the given category.
389 """
390 doLog(DEBUG, object, cat, format, args)
391
392
394 """
395 Log a log message. Used for debugging recurring events.
396 """
397 doLog(LOG, object, cat, format, args)
398
399
401 """Write to a file object, ignoring errors.
402 """
403 try:
404 if args:
405 file.write(format % args)
406 else:
407 file.write(format)
408 except IOError, e:
409 if e.errno == errno.EPIPE:
410
411
412 os._exit(os.EX_OSERR)
413
414
415
417 """
418 A log handler that writes to stderr.
419
420 @type level: string
421 @type object: string (or None)
422 @type category: string
423 @type message: string
424 """
425
426 o = ""
427 if object:
428 o = '"' + object + '"'
429
430 where = "(%s:%d)" % (file, line)
431
432
433
434 safeprintf(sys.stderr, '%s [%5d] %-32s %-17s %-15s ',
435 getFormattedLevelName(level), os.getpid(), o, category,
436 time.strftime("%b %d %H:%M:%S"))
437
438 try:
439 safeprintf(sys.stderr, '%-4s %s %s\n', "", message, where)
440 except UnicodeEncodeError:
441
442
443 message = message.encode('UTF-8')
444 safeprintf(sys.stderr, '%-4s %s %s\n', "", message, where)
445
446 sys.stderr.flush()
447
448
472
473
474
475
476
477
478 -def init(envVarName, enableColorOutput=False):
503
504
517
518
520 """
521 Returns the currently active DEBUG string.
522 @rtype: str
523 """
524 global _DEBUG
525 return _DEBUG
526
527
529 """
530 Set the package names to scrub from filenames.
531 Filenames from these paths in log messages will be scrubbed to their
532 relative file path instead of the full absolute path.
533
534 @type packages: list of str
535 """
536 global _PACKAGE_SCRUB_LIST
537 _PACKAGE_SCRUB_LIST = packages
538
539
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: if func is not a callable
562 """
563
564 if not callable(func):
565 raise TypeError("func must be callable")
566
567 if func not in _log_handlers:
568 _log_handlers.append(func)
569
570
572 """
573 Add a custom log handler.
574
575 @param func: a function object with prototype (level, object, category,
576 message) where level is either ERROR, WARN, INFO, DEBUG, or
577 LOG, and the rest of the arguments are strings or None. Use
578 getLevelName(level) to get a printable name for the log level.
579 @type func: a callable function
580
581 @raises TypeError: TypeError if func is not a callable
582 """
583 if not callable(func):
584 raise TypeError("func must be callable")
585
586 if func not in _log_handlers_limited:
587 _log_handlers_limited.append(func)
588
589
591 """
592 Remove a registered log handler.
593
594 @param func: a function object with prototype (level, object, category,
595 message) where level is either ERROR, WARN, INFO, DEBUG, or
596 LOG, and the rest of the arguments are strings or None. Use
597 getLevelName(level) to get a printable name for the log level.
598 @type func: a callable function
599
600 @raises ValueError: if func is not registered
601 """
602 _log_handlers.remove(func)
603
604
606 """
607 Remove a registered limited log handler.
608
609 @param func: a function object with prototype (level, object, category,
610 message) where level is either ERROR, WARN, INFO, DEBUG, or
611 LOG, and the rest of the arguments are strings or None. Use
612 getLevelName(level) to get a printable name for the log level.
613 @type func: a callable function
614
615 @raises ValueError: if func is not registered
616 """
617 _log_handlers_limited.remove(func)
618
619
620
621
622 -def error(cat, format, *args):
624
625
628
629
630 -def info(cat, format, *args):
632
633
634 -def debug(cat, format, *args):
636
637
638 -def log(cat, format, *args):
640
641
642
643
645 """
646 Return a short message based on an exception, useful for debugging.
647 Tries to find where the exception was triggered.
648 """
649 stack = traceback.extract_tb(sys.exc_info()[2])
650 if filename:
651 stack = [f for f in stack if f[0].find(filename) > -1]
652
653
654 if stack:
655 (filename, line, func, text) = stack[frame]
656 else:
657 (filename, line, func, text) = ('no stack', 0, 'none', '')
658
659 filename = scrubFilename(filename)
660 exc = exception.__class__.__name__
661 msg = ""
662
663
664 if str(exception):
665 msg = ": %s" % str(exception)
666 return "exception %(exc)s at %(filename)s:%(line)s: %(func)s()%(msg)s" \
667 % locals()
668
669
671 """
672 Reopens the stdout and stderr output files, as set by
673 L{outputToFiles}.
674 """
675 if not _stdout and not _stderr:
676 debug('log', 'told to reopen log files, but log files not set')
677 return
678
679 def reopen(name, fileno, *args):
680 oldmask = os.umask(0026)
681 try:
682 f = open(name, 'a+', *args)
683 finally:
684 os.umask(oldmask)
685
686 os.dup2(f.fileno(), fileno)
687
688 if _stdout:
689 reopen(_stdout, sys.stdout.fileno())
690
691 if _stderr:
692 reopen(_stderr, sys.stderr.fileno(), 0)
693 debug('log', 'opened log %r', _stderr)
694
695
697 """
698 Redirect stdout and stderr to named files.
699
700 Records the file names so that a future call to reopenOutputFiles()
701 can open the same files. Installs a SIGHUP handler that will reopen
702 the output files.
703
704 Note that stderr is opened unbuffered, so if it shares a file with
705 stdout then interleaved output may not appear in the order that you
706 expect.
707 """
708 global _stdout, _stderr, _old_hup_handler
709 _stdout, _stderr = stdout, stderr
710 reopenOutputFiles()
711
712 def sighup(signum, frame):
713 info('log', "Received SIGHUP, reopening logs")
714 reopenOutputFiles()
715 if _old_hup_handler:
716 info('log', "Calling old SIGHUP hander")
717 _old_hup_handler(signum, frame)
718
719 try:
720 import signal
721 except ImportError:
722 debug('log', 'POSIX signals not supported, unable to install'
723 ' SIGHUP handler')
724 else:
725 debug('log', 'installing SIGHUP handler')
726 handler = signal.signal(signal.SIGHUP, sighup)
727 if handler == signal.SIG_DFL or handler == signal.SIG_IGN:
728 _old_hup_handler = None
729 else:
730 _old_hup_handler = handler
731
732
733
734
735
737 """
738 Base class for objects that want to be able to log messages with
739 different level of severity. The levels are, in order from least
740 to most: log, debug, info, warning, error.
741
742 @cvar logCategory: Implementors can provide a category to log their
743 messages under.
744 """
745
746 logCategory = 'default'
747
749 """
750 Sets a marker that written to the logs. Setting this
751 marker to multiple elements at a time helps debugging.
752 @param marker: A string write to the log.
753 @type marker: str
754 @param level: The log level. It can be log.WARN, log.INFO,
755 log.DEBUG, log.ERROR or log.LOG.
756 @type level: int
757 """
758
759 if level == ERROR:
760 self.error('%s', marker)
761
762 doLog(level, self.logObjectName(), self.logCategory, '%s', marker)
763
770
777
778 - def info(self, *args):
784
791
792 - def log(self, *args):
798
799 - def doLog(self, level, where, format, *args, **kwargs):
800 """
801 Log a message at the given level, with the possibility of going
802 higher up in the stack.
803
804 @param level: log level
805 @type level: int
806 @param where: how many frames to go back from the last log frame;
807 or a function (to log for a future call)
808 @type where: int (negative), or function
809
810 @param kwargs: a dict of pre-calculated values from a previous
811 doLog call
812
813 @return: a dict of calculated variables, to be reused in a
814 call to doLog that should show the same location
815 @rtype: dict
816 """
817 if _canShortcutLogging(self.logCategory, level):
818 return {}
819 args = self.logFunction(*args)
820 return doLog(level, self.logObjectName(), self.logCategory,
821 format, args, where=where, **kwargs)
822
839
841 """Overridable log function. Default just returns passed message."""
842 return args
843
845 """Overridable object name function."""
846
847 for name in ['logName', 'name']:
848 if hasattr(self, name):
849 return getattr(self, name)
850
851 return None
852
853
854
855
856 _initializedTwisted = False
857
858
859 __theTwistedLogObserver = None
860
861
870
871
872
873
874
876 """
877 Return a short message based on L{twisted.python.failure.Failure}.
878 Tries to find where the exception was triggered.
879 """
880 exc = str(failure.type)
881 msg = failure.getErrorMessage()
882 if len(failure.frames) == 0:
883 return "failure %(exc)s: %(msg)s" % locals()
884
885 (func, filename, line, some, other) = failure.frames[-1]
886 filename = scrubFilename(filename)
887 return "failure %(exc)s at %(filename)s:%(line)s: %(func)s(): %(msg)s" \
888 % locals()
889
890
892 """
893 Log a warning about a Failure. Useful as an errback handler:
894 d.addErrback(warningFailure)
895
896 @param swallow: whether to swallow the failure or not
897 @type swallow: bool
898 """
899 warning('', getFailureMessage(failure))
900 if not swallow:
901 return failure
902
903
933
934
935
936
937
938
940 """
941 Twisted log observer that integrates with our logging.
942 """
943 logCategory = "logobserver"
944
946 self._ignoreErrors = []
947
948 - def emit(self, eventDict):
949 method = log
950 edm = eventDict['message']
951 if not edm:
952 if eventDict['isError'] and 'failure' in eventDict:
953 f = eventDict['failure']
954 for failureType in self._ignoreErrors:
955 r = f.check(failureType)
956 if r:
957 self.debug("Failure of type %r, ignoring" %
958 failureType)
959 return
960
961 self.log("Failure %r" % f)
962
963 method = debug
964 msg = "A twisted traceback occurred."
965 if getCategoryLevel("twisted") < WARN:
966 msg += " Run with debug level >= 2 to see the traceback."
967
968 warning('twisted', msg)
969 text = f.getTraceback()
970 safeprintf(sys.stderr, "\nTwisted traceback:\n")
971 safeprintf(sys.stderr, text + '\n')
972 elif 'format' in eventDict:
973 text = eventDict['format'] % eventDict
974 else:
975
976 return
977 else:
978 text = ' '.join(map(str, edm))
979
980 msgStr = " [%(system)s] %(text)s\n" % {
981 'system': eventDict['system'],
982 'text': text.replace("\n", "\n\t")}
983
984
985 method('twisted', msgStr)
986
988 for failureType in types:
989 self._ignoreErrors.append(failureType)
990
992 self._ignoreErrors = []
993
994
1002
1003
1011
1012
1014 """
1015 Make a logger from the standard library log through the Flumotion logging
1016 system.
1017
1018 @param loggerName: The standard logger to adapt, e.g. 'library.module'
1019 @type loggerName: str
1020 @param logCategory: The Flumotion log category to use when reporting output
1021 from the standard logger, e.g. 'librarymodule'
1022 @type logCategory: str
1023 @param targetModule: The name of the module that the logging should look
1024 like it's coming from. Use this if you don't want to
1025 see the file names and line numbers of the library
1026 who's logger you are adapting.
1027 @type targetModule: str or None
1028 """
1029 logger = logging.getLogger(loggerName)
1030
1031 if map(lambda h: isinstance(h, LogHandler), logger.handlers):
1032 return
1033 logger.setLevel(logLevelToStdLevel(getCategoryLevel(logCategory)))
1034 logger.addHandler(LogHandler(logCategory, targetModule))
1035
1036
1038 """
1039 A standard library logging handler that logs through the log system of this
1040 module.
1041 """
1042
1043 - def __init__(self, logCategory, targetModule):
1047
1048 - def emit(self, record):
1049 level = stdLevelToLogLevel(record.levelno)
1050 if _canShortcutLogging(self.logCategory, level):
1051 return
1052
1053 filename, lineno = getFileLine(-1, self.targetModule)
1054 doLog(level, None, self.logCategory,
1055 self.format(record), None, 0,
1056 scrubFilename(filename), lineno)
1057