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