Skip to content

Commit

Permalink
Fix issue w/ not detecting successful server start
Browse files Browse the repository at this point in the history
Problem description:
--------------------

From time to time test-run cannot detect a successful server start and
fails with the following error:

    [012]
    [012] Failed to find 'entering the event loop|will retry binding|hot standby mode' pattern in /tmp/t/012_vinyl/vinyl.log logfile within 290 seconds
    [012]
    [012] [Instance "vinyl"] Failed to start within 290 seconds
    [012]
    [012] Last 15 lines of Tarantool Log file [Instance "vinyl"][/tmp/t/012_vinyl/vinyl.log]:
    [012] 2022-06-09 14:18:34.787 [1684755] snapshot/101/main I> done
    [012] 2022-06-09 14:18:34.788 [1684755] main/103/vinyl I> RAFT: fencing enabled
    [012] 2022-06-09 14:18:34.788 [1684755] main/103/vinyl I> ready to accept requests
    [012] 2022-06-09 14:18:34.788 [1684755] main/105/gc I> wal/engine cleanup is resumed
    [012] 2022-06-09 14:18:34.788 [1684755] main/103/vinyl I> set 'log_level' configuration option to 5
    [012] 2022-06-09 14:18:34.788 [1684755] main/106/checkpoint_daemon I> scheduled next checkpoint for Thu Jun  9 15:48:30 2022
    [012] 2022-06-09 14:18:34.788 [1684755] main/103/vinyl I> set 'log_format' configuration option to "plain"
    [012] 2022-06-09 14:18:34.788 [1684755] main/103/vinyl I> set 'memtx_memory' configuration option to 536870912
    [012] 2022-06-09 14:18:34.788 [1684755] main/103/vinyl I> set 'memtx_max_tuple_size' configuration option to 4194304
    [012] 2022-06-09 14:18:34.788 [1684755] main/103/vinyl I> set 'vinyl_cache' configuration option to 10240
    [012] 2022-06-09 14:18:34.788 [1684755] main/103/vinyl I> set 'listen' configuration option to "\/tmp\/t\/012_vinyl\/vinyl.i"
    [012] 2022-06-09 14:18:34.788 [1684755] main/103/vinyl I> set 'vinyl_max_tuple_size' configuration option to 6291456
    [012] 2022-06-09 14:18:34.789 [1684755] main/103/vinyl I> set 'vinyl_memory' configuration option to 536870912
    [012] 2022-06-09 14:18:34.790 [1684755] main/119/console/unix/:/tmp/t/012_vinyl/vinyl.c I> started
    [012] 2022-06-09 14:18:34.790 [1684755] main I> entering the event loop
    [012] Exception:
    [012] [Instance "vinyl"] Failed to start within 290 seconds

The error says that test-run cannot find the 'entering the event loop'
message in the log file, but as we can see from the log above this
message is present in the log file.

What's going on?
----------------

It looks like test-run reads the line with the message at the moment
when the line is written to the log file and it reads just some part
of the line (for example, '2022-06-09 14:18:34.790 [1684755] main I>
entering the '). After that test-run tries to find the pattern in the
just read line and doesn't find it. Then test-run reads the rest part
of the line ('event loop') and doesn't find the pattern again. In other
words, test-run reads the same line a few times by parts and doesn't
find the pattern in those parts. After that it reaches the end of the
file and waits for new log messages.

Fix description:
----------------

The fix is quite simple: check the just read line ends with the '\n'
symbol (which means that the message is complete) and if it ends, try
to find the pattern, otherwise, re-read the line from the beginning
and try again.

Fixes #343
  • Loading branch information
ylobankov committed Jun 10, 2022
1 parent e221190 commit bf67906
Showing 1 changed file with 11 additions and 2 deletions.
13 changes: 11 additions & 2 deletions lib/tarantool_server.py
Expand Up @@ -481,11 +481,20 @@ def seek_wait(self, msg, proc=None, name=None, deadline=None):
raise TarantoolStartError(name)
log_str = f.readline()
if not log_str:
# We reached the end of the logfile.
gevent.sleep(0.001)
f.seek(cur_pos, os.SEEK_SET)
continue
if re.findall(msg, log_str):
return True
else:
# if the whole line is read, check the pattern in the line.
# Otherwise, set the cursor back to read the line again.
if log_str.endswith('\n'):
if re.findall(msg, log_str):
return True
else:
gevent.sleep(0.001)
f.seek(cur_pos, os.SEEK_SET)
continue
cur_pos = f.tell()

color_stdout("\nFailed to find '{}' pattern in {} logfile within {} "
Expand Down

0 comments on commit bf67906

Please sign in to comment.