logger.py

   1
   2 """A very simple logger that tries to be concurrency-safe."""
   3
   4 import os, sys
   5 import time
   6 import traceback
   7 import subprocess
   8 import select
   9
  10 LOG_FILE    = '/var/log/nodemanager'
  11 LOG_SLIVERS = '/var/lib/nodemanager/getslivers.txt'
  12 LOG_DATABASE = '/var/lib/nodemanager/database.txt'
  13
  14 # basically define 3 levels
  15 LOG_NONE=0
  16 LOG_NODE=1
  17 LOG_VERBOSE=2
  18 # default is to log a reasonable amount of stuff for when running on operational nodes
  19 LOG_LEVEL=LOG_NODE
  20
  21 def set_level(level):
  22     global LOG_LEVEL
  23     try:
  24         assert level in [LOG_NONE,LOG_NODE,LOG_VERBOSE]
  25         LOG_LEVEL=level
  26     except:
  27         logger.log("Failed to set LOG_LEVEL to %s"%level)
  28
  29 def verbose(msg):
  30     log('(v) '+msg,LOG_VERBOSE)
  31
  32 def log(msg,level=LOG_NODE):
  33     """Write <msg> to the log file if level >= current log level (default LOG_NODE)."""
  34     if (level > LOG_LEVEL):
  35         return
  36     try:
  37         fd = os.open(LOG_FILE, os.O_WRONLY | os.O_CREAT | os.O_APPEND, 0600)
  38         if not msg.endswith('\n'): msg += '\n'
  39         os.write(fd, '%s: %s' % (time.asctime(time.gmtime()), msg))
  40         os.close(fd)
  41     except OSError:
  42         sys.stderr.write(msg)
  43         sys.stderr.flush()
  44
  45 date_width=24
  46 def log_exc(msg="",name=None):
  47     """Log traceback resulting from an exception."""
  48     printout=""
  49     if name: printout += "%s: "%name
  50     printout += "EXCEPTION caught <%s> \n" %msg
  51     for frame in traceback.format_exc().split("\n"):
  52         printout+=(date_width+2)*" "+"%s\n"%frame
  53     log(printout)
  54
  55 def log_trace(msg="",name=None):
  56     """Log current stack"""
  57     printout=""
  58     if name: printout += "%s: "%name
  59     printout += "LOGTRACE\n"
  60     for frame in traceback.format_stack():
  61         printout += "..."+frame
  62     log(printout)
  63
  64
  65 ########## snapshot data to a file
  66 # for some reason the various modules are still triggered even when the
  67 # data from PLC cannot be reached
  68 # we show this message instead of the exception stack instead in this case
  69 def log_missing_data (msg,key):
  70     log("%s: could not find the %s key in data (PLC connection down?) - IGNORED"%(msg,key))
  71
  72 def log_data_in_file (data, file, message="",level=LOG_NODE):
  73     if (level > LOG_LEVEL):
  74         return
  75     import pprint, time
  76     try:
  77         f=open(file,'w')
  78         now=time.strftime("Last update: %Y.%m.%d at %H:%M:%S %Z", time.localtime())
  79         f.write(now+'\n')
  80         if message: f.write('Message:'+message+'\n')
  81         pp=pprint.PrettyPrinter(stream=f,indent=2)
  82         pp.pprint(data)
  83         f.close()
  84         verbose("logger:.log_data_in_file Owerwrote %s"%file)
  85     except:
  86         log_exc('logger.log_data_in_file failed - file=%s - message=%r'%(file,message))
  87
  88 def log_slivers (data):
  89     log_data_in_file (data, LOG_SLIVERS, "raw GetSlivers")
  90 def log_database (db):
  91     log_data_in_file (db, LOG_DATABASE, "raw database")
  92
  93 #################### child processes
  94 # avoid waiting until the process returns;
  95 # that makes debugging of hanging children hard
  96
  97 class Buffer:
  98     def __init__ (self,message='log_call: '):
  99         self.buffer=''
 100         self.message=message
 101
 102     def add (self,c):
 103         self.buffer += c
 104         if c=='\n': self.flush()
 105
 106     def flush (self):
 107         if self.buffer:
 108             log (self.message + self.buffer)
 109             self.buffer=''
 110
 111 # time out in seconds - avoid hanging subprocesses - default is 5 minutes
 112 default_timeout_minutes=5
 113
 114 # returns a bool that is True when everything goes fine and the retcod is 0
 115 def log_call(command,timeout=default_timeout_minutes*60,poll=1):
 116     message=" ".join(command)
 117     log("log_call: running command %s" % message)
 118     verbose("log_call: timeout=%r s" % timeout)
 119     verbose("log_call: poll=%r s" % poll)
 120     trigger=time.time()+timeout
 121     result = False
 122     try:
 123         child = subprocess.Popen(command, bufsize=1,
 124                                  stdout=subprocess.PIPE, stderr=subprocess.STDOUT, close_fds=True)
 125         buffer = Buffer()
 126         while True:
 127             # see if anything can be read within the poll interval
 128             (r,w,x)=select.select([child.stdout],[],[],poll)
 129             if r: buffer.add(child.stdout.read(1))
 130             # is process over ?
 131             returncode=child.poll()
 132             # yes
 133             if returncode != None:
 134                 buffer.flush()
 135                 # child is done and return 0
 136                 if returncode == 0:
 137                     log("log_call:end command (%s) completed" % message)
 138                     result=True
 139                     break
 140                 # child has failed
 141                 else:
 142                     log("log_call:end command (%s) returned with code %d" %(message,returncode))
 143                     break
 144             # no : still within timeout ?
 145             if time.time() >= trigger:
 146                 buffer.flush()
 147                 child.terminate()
 148                 log("log_call:end terminating command (%s) - exceeded timeout %d s"%(message,timeout))
 149                 break
 150     except: log_exc("failed to run command %s" % message)
 151     return result