app+luatest: eliminate stdout buffering and stream mixing problems

lib/app_server.py

@@ -6,7 +6,7 @@
 import signal
 import sys
 
-from gevent.subprocess import Popen, PIPE
+from gevent.subprocess import Popen
 
 from lib.colorer import color_stdout
 from lib.colorer import color_log
@@ -33,17 +33,14 @@ def timeout_handler(server_process, test_timeout):
 
 def run_server(execs, cwd, server, logfile, retval, test_id):
     os.putenv("LISTEN", server.listen_uri)
-    server.process = Popen(execs, stdout=PIPE, stderr=PIPE, cwd=cwd)
+    with open(logfile, 'ab') as f:
+        server.process = Popen(execs, stdout=sys.stdout, stderr=f, cwd=cwd)
     sampler.register_process(server.process.pid, test_id, server.name)
     test_timeout = Options().args.test_timeout
     timer = Timer(test_timeout, timeout_handler, (server.process, test_timeout))
     timer.start()
-    stdout, stderr = server.process.communicate()
-    timer.cancel()
-    sys.stdout.write_bytes(stdout)
-    with open(logfile, 'ab') as f:
-        f.write(stderr)
     retval['returncode'] = server.process.wait()
+    timer.cancel()
     server.process = None
 
 
@@ -128,10 +125,18 @@ def logfile(self):
         return os.path.join(self.vardir, file_name)
 
     def prepare_args(self, args=[]):
-        cli_args = [os.path.join(os.getcwd(), self.current_test.name)] + args
+        # Disable stdout bufferization.
+        cli_args = [self.binary, '-e', "io.stdout:setvbuf('no')"]
+
+        # Disable schema upgrade if requested.
         if self.disable_schema_upgrade:
-            cli_args = [self.binary, '-e',
-                        self.DISABLE_AUTO_UPGRADE] + cli_args
+            cli_args.extend(['-e', self.DISABLE_AUTO_UPGRADE])
+
+        # Add path to the script (the test).
+        cli_args.extend([os.path.join(os.getcwd(), self.current_test.name)])
+
+        # Add extra args if provided.
+        cli_args.extend(args)
 
         return cli_args
 

lib/luatest_server.py

@@ -3,8 +3,7 @@
 import re
 import sys
 
-from subprocess import Popen, PIPE
-from subprocess import STDOUT
+from subprocess import Popen
 from threading import Timer
 
 from lib.colorer import color_stdout
@@ -36,20 +35,23 @@ def execute(self, server):
         """Execute test by luatest command
 
         Execute `luatest -c --verbose <name>_test.lua --output tap` command.
-        Use capture mode. Provide a verbose output in the tap format.
+        Disable capture mode. Provide a verbose output in the tap format.
         Extend the command by `--pattern <pattern>` if the corresponding
         option is provided.
         """
         server.current_test = self
         script = os.path.join(os.path.basename(server.testdir), self.name)
-        command = ['luatest', '-c', '--verbose', script, '--output', 'tap']
+
+        # Disable stdout buffering.
+        command = [server.binary, '-e', "io.stdout:setvbuf('no')"]
+        # Add luatest as the script.
+        command.extend([server.luatest])
+        # Add luatest command-line options.
+        command.extend(['-c', '--verbose', script, '--output', 'tap'])
         if Options().args.pattern:
             for p in Options().args.pattern:
                 command.extend(['--pattern', p])
 
-        # Tarantool's build directory is added to PATH in
-        # TarantoolServer.find_exe().
-        #
         # We start luatest from the project source directory, it
         # is the usual way to use luatest.
         #
@@ -58,12 +60,14 @@ def execute(self, server):
         # and so on.
         os.environ['VARDIR'] = server.vardir
         project_dir = os.environ['SOURCEDIR']
-        proc = Popen(command, cwd=project_dir, stdout=PIPE, stderr=STDOUT)
+
+        with open(server.logfile, 'ab') as f:
+            proc = Popen(command, cwd=project_dir, stdout=sys.stdout, stderr=f)
         sampler.register_process(proc.pid, self.id, server.name)
         test_timeout = Options().args.test_timeout
         timer = Timer(test_timeout, timeout_handler, (proc, test_timeout))
         timer.start()
-        sys.stdout.write_bytes(proc.communicate()[0])
+        proc.wait()
         timer.cancel()
         if proc.returncode != 0:
             raise TestExecutionError
