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.upper() == "ALL":
249 verbose(2, "Enabling all registered debug handlers")
250 self.__active = registered_keys
251 break
252
253 regexp_str = "^%s$" % item
254 try:
255 regexp = re.compile(regexp_str)
256 except:
257 raise ValueError, \
258 "Unable to create regular expression out of %s" % item
259 matching_keys = filter(regexp.match, registered_keys)
260 toactivate = matching_keys
261 if len(toactivate) == 0:
262 ids = self.registered.keys()
263 ids.sort()
264 raise ValueError, \
265 "Unknown debug ID '%s' was asked to become active," \
266 " or regular expression '%s' did not get any match" \
267 " among known ids: %s" \
268 % (item, regexp_str, ids)
269 else:
270 toactivate = [item]
271
272
273 for item_ in toactivate:
274 if not (item_ in registered_keys):
275 raise ValueError, \
276 "Unknown debug ID %s was asked to become active" \
277 % item_
278 self.__active += toactivate
279
280 self.__active = list(Set(self.__active))
281 self.__maxstrlength = max([len(str(x)) for x in self.__active] + [0])
282 if len(self.__active):
283 verbose(2, "Enabling debug handlers: %s" % `self.__active`)
284
285
287 """Either to print set Id at each line"""
288 self.__printsetid = printsetid
289
290
291 - def __call__(self, setid, msg, *args, **kwargs):
292 """
293 Write msg
294
295 It appends a newline since most commonly each call is a separate
296 message
297 """
298
299 if setid in self.__active:
300 if len(msg)>0 and self.__printsetid:
301 msg = "[%%-%ds] " % self.__maxstrlength % (setid) + msg
302 Logger.__call__(self, msg, *args, **kwargs)
303
304
305 - def register(self, setid, description):
306 """ "Register" a new setid with a given description for easy finding
307 """
308
309 if self.__registered.has_key(setid):
310 raise ValueError, \
311 "Setid %s is already known with description '%s'" % \
312 ( `setid`, self.__registered[setid] )
313 self.__registered[setid] = description
314
315
317 """Given a string listing registered(?) setids, make then active
318 """
319
320
321 self.active = value.split(",")
322
323
324 printsetid = property(fget=lambda self: self.__printsetid, \
325 fset=_setPrintsetid)
326 active = property(fget=lambda self: self.__active, fset=_setActive)
327 registered = property(fget=lambda self: self.__registered)
328
329
330 if __debug__:
331
332 import os, re
333 import traceback
334 import time
335 from os import getpid
336 from os.path import basename, dirname
337
339 """Return stat information on current process.
340
341 Usually it is needed to know where the memory is gone, that is
342 why VmSize is the default for the field to spit out
343 TODO: Spit out multiple fields. Use some better way than parsing proc
344 """
345
346 fd = open('/proc/%d/status' % getpid())
347 lines = fd.readlines()
348 fd.close()
349 match = filter(lambda x:re.match('^%s:'%field, x), lines)[0].strip()
350 match = re.sub('[ \t]+', ' ', match)
351 return match
352
354 """Custom function to include directory name if filename is too common
355
356 Also strip .py at the end
357 """
358 base = basename(s).rstrip('py').rstrip('.')
359 if base in Set(['base', '__init__']):
360 base = basename(dirname(s)) + '.' + base
361 return base
362
365 """Initialize TrackBack metric
366
367 :Parameters:
368 collide : bool
369 if True then prefix common with previous invocation gets
370 replaced with ...
371 """
372 self.__prev = ""
373 self.__collide = collide
374
376 ftb = traceback.extract_stack(limit=100)[:-2]
377 entries = [[mbasename(x[0]), str(x[1])] for x in ftb]
378 entries = filter(lambda x:x[0] != 'unittest', entries)
379
380
381 entries_out = [entries[0]]
382 for entry in entries[1:]:
383 if entry[0] == entries_out[-1][0]:
384 entries_out[-1][1] += ',%s' % entry[1]
385 else:
386 entries_out.append(entry)
387 sftb = '>'.join(['%s:%s' % (mbasename(x[0]),
388 x[1]) for x in entries_out])
389 if self.__collide:
390
391 prev_next = sftb
392 common_prefix = os.path.commonprefix((self.__prev, sftb))
393 common_prefix2 = re.sub('>[^>]*$', '', common_prefix)
394
395 if common_prefix2 != "":
396 sftb = '...' + sftb[len(common_prefix2):]
397 self.__prev = prev_next
398
399 return sftb
400
401
403 """Simple helper class to provide relative time it took from previous
404 invocation"""
405
406 - def __init__(self, format="%3.3f sec"):
407 self.__prev = None
408 self.__format = format
409
411 dt = 0.0
412 ct = time.time()
413 if not self.__prev is None:
414 dt = ct - self.__prev
415 self.__prev = ct
416 return self.__format % dt
417
418
420 """
421 Logger for debugging purposes.
422
423 Expands SetLogger with ability to print some interesting information
424 (named Metric... XXX) about current process at each debug printout
425 """
426
427 _known_metrics = {
428 'vmem' : lambda : parseStatus(field='VmSize'),
429 'pid' : lambda : parseStatus(field='Pid'),
430 'asctime' : time.asctime,
431 'tb' : TraceBack(),
432 'tbc' : TraceBack(collide=True),
433 }
434
435
436 - def __init__(self, metrics=None, offsetbydepth=True, *args, **kwargs):
447
448
450 """Register some metric to report
451
452 func can be either a function call or a string which should
453 correspond to known metrics
454 """
455
456 if isinstance(func, basestring):
457 if func in ['all', 'ALL']:
458 func = self._known_metrics.keys()
459
460 if isinstance(func, basestring):
461 if DebugLogger._known_metrics.has_key(func):
462 func = DebugLogger._known_metrics[func]
463 else:
464 raise ValueError, \
465 "Unknown name %s for metric in DebugLogger" % \
466 func + " Known metrics are " + \
467 `DebugLogger._known_metrics.keys()`
468 elif isinstance(func, list):
469 self.__metrics = []
470 for item in func:
471 self.registerMetric(item)
472 return
473
474 if not func in self.__metrics:
475 try:
476 from mvpa.base import debug
477 debug("DBG", "Registering metric %s" % func)
478 self.__metrics.append(func)
479 except:
480 pass
481
482
483 - def __call__(self, setid, msg, *args, **kwargs):
484
485 if not self.registered.has_key(setid):
486 raise ValueError, "Not registered debug ID %s" % setid
487
488 if not setid in self.active:
489
490
491 return
492
493 if len(msg) > 0:
494 msg_ = ' / '.join([str(x()) for x in self.__metrics])
495
496 if len(msg_)>0:
497 msg_ = "{%s}" % msg_
498
499
500 if self._offsetbydepth:
501 level = len(traceback.extract_stack())-2
502 else:
503 level = 1
504
505 if len(msg)>250 and 'DBG' in self.active and not setid.endswith('_TB'):
506 tb = traceback.extract_stack(limit=2)
507 msg += " !!!2LONG!!!. From %s" % str(tb[0])
508
509 msg = "DBG%s:%s%s" % (msg_, " "*level, msg)
510
511 SetLogger.__call__(self, setid, msg, *args, **kwargs)
512
513
515 self._offsetbydepth = b
516
517 offsetbydepth = property(fget=lambda x:x._offsetbydepth,
518 fset=_setOffsetByDepth)
519
520 metrics = property(fget=lambda x:x.__metrics,
521 fset=registerMetric)
522