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/nm'
  13 LOG_SLIVERS = '/var/log/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 #################### child processes
  45 # avoid waiting until the process returns;
  46 # that makes debugging of hanging children hard
  47
  48 # time out in seconds - avoid hanging subprocesses - default is 5 minutes
  49 default_timeout_minutes=5
  50
  51 def log_call(command,timeout=default_timeout_minutes*60,poll=0.3):
  52     log('log_call: running command %s' % ' '.join(command))
  53     verbose('log_call: timeout %r s' % timeout)
  54     verbose('log_call: poll %r s' % poll)
  55     trigger=time.time()+timeout
  56     try:
  57         child = subprocess.Popen(command, stdout=subprocess.PIPE, stderr=subprocess.PIPE, close_fds=True)
  58         while True:
  59             # see if anything can be read within the poll interval
  60             (r,w,x)=select.select([child.stdout,child.stderr],[],[],poll)
  61             # read and log it
  62             for fd in r:
  63                 input=fd.read()
  64                 if input: log(input)
  65             # is process over ?
  66             returncode=child.poll()
  67             # yes
  68             if returncode != None:
  69                 # child is done and return 0
  70                 if returncode == 0:
  71                     verbose('log_call: command completed %s' % ' '.join(command))
  72                     break
  73                 # child has failed
  74                 else:
  75                     raise Exception("log_call: failed with returncode %d"%returncode)
  76             # no : still within timeout ?
  77             if time.time() >= trigger:
  78                 child.terminate()
  79                 raise Exception("log_call: terminated command - exceeded timeout %d s"%timeout)
  80     except: log_exc('failed to run command %s' % ' '.join(command))
  81
  82 def log_exc(msg="",name=None):
  83     """Log the traceback resulting from an exception."""
  84     if name:
  85         log("%s: EXCEPTION caught <%s> \n %s" %(name, msg, traceback.format_exc()))
  86     else:
  87         log("EXCEPTION caught <%s> \n %s" %(msg, traceback.format_exc()))
  88
  89 # for some reason the various modules are still triggered even when the
  90 # data from PLC cannot be reached
  91 # we show this message instead of the exception stack instead in this case
  92 def log_missing_data (msg,key):
  93     log("%s: could not find the %s key in data (PLC connection down?) - IGNORED"%(msg,key))
  94
  95 def log_data_in_file (data, file, message=""):
  96     import pprint, time
  97     try:
  98         f=open(file,'w')
  99         now=time.strftime("Last update: %Y.%m.%d at %H:%M:%S %Z", time.localtime())
 100         f.write(now+'\n')
 101         if message: f.write('Message:'+message+'\n')
 102         pp=pprint.PrettyPrinter(stream=f,indent=2)
 103         pp.pprint(data)
 104         f.close()
 105     except:
 106         log_verbose('log_data_in_file failed - file=%s - message=%r'%(file,message))
 107
 108 def log_slivers (data):
 109     log_data_in_file (data, LOG_SLIVERS, "raw GetSlivers")