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 # GOALS 20 # any logger should be able 21 # to log into a file or stdout/stderr 22 # provide ability to log with/without a new line at the end 23 # 24 # debug logger should be able 25 # to log sets of debug statements 26 # add/remove debug setid items 27 # give verbose description about registered debugset items 28

29 -class Logger(object):

30 """ 31 Base class to provide logging 32 """ 33

34 - def __init__(self, handlers=None):

35 """Initialize the logger with a set of handlers to use for output 36 37 Each hanlder must have write() method implemented 38 """ 39 if handlers == None: 40 handlers = [stdout] 41 self.__close_handlers = [] 42 self.__handlers = [] # pylint friendliness 43 self._setHandlers(handlers) 44 self.__lfprev = True 45 self.__crprev = 0 # number of symbols in previous cr-ed

46

47 - def __del__(self):

48 self._closeOpenedHandlers()

49

50 - def _setHandlers(self, handlers):

51 """Set list of handlers for the log. 52 53 A handler can be opened files, stdout, stderr, or a string, which 54 will be considered a filename to be opened for writing 55 """ 56 handlers_ = [] 57 self._closeOpenedHandlers() 58 for handler in handlers: 59 if isinstance(handler, basestring): 60 try: 61 handler = {'stdout' : stdout, 62 'stderr' : stderr}[handler.lower()] 63 except: 64 try: 65 handler = open(handler, 'w') 66 self.__close_handlers.append(handler) 67 except: 68 raise RuntimeError, \ 69 "Cannot open file %s for writing by the logger" \ 70 % handler 71 handlers_.append(handler) 72 self.__handlers = handlers_

73

74 - def _closeOpenedHandlers(self):

75 """Close opened handlers (such as opened logfiles 76 """ 77 for handler in self.__close_handlers: 78 handler.close()

79

80 - def _getHandlers(self):

81 """Return active handlers 82 """ 83 return self.__handlers

84 85

86 - def __call__(self, msg, lf=True, cr=False, *args, **kwargs):

87 """ 88 Write msg to each of the handlers. 89 90 It can append a newline (lf = Line Feed) or return 91 to the beginning before output and to take care about 92 cleaning previous message if present 93 94 it appends a newline (lf = Line Feed) since most commonly each 95 call is a separate message 96 """ 97 if kwargs.has_key('msgargs'): 98 msg = msg % kwargs['msgargs'] 99 100 if cr: 101 msg_ = "" 102 if self.__crprev > 0: 103 # wipe out older line to make sure to see no ghosts 104 msg_ = "\r%s" % (" "*self.__crprev) 105 msg_ += "\r" + msg 106 self.__crprev = len(msg) 107 msg = msg_ 108 # since it makes no sense this days for cr and lf, 109 # override lf 110 lf = False 111 else: 112 self.__crprev += len(msg) 113 114 if lf: 115 msg = msg + "\n" 116 self.__crprev = 0 # nothing to clear 117 118 for handler in self.__handlers: 119 try: 120 handler.write(msg) 121 except: 122 print "Failed writing on handler %s" % handler 123 raise 124 try: 125 handler.flush() 126 except: 127 # it might be not implemented.. 128 pass 129 130 self.__lfprev = lf

131 132 handlers = property(fget=_getHandlers, fset=_setHandlers) 133 lfprev = property(fget=lambda self:self.__lfprev)

134 135 136

137 -class LevelLogger(Logger):

138 """ 139 Logger which prints based on level -- ie everything which is smaller 140 than specified level 141 """ 142

143 - def __init__(self, level=0, indent=" ", *args, **kwargs):

144 """Define level logger. 145 146 It is defined by 147 `level`, int: to which messages are reported 148 `indent`, string: symbol used to indent 149 """ 150 Logger.__init__(self, *args, **kwargs) 151 self.__level = level # damn pylint ;-) 152 self.__indent = indent 153 self._setLevel(level) 154 self._setIndent(indent)

155

156 - def _setLevel(self, level):

