logger.py

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