src/loggingSimple.py

   1 #!/usr/bin/env python
   2 # -*- coding: utf-8 -*-
   3
   4 """
   5 salomeTools logger. using logging package
   6
   7 | http://sametmax.com/ecrire-des-logs-en-python/
   8 |
   9 | Define two LoggerSat instances in salomeTools, no more need.
  10 |   - _loggerDefault as production/development logger
  11 |   - _loggerUnittest as unittest logger
  12 |
  13
  14 """
  15
  16
  17 import os
  18 import sys
  19 import time
  20 import random
  21 import logging as LOGI
  22
  23 from logging.handlers import BufferingHandler
  24 import pprint as PP
  25
  26 import src.debug as DBG  # Easy print stderr (for DEBUG only)
  27
  28 _verbose = False
  29 _name = "loggingSimple"
  30 _loggerDefaultName = 'SimpleDefaultLogger'
  31 _loggerUnittestName = 'SimpleUnittestLogger'
  32
  33 _STEP = LOGI.INFO - 1  # step level is just below INFO
  34 _TRACE = LOGI.INFO - 2  # trace level is just below STEP
  35
  36 LOGI.STEP = _STEP  # only for coherency,
  37 LOGI.TRACE = _TRACE  # only for coherency,
  38
  39 _knownLevels = "CRITICAL ERROR WARNING INFO STEP TRACE DEBUG".upper().split()
  40 _knownLevelsStr = "[%s]" % "|".join(_knownLevels)
  41
  42
  43 #################################################################
  44 # utilities methods
  45 #################################################################
  46
  47 def filterLevel(aLevel):
  48   """
  49   filter levels logging values from firsts characters levels.
  50   No case sensitive
  51
  52   | example:
  53   | 'i' -> 'INFO'
  54   | 'cRiT' -> 'CRITICAL'
  55   """
  56   aLev = aLevel.upper()
  57   knownLevels = _knownLevels
  58   maxLen = max([len(i) for i in knownLevels])
  59   for i in range(maxLen):
  60     for lev in knownLevels:
  61       if aLev == lev[:i]:
  62         # DBG.write("filterLevel", "%s -> %s" % (aLevel, lev))
  63         return lev
  64   msg = "Unknown level '%s', accepted are:\n%s" % (aLev, ", ".join(knownLevels))
  65   return msg
  66   # raise Exception(msg)
  67
  68
  69 def indent(msg, nb, car=" "):
  70   """indent nb car (spaces) multi lines message except first one"""
  71   s = msg.split("\n")
  72   res = ("\n" + car * nb).join(s)
  73   return res
  74
  75
  76 def indentUnittest(msg, prefix=" | "):
  77   """
  78   indent multi lines message except first one with prefix.
  79   prefix default is designed for less spaces for size logs files
  80   and keep logs human eye readable
  81   """
  82   s = msg.split("\n")
  83   res = ("\n" + prefix).join(s)
  84   return res
  85
  86
  87 def log(msg, force=False):
  88   """elementary log when no logging.Logger yet"""
  89   prefix = "---- %s.log: " % _name
  90   nb = len(prefix)
  91   if _verbose or force:
  92     print(prefix + indent(msg, nb))
  93
  94
  95 # just for debug info where is import logging
  96 log("import logging on %s" % LOGI.__file__)
  97
  98
  99 def getStrDirLogger(logger):
 100   """
 101   Returns multi line string for logger description, with dir(logger).
 102   Used for debug
 103   """
 104   lgr = logger  # shortcut
 105   msg = "%s(name=%s, dateLogger=%s):\n%s\n"
 106   cName = lgr.__class__.__name__
 107   res = msg % (cName, lgr.name, lgr.dateLogger, PP.pformat(dir(lgr)))
 108   return res
 109
 110
 111 def getStrHandler(handler):
 112   """
 113   Returns one line string for handler description
 114   (as inexisting __repr__)
 115   to avoid create inherited classe(s) handler
 116   """
 117   h = handler  # shortcut
 118   msg = "%s(name=%s)"
 119   cName = h.__class__.__name__
 120   res = msg % (cName, h.get_name())
 121   return res
 122
 123
 124 def getStrShort(msg):
 125   """Returns short string for msg (as first caracters without line feed"""
 126   # log("getStrShort " + str(msg), True)
 127   res = msg.replace("\n", "//")[0:30]
 128   return res
 129
 130
 131 def getStrLogRecord(logRecord):
 132   """
 133   Returns one line string for simple logging LogRecord description
 134   """
 135   msg = "LogRecord(level='%s', msg='%s...')"
 136   shortMsg = getStrShort(logRecord.msg)
 137   levelName = logRecord.levelname
 138   res = msg % (levelName, shortMsg)
 139   return res
 140
 141
 142 def getListOfStrLogRecord(listOfLogRecord):
 143   """
 144   Returns one line string for logging LogRecord description
 145   """
 146   res = [getStrLogRecord(l) for l in listOfLogRecord]
 147   return res
 148
 149
 150 #################################################################
 151 # salometools logger classes
 152 #################################################################
 153
 154 try:
 155   unicode
 156   _unicode = True
 157 except NameError:
 158   _unicode = False
 159
 160
 161 def getMessage(self):
 162   """
 163   modified from logging.__init__.LogRecord.getMessage,
 164   better message on format error
 165   Return the message for this LogRecord.
 166
 167   Return the message for this LogRecord after merging any user-supplied
 168   arguments with the message.
 169   """
 170   if not _unicode:  # if no unicode support...
 171     msg = str(self.msg)
 172   else:
 173     msg = self.msg
 174     if not isinstance(msg, basestring):
 175       try:
 176         msg = str(self.msg)
 177       except UnicodeError:
 178         msg = self.msg  # Defer encoding till later
 179   if self.args:
 180     try:  # better message on format error
 181       msg = msg % self.args
 182     except Exception as e:
 183       msg = "ERROR: %s with args %s" % (msg, PP.pformat(self.args))
 184       log(msg, True)
 185   return msg
 186
 187
 188 LOGI.LogRecord.getMessage = getMessage  # better message if error
 189
 190
 191 #################################################################
 192 class LoggerSimple(LOGI.Logger):
 193   """
 194   Inherited class logging.Logger for logger salomeTools
 195
 196   | add a level STEP as log.step(msg)
 197   | add a level TRACE as log.trace(msg)
 198   | below log.info(msg)
 199   | above log.debug(msg)
 200   | to assume message step inside files xml 'command's internal traces'
 201   | to assume store long log asci in files txt outside files xml
 202   |
 203   | see: /usr/lib64/python2.7/logging/__init__.py etc.
 204   """
 205
 206   def __init__(self, name, level=LOGI.INFO):
 207     """
 208     Initialize the logger with a name and an optional level.
 209     """
 210     super(LoggerSimple, self).__init__(name, level)
 211     LOGI.addLevelName(_STEP, "STEP")
 212     LOGI.addLevelName(_TRACE, "TRACE")
 213     self.dateLogger = "NoDateLogger"
 214     self.dateHour = None  # datehour of main command
 215     self.isClosed = False
 216     self.STEP = _STEP
 217     self.TRACE = _TRACE
 218
 219   def close(self):
 220     """
 221     final stuff for logger, done at end salomeTools
 222     flushed and closed xml files have to be not overriden/appended
 223     """
 224     if self.isClosed:
 225       raise Exception("logger closed yet: %s" % self)
 226     log("close stuff logger %s" % self)  # getStrDirLogger(self)
 227     for handl in list(self.handlers):  # get original list
 228       log("close stuff handler %s" % getStrHandler(handl))
 229       handl.close()  # Tidy up any resources used by the handler.
 230       self.removeHandler(handl)
 231     # todo etc
 232     self.isClosed = True  # done at end of execution
 233     return
 234
 235   def __repr__(self):
 236     """one line string representation"""
 237     msg = "%s(name=%s, dateLogger=%s, handlers=%s)"
 238     cName = self.__class__.__name__
 239     h = [getStrHandler(h) for h in self.handlers]
 240     h = "[" + ", ".join(h) + "]"
 241     res = msg % (cName, self.name, self.dateLogger, h)
 242     return res
 243
 244   def trace(self, msg, *args, **kwargs):
 245     """
 246     Log 'msg % args' with severity '_TRACE'.
 247     """
 248     log("trace stuff logger '%s' msg '%s...'" % (self.name, getStrShort(msg)))
 249     if self.isEnabledFor(_TRACE):
 250       self._log(_TRACE, msg, args, **kwargs)
 251
 252   def step(self, msg, *args, **kwargs):
 253     """
 254     Log 'msg % args' with severity '_STEP'.
 255     """
 256     log("step stuff logger '%s' msg '%s...'" % (self.name, getStrShort(msg)))
 257     if self.isEnabledFor(_STEP):
 258       self._log(_STEP, msg, args, **kwargs)
 259
 260   def setLevelMainHandler(self, level):
 261     handl =  self.handlers[0]  # get main handler
 262     log("setLevelMainHandler %s" % level)
 263     handl.setLevel(level)
 264
 265
 266 #################################################################
 267 class UnittestFormatter(LOGI.Formatter):
 268   """
 269   this formatter prefixes level name and indents all messages
 270   """
 271   def format(self, record):
 272     # print "", record.levelname #type(record), dir(record)
 273     # nb = len("2018-03-17 12:15:41 :: INFO     :: ")
 274     res = super(UnittestFormatter, self).format(record)
 275     res = indentUnittest(res)
 276     return res
 277
 278 #################################################################
 279 class DefaultFormatter(LOGI.Formatter):
 280   """
 281   this formatter prefixes level name and indents all messages but INFO stay "as it"
 282   """
 283   def format(self, record):
 284     # print "", record.levelname #type(record), dir(record)
 285     # nb = len("2018-03-17 12:15:41 :: INFO     :: ")
 286     if record.levelname == "INFO":
 287       res = record.getMessage()
 288     else:
 289       res = super(DefaultFormatter, self).format(record)
 290       res = indentUnittest(res)
 291     return res
 292
 293
 294 #################################################################
 295 class UnittestStream(object):
 296   """
 297   write my stream class
 298   only write and flush are used for the streaming
 299
 300   | https://docs.python.org/2/library/logging.handlers.html
 301   | https://stackoverflow.com/questions/31999627/storing-logger-messages-in-a-string
 302   """
 303
 304   def __init__(self):
 305     self._logs = ''
 306
 307   def getLogs(self):
 308     return self._logs
 309
 310   def getLogsAndClear(self):
 311     res = self._logs
 312     self._logs = ''
 313     return res
 314
 315   def write(self, astr):
 316     """final method called when message is logged"""
 317     # log("UnittestStream.write('%s')" % astr, True) # for debug ...
 318     self._logs += astr
 319
 320   def flush(self):
 321     pass
 322
 323   def __str__(self):
 324     return self._logs
 325
 326
 327 #################################################################
 328 class StreamHandlerSimple(LOGI.StreamHandler):
 329   """
 330   A handler class which writes logging records, appropriately formatted,
 331   to a stream. Note that this class does not close the stream, as
 332   sys.stdout or sys.stderr may be used.
 333
 334   from logging.StreamHandler class,
 335   modified for 'no return' mode line if '...' at end of record message
 336   """
 337
 338   def emit(self, record):
 339     """
 340     Emit a record.
 341
 342     If a formatter is specified, it is used to format the record.
 343     The record is then written to the stream with a trailing newline.  If
 344     exception information is present, it is formatted using
 345     traceback.print_exception and appended to the stream.  If the stream
 346     has an 'encoding' attribute, it is used to determine how to do the
 347     output to the stream.
 348     """
 349     # log("StreamHandlerSimple.emit('%s')" % record, True) # for debug ...
 350     try:
 351       msg = self.format(record)
 352       stream = self.stream
 353       fs = '%s\n'
 354       ufs = u'%s\n'
 355       if not _unicode:  # if no unicode support...
 356         stream.write(fs % msg)
 357       else:
 358         try:
 359           if (isinstance(msg, unicode) and
 360             getattr(stream, 'encoding', None)):
 361             # ufs = u'%s\n'
 362             try:
 363               stream.write(ufs % msg)
 364             except UnicodeEncodeError:
 365               # Printing to terminals sometimes fails. For example,
 366               # with an encoding of 'cp1251', the above write will
 367               # work if written to a stream opened or wrapped by
 368               # the codecs module, but fail when writing to a
 369               # terminal even when the codepage is set to cp1251.
 370               # An extra encoding step seems to be needed.
 371               stream.write((ufs % msg).encode(stream.encoding))
 372           else:
 373             stream.write(fs % msg)
 374         except UnicodeError:
 375           stream.write(fs % msg.encode("UTF-8"))
 376       self.flush()
 377     except (KeyboardInterrupt, SystemExit):
 378       raise
 379     except:
 380       self.handleError(record)
 381
 382
 383
 384 #################################################################
 385 # methods to define two LoggerSimple instances in salomeTools,
 386 # no more need
 387 #################################################################
 388 def initLoggerAsDefault(logger, fmt=None, level=None):
 389   """
 390   init logger as prefixed message and indented message if multi line
 391   exept info() outed 'as it' without any format.
 392   level could be modified during execution
 393   """
 394   log("initLoggerAsDefault name=%s\nfmt='%s' level='%s'" % (logger.name, fmt, level))
 395   #handler = StreamHandlerSimple(sys.stdout)  # Logging vers console
 396   handler = LOGI.StreamHandler(sys.stdout)  # Logging vers console
 397   handler.set_name(logger.name + "_console")
 398   if fmt is not None:
 399     # formatter = UnittestFormatter(fmt, "%y-%m-%d %H:%M:%S")
 400     formatter = DefaultFormatter(fmt, "%y-%m-%d %H:%M:%S")
 401     handler.setFormatter(formatter)
 402   handler.idCommandHandlers = 0
 403   logger.addHandler(handler)
 404   # as RootLogger is level WARNING
 405   # my logger is not notset but low, handlers needs setlevel greater
 406   logger.setLevel(LOGI.DEBUG)
 407   # import src/debug as DBG
 408   # tmp = (logger.getEffectiveLevel(), LOGI.NOTSET, logger.level, logger.parent.level)
 409   # DBG.write("logger levels tmp, True)
 410   if level is not None:  # level could be modified during execution
 411     handler.setLevel(level)  # on screen log as user wants
 412   else:
 413     handler.setLevel(LOGI.STEP)  # on screen no log step, which are in xml files
 414   return
 415
 416
 417 def initLoggerAsUnittest(logger, fmt=None, level=None):
 418   """
 419   init logger as silent on stdout/stderr
 420   used for retrieve messages in memory for post execution unittest
 421   https://docs.python.org/2/library/logging.handlers.html
 422   """
 423   log("initLoggerAsUnittest name=%s\nfmt='%s' level='%s'" % (logger.name, fmt, level))
 424   stream = UnittestStream()
 425   handler = LOGI.StreamHandler(stream)  # Logging vers stream
 426   handler.set_name(logger.name + "_unittest")
 427   if fmt is not None:
 428     # formatter = LOGI.Formatter(fmt, "%Y-%m-%d %H:%M:%S")
 429     formatter = UnittestFormatter(fmt, "%Y-%m-%d %H:%M:%S")
 430     handler.setFormatter(formatter)
 431   handler.idCommandHandlers = 0
 432   logger.addHandler(handler)
 433   logger.stream = stream
 434   logger.getLogs = stream.getLogs
 435   logger.getLogsAndClear = stream.getLogsAndClear
 436   if level is not None:
 437     logger.setLevel(level)
 438   else:
 439     logger.setLevel(LOGI.DEBUG)
 440
 441
 442 def getDefaultLogger():
 443   log("getDefaultLogger %s" % _loggerDefaultName)
 444   # case multithread may be problem as not LOGI._acquireLock()
 445   previousClass = LOGI._loggerClass
 446   LOGI.setLoggerClass(LoggerSimple)  # to get LoggerSimple instance with trace etc.
 447   res = LOGI.getLogger(_loggerDefaultName)
 448   LOGI.setLoggerClass(previousClass)
 449   return res
 450
 451
 452 def getUnittestLogger():
 453   log("getUnittestLogger %s" % _loggerUnittestName)
 454   # case multithread may be problem as not LOGI._acquireLock()
 455   previousClass = LOGI._loggerClass
 456   LOGI.setLoggerClass(LoggerSimple)  # to get LoggerSimple instance with trace etc.
 457   res = LOGI.getLogger(_loggerUnittestName)
 458   LOGI.setLoggerClass(previousClass)
 459   return res
 460
 461
 462 #################################################################
 463 # small tests as demonstration, see unittest also
 464 #################################################################
 465 def testLogger_2(logger):
 466   """small test"""
 467   # print getStrDirLogger(logger)
 468   logger.debug('test logger debug')
 469   logger.trace('test logger trace')
 470   logger.info('test logger info')
 471   logger.warning('test logger warning')
 472   logger.error('test logger error')
 473   logger.critical('test logger critical')
 474   logger.info('\ntest logger info:\n- second line\n- third line\n')
 475   logger.warning('test logger warning:\n- second line\n- third line')
 476
 477 def testMain_2():
 478   print("\n**** DEFAULT logger")
 479   logdef = getDefaultLogger()
 480   # use of setColorLevelname <color>...<reset>, so do not use %(levelname)-8s
 481   initLoggerAsDefault(logdef, '%(levelname)-8s :: %(message)s', level=LOGI.DEBUG)
 482   testLogger_2(logdef)
 483
 484   print("\n**** UNITTEST logger")
 485   loguni = getUnittestLogger()
 486   initLoggerAsUnittest(loguni, '%(asctime)s :: %(levelname)-8s :: %(message)s', level=LOGI.DEBUG)
 487   testLogger_2(loguni)  # is silent
 488   # log("loguni.getLogs():\n%s" % loguni.getLogs())
 489   print("loguni.streamUnittest:\n%s" % loguni.getLogs())
 490
 491
 492 #################################################################
 493 # in production, or not (if __main__)
 494 #################################################################
 495 if __name__ == "__main__":
 496   # for example, not in production
 497   # get path to salomeTools sources
 498   curdir = os.path.dirname(os.path.dirname(__file__))
 499   # Make the src & commands package accessible from all code
 500   sys.path.insert(0, curdir)
 501   testMain_2()
 502   # here we have sys.exit()
 503 else:
 504   # in production
 505   # get two LoggerSat instance used in salomeTools, no more needed.
 506   _loggerDefault = getDefaultLogger()
 507   _loggerUnittest = getUnittestLogger()
 508   initLoggerAsDefault(_loggerDefault, '%(levelname)-8s :: %(message)s')
 509   initLoggerAsUnittest(_loggerUnittest, '%(asctime)s :: %(levelname)s :: %(message)s')