@@ -89,11 +93,17 @@ def __init__(self, _ini=None, test_suite=None):
 
     @property
     def logfile(self):
-        return self.current_test.tmp_result
-
-    @property
-    def binary(self):
-        return LuatestServer.prepare_args(self)[0]
+        # Remove the suite name using basename().
+        test_name = os.path.basename(self.current_test.name)
+        # Strip '.lua' from the end.
+        #
+        # The '_test' postfix is kept to ease distinguish this
+        # log file from luatest.server instance logs.
+        test_name = test_name[:-len('.lua')]
+        # Add '.log'.
+        file_name = test_name + '.log'
+        # Put into vardir.
+        return os.path.join(self.vardir, file_name)
 
     def deploy(self, vardir=None, silent=True, wait=True):
         self.vardir = vardir
@@ -106,14 +116,15 @@ def find_exe(cls, builddir):
         cls.binary = TarantoolServer.binary
         cls.debug = bool(re.findall(r'^Target:.*-Debug$', str(cls.version()),
                                     re.M))
+        cls.luatest = os.environ['TEST_RUN_DIR'] + '/lib/luatest/bin/luatest'
 
     @classmethod
     def verify_luatest_exe(cls):
         """Verify that luatest executable is available."""
         try:
             # Just check that the command returns zero exit code.
             with open(os.devnull, 'w') as devnull:
-                returncode = Popen(['luatest', '--version'],
+                returncode = Popen([cls.luatest, '--version'],
                                    stdout=devnull,
                                    stderr=devnull).wait()
             if returncode != 0:
@@ -145,6 +156,3 @@ def patterned(test, patterns):
                             for k in sorted(tests)]
         test_suite.tests = sum([patterned(x, test_suite.args.tests)
                                 for x in test_suite.tests], [])
-
-    def print_log(self, lines):
-        pass

lib/server.py

@@ -143,17 +143,31 @@ def stop(self, silent=True):
     def restart(self):
         pass
 
-    def print_log(self, lines=None):
-        msg = ('\n{prefix} of Tarantool Log file [Instance "{instance}"]' +
-               '[{logfile}]:\n').format(
-            prefix="Last {0} lines".format(lines) if lines else "Output",
-            instance=self.name,
-            logfile=self.logfile or 'null')
-        color_stdout(msg, schema='error')
-        if os.path.exists(self.logfile):
-            print_tail_n(self.logfile, lines)
+    def print_log(self, num_lines=None):
+        """ Show information from the given log file.
+        """
+        prefix = '\n[test-run server "{instance}"] '.format(instance=self.name)
+        if not self.logfile:
+            msg = 'No log file is set (internal test-run error)\n'
+            color_stdout(prefix + msg, schema='error')
+        elif not os.path.exists(self.logfile):
+            fmt_str = 'The log file {logfile} does not exist\n'
+            msg = fmt_str.format(logfile=self.logfile)
+            color_stdout(prefix + msg, schema='error')
+        elif os.path.getsize(self.logfile) == 0:
+            fmt_str = 'The log file {logfile} has zero size\n'
+            msg = fmt_str.format(logfile=self.logfile)
+            color_stdout(prefix + msg, schema='error')
+        elif num_lines:
+            fmt_str = 'Last {num_lines} lines of the log file {logfile}:\n'
+            msg = fmt_str.format(logfile=self.logfile, num_lines=num_lines)
+            color_stdout(prefix + msg, schema='error')
+            print_tail_n(self.logfile, num_lines)
         else:
-            color_stdout("    Can't find log:\n", schema='error')
+            fmt_str = 'The log file {logfile}:\n'
+            msg = fmt_str.format(logfile=self.logfile)
+            color_stdout(msg, schema='error')
+            print_tail_n(self.logfile, num_lines)
 
     @staticmethod
     def exclude_tests(test_names, exclude_patterns):

lib/test.py

@@ -91,6 +91,11 @@ def close(self):
     def flush(self):
         self.stream.flush()
 
+    def fileno(self):
+        """ May be used for direct writting. Discards any filters.
+        """
+        return self.stream.fileno()
+
 
 def get_filename_by_test(postfix, test_name):
     """For <..>/<name>_test.* or <..>/<name>.test.* return <name> + postfix