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

Source Code for Module mvpa.base.verbosity

  1  #emacs: -*- mode: python-mode; py-indent-offset: 4; indent-tabs-mode: nil -*- 
  2  #ex: set 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.upper() == "ALL": 249 verbose(2, "Enabling all registered debug handlers") 250 self.__active = registered_keys 251 break 252 # try to match item as it is regexp 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 # Lets check if asked items are known 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)) # select just unique ones 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
286 - def _setPrintsetid(self, printsetid):
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
316 - def setActiveFromString(self, value):
317 """Given a string listing registered(?) setids, make then active 318 """ 319 # somewhat evil but works since verbose must be initiated 320 # by now 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
338 - def parseStatus(field='VmSize'):
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
353 - def mbasename(s):
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
363 - class TraceBack(object):
364 - def __init__(self, collide=False):
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
375 - def __call__(self):
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 # lets make it more consize 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 # lets remove part which is common with previous invocation 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
402 - class RelativeTime(object):
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
410 - def __call__(self):
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
419 - class DebugLogger(SetLogger):
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):
437 if metrics == None: 438 metrics = [] 439 SetLogger.__init__(self, *args, **kwargs) 440 self.__metrics = [] 441 self._offsetbydepth = offsetbydepth 442 self._reltimer = RelativeTime() 443 self._known_metrics = DebugLogger._known_metrics 444 self._known_metrics['reltime'] = self._reltimer 445 for metric in metrics: 446 self._registerMetric(metric)
447 448
449 - def registerMetric(self, func):
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 = [] # reset 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 # don't even compute the metrics, since they might 490 # be statefull as RelativeTime 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 # determine blank offset using backstacktrace 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
514 - def _setOffsetByDepth(self, b):
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