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.
Problem description:
From time to time test-run cannot detect a successful server start and fails with the following error:
The error says that test-run cannot find the
entering the event loopmessage 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