157 """Set logging level 158 """ 159 ilevel = int(level) 160 if ilevel < 0: 161 raise ValueError, \ 162 "Negative verbosity levels (got %d) are not supported" \ 163 % ilevel 164 self.__level = ilevel

165 166

167 - def _setIndent(self, indent):

168 """Either to indent the lines based on message log level""" 169 self.__indent = "%s" % indent

170 171

172 - def __call__(self, level, msg, *args, **kwargs):

173 """ 174 Write msg and indent using self.indent it if it was requested 175 176 it appends a newline since most commonly each call is a separate 177 message 178 """ 179 if level <= self.level: 180 if self.lfprev and self.indent: 181 # indent if previous line ended with newline 182 msg = self.indent*level + msg 183 Logger.__call__(self, msg, *args, **kwargs)

184 185 level = property(fget=lambda self: self.__level, fset=_setLevel) 186 indent = property(fget=lambda self: self.__indent, fset=_setIndent)

187 188

189 -class OnceLogger(Logger):

190 """ 191 Logger which prints a message for a given ID just once. 192 193 It could be used for one-time warning to don't overfill the output 194 with useless repeatative messages 195 """ 196

197 - def __init__(self, *args, **kwargs):

198 """Define once logger. 199 """ 200 Logger.__init__(self, *args, **kwargs) 201 self._known = {}

202 203

204 - def __call__(self, ident, msg, count=1, *args, **kwargs):

205 """ 206 Write `msg` if `ident` occured less than `count` times by now. 207 """ 208 if not self._known.has_key(ident): 209 self._known[ident] = 0 210 211 if count < 0 or self._known[ident] < count: 212 self._known[ident] += 1 213 Logger.__call__(self, msg, *args, **kwargs)

214 215

216 -class SetLogger(Logger):

217 """ 218 Logger which prints based on defined sets identified by Id. 219 """ 220

221 - def __init__(self, register=None, active=None, printsetid=True, 222 *args, **kwargs):

223 if register == None: 224 register = {} 225 if active == None: 226 active = [] 227 Logger.__init__(self, *args, **kwargs) 228 self.__printsetid = printsetid 229 self.__registered = register # all "registered" sets descriptions 230 # which to output... pointless since __registered 231 self._setActive(active) 232 self._setPrintsetid(printsetid)

233 234

235 - def _setActive(self, active):

236 """Set active logging set 237 """ 238 # just unique entries... we could have simply stored Set I guess, 239 # but then smth like debug.active += ["BLAH"] would not work 240 from mvpa.base import verbose 241 self.__active = [] 242 registered_keys = self.__registered.keys() 243 for item in list(set(active)): 244 if item == '': 245 continue 246 if isinstance(item, basestring): 247 if item in ['?', 'list', 'help']: 248 self.print_registered(detailed=(item != '?')) 249 raise SystemExit(0) 250 if item.upper() == "ALL": 251 verbose(2, "Enabling all registered debug handlers") 252 self.__active = registered_keys 253 break 254 # try to match item as it is regexp 255 regexp_str = "^%s$" % item 256 try: 257 regexp = re.compile(regexp_str) 258 except: 259 raise ValueError, \ 260 "Unable to create regular expression out of %s" % item 261 matching_keys = filter(regexp.match, registered_keys) 262 toactivate = matching_keys 263 if len(toactivate) == 0: 264 ids = self.registered.keys() 265 ids.sort() 266 raise ValueError, \ 267 "Unknown debug ID '%s' was asked to become active," \ 268 " or regular expression '%s' did not get any match" \ 269 " among known ids: %s" \ 270 % (item, regexp_str, ids) 271 else: 272 toactivate = [item] 273 274 # Lets check if asked items are known 275 for item_ in toactivate: 276 if not (item_ in registered_keys): 277 raise ValueError, \ 278 "Unknown debug ID %s was asked to become active" \ 279 % item_ 280 self.__active += toactivate 281 282 self.__active = list(set(self.__active)) # select just unique ones 283 self.__maxstrlength = max([len(str(x)) for x in self.__active] + [0]) 284 if len(self.__active): 285 verbose(2, "Enabling debug handlers: %s" % `self.__active`)

286 287

