1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22 """
23 Flumotion logging
24
25 Just like in GStreamer, five levels of log information are defined.
26 These are, in order of decreasing verbosity: log, debug, info, warning, error.
27
28 API Stability: stabilizing
29
30 Maintainer: U{Thomas Vander Stichele <thomas at apestaart dot org>}
31 """
32
33 import errno
34 import sys
35 import os
36 import fnmatch
37 import time
38 import types
39 import traceback
40
41
42 _FLU_DEBUG = "*:1"
43
44
45 _categories = {}
46
47
48 _log_handlers = []
49 _log_handlers_limited = []
50
51 _initialized = False
52
53
54 ERROR = 1
55 WARN = 2
56 INFO = 3
57 DEBUG = 4
58 LOG = 5
59
61 """
62 Return the name of a log level.
63 """
64 assert isinstance(level, int) and level > 0 and level < 6, \
65 "Bad debug level"
66 return ('ERROR', 'WARN', 'INFO', 'DEBUG', 'LOG')[level - 1]
67
69 """
70 Register a given category in the debug system.
71 A level will be assigned to it based on the setting of FLU_DEBUG.
72 """
73
74
75 global _FLU_DEBUG
76 global _levels
77 global _categories
78
79 level = 0
80 chunks = _FLU_DEBUG.split(',')
81 for chunk in chunks:
82 if not chunk:
83 continue
84 if ':' in chunk:
85 spec, value = chunk.split(':')
86 else:
87 spec = '*'
88 value = chunk
89
90
91
92 if category in fnmatch.filter((category, ), spec):
93
94 if not value:
95 continue
96 try:
97 level = int(value)
98 except ValueError:
99 level = 5
100
101 _categories[category] = level
102
104 """
105 @param category: string
106
107 Get the debug level at which this category is being logged, adding it
108 if it wasn't registered yet.
109 """
110 global _categories
111 if not _categories.has_key(category):
112 registerCategory(category)
113 return _categories[category]
114
122
124 '''
125 Scrub the filename of everything before 'flumotion' and'twisted' to make them shorter.
126 '''
127 i = filename.rfind('flumotion')
128 if i != -1:
129
130 filename = filename[i:]
131 else:
132
133 i = filename.rfind('twisted')
134 if i != -1:
135 filename = filename[i:]
136
137 return filename
138
140 """
141 Return the filename and line number for the given location.
142
143 If where is a negative integer, look for the code entry in the current
144 stack that is the given number of frames above this module.
145 If where is a function, look for the code entry of the function.
146
147 @param where: how many frames to go back up, or function
148 @type where: int (negative) or function
149
150 @return: tuple of (file, line)
151 @rtype: tuple of (str, int)
152 """
153 co = None
154 lineno = None
155
156 if isinstance(where, types.FunctionType):
157 co = where.func_code
158 lineno = co.co_firstlineno
159 elif isinstance(where, types.MethodType):
160 co = where.im_func.func_code
161 lineno = co.co_firstlineno
162 else:
163 stackFrame = sys._getframe()
164 while stackFrame:
165 co = stackFrame.f_code
166 if not co.co_filename.endswith('log.py'):
167
168 while where < -1:
169 stackFrame = stackFrame.f_back
170 where += 1
171 co = stackFrame.f_code
172 lineno = stackFrame.f_lineno
173 break
174 stackFrame = stackFrame.f_back
175
176 if not co:
177 return "<unknown file>", 0
178
179 return scrubFilename(co.co_filename), lineno
180
182 """
183 Ellipsize the representation of the given object.
184 """
185 r = repr(o)
186 if len(r) < 800:
187 return r
188
189 r = r[:60] + ' ... ' + r[-15:]
190 return r
191
209
210 -def doLog(level, object, category, format, args, where=-1,
211 file=None, line=None):
212 """
213 @param where: what to log file and line number for;
214 -1 for one frame above log.py; -2 and down for higher up;
215 a function for a (future) code object
216 @type where: int or callable
217 @param file: file to show the message as coming from, if caller knows best
218 @type file: str
219 @param line: line to show the message as coming from, if caller knows best
220 @type line: int
221
222 @return: dict of calculated variables, if they needed calculating.
223 currently contains file and line; this prevents us from
224 doing this work in the caller when it isn't needed because
225 of the debug level
226 """
227 ret = {}
228
229 if args:
230 message = format % args
231 else:
232 message = format
233
234
235 if _log_handlers:
236 if file is None and line is None:
237 (file, line) = getFileLine(where=where)
238 ret['file'] = file
239 ret['line'] = line
240 for handler in _log_handlers:
241 try:
242 handler(level, object, category, file, line, message)
243 except TypeError:
244 raise SystemError, "handler %r raised a TypeError" % handler
245
246 if level > getCategoryLevel(category):
247 return ret
248
249 for handler in _log_handlers_limited:
250
251
252 if file is None and line is None:
253 (file, line) = getFileLine(where=where)
254 ret['file'] = file
255 ret['line'] = line
256 try:
257 handler(level, object, category, file, line, message)
258 except TypeError:
259 raise SystemError, "handler %r raised a TypeError" % handler
260
261 return ret
262
264 """
265 Log a fatal error message in the given category.
266 This will also raise a L{flumotion.common.errors.SystemError}.
267 """
268 doLog(ERROR, object, cat, format, args)
269
270
271
272
273 from flumotion.common.errors import SystemError
274 if args:
275 raise SystemError(format % args)
276 else:
277 raise SystemError(format)
278
280 """
281 Log a warning message in the given category.
282 This is used for non-fatal problems.
283 """
284 doLog(WARN, object, cat, format, args)
285
287 """
288 Log an informational message in the given category.
289 """
290 doLog(INFO, object, cat, format, args)
291
293 """
294 Log a debug message in the given category.
295 """
296 doLog(DEBUG, object, cat, format, args)
297
299 """
300 Log a log message. Used for debugging recurring events.
301 """
302 doLog(LOG, object, cat, format, args)
303
304 -def error(cat, format, *args):
306
309
310 -def info(cat, format, *args):
312
313 -def debug(cat, format, *args):
315
316 -def log(cat, format, *args):
318
320 """
321 Log a warning about a Failure. Useful as an errback handler:
322 d.addErrback(warningFailure)
323
324 @param swallow: whether to swallow the failure or not
325 @type swallow: bool
326 """
327 warning('', getFailureMessage(failure))
328 if not swallow:
329 return failure
330
332 """
333 Base class for objects that want to be able to log messages with
334 different level of severity. The levels are, in order from least
335 to most: log, debug, info, warning, error.
336
337 @cvar logCategory: Implementors can provide a category to log their
338 messages under.
339 """
340
341 logCategory = 'default'
342
349
356
357 - def info(self, *args):
363
370
371 - def log(self, *args):
377
378 - def doLog(self, level, where, format, *args, **kwargs):
379 """
380 Log a message at the given level, with the possibility of going
381 higher up in the stack.
382
383 @param level: log level
384 @type level: int
385 @param where: how many frames to go back from the last log frame;
386 or a function (to log for a future call)
387 @type where: int (negative), or function
388
389 @param kwargs: a dict of pre-calculated values from a previous
390 doLog call
391
392 @return: a dict of calculated variables, to be reused in a
393 call to doLog that should show the same location
394 @rtype: dict
395 """
396 if _canShortcutLogging(self.logCategory, level):
397 return {}
398 args = self.logFunction(*args)
399 return doLog(level, self.logObjectName(), self.logCategory,
400 format, args, where=where, **kwargs)
401
418
420 """Overridable log function. Default just returns passed message."""
421 return args
422
424 """Overridable object name function."""
425
426 for name in ['logName', 'name']:
427 if hasattr(self, name):
428 return getattr(self, name)
429
430 return None
431
432
433
435 """
436 Twisted log observer that integrates with Flumotion's logging.
437 """
438 logCategory = "logobserver"
439
441 self._ignoreErrors = []
442
443 - def emit(self, eventDict):
444 method = log
445 edm = eventDict['message']
446 if not edm:
447 if eventDict['isError'] and eventDict.has_key('failure'):
448 f = eventDict['failure']
449 for type in self._ignoreErrors:
450 r = f.check(type)
451 if r:
452 self.debug("Failure of type %r, ignoring" % type)
453 return
454
455 self.log("Failure %r" % f)
456
457 method = debug
458 msg = "A twisted traceback occurred."
459 if getCategoryLevel("twisted") < WARN:
460 msg += " Run with debug level >= 2 to see the traceback."
461
462 warning('twisted', msg)
463 text = f.getTraceback()
464 print "\nTwisted traceback:\n"
465 print text
466 elif eventDict.has_key('format'):
467 text = eventDict['format'] % eventDict
468 else:
469
470 return
471 else:
472 text = ' '.join(map(str, edm))
473
474 fmtDict = { 'system': eventDict['system'],
475 'text': text.replace("\n", "\n\t")
476 }
477 msgStr = " [%(system)s] %(text)s\n" % fmtDict
478
479
480 method('twisted', msgStr)
481
485
487 self._ignoreErrors = []
488
489
490 __theFluLogObserver = None
491
500
502 """
503 A log handler that writes to stderr.
504
505 @type level: string
506 @type object: string (or None)
507 @type category: string
508 @type message: string
509 """
510
511 o = ""
512 if object:
513 o = '"' + object + '"'
514
515 where = "(%s:%d)" % (file, line)
516
517 try:
518
519
520 sys.stderr.write('%-5s [%5d] %-32s %-17s %-15s ' % (
521 getLevelName(level), os.getpid(), o, category,
522 time.strftime("%b %d %H:%M:%S")))
523 sys.stderr.write('%-4s %s %s\n' % ("", message, where))
524
525
526
527
528
529 sys.stderr.flush()
530 except IOError, e:
531 if e.errno == errno.EPIPE:
532
533
534 os._exit(os.EX_OSERR)
535
536
538 """
539 Add a custom log handler.
540
541 @param func: a function object
542 with prototype (level, object, category, message)
543 where level is either ERROR, WARN, INFO, DEBUG, or
544 LOG, and the rest of the arguments are strings or
545 None. Use getLevelName(level) to get a printable
546 name for the log level.
547 @type func: a callable function
548 @type limited: boolean
549 @param limited: whether to automatically filter based on FLU_DEBUG
550 """
551
552 if not callable(func):
553 raise TypeError, "func must be callable"
554
555 if limited:
556 _log_handlers_limited.append(func)
557 else:
558 _log_handlers.append(func)
559
561 """
562 Initialize the logging system and parse the FLU_DEBUG environment variable.
563 Needs to be called before starting the actual application.
564 """
565 global _initialized
566
567 if _initialized:
568 return
569
570 if os.environ.has_key('FLU_DEBUG'):
571
572 setFluDebug(os.environ['FLU_DEBUG'])
573 addLogHandler(stderrHandler, limited=True)
574
575 _initialized = True
576
577 _stdout = None
578 _stderr = None
580 """
581 Reopens the stdout and stderr output files, as set by
582 L{flumotion.common.log.outputToFiles}.
583 """
584 if not (_stdout and _stderr):
585 debug('log', 'told to reopen log files, but log files not set')
586 return
587
588 oldmask = os.umask(0026)
589 try:
590 so = open(_stdout, 'a+')
591 se = open(_stderr, 'a+', 0)
592 finally:
593 os.umask(oldmask)
594
595 os.dup2(so.fileno(), sys.stdout.fileno())
596 os.dup2(se.fileno(), sys.stderr.fileno())
597
598 debug('log', 'opened log %r', _stderr)
599
601 """
602 Redirect stdout and stderr to named files.
603
604 Records the file names so that a future call to reopenOutputFiles()
605 can open the same files. Installs a SIGHUP handler that will reopen
606 the output files.
607
608 Note that stderr is opened unbuffered, so if it shares a file with
609 stdout then interleaved output may not appear in the order that you
610 expect.
611 """
612 global _stdout, _stderr
613 _stdout, _stderr = stdout, stderr
614 reopenOutputFiles()
615
616 def sighup(signum, frame):
617 info('log', "Received SIGHUP, reopening logs")
618 reopenOutputFiles()
619
620 debug('log', 'installing SIGHUP handler')
621 import signal
622 signal.signal(signal.SIGHUP, sighup)
623
624 _initializedTwisted = False
625
627 """
628 Integrate twisted's logger with Flumotion's logger.
629
630 This is done in a separate method because calling this imports and sets
631 up a reactor. Since we want basic logging working before choosing a
632 reactor, we need to separate these.
633 """
634 global _initializedTwisted
635
636 if _initializedTwisted:
637 return
638
639 debug('log', 'Integrating twisted logger')
640
641
642 from twisted.python import log as tlog
643
644
645
646 from twisted.spread import pb
647
648
649
650 observer = _getTheFluLogObserver()
651 observer.ignoreErrors([pb.Error,])
652 tlog.startLoggingWithObserver(observer.emit, False)
653
654 _initializedTwisted = True
655
665
677
679 """
680 Return a short message based on an exception, useful for debugging.
681 Tries to find where the exception was triggered.
682 """
683 stack = traceback.extract_tb(sys.exc_info()[2])
684 if filename:
685 stack = [f for f in stack if f[0].find(filename) > -1]
686
687 (filename, line, func, text) = stack[frame]
688 filename = scrubFilename(filename)
689 exc = exception.__class__.__name__
690 msg = ""
691
692
693 if str(exception):
694 msg = ": %s" % str(exception)
695 return "exception %(exc)s at %(filename)s:%(line)s: %(func)s()%(msg)s" % locals()
696
698 """
699 Return a short message based on L{twisted.python.failure.Failure}.
700 Tries to find where the exception was triggered.
701 """
702 exc = str(failure.type)
703 msg = failure.getErrorMessage()
704 if len(failure.frames) == 0:
705 return "failure %(exc)s: %(msg)s" % locals()
706
707 (func, filename, line, some, other) = failure.frames[-1]
708 filename = scrubFilename(filename)
709 return "failure %(exc)s at %(filename)s:%(line)s: %(func)s(): %(msg)s" % locals()
710