improve logging

cloudooo/handler/ooo/application/application.py

@@ -29,8 +29,7 @@
 from zope.interface import implements
 from cloudooo.interfaces.application import IApplication
 from cloudooo.util import logger
-from cloudooo.handler.ooo.util import waitStopDaemon
-from psutil import pid_exists, Process, AccessDenied
+from psutil import pid_exists, Process, AccessDenied, TimeoutExpired, NoSuchProcess
 
 
 class Application(object):
@@ -47,17 +46,36 @@ class Application(object):
                                                     self.getAddress()[-1],
                                                     self.pid()))
 
-  def stop(self):
+  def stopProcess(self, process_pid):
     """Stop the process"""
-    if hasattr(self, 'process') and self.status():
-      process_pid = self.process.pid
-      logger.debug("Stop Pid - %s" % process_pid)
+    error = False
+    logger.debug("Stop Pid - %s", process_pid)
+    returncode = None
+    try:
+      process = Process(process_pid)
+      cmdline = " ".join(process.cmdline())
+      process.terminate()
+      returncode = process.wait(self.timeout)
+    except NoSuchProcess:
+      pass
+    except TimeoutExpired:
+      error = True
+      logger.error("Process %s survived SIGTERM after %s", process_pid, self.timeout)
       try:
-        self.process.terminate()
-        waitStopDaemon(self, self.timeout)
-      finally:
-        if pid_exists(process_pid) or self.status():
-          Process(process_pid).kill()
+        process.kill()
+        returncode = process.wait(self.timeout)
+      except NoSuchProcess:
+        pass
+      except TimeoutExpired:
+        logger.error("Process %s survived SIGKILL after %s", process_pid, self.timeout)
+    if error and returncode:
+      logger.error("Process %s cmdline: %s ended with returncode %s", process_pid, cmdline, returncode)
+    elif returncode != 0:
+      logger.debug("Process %s ended with returncode %s", process_pid, returncode)
+
+  def stop(self):
+    if hasattr(self, 'process'):
+      self.stopProcess(self.process.pid)
       delattr(self, "process")
 
   def loadSettings(self, hostname, port, path_run_dir, **kwargs):

cloudooo/handler/ooo/application/openoffice.py

@@ -37,7 +37,7 @@ from application import Application
 from cloudooo.interfaces.lockable import ILockable
 from cloudooo.util import logger, convertStringToBool
 from cloudooo.handler.ooo.util import waitStartDaemon, \
-                                      removeDirectory, waitStopDaemon, \
+                                      removeDirectory, \
                                       socketStatus
 
 
@@ -105,7 +105,6 @@ class OpenOffice(Application):
     """Start OpenOffice.org process"""
     for i in range(5):
       self.stop()
-      waitStopDaemon(self, self.timeout)
       self.process = Popen(command,
                            close_fds=True,
                            env=env)
@@ -121,14 +120,16 @@ class OpenOffice(Application):
           for connection in process.connections():
             if connection.status == "LISTEN" and \
                 connection.laddr[1] == self.port:
-              process.terminate()
+              self.stopProcess(process.pid)
+              break
       except AccessDenied, e:
         pass
       except TypeError, e:
         # exception to prevent one psutil issue with zombie processes
-        logger.debug(e)
+        logger.error(e)
       except NotImplementedError, e:
-        logger.error("lsof isn't installed on this machine: " + str(e))
+        logger.error("lsof isn't installed on this machine: %s", str(e))
+        break
 
   def start(self, init=True):
     """Start Instance."""

cloudooo/handler/ooo/handler.py

@@ -119,11 +119,18 @@ class Handler(object):
       self._startTimeout()
       process = Popen(command_list, stdout=PIPE, stderr=PIPE, close_fds=True,
                       env=openoffice.environment_dict.copy())
+      logger.debug("Process %s running", process.pid)
       stdout, stderr = process.communicate()
     finally:
       self._stopTimeout()
       if pid_exists(process.pid):
+        logger.debug("Process %s terminated", process.pid)
         process.terminate()
+    if (process.returncode < 0 and process.returncode != -6) or stderr:
+      logger.error("Process %s command:%s", process.pid, " ".join(command_list))
+      logger.error("Process %s stdout:%s", process.pid, stdout)
+      logger.error("Process %s stderr:%s", process.pid, stderr)
+    logger.debug("Process %s terminated with returncode %s", process.pid, process.returncode)
     return stdout, stderr
 
   def _callUnoConverter(self, *feature_list, **kw):
@@ -131,7 +138,9 @@ class Handler(object):
     if not openoffice.status():
       openoffice.start()
     command_list = self._getCommand(*feature_list, **kw)
+    logger.debug("run convert first")
     stdout, stderr = self._subprocess(command_list)
+    logger.debug("stop convert first")
     if not stdout and stderr:
       first_error = stderr
       logger.error(stderr)
@@ -139,10 +148,11 @@ class Handler(object):
       openoffice.restart()
       kw['document_url'] = self.document.getUrl()
       command = self._getCommand(*feature_list, **kw)
+      logger.debug("run convert second")
       stdout, stderr = self._subprocess(command)
+      logger.debug("stop convert second")
       if not stdout and stderr:
         second_error = "\nerror of the second run: " + stderr
-        logger.error(second_error)
         raise Exception(first_error + second_error)
 
     return stdout, stderr

cloudooo/handler/ooo/mimemapper.py

@@ -33,6 +33,7 @@ from subprocess import STDOUT
 from zope.interface import implements
 from filter import Filter
 from os import environ, path
+from cloudooo.util import logger
 from cloudooo.interfaces.mimemapper import IMimemapper
 from types import InstanceType
 import json
@@ -124,8 +125,10 @@ class MimeMapper(object):
             "--hostname=%s" % hostname,
             "--port=%s" % port]
 
-    process = Popen(command, stdout=PIPE, stderr=STDOUT, close_fds=True)
+    process = Popen(command, stdout=PIPE, stderr=PIPE, close_fds=True)
     stdout, stderr = process.communicate()
+    if stderr:
+      logger.error(stderr)
     if process.returncode:
       raise ValueError(stdout)
     filter_dict, type_dict = json.loads(stdout)