288 - def _setPrintsetid(self, printsetid):

289 """Either to print set Id at each line""" 290 self.__printsetid = printsetid

291 292

293 - def __call__(self, setid, msg, *args, **kwargs):

294 """ 295 Write msg 296 297 It appends a newline since most commonly each call is a separate 298 message 299 """ 300 301 if setid in self.__active: 302 if len(msg)>0 and self.__printsetid: 303 msg = "[%%-%ds] " % self.__maxstrlength % (setid) + msg 304 Logger.__call__(self, msg, *args, **kwargs)

305 306

307 - def register(self, setid, description):

308 """ "Register" a new setid with a given description for easy finding 309 """ 310 311 if self.__registered.has_key(setid): 312 raise ValueError, \ 313 "Setid %s is already known with description '%s'" % \ 314 ( `setid`, self.__registered[setid] ) 315 self.__registered[setid] = description

316 317

318 - def setActiveFromString(self, value):

319 """Given a string listing registered(?) setids, make then active 320 """ 321 # somewhat evil but works since verbose must be initiated 322 # by now 323 self.active = value.split(",")

324 325

326 - def print_registered(self, detailed=True):

327 print "Registered debug entries: ", 328 kd = self.registered 329 rks = sorted(kd.keys()) 330 maxl = max([len(k) for k in rks]) 331 if not detailed: 332 # short list 333 print ', '.join(rks) 334 else: 335 print 336 for k in rks: 337 print '%%%ds %%s' % maxl % (k, kd[k])

338 339 340 printsetid = property(fget=lambda self: self.__printsetid, \ 341 fset=_setPrintsetid) 342 active = property(fget=lambda self: self.__active, fset=_setActive) 343 registered = property(fget=lambda self: self.__registered)

344 345 346 if __debug__: 347 348 import os, re 349 import traceback 350 import time 351 from os import getpid 352 from os.path import basename, dirname 353

354 - def parseStatus(field='VmSize'):

355 """Return stat information on current process. 356 357 Usually it is needed to know where the memory is gone, that is 358 why VmSize is the default for the field to spit out 359 TODO: Spit out multiple fields. Use some better way than parsing proc 360 """ 361 362 fd = open('/proc/%d/status' % getpid()) 363 lines = fd.readlines() 364 fd.close() 365 match = filter(lambda x:re.match('^%s:'%field, x), lines)[0].strip() 366 match = re.sub('[ \t]+', ' ', match) 367 return match

368

369 - def mbasename(s):

370 """Custom function to include directory name if filename is too common 371 372 Also strip .py at the end 373 """ 374 base = basename(s).rstrip('py').rstrip('.') 375 if base in ['base', '__init__']: 376 base = basename(dirname(s)) + '.' + base 377 return base

378

379 - class TraceBack(object):

380 - def __init__(self, collide=False):

381 """Initialize TrackBack metric 382 383 :Parameters: 384 collide : bool 385 if True then prefix common with previous invocation gets 386 replaced with ... 387 """ 388 self.__prev = "" 389 self.__collide = collide

390

391 - def __call__(self):

392 ftb = traceback.extract_stack(limit=100)[:-2] 393 entries = [[mbasename(x[0]), str(x[1])] for x in ftb] 394 entries = filter(lambda x:x[0] != 'unittest', entries) 395 396 # lets make it more consize 397 entries_out = [entries[0]] 398 for entry in entries[1:]: 399 if entry[0] == entries_out[-1][0]: 400 entries_out[-1][1] += ',%s' % entry[1] 401 else: 402 entries_out.append(entry) 403 sftb = '>'.join(['%s:%s' % (mbasename(x[0]), 404 x[1]) for x in entries_out]) 405 if self.__collide: 406 # lets remove part which is common with previous invocation 407 prev_next = sftb 408 common_prefix = os.path.commonprefix((self.__prev, sftb)) 409 common_prefix2 = re.sub('>[^>]*$', '', common_prefix) 410 411 if common_prefix2 != "": 412 sftb = '...' + sftb[len(common_prefix2):] 413 self.__prev = prev_next 414 415 return sftb

