1
2
3
4
5
6
7
8
9 """Verbose output and debugging facility
10
11 Examples:
12 from verbosity import verbose, debug; debug.active = [1,2,3]; debug(1, "blah")
13
14 """
15
16 __docformat__ = 'restructuredtext'
17
18 from sys import stdout, stderr
19 from sets import Set
20
21
22
23
24
25
26
27
28
29
31 """
32 Base class to provide logging
33 """
34
36 """Initialize the logger with a set of handlers to use for output
37
38 Each hanlder must have write() method implemented
39 """
40 if handlers == None:
41 handlers = [stdout]
42 self.__close_handlers = []
43 self.__handlers = []
44 self._setHandlers(handlers)
45 self.__lfprev = True
46 self.__crprev = 0
47
50
52 """Set list of handlers for the log.
53
54 A handler can be opened files, stdout, stderr, or a string, which
55 will be considered a filename to be opened for writing
56 """
57 handlers_ = []
58 self._closeOpenedHandlers()
59 for handler in handlers:
60 if isinstance(handler, basestring):
61 try:
62 handler = {'stdout' : stdout,
63 'stderr' : stderr}[handler.lower()]
64 except:
65 try:
66 handler = open(handler, 'w')
67 self.__close_handlers.append(handler)
68 except:
69 raise RuntimeError, \
70 "Cannot open file %s for writing by the logger" \
71 % handler
72 handlers_.append(handler)
73 self.__handlers = handlers_
74
76 """Close opened handlers (such as opened logfiles
77 """
78 for handler in self.__close_handlers:
79 handler.close()
80
82 """Return active handlers
83 """
84 return self.__handlers
85
86
87 - def __call__(self, msg, lf=True, cr=False, *args, **kwargs):
88 """
89 Write msg to each of the handlers.
90
91 It can append a newline (lf = Line Feed) or return
92 to the beginning before output and to take care about
93 cleaning previous message if present
94
95 it appends a newline (lf = Line Feed) since most commonly each
96 call is a separate message
97 """
98 if kwargs.has_key('msgargs'):
99 msg = msg % kwargs['msgargs']
100
101 if cr:
102 msg_ = ""
103 if self.__crprev > 0:
104
105 msg_ = "\r%s" % (" "*self.__crprev)
106 msg_ += "\r" + msg
107 self.__crprev = len(msg)
108 msg = msg_
109
110
111 lf = False
112 else:
113 self.__crprev += len(msg)
114
115 if lf:
116 msg = msg + "\n"
117 self.__crprev = 0
118
119 for handler in self.__handlers:
120 try:
121 handler.write(msg)
122 except:
123 print "Failed writing on handler %s" % handler
124 raise
125 try:
126 handler.flush()
127 except:
128
129 pass
130
131 self.__lfprev = lf
132
133 handlers = property(fget=_getHandlers, fset=_setHandlers)
134 lfprev = property(fget=lambda self:self.__lfprev)
135
136
137
139 """
140 Logger which prints based on level -- ie everything which is smaller
141 than specified level
142 """
143
144 - def __init__(self, level=0, indent=" ", *args, **kwargs):
145 """Define level logger.
146
147 It is defined by
148 `level`, int: to which messages are reported
149 `indent`, string: symbol used to indent
150 """
151 Logger.__init__(self, *args, **kwargs)
152 self.__level = level
153 self.__indent = indent
154 self._setLevel(level)
155 self._setIndent(indent)
156
158 """Set logging level
159 """
160 ilevel = int(level)
161 if ilevel < 0:
162 raise ValueError, \
163 "Negative verbosity levels (got %d) are not supported" \
164 % ilevel
165 self.__level = ilevel
166
167
169 """Either to indent the lines based on message log level"""
170 self.__indent = "%s" % indent
171
172
173 - def __call__(self, level, msg, *args, **kwargs):
174 """
175 Write msg and indent using self.indent it if it was requested
176
177 it appends a newline since most commonly each call is a separate
178 message
179 """
180 if level <= self.level:
181 if self.lfprev and self.indent:
182
183 msg = self.indent*level + msg
184 Logger.__call__(self, msg, *args, **kwargs)
185
186 level = property(fget=lambda self: self.__level, fset=_setLevel)
187 indent = property(fget=lambda self: self.__indent, fset=_setIndent)
188
189
191 """
192 Logger which prints a message for a given ID just once.
193
194 It could be used for one-time warning to don't overfill the output
195 with useless repeatative messages
196 """
197
199 """Define once logger.
200 """
201 Logger.__init__(self, *args, **kwargs)
202 self._known = {}
203
204
205 - def __call__(self, ident, msg, count=1, *args, **kwargs):
206 """
207 Write `msg` if `ident` occured less than `count` times by now.
208 """
209 if not self._known.has_key(ident):
210 self._known[ident] = 0
211
212 if count < 0 or self._known[ident] < count:
213 self._known[ident] += 1
214 Logger.__call__(self, msg, *args, **kwargs)
215
216
218 """
219 Logger which prints based on defined sets identified by Id.
220 """
221
222 - def __init__(self, register=None, active=None, printsetid=True,
223 *args, **kwargs):
234
235
237 """Set active logging set
238 """
239
240
241 from mvpa.base import verbose
242 self.__active = []
243 registered_keys = self.__registered.keys()
244 for item in list(Set(active)):
245 if item == '':
246 continue
247 if isinstance(item, basestring):
248 if item in ['?', 'list', 'help']:
249 self.print_registered(detailed=(item != '?'))
250 raise SystemExit(0)
251 if item.upper() == "ALL":
252 verbose(2, "Enabling all registered debug handlers")
253 self.__active = registered_keys
254 break
255
256 regexp_str = "^%s$" % item
257 try:
258 regexp = re.compile(regexp_str)
259 except:
260 raise ValueError, \
261 "Unable to create regular expression out of %s" % item
262 matching_keys = filter(regexp.match, registered_keys)
263 toactivate = matching_keys
264 if len(toactivate) == 0:
265 ids = self.registered.keys()
266 ids.sort()
267 raise ValueError, \
268 "Unknown debug ID '%s' was asked to become active," \
269 " or regular expression '%s' did not get any match" \
270 " among known ids: %s" \
271 % (item, regexp_str, ids)
272 else:
273 toactivate = [item]
274
275
276 for item_ in toactivate:
277 if not (item_ in registered_keys):
278 raise ValueError, \
279 "Unknown debug ID %s was asked to become active" \
280 % item_
281 self.__active += toactivate
282
283 self.__active = list(Set(self.__active))
284 self.__maxstrlength = max([len(str(x)) for x in self.__active] + [0])
285 if len(self.__active):
286 verbose(2, "Enabling debug handlers: %s" % `self.__active`)
287
288
290 """Either to print set Id at each line"""
291 self.__printsetid = printsetid
292
293
294 - def __call__(self, setid, msg, *args, **kwargs):
295 """
296 Write msg
297
298 It appends a newline since most commonly each call is a separate
299 message
300 """
301
302 if setid in self.__active:
303 if len(msg)>0 and self.__printsetid:
304 msg = "[%%-%ds] " % self.__maxstrlength % (setid) + msg
305 Logger.__call__(self, msg, *args, **kwargs)
306
307
308 - def register(self, setid, description):
309 """ "Register" a new setid with a given description for easy finding
310 """
311
312 if self.__registered.has_key(setid):
313 raise ValueError, \
314 "Setid %s is already known with description '%s'" % \
315 ( `setid`, self.__registered[setid] )
316 self.__registered[setid] = description
317
318
320 """Given a string listing registered(?) setids, make then active
321 """
322
323
324 self.active = value.split(",")
325
326
328 print "Registered debug entries: ",
329 kd = self.registered
330 rks = sorted(kd.keys())
331 maxl = max([len(k) for k in rks])
332 if not detailed:
333
334 print ', '.join(rks)
335 else:
336 print
337 for k in rks:
338 print '%%%ds %%s' % maxl % (k, kd[k])
339
340
341 printsetid = property(fget=lambda self: self.__printsetid, \
342 fset=_setPrintsetid)
343 active = property(fget=lambda self: self.__active, fset=_setActive)
344 registered = property(fget=lambda self: self.__registered)
345
346
347 if __debug__:
348
349 import os, re
350 import traceback
351 import time
352 from os import getpid
353 from os.path import basename, dirname
354
356 """Return stat information on current process.
357
358 Usually it is needed to know where the memory is gone, that is
359 why VmSize is the default for the field to spit out
360 TODO: Spit out multiple fields. Use some better way than parsing proc
361 """
362
363 fd = open('/proc/%d/status' % getpid())
364 lines = fd.readlines()
365 fd.close()
366 match = filter(lambda x:re.match('^%s:'%field, x), lines)[0].strip()
367 match = re.sub('[ \t]+', ' ', match)
368 return match
369
371 """Custom function to include directory name if filename is too common
372
373 Also strip .py at the end
374 """
375 base = basename(s).rstrip('py').rstrip('.')
376 if base in Set(['base', '__init__']):
377 base = basename(dirname(s)) + '.' + base
378 return base
379
382 """Initialize TrackBack metric
383
384 :Parameters:
385 collide : bool
386 if True then prefix common with previous invocation gets
387 replaced with ...
388 """
389 self.__prev = ""
390 self.__collide = collide
391
393 ftb = traceback.extract_stack(limit=100)[:-2]
394 entries = [[mbasename(x[0]), str(x[1])] for x in ftb]
395 entries = filter(lambda x:x[0] != 'unittest', entries)
396
397
398 entries_out = [entries[0]]
399 for entry in entries[1:]:
400 if entry[0] == entries_out[-1][0]:
401 entries_out[-1][1] += ',%s' % entry[1]
402 else:
403 entries_out.append(entry)
404 sftb = '>'.join(['%s:%s' % (mbasename(x[0]),
405 x[1]) for x in entries_out])
406 if self.__collide:
407
408 prev_next = sftb
409 common_prefix = os.path.commonprefix((self.__prev, sftb))
410 common_prefix2 = re.sub('>[^>]*$', '', common_prefix)
411
412 if common_prefix2 != "":
413 sftb = '...' + sftb[len(common_prefix2):]
414 self.__prev = prev_next
415
416 return sftb
417
418
420 """Simple helper class to provide relative time it took from previous
421 invocation"""
422
423 - def __init__(self, format="%3.3f sec"):
424 self.__prev = None
425 self.__format = format
426
428 dt = 0.0
429 ct = time.time()
430 if not self.__prev is None:
431 dt = ct - self.__prev
432 self.__prev = ct
433 return self.__format % dt
434
435
437 """
438 Logger for debugging purposes.
439
440 Expands SetLogger with ability to print some interesting information
441 (named Metric... XXX) about current process at each debug printout
442 """
443
444 _known_metrics = {
445 'vmem' : lambda : parseStatus(field='VmSize'),
446 'pid' : lambda : parseStatus(field='Pid'),
447 'asctime' : time.asctime,
448 'tb' : TraceBack(),
449 'tbc' : TraceBack(collide=True),
450 }
451
452
453 - def __init__(self, metrics=None, offsetbydepth=True, *args, **kwargs):
464
465
467 """Register some metric to report
468
469 func can be either a function call or a string which should
470 correspond to known metrics
471 """
472
473 if isinstance(func, basestring):
474 if func in ['all', 'ALL']:
475 func = self._known_metrics.keys()
476
477 if isinstance(func, basestring):
478 if DebugLogger._known_metrics.has_key(func):
479 func = DebugLogger._known_metrics[func]
480 else:
481 if func in ['?', 'list', 'help']:
482 print 'Known debug metrics: ', \
483 ', '.join(DebugLogger._known_metrics.keys())
484 raise SystemExit(0)
485 else:
486 raise ValueError, \
487 "Unknown name %s for metric in DebugLogger" % \
488 func + " Known metrics are " + \
489 `DebugLogger._known_metrics.keys()`
490 elif isinstance(func, list):
491 self.__metrics = []
492 for item in func:
493 self.registerMetric(item)
494 return
495
496 if not func in self.__metrics:
497 try:
498 from mvpa.base import debug
499 debug("DBG", "Registering metric %s" % func)
500 self.__metrics.append(func)
501 except:
502 pass
503
504
505 - def __call__(self, setid, msg, *args, **kwargs):
506
507 if not self.registered.has_key(setid):
508 raise ValueError, "Not registered debug ID %s" % setid
509
510 if not setid in self.active:
511
512
513 return
514
515 if len(msg) > 0:
516 msg_ = ' / '.join([str(x()) for x in self.__metrics])
517
518 if len(msg_)>0:
519 msg_ = "{%s}" % msg_
520
521
522 if self._offsetbydepth:
523 level = len(traceback.extract_stack())-2
524 else:
525 level = 1
526
527 if len(msg)>250 and 'DBG' in self.active and not setid.endswith('_TB'):
528 tb = traceback.extract_stack(limit=2)
529 msg += " !!!2LONG!!!. From %s" % str(tb[0])
530
531 msg = "DBG%s:%s%s" % (msg_, " "*level, msg)
532
533 SetLogger.__call__(self, setid, msg, *args, **kwargs)
534
535
537 self._offsetbydepth = b
538
539 offsetbydepth = property(fget=lambda x:x._offsetbydepth,
540 fset=_setOffsetByDepth)
541
542 metrics = property(fget=lambda x:x.__metrics,
543 fset=registerMetric)
544