Package mvpa :: Package base :: Module verbosity
[hide private]
[frames] | no frames]

Source Code for Module mvpa.base.verbosity

  1  # emacs: -*- mode: python; py-indent-offset: 4; indent-tabs-mode: nil -*- 
  2  # vi: set ft=python sts=4 ts=4 sw=4 et: 
  3  ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ## 
  4  # 
  5  #   See COPYING file distributed along with the PyMVPA package for the 
  6  #   copyright and license terms. 
  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  # GOALS 
 21  #  any logger should be able 
 22  #   to log into a file or stdout/stderr 
 23  #   provide ability to log with/without a new line at the end 
 24  # 
 25  #  debug logger should be able 
 26  #    to log sets of debug statements 
 27  #    add/remove debug setid items 
 28  #    give verbose description about registered debugset items 
 29   
30 -class Logger(object):
31 """ 32 Base class to provide logging 33 """ 34
35 - def __init__(self, handlers=None):
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 = [] # pylint friendliness 44 self._setHandlers(handlers) 45 self.__lfprev = True 46 self.__crprev = 0 # number of symbols in previous cr-ed
47
48 - def __del__(self):
50
51 - def _setHandlers(self, handlers):
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
75 - def _closeOpenedHandlers(self):
76 """Close opened handlers (such as opened logfiles 77 """ 78 for handler in self.__close_handlers: 79 handler.close()
80
81 - def _getHandlers(self):
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 # wipe out older line to make sure to see no ghosts 105 msg_ = "\r%s" % (" "*self.__crprev) 106 msg_ += "\r" + msg 107 self.__crprev = len(msg) 108 msg = msg_ 109 # since it makes no sense this days for cr and lf, 110 # override lf 111 lf = False 112 else: 113 self.__crprev += len(msg) 114 115 if lf: 116 msg = msg + "\n" 117 self.__crprev = 0 # nothing to clear 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 # it might be not implemented.. 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
138 -class LevelLogger(Logger):
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 # damn pylint ;-) 153 self.__indent = indent 154 self._setLevel(level) 155 self._setIndent(indent)
156
157 - def _setLevel(self, level):
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
168 - def _setIndent(self, indent):
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 # indent if previous line ended with newline 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
190 -class OnceLogger(Logger):
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
198 - def __init__(self, *args, **kwargs):
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
217 -class SetLogger(Logger):
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):
224 if register == None: 225 register = {} 226 if active == None: 227 active = [] 228 Logger.__init__(self, *args, **kwargs) 229 self.__printsetid = printsetid 230 self.__registered = register # all "registered" sets descriptions 231 # which to output... pointless since __registered 232 self._setActive(active) 233 self._setPrintsetid(printsetid)
234 235
236 - def _setActive(self, active):
237 """Set active logging set 238 """ 239 # just unique entries... we could have simply stored Set I guess, 240 # but then smth like debug.active += ["BLAH"] would not work 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 # try to match item as it is regexp 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 # Lets check if asked items are known 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)) # select just unique ones 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
289 - def _setPrintsetid(self, printsetid):
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
319 - def setActiveFromString(self, value):
320 """Given a string listing registered(?) setids, make then active 321 """ 322 # somewhat evil but works since verbose must be initiated 323 # by now 324 self.active = value.split(",")
325 326
327 - def print_registered(self, detailed=True):
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 # short list 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
355 - def parseStatus(field='VmSize'):
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
370 - def mbasename(s):
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
380 - class TraceBack(object):
381 - def __init__(self, collide=False):
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
392 - def __call__(self):
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 # lets make it more consize 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 # lets remove part which is common with previous invocation 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
419 - class RelativeTime(object):
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
427 - def __call__(self):
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
436 - class DebugLogger(SetLogger):
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):
454 if metrics == None: 455 metrics = [] 456 SetLogger.__init__(self, *args, **kwargs) 457 self.__metrics = [] 458 self._offsetbydepth = offsetbydepth 459 self._reltimer = RelativeTime() 460 self._known_metrics = DebugLogger._known_metrics 461 self._known_metrics['reltime'] = self._reltimer 462 for metric in metrics: 463 self._registerMetric(metric)
464 465
466 - def registerMetric(self, func):
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 = [] # reset 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 # don't even compute the metrics, since they might 512 # be statefull as RelativeTime 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 # determine blank offset using backstacktrace 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
536 - def _setOffsetByDepth(self, b):
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