Add timeout for starting tarantool server

Function wait_until_started in TarantoolServer contains seek_wait,
which waits pattern in logfile. If there is no pattern, server is
hanging. Was added start-server-time (by default equals to 90 secs).
The pattern is sought until the time runs out and wait_until_started
returns True if the pattern was found (else False). Was added new
 logging that the instance wasn't started.

Fixes: #276

lib/options.py

@@ -211,6 +211,14 @@ def __init__(self):
                 help="""Break the test process with kill signal if the test runs
                 longer than this amount of seconds. Default: 110 [seconds].""")
 
+        parser.add_argument(
+            "--server-start-timeout",
+            dest="server_start_timeout",
+            default=env_int('SERVER_START_TIMEOUT', 90),
+            type=int,
+            help="""Break the test process with kill signal if the test starts
+            longer than this amount of seconds. Default: 90 [seconds].""")
+
         parser.add_argument(
                 "--no-output-timeout",
                 dest="no_output_timeout",

lib/preprocessor.py

@@ -9,6 +9,7 @@
 
 from lib.admin_connection import AdminAsyncConnection
 from lib.colorer import color_log
+from lib.colorer import color_stdout
 from lib.utils import signum
 from lib.utils import signame
 from lib.utils import integer_types
@@ -206,8 +207,14 @@ def server_start(self, ctype, sname, opts):
             if crash_expected:
                 # disable crash detector
                 self.servers[sname].crash_expected = True
-            self.servers[sname].start(silent=True, rais=True, wait=wait,
-                                      wait_load=wait_load, args=args)
+            is_started = self.servers[sname].start(
+                    silent=True, rais=True, wait=wait,
+                    wait_load=wait_load, args=args)
+            if not is_started and wait and wait_load:
+                color_stdout('\n[Instance "{0}"] Failed to start tarantool '
+                             'instance\n'.format(sname),
+                             schema='error')
+                self.kill_current_test()
         except Exception as e:
             crash_occured = True
             if not (crash_expected and

lib/tarantool_server.py

@@ -415,8 +415,15 @@ def execute(self, server):
 
 
 class TarantoolStartError(OSError):
-    def __init__(self, name=None):
+    def __init__(self, name=None, timeout=None):
         self.name = name
+        self.timeout = timeout
+
+    def __str__(self):
+        if self.timeout:
+            return "[instance '{}'] Start timeout {} was reached.".format(
+                self.name, self.timeout)
+        return "Failed {}".format(self.name)
 
 
 class TarantoolLog(object):
@@ -445,7 +452,7 @@ def seek_once(self, msg):
                 if pos != -1:
                     return pos
 
-    def seek_wait(self, msg, proc=None, name=None):
+    def seek_wait(self, msg, proc=None, name=None, timeout=90):
         while True:
             if os.path.exists(self.path):
                 break
@@ -454,7 +461,8 @@ def seek_wait(self, msg, proc=None, name=None):
         with open(self.path, 'r') as f:
             f.seek(self.log_begin, os.SEEK_SET)
             cur_pos = self.log_begin
-            while True:
+            deadline = time.time() + timeout
+            while time.time() < deadline:
                 if not (proc is None):
                     if not (proc.poll() is None):
                         raise TarantoolStartError(name)
@@ -464,8 +472,9 @@ def seek_wait(self, msg, proc=None, name=None):
                     f.seek(cur_pos, os.SEEK_SET)
                     continue
                 if re.findall(msg, log_str):
-                    return
+                    return True
                 cur_pos = f.tell()
+        return False
 
 
 class TarantoolServer(Server):
@@ -824,12 +833,12 @@ def cleanup(self, *args, **kwargs):
     def start(self, silent=True, wait=True, wait_load=True, rais=True, args=[],
               **kwargs):
         if self._start_against_running:
-            return
+            return True
         if self.status == 'started':
             if not silent:
                 color_stdout('The server is already started.\n',
                              schema='lerror')
-            return
+            return True
 
         args = self.prepare_args(args)
         self.pidfile = '%s.pid' % self.name
@@ -874,7 +883,7 @@ def start(self, silent=True, wait=True, wait_load=True, rais=True, args=[],
         if wait:
             try:
                 self.wait_until_started(wait_load)
-            except TarantoolStartError:
+            except TarantoolStartError as err:
                 # Python tests expect we raise an exception when non-default
                 # server fails
                 if self.crash_expected:
@@ -886,6 +895,11 @@ def start(self, silent=True, wait=True, wait_load=True, rais=True, args=[],
                     color_stdout('\n[Instance "{0.name}"] Tarantool server '
                                  'failed to start\n'.format(self),
                                  schema='error')
+                    if err.timeout:
+                        color_stdout(
+                            '\n[Instance "{0.name}"] Tarantool server start '
+                            'timeout {1} was reached.\n'.format(
+                                self, err.timeout), schema='error')
                     self.print_log(15)
                 # Raise exception when caller ask for it (e.g. in case of
                 # non-default servers)
@@ -913,6 +927,7 @@ def start(self, silent=True, wait=True, wait_load=True, rais=True, args=[],
                                                    actual_version),
                              schema='error')
                 raise TarantoolStartError(self.name)
+        return True
 
     def crash_detect(self):
         if self.crash_expected:
@@ -1083,6 +1098,17 @@ def kill_old_server(self, silent=True):
         self.wait_until_stopped(pid)
         return True
 
+    def wait_load(self, timeout):
+        """Wait until the server log file is matched the entry pattern
+
+        If the entry pattern couldn't be found in a log file until a timeout
+        is up, it will raise a TarantoolStartError exception.
+        """
+        msg = 'entering the event loop|will retry binding|hot standby mode'
+        p = self.process if not self.gdb and not self.lldb else None
+        if not self.logfile_pos.seek_wait(msg, p, self.name, timeout):
+            raise TarantoolStartError(self.name, timeout)
+
     def wait_until_started(self, wait_load=True):
         """ Wait until server is started.
 
@@ -1094,12 +1120,11 @@ def wait_until_started(self, wait_load=True):
         color_log('DEBUG: [Instance {}] Waiting until started '
                   '(wait_load={})\n'.format(self.name, str(wait_load)),
                   schema='info')
-
+        timeout = Options().args.server_start_timeout
         if wait_load:
-            msg = 'entering the event loop|will retry binding|hot standby mode'
-            p = self.process if not self.gdb and not self.lldb else None
-            self.logfile_pos.seek_wait(msg, p, self.name)
-        while True:
+            self.wait_load(timeout)
+        deadline = time.time() + timeout
+        while time.time() < deadline:
             try:
                 temp = AdminConnection('localhost', self.admin.port)
                 if not wait_load:
@@ -1125,6 +1150,8 @@ def wait_until_started(self, wait_load=True):
                     time.sleep(0.1)
                     continue
                 raise
+        else:
+            raise TarantoolStartError(self.name, timeout)
 
     def wait_until_stopped(self, pid):
         while True: