1
# -*- Mode: Python; test-case-name: test_log -*-
2
# vi:si:et:sw=4:sts=4:ts=4
4
# This file is released under the standard PSF license.
9
Five levels of log information are defined.
10
These are, in order of decreasing verbosity: log, debug, info, warning, error.
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.
16
Maintainer: U{Thomas Vander Stichele <thomas at apestaart dot org>}
28
# environment variables controlling levels for each category
30
# name of the environment variable controlling our logging
32
# package names we should scrub filenames for
33
_PACKAGE_SCRUB_LIST = []
35
# dynamic dictionary of categories already seen and their level
38
# log handlers registered
40
_log_handlers_limited = []
46
_old_hup_handler = None
56
COLORS = {ERROR: 'RED',
62
_FORMATTED_LEVELS = []
63
_LEVEL_NAMES = ['ERROR', 'WARN', 'INFO', 'DEBUG', 'LOG']
66
def getLevelName(level):
68
Return the name of a log level.
69
@param level: The level we want to know the name
71
@return: The name of the level
74
assert isinstance(level, int) and level > 0 and level < 6, \
75
TypeError("Bad debug level")
76
return getLevelNames()[level - 1]
81
Return a list with the level names
82
@return: A list with the level names
88
def getLevelInt(levelName):
90
Return the integer value of the levelName.
91
@param levelName: The string value of the level name
93
@return: The value of the level name we are interested in.
96
assert isinstance(levelName, str) and levelName in getLevelNames(), \
97
"Bad debug level name"
98
return getLevelNames().index(levelName)+1
101
def getFormattedLevelName(level):
102
assert isinstance(level, int) and level > 0 and level < 6, \
103
TypeError("Bad debug level")
104
return _FORMATTED_LEVELS[level - 1]
107
def registerCategory(category):
109
Register a given category in the debug system.
110
A level will be assigned to it based on previous calls to setDebug.
112
# parse what level it is set to based on _DEBUG
113
# example: *:2,admin:4
119
chunks = _DEBUG.split(',')
124
spec, value = chunk.split(':')
129
# our glob is unix filename style globbing, so cheat with fnmatch
130
# fnmatch.fnmatch didn't work for this, so don't use it
131
if category in fnmatch.filter((category, ), spec):
132
# we have a match, so set level based on string or int
137
except ValueError: # e.g. *; we default to most
140
_categories[category] = level
143
def getCategoryLevel(category):
145
@param category: string
147
Get the debug level at which this category is being logged, adding it
148
if it wasn't registered yet.
151
if not category in _categories:
152
registerCategory(category)
153
return _categories[category]
156
def setLogSettings(state):
157
"""Update the current log settings.
158
This can restore an old saved log settings object returned by
160
@param state: the settings to set
165
global _log_handlers_limited
170
_log_handlers_limited) = state
172
for category in _categories:
173
registerCategory(category)
176
def getLogSettings():
177
"""Fetches the current log settings.
178
The returned object can be sent to setLogSettings to restore the
180
@returns: the current settings
185
_log_handlers_limited)
188
def _canShortcutLogging(category, level):
190
# we have some loggers operating without filters, have to do
194
return level > getCategoryLevel(category)
197
def scrubFilename(filename):
199
Scrub the filename to a relative path for all packages in our scrub list.
201
global _PACKAGE_SCRUB_LIST
202
for package in _PACKAGE_SCRUB_LIST:
203
i = filename.rfind(package)
210
def getFileLine(where=-1):
212
Return the filename and line number for the given location.
214
If where is a negative integer, look for the code entry in the current
215
stack that is the given number of frames above this module.
216
If where is a function, look for the code entry of the function.
218
@param where: how many frames to go back up, or function
219
@type where: int (negative) or function
221
@return: tuple of (file, line)
222
@rtype: tuple of (str, int)
228
if isinstance(where, types.FunctionType):
230
lineno = co.co_firstlineno
232
elif isinstance(where, types.MethodType):
233
co = where.im_func.func_code
234
lineno = co.co_firstlineno
237
stackFrame = sys._getframe()
239
co = stackFrame.f_code
240
if not co.co_filename.endswith('log.py'):
241
# wind up the stack according to frame
243
stackFrame = stackFrame.f_back
245
co = stackFrame.f_code
246
lineno = stackFrame.f_lineno
249
stackFrame = stackFrame.f_back
252
return "<unknown file>", 0
254
return scrubFilename(co.co_filename), lineno, name
259
Ellipsize the representation of the given object.
265
r = r[:60] + ' ... ' + r[-15:]
269
def getFormatArgs(startFormat, startArgs, endFormat, endArgs, args, kwargs):
271
Helper function to create a format and args to use for logging.
272
This avoids needlessly interpolating variables.
274
debugArgs = startArgs[:]
276
debugArgs.append(ellipsize(a))
278
for items in kwargs.items():
279
debugArgs.extend(items)
280
debugArgs.extend(endArgs)
281
format = startFormat \
282
+ ', '.join(('%s', ) * len(args)) \
283
+ (kwargs and ', ' or '') \
284
+ ', '.join(('%s=%r', ) * len(kwargs)) \
286
return format, debugArgs
289
def doLog(level, object, category, format, args, where=-1,
290
filePath=None, line=None):
292
@param where: what to log file and line number for;
293
-1 for one frame above log.py; -2 and down for higher up;
294
a function for a (future) code object
295
@type where: int or callable
296
@param filePath: file to show the message as coming from, if caller
299
@param line: line to show the message as coming from, if caller
303
@return: dict of calculated variables, if they needed calculating.
304
currently contains file and line; this prevents us from
305
doing this work in the caller when it isn't needed because
311
message = format % args
315
# first all the unlimited ones
317
if filePath is None and line is None:
318
(filePath, line, funcname) = getFileLine(where=where)
319
ret['filePath'] = filePath
322
message = "\033[00m\033[32;01m%s:\033[00m %s" % (funcname, message)
323
for handler in _log_handlers:
325
handler(level, object, category, file, line, message)
327
raise SystemError("handler %r raised a TypeError: %s" % (
328
handler, getExceptionMessage(e)))
330
if level > getCategoryLevel(category):
333
if _log_handlers_limited:
334
if filePath is None and line is None:
335
(filePath, line, funcname) = getFileLine(where=where)
336
ret['filePath'] = filePath
339
message = "\033[00m\033[32;01m%s:\033[00m %s" % (funcname, message)
340
for handler in _log_handlers_limited:
341
# set this a second time, just in case there weren't unlimited
342
# loggers there before
344
handler(level, object, category, filePath, line, message)
346
raise SystemError("handler %r raised a TypeError" % handler)
351
def errorObject(object, cat, format, *args):
353
Log a fatal error message in the given category.
354
This will also raise a L{SystemExit}.
356
doLog(ERROR, object, cat, format, args)
358
# we do the import here because having it globally causes weird import
359
# errors if our gstreactor also imports .log, which brings in errors
362
raise SystemExit(format % args)
364
raise SystemExit(format)
367
def warningObject(object, cat, format, *args):
369
Log a warning message in the given category.
370
This is used for non-fatal problems.
372
doLog(WARN, object, cat, format, args)
375
def infoObject(object, cat, format, *args):
377
Log an informational message in the given category.
379
doLog(INFO, object, cat, format, args)
382
def debugObject(object, cat, format, *args):
384
Log a debug message in the given category.
386
doLog(DEBUG, object, cat, format, args)
389
def logObject(object, cat, format, *args):
391
Log a log message. Used for debugging recurring events.
393
doLog(LOG, object, cat, format, args)
396
def safeprintf(file, format, *args):
397
"""Write to a file object, ignoring errors.
401
file.write(format % args)
405
if e.errno == errno.EPIPE:
406
# if our output is closed, exit; e.g. when logging over an
407
# ssh connection and the ssh connection is closed
408
os._exit(os.EX_OSERR)
409
# otherwise ignore it, there's nothing you can do
412
def stderrHandler(level, object, category, file, line, message):
414
A log handler that writes to stderr.
417
@type object: string (or None)
418
@type category: string
419
@type message: string
424
o = '"' + object + '"'
426
where = "(%s:%d)" % (file, line)
428
# level pid object cat time
429
# 5 + 1 + 7 + 1 + 32 + 1 + 17 + 1 + 15 == 80
430
safeprintf(sys.stderr, '%s [%5d] [0x%12x] %-32s %-17s %-15s %-4s %s %s\n',
431
getFormattedLevelName(level), os.getpid(), thread.get_ident(),
433
time.strftime("%b %d %H:%M:%S")
434
, "", message, where)
438
def _preformatLevels(noColorEnvVarName):
444
# we don't need to catch this if termcolor is in same package as
448
if (noColorEnvVarName is not None
449
and termcolor is not None
450
and (noColorEnvVarName not in os.environ
451
or not os.environ[noColorEnvVarName])):
453
t = termcolor.TerminalController()
454
formatter = lambda level: ''.join((t.BOLD, getattr(t, COLORS[level]),
455
format % (_LEVEL_NAMES[level-1], ), t.NORMAL))
457
formatter = lambda level: format % (_LEVEL_NAMES[level-1], )
459
for level in ERROR, WARN, INFO, DEBUG, LOG:
460
_FORMATTED_LEVELS.append(formatter(level))
462
### "public" useful API
467
def init(envVarName, enableColorOutput=False):
469
Initialize the logging system and parse the environment variable
471
Needs to be called before starting the actual application.
479
_ENV_VAR_NAME = envVarName
481
if enableColorOutput:
482
_preformatLevels(envVarName + "_NO_COLOR")
484
_preformatLevels(None)
486
if envVarName in os.environ:
487
# install a log handler that uses the value of the environment var
488
setDebug(os.environ[envVarName])
489
addLimitedLogHandler(stderrHandler)
494
def setDebug(string):
495
"""Set the DEBUG string. This controls the log output."""
501
debug('log', "%s set to %s" % (_ENV_VAR_NAME, _DEBUG))
503
# reparse all already registered category levels
504
for category in _categories:
505
registerCategory(category)
510
Returns the currently active DEBUG string.
517
def setPackageScrubList(*packages):
519
Set the package names to scrub from filenames.
520
Filenames from these paths in log messages will be scrubbed to their
521
relative file path instead of the full absolute path.
523
@type packages: list of str
525
global _PACKAGE_SCRUB_LIST
526
_PACKAGE_SCRUB_LIST = packages
531
Resets the logging system, removing all log handlers.
533
global _log_handlers, _log_handlers_limited, _initialized
536
_log_handlers_limited = []
540
def addLogHandler(func):
542
Add a custom log handler.
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
550
@raises TypeError: if func is not a callable
553
if not callable(func):
554
raise TypeError("func must be callable")
556
if func not in _log_handlers:
557
_log_handlers.append(func)
560
def addLimitedLogHandler(func):
562
Add a custom log handler.
564
@param func: a function object with prototype (level, object, category,
565
message) where level is either ERROR, WARN, INFO, DEBUG, or
566
LOG, and the rest of the arguments are strings or None. Use
567
getLevelName(level) to get a printable name for the log level.
568
@type func: a callable function
570
@raises TypeError: TypeError if func is not a callable
572
if not callable(func):
573
raise TypeError("func must be callable")
575
if func not in _log_handlers_limited:
576
_log_handlers_limited.append(func)
579
def removeLogHandler(func):
581
Remove a registered log handler.
583
@param func: a function object with prototype (level, object, category,
584
message) where level is either ERROR, WARN, INFO, DEBUG, or
585
LOG, and the rest of the arguments are strings or None. Use
586
getLevelName(level) to get a printable name for the log level.
587
@type func: a callable function
589
@raises ValueError: if func is not registered
591
_log_handlers.remove(func)
594
def removeLimitedLogHandler(func):
596
Remove a registered limited log handler.
598
@param func: a function object with prototype (level, object, category,
599
message) where level is either ERROR, WARN, INFO, DEBUG, or
600
LOG, and the rest of the arguments are strings or None. Use
601
getLevelName(level) to get a printable name for the log level.
602
@type func: a callable function
604
@raises ValueError: if func is not registered
606
_log_handlers_limited.remove(func)
608
# public log functions
611
def error(cat, format, *args):
612
errorObject(None, cat, format, *args)
615
def warning(cat, format, *args):
616
warningObject(None, cat, format, *args)
619
def info(cat, format, *args):
620
infoObject(None, cat, format, *args)
623
def debug(cat, format, *args):
624
debugObject(None, cat, format, *args)
627
def log(cat, format, *args):
628
logObject(None, cat, format, *args)
630
# public utility functions
633
def getExceptionMessage(exception, frame=-1, filename=None):
635
Return a short message based on an exception, useful for debugging.
636
Tries to find where the exception was triggered.
638
stack = traceback.extract_tb(sys.exc_info()[2])
640
stack = [f for f in stack if f[0].find(filename) > -1]
641
#import code; code.interact(local=locals())
642
(filename, line, func, text) = stack[frame]
643
filename = scrubFilename(filename)
644
exc = exception.__class__.__name__
646
# a shortcut to extract a useful message out of most exceptions
649
msg = ": %s" % str(exception)
650
return "exception %(exc)s at %(filename)s:%(line)s: %(func)s()%(msg)s" \
654
def reopenOutputFiles():
656
Reopens the stdout and stderr output files, as set by
659
if not _stdout and not _stderr:
660
debug('log', 'told to reopen log files, but log files not set')
663
def reopen(name, fileno, *args):
664
oldmask = os.umask(0026)
666
f = open(name, 'a+', *args)
670
os.dup2(f.fileno(), fileno)
673
reopen(_stdout, sys.stdout.fileno())
676
reopen(_stderr, sys.stderr.fileno(), 0)
677
debug('log', 'opened log %r', _stderr)
680
def outputToFiles(stdout=None, stderr=None):
682
Redirect stdout and stderr to named files.
684
Records the file names so that a future call to reopenOutputFiles()
685
can open the same files. Installs a SIGHUP handler that will reopen
688
Note that stderr is opened unbuffered, so if it shares a file with
689
stdout then interleaved output may not appear in the order that you
692
global _stdout, _stderr, _old_hup_handler
693
_stdout, _stderr = stdout, stderr
696
def sighup(signum, frame):
697
info('log', "Received SIGHUP, reopening logs")
700
info('log', "Calling old SIGHUP hander")
701
_old_hup_handler(signum, frame)
703
debug('log', 'installing SIGHUP handler')
705
handler = signal.signal(signal.SIGHUP, sighup)
706
if handler == signal.SIG_DFL or handler == signal.SIG_IGN:
707
_old_hup_handler = None
709
_old_hup_handler = handler
712
# base class for loggable objects
715
class Loggable(object):
717
Base class for objects that want to be able to log messages with
718
different level of severity. The levels are, in order from least
719
to most: log, debug, info, warning, error.
721
@cvar logCategory: Implementors can provide a category to log their
726
def writeMarker(self, marker, level):
728
Sets a marker that written to the logs. Setting this
729
marker to multiple elements at a time helps debugging.
730
@param marker: A string write to the log.
732
@param level: The log level. It can be log.WARN, log.INFO,
733
log.DEBUG, log.ERROR or log.LOG.
736
logHandlers = {WARN: self.warning,
741
logHandler = logHandlers.get(level)
743
logHandler('%s', marker)
745
def error(self, *args):
746
"""Log an error. By default this will also raise an exception."""
747
if _canShortcutLogging(self.logCategory, ERROR):
749
errorObject(self.logObjectName(), self.logCategory,
750
*self.logFunction(*args))
752
def warning(self, *args):
753
"""Log a warning. Used for non-fatal problems."""
754
if _canShortcutLogging(self.logCategory, WARN):
756
warningObject(self.logObjectName(), self.logCategory,
757
*self.logFunction(*args))
759
def info(self, *args):
760
"""Log an informational message. Used for normal operation."""
761
if _canShortcutLogging(self.logCategory, INFO):
763
infoObject(self.logObjectName(), self.logCategory,
764
*self.logFunction(*args))
766
def debug(self, *args):
767
"""Log a debug message. Used for debugging."""
768
if _canShortcutLogging(self.logCategory, DEBUG):
770
debugObject(self.logObjectName(), self.logCategory,
771
*self.logFunction(*args))
773
def log(self, *args):
774
"""Log a log message. Used for debugging recurring events."""
775
if _canShortcutLogging(self.logCategory, LOG):
777
logObject(self.logObjectName(), self.logCategory,
778
*self.logFunction(*args))
780
def doLog(self, level, where, format, *args, **kwargs):
782
Log a message at the given level, with the possibility of going
783
higher up in the stack.
785
@param level: log level
787
@param where: how many frames to go back from the last log frame;
788
or a function (to log for a future call)
789
@type where: int (negative), or function
791
@param kwargs: a dict of pre-calculated values from a previous
794
@return: a dict of calculated variables, to be reused in a
795
call to doLog that should show the same location
798
if _canShortcutLogging(self.logCategory, level):
800
args = self.logFunction(*args)
801
return doLog(level, self.logObjectName(), self.logCategory,
802
format, args, where=where, **kwargs)
804
def warningFailure(self, failure, swallow=True):
806
Log a warning about a Twisted Failure. Useful as an errback handler:
807
d.addErrback(self.warningFailure)
809
@param swallow: whether to swallow the failure or not
812
if _canShortcutLogging(self.logCategory, WARN):
816
warningObject(self.logObjectName(), self.logCategory,
817
*self.logFunction(getFailureMessage(failure)))
821
def logFunction(self, *args):
822
"""Overridable log function. Default just returns passed message."""
825
def logObjectName(self):
826
"""Overridable object name function."""
828
for name in ['logName', 'name']:
829
if hasattr(self, name):
830
return getattr(self, name)
834
def handleException(self, exc):
835
self.warning(getExceptionMessage(exc))
837
# Twisted helper stuff
840
_initializedTwisted = False
843
__theTwistedLogObserver = None
846
def _getTheTwistedLogObserver():
847
# used internally and in test
848
global __theTwistedLogObserver
850
if not __theTwistedLogObserver:
851
__theTwistedLogObserver = TwistedLogObserver()
853
return __theTwistedLogObserver
856
# public helper methods
859
def getFailureMessage(failure):
861
Return a short message based on L{twisted.python.failure.Failure}.
862
Tries to find where the exception was triggered.
864
exc = str(failure.type)
865
msg = failure.getErrorMessage()
866
if len(failure.frames) == 0:
867
return "failure %(exc)s: %(msg)s" % locals()
869
(func, filename, line, some, other) = failure.frames[-1]
870
filename = scrubFilename(filename)
871
return "failure %(exc)s at %(filename)s:%(line)s: %(func)s(): %(msg)s" \
875
def warningFailure(failure, swallow=True):
877
Log a warning about a Failure. Useful as an errback handler:
878
d.addErrback(warningFailure)
880
@param swallow: whether to swallow the failure or not
883
warning('', getFailureMessage(failure))
890
Integrate twisted's logger with our logger.
892
This is done in a separate method because calling this imports and sets
893
up a reactor. Since we want basic logging working before choosing a
894
reactor, we need to separate these.
896
global _initializedTwisted
898
if _initializedTwisted:
901
debug('log', 'Integrating twisted logger')
903
# integrate twisted's logging with us
904
from twisted.python import log as tlog
906
# this call imports the reactor
907
# that is why we do this in a separate method
908
from twisted.spread import pb
910
# we don't want logs for pb.Error types since they
911
# are specifically raised to be handled on the other side
912
observer = _getTheTwistedLogObserver()
913
observer.ignoreErrors([pb.Error, ])
914
tlog.startLoggingWithObserver(observer.emit, False)
916
_initializedTwisted = True
919
# we need an object as the observer because startLoggingWithObserver
920
# expects a bound method
923
class TwistedLogObserver(Loggable):
925
Twisted log observer that integrates with our logging.
927
logCategory = "logobserver"
930
self._ignoreErrors = [] # Failure types
932
def emit(self, eventDict):
933
method = log # by default, lowest level
934
edm = eventDict['message']
936
if eventDict['isError'] and 'failure' in eventDict:
937
f = eventDict['failure']
938
for failureType in self._ignoreErrors:
939
r = f.check(failureType)
941
self.debug("Failure of type %r, ignoring" %
945
self.log("Failure %r" % f)
947
method = debug # tracebacks from errors at debug level
948
msg = "A twisted traceback occurred."
949
if getCategoryLevel("twisted") < WARN:
950
msg += " Run with debug level >= 2 to see the traceback."
951
# and an additional warning
952
warning('twisted', msg)
953
text = f.getTraceback()
954
safeprintf(sys.stderr, "\nTwisted traceback:\n")
955
safeprintf(sys.stderr, text + '\n')
956
elif 'format' in eventDict:
957
text = eventDict['format'] % eventDict
959
# we don't know how to log this
962
text = ' '.join(map(str, edm))
964
fmtDict = {'system': eventDict['system'],
965
'text': text.replace("\n", "\n\t")}
966
msgStr = " [%(system)s] %(text)s\n" % fmtDict
967
# because msgstr can contain %, as in a backtrace, make sure we
968
# don't try to splice it
969
method('twisted', msgStr)
971
def ignoreErrors(self, *types):
972
for failureType in types:
973
self._ignoreErrors.append(failureType)
975
def clearIgnores(self):
976
self._ignoreErrors = []
added
removed
pitivi/log/log.py
