grid: log buildout output in realtime

Don't buffer output and use a separate thread to read subprocess process output
and send it line by line to logging, instead of reading from the main thread
which output lines with a delay.

fixes https://erp5js.nexedi.net/#/bug_module/20210311-90BA30

slapos/grid/utils.py

@@ -36,6 +36,7 @@ import pwd
 import stat
 import subprocess
 import sys
+import threading
 import logging
 import psutil
 import time
@@ -87,6 +88,26 @@ LOCALE_ENVIRONMENT_REMOVE_LIST = [
   'LC_TIME',
 ]
 
+
+def logAndAccumulateOutput(process_stdout, buffer, logger):
+  """Read process output and place the output in `buffer`, logging the lines
+  one by one as they are emitted.
+  """
+  current_output = ''
+  while 1:
+    data = os.read(process_stdout.fileno(), 4096)
+    if not data:
+      return
+    data = data.decode('utf-8', 'replace')
+    buffer.append(data)
+    current_output += data
+    for current_output_line in current_output.splitlines(True):
+      if current_output_line.endswith('\n'):
+        logger.info(current_output_line.rstrip('\n'))
+      else:
+        current_output = current_output_line
+
+
 class SlapPopen(subprocess.Popen):
   """
   Almost normal subprocess with greedish features and logging.
@@ -113,6 +134,7 @@ class SlapPopen(subprocess.Popen):
     # don't leak log & co. filedescriptors to child process
     kwargs.setdefault('close_fds', True)
 
+    kwargs.setdefault('bufsize', 0)
     subprocess.Popen.__init__(self, *args, **kwargs)
     if debug:
       self.wait()
@@ -123,12 +145,17 @@ class SlapPopen(subprocess.Popen):
     self.stdin = None
 
     output_lines = []
-    for line in self.stdout:
-      if type(line) is not str:
-        line = line.decode(errors='replace')
-      output_lines.append(line)
-      logger.info(line.rstrip('\n'))
+
+    # BBB: reading output in a separate thread is not needed on python 3,
+    # iterating on self.stdout seems enough.
+    t = threading.Thread(
+        target=logAndAccumulateOutput,
+        args=(self.stdout, output_lines, logger))
+    t.start()
+    try:
       self.wait()
+    finally:
+      t.join()
     self.output = ''.join(output_lines)
 
 

slapos/tests/test_grid_utils.py

 ##############################################################################
-#
+# coding: utf-8
 # Copyright (c) 2018 Vifib SARL and Contributors. All Rights Reserved.
 #
 # WARNING: This program as such is intended to be used by professional
@@ -24,14 +24,15 @@
 # Foundation, Inc., 59 Temple Place - Suite 330, Boston, MA  02111-1307, USA.
 #
 ##############################################################################
+from __future__ import unicode_literals
+import logging
 import os
 import sys
 import tempfile
+import textwrap
 import unittest
-import logging
-import mock
-
 
+import mock
 import slapos.grid.utils
 
 
@@ -62,6 +63,37 @@ class SlapPopenTestCase(unittest.TestCase):
     # output is also logged "live"
     logger.info.assert_called_with('hello')
 
+  def test_exec_multiline(self):
+    self.script.write(textwrap.dedent('''\
+      #!/bin/sh
+      echo -n he
+      echo -n l
+      sleep 0.1
+      echo lo
+      echo world
+    ''').encode())
+    self.script.close()
+
+    logger = mock.MagicMock()
+    program = slapos.grid.utils.SlapPopen(
+        self.script.name,
+        logger=logger)
+
+    self.assertEqual('hello\nworld\n', program.output)
+    self.assertEqual(logger.info.call_args_list, [mock.call('hello'), mock.call('world')])
+
+  def test_exec_non_ascii(self):
+    self.script.write(b'#!/bin/sh\necho h\xc3\xa9h\xc3\xa9')
+    self.script.close()
+
+    logger = mock.MagicMock()
+    program = slapos.grid.utils.SlapPopen(
+        self.script.name,
+        logger=logger)
+
+    self.assertEqual('héhé\n', program.output)
+    logger.info.assert_called_with('héhé')
+
   def test_debug(self):
     """Test debug=True, which keeps interactive.
     """