X-Git-Url: http://git.onelab.eu/?a=blobdiff_plain;ds=sidebyside;f=logger.py;h=c4f6ce6354cff1fb40beb3d714335d02fd689571;hb=33f472e3e3589569f0272f7f53d07b011d2a5490;hp=0b083ca670b559560f5758011d8c7d87df4c6756;hpb=2f100cd2a78a0f91022bc4a895007975181cf353;p=nodemanager.git

diff --git a/logger.py b/logger.py
index 0b083ca..c4f6ce6 100644
--- a/logger.py
+++ b/logger.py
@@ -1,13 +1,13 @@
-#
-# Something relevant
-#
+# $Id$
+# $URL$
+
 """A very simple logger that tries to be concurrency-safe."""
 
 import os, sys
-import subprocess
 import time
 import traceback
-
+import subprocess
+import select
 
 LOG_FILE = '/var/log/nm'
 LOG_SLIVERS = '/var/log/getslivers.txt'
@@ -26,7 +26,7 @@ def set_level(level):
     LOG_LEVEL=level
 
 def verbose(msg):
-    log(msg,LOG_VERBOSE)
+    log('(v) '+msg,LOG_VERBOSE)
 
 def log(msg,level=LOG_NODE):
     """Write <msg> to the log file if level >= current log level (default LOG_NODE)."""
@@ -41,26 +41,88 @@ def log(msg,level=LOG_NODE):
         sys.stderr.write(msg)
         sys.stderr.flush()
 
-def log_call(*args):
-    log('running command %s' % ' '.join(args))
-    try: subprocess.call(args, close_fds=True)
-    except: log_exc()
-
-def log_exc(name = None):
+def log_exc(msg="",name=None):
     """Log the traceback resulting from an exception."""
-    if name:  
-        log("operation on %s failed.  \n %s" %(name, traceback.format_exc()))
+    if name: 
+        log("%s: EXCEPTION caught <%s> \n %s" %(name, msg, traceback.format_exc()))
     else:
-        log(traceback.format_exc())
+        log("EXCEPTION caught <%s> \n %s" %(msg, traceback.format_exc()))
 
-def log_slivers (data):
+########## snapshot data to a file
+# for some reason the various modules are still triggered even when the
+# data from PLC cannot be reached
+# we show this message instead of the exception stack instead in this case
+def log_missing_data (msg,key):
+    log("%s: could not find the %s key in data (PLC connection down?) - IGNORED"%(msg,key))
+
+def log_data_in_file (data, file, message=""):
     import pprint, time
     try:
-        f=open(LOG_SLIVERS,'w')
-        now=time.strftime("GetSlivers stored on %Y.%m.%d at %H:%M:%S", time.localtime())
+        f=open(file,'w')
+        now=time.strftime("Last update: %Y.%m.%d at %H:%M:%S %Z", time.localtime())
         f.write(now+'\n')
+        if message: f.write('Message:'+message+'\n')
         pp=pprint.PrettyPrinter(stream=f,indent=2)
         pp.pprint(data)
         f.close()
     except:
-        log_verbose('Cannot save GetSlivers in %s'%LOG_SLIVERS)
+        log_verbose('log_data_in_file failed - file=%s - message=%r'%(file,message))
+
+def log_slivers (data):
+    log_data_in_file (data, LOG_SLIVERS, "raw GetSlivers")
+
+#################### child processes
+# avoid waiting until the process returns; 
+# that makes debugging of hanging children hard
+
+class Buffer:
+    def __init__ (self,message='log_call: '):
+        self.buffer=''
+        self.message=message
+        
+    def add (self,c):
+        self.buffer += c
+        if c=='\n': self.flush()
+
+    def flush (self):
+        if self.buffer:
+            log (self.message + self.buffer)
+            self.buffer=''
+
+# time out in seconds - avoid hanging subprocesses - default is 5 minutes
+default_timeout_minutes=5
+
+def log_call(command,timeout=default_timeout_minutes*60,poll=1):
+    message=" ".join(command)
+    log("log_call: running command %s" % message)
+    verbose("log_call: timeout=%r s" % timeout)
+    verbose("log_call: poll=%r s" % poll)
+    trigger=time.time()+timeout
+    try: 
+        child = subprocess.Popen(command, bufsize=1, 
+                                 stdout=subprocess.PIPE, stderr=subprocess.STDOUT, close_fds=True)
+        buffer = Buffer()
+        while True:
+            # see if anything can be read within the poll interval
+            (r,w,x)=select.select([child.stdout],[],[],poll)
+            if r: buffer.add(child.stdout.read(1))
+            # is process over ?
+            returncode=child.poll()
+            # yes
+            if returncode != None:
+                buffer.flush()
+                # child is done and return 0
+                if returncode == 0: 
+                    log("log_call: command completed (%s)" % message)
+                    break
+                # child has failed
+                else:
+                    log("log_call: command return=%d (%s)" %(returncode,message))
+                    raise Exception("log_call: failed with returncode %d"%returncode)
+            # no : still within timeout ?
+            if time.time() >= trigger:
+                buffer.flush()
+                child.terminate()
+                raise Exception("log_call: terminated command - exceeded timeout %d s"%timeout)
+    except: log_exc("failed to run command %s" % message)
+