sfa/util/sfalogging.py

   1 #!/usr/bin/python\r
   2 \r
   3 #----------------------------------------------------------------------\r
   4 # Copyright (c) 2008 Board of Trustees, Princeton University\r
   5 #\r
   6 # Permission is hereby granted, free of charge, to any person obtaining\r
   7 # a copy of this software and/or hardware specification (the "Work") to\r
   8 # deal in the Work without restriction, including without limitation the\r
   9 # rights to use, copy, modify, merge, publish, distribute, sublicense,\r
  10 # and/or sell copies of the Work, and to permit persons to whom the Work\r
  11 # is furnished to do so, subject to the following conditions:\r
  12 #\r
  13 # The above copyright notice and this permission notice shall be\r
  14 # included in all copies or substantial portions of the Work.\r
  15 #\r
  16 # THE WORK IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS \r
  17 # OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF \r
  18 # MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND \r
  19 # NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT \r
  20 # HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, \r
  21 # WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, \r
  22 # OUT OF OR IN CONNECTION WITH THE WORK OR THE USE OR OTHER DEALINGS \r
  23 # IN THE WORK.\r
  24 #----------------------------------------------------------------------\r
  25 \r
  26 import os, sys\r
  27 import traceback\r
  28 import logging, logging.handlers\r
  29 \r
  30 CRITICAL=logging.CRITICAL\r
  31 ERROR=logging.ERROR\r
  32 WARNING=logging.WARNING\r
  33 INFO=logging.INFO\r
  34 DEBUG=logging.DEBUG\r
  35 \r
  36 # a logger that can handle tracebacks \r
  37 class _SfaLogger:\r
  38     def __init__ (self,logfile=None,loggername=None,level=logging.INFO):\r
  39         # default is to locate loggername from the logfile if avail.\r
  40         if not logfile:\r
  41             #loggername='console'\r
  42             #handler=logging.StreamHandler()\r
  43             #handler.setFormatter(logging.Formatter("%(levelname)s %(message)s"))\r
  44             logfile = "/var/log/sfa.log"\r
  45 \r
  46         if not loggername:\r
  47             loggername=os.path.basename(logfile)\r
  48         try:\r
  49             handler=logging.handlers.RotatingFileHandler(logfile,maxBytes=1000000, backupCount=5) \r
  50         except IOError:\r
  51             # This is usually a permissions error becaue the file is\r
  52             # owned by root, but httpd is trying to access it.\r
  53             tmplogfile=os.getenv("TMPDIR", "/tmp") + os.path.sep + os.path.basename(logfile)\r
  54             # In strange uses, 2 users on same machine might use same code,\r
  55             # meaning they would clobber each others files\r
  56             # We could (a) rename the tmplogfile, or (b)\r
  57             # just log to the console in that case.\r
  58             # Here we default to the console.\r
  59             if os.path.exists(tmplogfile) and not os.access(tmplogfile,os.W_OK):\r
  60                 loggername = loggername + "-console"\r
  61                 handler = logging.StreamHandler()\r
  62             else:\r
  63                 handler=logging.handlers.RotatingFileHandler(tmplogfile,maxBytes=1000000, backupCount=5) \r
  64         handler.setFormatter(logging.Formatter("%(asctime)s - %(levelname)s - %(message)s"))\r
  65         self.logger=logging.getLogger(loggername)\r
  66         self.logger.setLevel(level)\r
  67         # check if logger already has the handler we're about to add\r
  68         handler_exists = False\r
  69         for l_handler in self.logger.handlers:\r
  70             if l_handler.baseFilename == handler.baseFilename and \\r
  71                l_handler.level == handler.level:\r
  72                 handler_exists = True \r
  73 \r
  74         if not handler_exists:\r
  75             self.logger.addHandler(handler)\r
  76 \r
  77         self.loggername=loggername\r
  78 \r
  79     def setLevel(self,level):\r
  80         self.logger.setLevel(level)\r
  81 \r
  82     # shorthand to avoid having to import logging all over the place\r
  83     def setLevelDebug(self):\r
  84         self.logger.setLevel(logging.DEBUG)\r
  85 \r
  86     # define a verbose option with s/t like\r
  87     # parser.add_option("-v", "--verbose", action="count", dest="verbose", default=0)\r
  88     # and pass the coresponding options.verbose to this method to adjust level\r
  89     def setLevelFromOptVerbose(self,verbose):\r
  90         if verbose==0:\r
  91             self.logger.setLevel(logging.WARNING)\r
  92         elif verbose==1:\r
  93             self.logger.setLevel(logging.INFO)\r
  94         elif verbose>=2:\r
  95             self.logger.setLevel(logging.DEBUG)\r
  96     # in case some other code needs a boolean\r
  97     def getBoolVerboseFromOpt(self,verbose):\r
  98         return verbose>=1\r
  99 \r
 100     ####################\r
 101     def info(self, msg):\r
 102         self.logger.info(msg)\r
 103 \r
 104     def debug(self, msg):\r
 105         self.logger.debug(msg)\r
 106         \r
 107     def warn(self, msg):\r
 108         self.logger.warn(msg)\r
 109 \r
 110     # some code is using logger.warn(), some is using logger.warning()\r
 111     def warning(self, msg):\r
 112         self.logger.warning(msg)\r
 113    \r
 114     def error(self, msg):\r
 115         self.logger.error(msg)    \r
 116  \r
 117     def critical(self, msg):\r
 118         self.logger.critical(msg)\r
 119 \r
 120     # logs an exception - use in an except statement\r
 121     def log_exc(self,message):\r
 122         self.error("%s BEG TRACEBACK"%message+"\n"+traceback.format_exc().strip("\n"))\r
 123         self.error("%s END TRACEBACK"%message)\r
 124     \r
 125     def log_exc_critical(self,message):\r
 126         self.critical("%s BEG TRACEBACK"%message+"\n"+traceback.format_exc().strip("\n"))\r
 127         self.critical("%s END TRACEBACK"%message)\r
 128     \r
 129     # for investigation purposes, can be placed anywhere\r
 130     def log_stack(self,message):\r
 131         to_log="".join(traceback.format_stack())\r
 132         self.info("%s BEG STACK"%message+"\n"+to_log)\r
 133         self.info("%s END STACK"%message)\r
 134 \r
 135     def enable_console(self, stream=sys.stdout):\r
 136         formatter = logging.Formatter("%(message)s")\r
 137         handler = logging.StreamHandler(stream)\r
 138         handler.setFormatter(formatter)\r
 139         self.logger.addHandler(handler)\r
 140 \r
 141 \r
 142 info_logger = _SfaLogger(loggername='info', level=logging.INFO)\r
 143 debug_logger = _SfaLogger(loggername='debug', level=logging.DEBUG)\r
 144 warn_logger = _SfaLogger(loggername='warning', level=logging.WARNING)\r
 145 error_logger = _SfaLogger(loggername='error', level=logging.ERROR)\r
 146 critical_logger = _SfaLogger(loggername='critical', level=logging.CRITICAL)\r
 147 logger = info_logger\r
 148 sfi_logger = _SfaLogger(logfile=os.path.expanduser("~/.sfi/")+'sfi.log',loggername='sfilog', level=logging.DEBUG)\r
 149 ########################################\r
 150 import time\r
 151 \r
 152 def profile(logger):\r
 153     """\r
 154     Prints the runtime of the specified callable. Use as a decorator, e.g.,\r
 155     \r
 156     @profile(logger)\r
 157     def foo(...):\r
 158         ...\r
 159     """\r
 160     def logger_profile(callable):\r
 161         def wrapper(*args, **kwds):\r
 162             start = time.time()\r
 163             result = callable(*args, **kwds)\r
 164             end = time.time()\r
 165             args = map(str, args)\r
 166             args += ["%s = %s" % (name, str(value)) for (name, value) in kwds.iteritems()]\r
 167             # should probably use debug, but then debug is not always enabled\r
 168             logger.info("PROFILED %s (%s): %.02f s" % (callable.__name__, ", ".join(args), end - start))\r
 169             return result\r
 170         return wrapper\r
 171     return logger_profile\r
 172 \r
 173 \r
 174 if __name__ == '__main__': \r
 175     print 'testing sfalogging into logger.log'\r
 176     logger1=_SfaLogger('logger.log', loggername='std(info)')\r
 177     logger2=_SfaLogger('logger.log', loggername='error', level=logging.ERROR)\r
 178     logger3=_SfaLogger('logger.log', loggername='debug', level=logging.DEBUG)\r
 179     \r
 180     for (logger,msg) in [ (logger1,"std(info)"),(logger2,"error"),(logger3,"debug")]:\r
 181         \r
 182         print "====================",msg, logger.logger.handlers\r
 183    \r
 184         logger.enable_console()\r
 185         logger.critical("logger.critical")\r
 186         logger.error("logger.error")\r
 187         logger.warn("logger.warning")\r
 188         logger.info("logger.info")\r
 189         logger.debug("logger.debug")\r
 190         logger.setLevel(logging.DEBUG)\r
 191         logger.debug("logger.debug again")\r
 192     \r
 193         @profile(logger)\r
 194         def sleep(seconds = 1):\r
 195             time.sleep(seconds)\r
 196 \r
 197         logger.info('console.info')\r
 198         sleep(0.5)\r
 199         logger.setLevel(logging.DEBUG)\r
 200         sleep(0.25)\r
 201 \r