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  # 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