416 417

418 - class RelativeTime(object):

419 """Simple helper class to provide relative time it took from previous 420 invocation""" 421

422 - def __init__(self, format="%3.3f sec"):

423 self.__prev = None 424 self.__format = format

425

426 - def __call__(self):

427 dt = 0.0 428 ct = time.time() 429 if not self.__prev is None: 430 dt = ct - self.__prev 431 self.__prev = ct 432 return self.__format % dt

433 434

435 - class DebugLogger(SetLogger):

436 """ 437 Logger for debugging purposes. 438 439 Expands SetLogger with ability to print some interesting information 440 (named Metric... XXX) about current process at each debug printout 441 """ 442 443 _known_metrics = { 444 'vmem' : lambda : parseStatus(field='VmSize'), 445 'pid' : lambda : parseStatus(field='Pid'), 446 'asctime' : time.asctime, 447 'tb' : TraceBack(), 448 'tbc' : TraceBack(collide=True), 449 } 450 451

452 - def __init__(self, metrics=None, offsetbydepth=True, *args, **kwargs):

453 if metrics == None: 454 metrics = [] 455 SetLogger.__init__(self, *args, **kwargs) 456 self.__metrics = [] 457 self._offsetbydepth = offsetbydepth 458 self._reltimer = RelativeTime() 459 self._known_metrics = DebugLogger._known_metrics 460 self._known_metrics['reltime'] = self._reltimer 461 for metric in metrics: 462 self._registerMetric(metric)

463 464

465 - def registerMetric(self, func):

466 """Register some metric to report 467 468 func can be either a function call or a string which should 469 correspond to known metrics 470 """ 471 472 if isinstance(func, basestring): 473 if func in ['all', 'ALL']: 474 func = self._known_metrics.keys() 475 476 if isinstance(func, basestring): 477 if DebugLogger._known_metrics.has_key(func): 478 func = DebugLogger._known_metrics[func] 479 else: 480 if func in ['?', 'list', 'help']: 481 print 'Known debug metrics: ', \ 482 ', '.join(DebugLogger._known_metrics.keys()) 483 raise SystemExit(0) 484 else: 485 raise ValueError, \ 486 "Unknown name %s for metric in DebugLogger" % \ 487 func + " Known metrics are " + \ 488 `DebugLogger._known_metrics.keys()` 489 elif isinstance(func, list): 490 self.__metrics = [] # reset 491 for item in func: 492 self.registerMetric(item) 493 return 494 495 if not func in self.__metrics: 496 try: 497 from mvpa.base import debug 498 debug("DBG", "Registering metric %s" % func) 499 self.__metrics.append(func) 500 except: 501 pass

502 503

504 - def __call__(self, setid, msg, *args, **kwargs):

505 506 if not self.registered.has_key(setid): 507 raise ValueError, "Not registered debug ID %s" % setid 508 509 if not setid in self.active: 510 # don't even compute the metrics, since they might 511 # be statefull as RelativeTime 512 return 513 514 if len(msg) > 0: 515 msg_ = ' / '.join([str(x()) for x in self.__metrics]) 516 517 if len(msg_)>0: 518 msg_ = "{%s}" % msg_ 519 520 # determine blank offset using backstacktrace 521 if self._offsetbydepth: 522 level = len(traceback.extract_stack())-2 523 else: 524 level = 1 525 526 if len(msg)>250 and 'DBG' in self.active and not setid.endswith('_TB'): 527 tb = traceback.extract_stack(limit=2) 528 msg += " !!!2LONG!!!. From %s" % str(tb[0]) 529 530 msg = "DBG%s:%s%s" % (msg_, " "*level, msg) 531 532 SetLogger.__call__(self, setid, msg, *args, **kwargs)

533 534

535 - def _setOffsetByDepth(self, b):

536 self._offsetbydepth = b

537 538 offsetbydepth = property(fget=lambda x:x._offsetbydepth, 539 fset=_setOffsetByDepth) 540 541 metrics = property(fget=lambda x:x.__metrics, 542 fset=registerMetric)

543

Source Code for Module mvpa.base.verbosity