slapgrid: Fix promises not being logged to logfile

See merge request nexedi/slapos.core!356

slapos/grid/promise/runpromises.py

@@ -60,11 +60,11 @@ promise_checker = PromiseLauncher(config=config, logger=app.log)
 
 
 # Run promises
-# Redirect stdout to stderr (logger only uses stderr already)
-# to reserve stdout for error reporting
+# Redirect stderr to stdout (logger uses stderr)
+# to reserve stderr exclusively for error reporting
 
-out = os.dup(1)
-os.dup2(2, 1)
+err = os.dup(2)
+os.dup2(1, 2)
 
 try:
   promise_checker.run()
@@ -73,5 +73,5 @@ except Exception as e:
     error_str = unicode(str(e), 'utf-8', 'repr')
   else:
     error_str = str(e)
-  os.write(out, error_str.encode('utf-8', 'repr'))
+  os.write(err, error_str.encode('utf-8', 'repr'))
   sys.exit(2 if isinstance(e, PromiseError) else 1)

slapos/grid/slapgrid.py

@@ -726,26 +726,30 @@ stderr_logfile_backups=1
         else:
           command.append('--' + option)
           command.append(str(value))
-      process = subprocess.Popen(
-        command,
-        preexec_fn=lambda: dropPrivileges(uid, gid, logger=self.logger),
-        cwd=instance_path,
-        universal_newlines=True,
-        stdout=subprocess.PIPE)
       promises = plugins + len(listifdir(legacy_promise_dir))
       # Add a timeout margin to let the process kill the promises and cleanup
       timeout = promises * self.promise_timeout + 10
+      # The runpromise script uses stderr exclusively to propagate exception
+      # messages. It otherwise redirects stderr to stdout so that all outputs
+      # from the promises go to stdout.
       try:
-        # The logger logs everything to stderr, so runpromise redirects
-        # stdout to stderr in case a promise prints to stdout
-        # and reserves stdout to progagate exception messages.
-        out, _ = process.communicate(timeout=timeout)
+        process = SlapPopen(
+          command,
+          preexec_fn=lambda: dropPrivileges(uid, gid, logger=self.logger),
+          cwd=instance_path,
+          universal_newlines=True,
+          stdout=subprocess.PIPE,
+          stderr=subprocess.PIPE,
+          logger=self.logger,
+          timeout=timeout,
+        )
+        stderr = process.stderr.read()
         if process.returncode == 2:
-          raise PromiseError(out)
+          raise PromiseError(stderr)
         elif process.returncode:
-          raise Exception(out)
-        elif out:
-          self.logger.warn('Promise runner unexpected output:\n%s', out)
+          raise Exception(stderr)
+        elif stderr:
+          self.logger.warn('Promise runner unexpected output:\n%s', stderr)
       except subprocess.TimeoutExpired:
         killProcessTree(process.pid, self.logger)
         # The timeout margin was exceeded but this should be infrequent

slapos/grid/utils.py

@@ -34,13 +34,17 @@ import os
 import pkg_resources
 import pwd
 import stat
-import subprocess
 import sys
 import threading
 import logging
 import psutil
 import time
 
+if sys.version_info >= (3,):
+  import subprocess
+else:
+  import subprocess32 as subprocess
+
 
 from slapos.grid.exception import BuildoutFailedError, WrongPermissionError
 
@@ -119,6 +123,7 @@ class SlapPopen(subprocess.Popen):
   """
   def __init__(self, *args, **kwargs):
     logger = kwargs.pop('logger')
+    timeout = kwargs.pop('timeout', None)
 
     debug = kwargs.pop('debug', False)
     if debug:
@@ -154,7 +159,7 @@ class SlapPopen(subprocess.Popen):
         args=(self.stdout, output_lines, logger))
     t.start()
     try:
-      self.wait()
+      self.wait(timeout=timeout)
     finally:
       t.join()
     self.output = ''.join(output_lines)

slapos/tests/test_slapgrid.py

@@ -4214,6 +4214,32 @@ class TestSlapgridPluginPromiseWithInstancePython(TestSlapgridPromiseWithMaster)
         dummyLogger.mock_calls[-1][1][0] % dummyLogger.mock_calls[-1][1][1:],
         "  0[(not ready)]: Promise 'failing_promise_plugin.py' failed with output: héhé fake promise plugin error")
 
+  def test_succeeding_promise_logs_output(self):
+    computer = self.getTestComputerClass()(self.software_root, self.instance_root, 1, 1)
+    instance, = computer.instance_list
+
+    name = "succeeding_promise_plugin.py"
+    output = "hehe fake promise plugin succeded !"
+
+    instance.requested_state = 'started'
+    instance.setPluginPromise(
+        name,
+        promise_content="""if 1:
+          return self.logger.info(%r)
+        """ % output,
+    )
+
+    with httmock.HTTMock(computer.request_handler), \
+        patch.object(self.grid.logger, 'info',) as dummyLogger:
+      self.launchSlapgrid()
+
+    self.assertIn(
+      "Checking promise %s..." % name,
+      dummyLogger.mock_calls[-4][1][0] % dummyLogger.mock_calls[-4][1][1:])
+
+    self.assertIn(
+      output,
+      dummyLogger.mock_calls[-3][1][0] % dummyLogger.mock_calls[-3][1][1:])
 
 
 class TestSlapgridPluginPromiseWithInstancePythonOldSlapOSCompatibility(