Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

test: flaky box/net.box_readahead_gh-3958.test.lua #5082

Closed
avtikhon opened this issue Jun 16, 2020 · 0 comments
Closed

test: flaky box/net.box_readahead_gh-3958.test.lua #5082

avtikhon opened this issue Jun 16, 2020 · 0 comments
Assignees
@avtikhon
Labels
flaky test qa Issues related to tests or testing subsystem

Comments

@avtikhon
Copy link
Contributor

avtikhon commented Jun 16, 2020 •
edited

Tarantool version:
Tarantool 2.5.0-142-ged93557
Target: Linux-x86_64-RelWithDebInfo
Build options: cmake . -DCMAKE_INSTALL_PREFIX=/usr/local -DENABLE_BACKTRACE=ON
Compiler: /usr/bin/cc /usr/bin/c++
C_FLAGS: -static-libstdc++ -fexceptions -funwind-tables -fno-omit-frame-pointer -fno-stack-protector -fno-common -fopenmp -msse2 -std=c11 -Wall -Wextra -Wno-strict-aliasing -Wno-char-subscripts -Wno-format-truncation -Wno-gnu-alignof-expression -fno-gnu89-inline -Wno-cast-function-type
CXX_FLAGS: -static-libstdc++ -fexceptions -funwind-tables -fno-omit-frame-pointer -fno-stack-protector -fno-common -fopenmp -msse2 -std=c++11 -Wall -Wextra -Wno-strict-aliasing -Wno-char-subscripts -Wno-format-truncation -Wno-invalid-offsetof -Wno-gnu-alignof-expression -Wno-cast-function-type

OS version:
All

Bug description:
https://gitlab.com/tarantool/tarantool/-/jobs/596437749
https://gitlab.com/tarantool/tarantool/-/jobs/596508208
Issue:

 [014] --- box/net.box_readahead_gh-3958.result	Mon Jun 15 15:33:23 2020
 [014] +++ box/net.box_readahead_gh-3958.reject	Tue Jun 16 02:24:04 2020
 [014] @@ -46,6 +46,7 @@
 [014]  ...
 [014]  test_run:wait_log('default', 'readahead limit is reached', 1024, 0.1)
 [014]  ---
 [014] +- readahead limit is reached
 [014]  ...
 [014]  s:drop()
 [014]  ---
 [014] 
 [014] Last 15 lines of Tarantool Log file [Instance "box"][/tarantool/test/var/014_box/box.log]:
 [014] 2020-06-16 02:24:03.792 [5585] main/121/console/unix/: I> set 'read_only' configuration option to false
 [014] 2020-06-16 02:24:03.834 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.835 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.835 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.837 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.837 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.837 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.951 [5585] main/121/console/unix/: space.h:336 E> ER_NO_SUCH_INDEX_ID: No index #1 is defined in space '_space'
 [014] 2020-06-16 02:24:04.180 [5585] main/121/console/unix/: I> set 'readahead' configuration option to 128
 [014] 2020-06-16 02:24:04.183 [5585] main/121/console/unix/: I> set 'readahead' configuration option to 102400
 [014] 2020-06-16 02:24:04.189 [5585] main/453/console/unix/: I> set 'readahead' configuration option to 16320

Found that the root cause of the issue, was the previously run test 'box/net.box_call_blocks_gh-946.test.lua' on the same worker, in this case the log output mistakenly checked by wait_log/grep_log test_run function, which finds the grepping string in the log of the previous test. To avoid of it the tests can be swapped in worker running queue and in this case both tests pass, check swapped log output:

2020-06-17 10:57:39.881 [69372] main C> entering the event loop
2020-06-17 10:57:39.896 [69372] main/119/console/unix/: I> set 'readahead' configuration option to 128
2020-06-17 10:57:39.898 [69372] main/119/console/unix/: I> set 'readahead' configuration option to 102400
2020-06-17 10:57:40.003 [69372] main/156/console/unix/: I> set 'readahead' configuration option to 16320
2020-06-17 10:57:40.053 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.056 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.056 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.058 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.058 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.061 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.061 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.062 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.062 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.063 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.067 [69372] main C> got signal 15 - Terminated

To fix the issue we can currently use the workaround - fix the previous test 'box/net.box_call_blocks_gh-946.test.lua' for readehead value and it will help the failing test to pass:

diff --git a/test/box/net.box_call_blocks_gh-946.test.lua b/test/box/net.box_call_blocks_gh-946.test.lua
index 541541eda..951919737 100644
--- a/test/box/net.box_call_blocks_gh-946.test.lua
+++ b/test/box/net.box_call_blocks_gh-946.test.lua
@@ -5,6 +5,9 @@ net = require('net.box')
 
 test_run:cmd('create server connecter with script = "box/proxy.lua"')
 
+readahead = box.cfg.readahead
+box.cfg{readahead = 100 * 1024}
+
 --
 -- gh-946: long polling CALL blocks input
 --

Steps to reproduce:
Create reproducing list 'box.list.yaml':

- [box/net.box_call_blocks_gh-946.test.lua, null]
- [box/net.box_readahead_gh-3958.test.lua, null]

and run it:

./test-run.py --reproduce box.list.yaml

To check the rest of box/net.box_* tests used:

for f in box/net.box*.test.lua ; do echo $f >>box.list ; done
for f in `grep -v "#" box.list` ; do rm -rf box_test.list.yaml ; cp box_etalon.list.yaml box_test.list.yaml && sed "s#TEST#$f#g" -i box_test.list.yaml && ./test-run.py --reproduce box_test.list.yaml || break ; done

Optional (but very desirable):

  • coredump
  • backtrace
  • netstat
@avtikhon avtikhon added qa Issues related to tests or testing subsystem flaky test labels Jun 16, 2020
@avtikhon avtikhon self-assigned this Jun 16, 2020
@avtikhon avtikhon added this to ON REVIEW in Quality Assurance Jun 17, 2020
@avtikhon avtikhon moved this from ON REVIEW to DOING in Quality Assurance Jun 17, 2020
avtikhon added a commit that referenced this issue Jun 17, 2020
@avtikhon
test: fix flaky box/net.box_readahead_gh-3958 test
dfeac88 
Issue:

 [014] --- box/net.box_readahead_gh-3958.result	Mon Jun 15 15:33:23 2020
 [014] +++ box/net.box_readahead_gh-3958.reject	Tue Jun 16 02:24:04 2020
 [014] @@ -46,6 +46,7 @@
 [014]  ...
 [014]  test_run:wait_log('default', 'readahead limit is reached', 1024, 0.1)
 [014]  ---
 [014] +- readahead limit is reached
 [014]  ...
 [014]  s:drop()
 [014]  ---
 [014]
 [014] Last 15 lines of Tarantool Log file [Instance "box"][/tarantool/test/var/014_box/box.log]:
 [014] 2020-06-16 02:24:03.792 [5585] main/121/console/unix/: I> set 'read_only' configuration option to false
 [014] 2020-06-16 02:24:03.834 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.835 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.835 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.837 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.837 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.837 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.951 [5585] main/121/console/unix/: space.h:336 E> ER_NO_SUCH_INDEX_ID: No index #1 is defined in space '_space'
 [014] 2020-06-16 02:24:04.180 [5585] main/121/console/unix/: I> set 'readahead' configuration option to 128
 [014] 2020-06-16 02:24:04.183 [5585] main/121/console/unix/: I> set 'readahead' configuration option to 102400
 [014] 2020-06-16 02:24:04.189 [5585] main/453/console/unix/: I> set 'readahead' configuration option to 16320

Found that the root cause of the issue, was the previously run test
'box/net.box_call_blocks_gh-946.test.lua' on the same worker, in this
case the log output mistakenly checked by wait_log/grep_log test_run
function, which finds the grepping string in the log of the previous
test. To avoid of it the tests can be swapped in worker running queue
and in this case both tests pass, check swapped log output:

 2020-06-17 10:57:39.881 [69372] main C> entering the event loop
 2020-06-17 10:57:39.896 [69372] main/119/console/unix/: I> set 'readahead' configuration option to 128
 2020-06-17 10:57:39.898 [69372] main/119/console/unix/: I> set 'readahead' configuration option to 102400
 2020-06-17 10:57:40.003 [69372] main/156/console/unix/: I> set 'readahead' configuration option to 16320
 2020-06-17 10:57:40.053 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 2020-06-17 10:57:40.056 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 2020-06-17 10:57:40.056 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 2020-06-17 10:57:40.058 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 2020-06-17 10:57:40.058 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 2020-06-17 10:57:40.061 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 2020-06-17 10:57:40.061 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 2020-06-17 10:57:40.062 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 2020-06-17 10:57:40.062 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 2020-06-17 10:57:40.063 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 2020-06-17 10:57:40.067 [69372] main C> got signal 15 - Terminated

To fix the issue we can currently use the workaround - fix the
previous test 'box/net.box_call_blocks_gh-946.test.lua' for
'readehead' value and it will help the failing test to pass.

Also clean up of the test at its end improved.

Closes #5082
avtikhon added a commit that referenced this issue Jun 17, 2020
@avtikhon
test: fix flaky box/net.box_readahead_gh-3958 test
8ce5e51 
Issue:

 [014] --- box/net.box_readahead_gh-3958.result	Mon Jun 15 15:33:23 2020
 [014] +++ box/net.box_readahead_gh-3958.reject	Tue Jun 16 02:24:04 2020
 [014] @@ -46,6 +46,7 @@
 [014]  ...
 [014]  test_run:wait_log('default', 'readahead limit is reached', 1024, 0.1)
 [014]  ---
 [014] +- readahead limit is reached
 [014]  ...
 [014]  s:drop()
 [014]  ---
 [014]
 [014] Last 15 lines of Tarantool Log file [Instance "box"][/tarantool/test/var/014_box/box.log]:
 [014] 2020-06-16 02:24:03.792 [5585] main/121/console/unix/: I> set 'read_only' configuration option to false
 [014] 2020-06-16 02:24:03.834 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.835 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.835 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.837 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.837 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.837 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.951 [5585] main/121/console/unix/: space.h:336 E> ER_NO_SUCH_INDEX_ID: No index #1 is defined in space '_space'
 [014] 2020-06-16 02:24:04.180 [5585] main/121/console/unix/: I> set 'readahead' configuration option to 128
 [014] 2020-06-16 02:24:04.183 [5585] main/121/console/unix/: I> set 'readahead' configuration option to 102400
 [014] 2020-06-16 02:24:04.189 [5585] main/453/console/unix/: I> set 'readahead' configuration option to 16320

Found that the root cause of the issue, was the previously run test
'box/net.box_call_blocks_gh-946.test.lua' on the same worker, in this
case the log output mistakenly checked by wait_log/grep_log test_run
function, which finds the grepping string in the log of the previous
test. To avoid of it the tests can be swapped in worker running queue
and in this case both tests pass, check swapped log output:

 2020-06-17 10:57:39.881 [69372] main C> entering the event loop
 2020-06-17 10:57:39.896 [69372] main/119/console/unix/: I> set 'readahead' configuration option to 128
 2020-06-17 10:57:39.898 [69372] main/119/console/unix/: I> set 'readahead' configuration option to 102400
 2020-06-17 10:57:40.003 [69372] main/156/console/unix/: I> set 'readahead' configuration option to 16320
 2020-06-17 10:57:40.053 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 2020-06-17 10:57:40.056 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 2020-06-17 10:57:40.056 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 2020-06-17 10:57:40.058 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 2020-06-17 10:57:40.058 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 2020-06-17 10:57:40.061 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 2020-06-17 10:57:40.061 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 2020-06-17 10:57:40.062 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 2020-06-17 10:57:40.062 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 2020-06-17 10:57:40.063 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 2020-06-17 10:57:40.067 [69372] main C> got signal 15 - Terminated

To fix the issue we can currently use the workaround - fix the
previous test 'box/net.box_call_blocks_gh-946.test.lua' for
'readahead' value and it will help the failing test to pass.

Also clean up of the test at its end improved.

Closes #5082
@avtikhon avtikhon moved this from DOING to ON REVIEW in Quality Assurance Jun 17, 2020
@avtikhon avtikhon moved this from ON REVIEW to DOING in Quality Assurance Jun 19, 2020
avtikhon added a commit that referenced this issue Jun 23, 2020
@avtikhon
test: fix flaky box/net.box_readahead_gh-3958 test
90d2bb8 
Issue:

 [014] --- box/net.box_readahead_gh-3958.result	Mon Jun 15 15:33:23 2020
 [014] +++ box/net.box_readahead_gh-3958.reject	Tue Jun 16 02:24:04 2020
 [014] @@ -46,6 +46,7 @@
 [014]  ...
 [014]  test_run:wait_log('default', 'readahead limit is reached', 1024, 0.1)
 [014]  ---
 [014] +- readahead limit is reached
 [014]  ...
 [014]  s:drop()
 [014]  ---
 [014]
 [014] Last 15 lines of Tarantool Log file [Instance "box"][/tarantool/test/var/014_box/box.log]:
 [014] 2020-06-16 02:24:03.792 [5585] main/121/console/unix/: I> set 'read_only' configuration option to false
 [014] 2020-06-16 02:24:03.834 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.835 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.835 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.837 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.837 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.837 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 [014] 2020-06-16 02:24:03.951 [5585] main/121/console/unix/: space.h:336 E> ER_NO_SUCH_INDEX_ID: No index #1 is defined in space '_space'
 [014] 2020-06-16 02:24:04.180 [5585] main/121/console/unix/: I> set 'readahead' configuration option to 128
 [014] 2020-06-16 02:24:04.183 [5585] main/121/console/unix/: I> set 'readahead' configuration option to 102400
 [014] 2020-06-16 02:24:04.189 [5585] main/453/console/unix/: I> set 'readahead' configuration option to 16320

Found that the root cause of the issue, was the previously run test
'box/net.box_call_blocks_gh-946.test.lua' on the same worker, in this
case the log output mistakenly checked by wait_log/grep_log test_run
function, which finds the grepping string in the log of the previous
test. To avoid of it the tests can be swapped in worker running queue
and in this case both tests pass, check swapped log output:

 2020-06-17 10:57:39.881 [69372] main C> entering the event loop
 2020-06-17 10:57:39.896 [69372] main/119/console/unix/: I> set 'readahead' configuration option to 128
 2020-06-17 10:57:39.898 [69372] main/119/console/unix/: I> set 'readahead' configuration option to 102400
 2020-06-17 10:57:40.003 [69372] main/156/console/unix/: I> set 'readahead' configuration option to 16320
 2020-06-17 10:57:40.053 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 2020-06-17 10:57:40.056 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 2020-06-17 10:57:40.056 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 2020-06-17 10:57:40.058 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 2020-06-17 10:57:40.058 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 2020-06-17 10:57:40.061 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 2020-06-17 10:57:40.061 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 2020-06-17 10:57:40.062 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 2020-06-17 10:57:40.062 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 2020-06-17 10:57:40.063 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
 2020-06-17 10:57:40.067 [69372] main C> got signal 15 - Terminated

Also clean up of the test at its end improved.

Closes #5082
avtikhon added a commit that referenced this issue Jun 25, 2020
@avtikhon
test: fix flaky box/net.box_call_blocks_gh-946
1bc8694 
Issue:

2020-06-25 14:15:39.094 [26905] main/103/box C> Tarantool 2.4.1-161-g90d2bb8a3
2020-06-25 14:15:39.094 [26905] main/103/box C> log level 5
2020-06-25 14:15:39.094 [26905] main/103/box I> mapping 117440512 bytes for memtx tuple arena...
2020-06-25 14:15:39.094 [26905] main/103/box I> mapping 134217728 bytes for vinyl tuple arena...
2020-06-25 14:15:39.099 [26905] main/103/box I> instance uuid 79a797f5-48f5-4fb4-a191-20414bd1139a
2020-06-25 14:15:39.099 [26905] iproto/101/main I> binary: bound to unix/:(socket)
2020-06-25 14:15:39.100 [26905] main/103/box I> initializing an empty data directory
2020-06-25 14:15:39.126 [26905] main/103/box I> assigned id 1 to replica 79a797f5-48f5-4fb4-a191-20414bd1139a
2020-06-25 14:15:39.126 [26905] main/103/box I> cluster uuid c3f9022f-e3f2-4209-9afa-47a4df6ebf27
2020-06-25 14:15:39.127 [26905] snapshot/101/main I> saving snapshot `/home/avtikhon/Workspaces/tarantool/test/var/001_box/box/00000000000000000000.snap.inprogress'
2020-06-25 14:15:39.129 [26905] snapshot/101/main I> done
2020-06-25 14:15:39.130 [26905] main/103/box I> ready to accept requests
2020-06-25 14:15:39.130 [26905] main/103/box I> set 'log_level' configuration option to 5
2020-06-25 14:15:39.130 [26905] main/106/checkpoint_daemon I> scheduled next checkpoint for Thu Jun 25 15:33:23 2020
2020-06-25 14:15:39.130 [26905] main/103/box I> set 'memtx_memory' configuration option to 107374182
2020-06-25 14:15:39.130 [26905] main/103/box I> set 'listen' configuration option to "\/home\/avtikhon\/Workspaces\/tarantool\/test\/var\/001_box\/box.socket-iproto"
2020-06-25 14:15:39.130 [26905] main/103/box I> set 'log_format' configuration option to "plain"
2020-06-25 14:15:39.130 [26905] main/117/console/unix/:/home/avtikhon/Workspaces/tarantool/test/var/001_box/box.socket-admin I> started
2020-06-25 14:15:39.131 [26905] main C> entering the event loop
2020-06-25 14:15:39.211 [26905] iproto iproto.cc:606 W> stopping input on connection fd 23, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-25 14:15:39.214 [26905] iproto iproto.cc:606 W> stopping input on connection fd 23, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-25 14:15:39.214 [26905] iproto iproto.cc:606 W> stopping input on connection fd 23, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-25 14:15:39.217 [26905] iproto iproto.cc:606 W> stopping input on connection fd 23, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-25 14:15:39.217 [26905] iproto iproto.cc:606 W> stopping input on connection fd 23, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-25 14:15:39.221 [26905] iproto iproto.cc:606 W> stopping input on connection fd 23, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-25 14:15:39.221 [26905] iproto iproto.cc:606 W> stopping input on connection fd 23, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-25 14:15:39.221 [26905] iproto iproto.cc:606 W> stopping input on connection fd 23, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-25 14:15:39.221 [26905] iproto iproto.cc:606 W> stopping input on connection fd 23, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-25 14:15:39.221 [26905] iproto iproto.cc:606 W> stopping input on connection fd 23, aka unix/:(socket), peer of unix/:(socket), readah

To fix the issue increased 'readahead' value.

Found issue at the tests running after the current:

2020-06-25 14:11:30.402 [26731] main/103/box C> Tarantool 2.4.1-161-g90d2bb8a3
2020-06-25 14:11:30.402 [26731] main/103/box C> log level 5
2020-06-25 14:11:30.402 [26731] main/103/box I> mapping 117440512 bytes for memtx tuple arena...
2020-06-25 14:11:30.402 [26731] main/103/box I> mapping 134217728 bytes for vinyl tuple arena...
2020-06-25 14:11:30.407 [26731] main/103/box I> instance uuid 7bd70751-835c-40b7-8e90-43f31c8aa09c
2020-06-25 14:11:30.407 [26731] iproto/101/main I> binary: bound to unix/:(socket)
2020-06-25 14:11:30.407 [26731] main/103/box I> initializing an empty data directory
2020-06-25 14:11:30.433 [26731] main/103/box I> assigned id 1 to replica 7bd70751-835c-40b7-8e90-43f31c8aa09c
2020-06-25 14:11:30.433 [26731] main/103/box I> cluster uuid 17fa0851-2b2d-4cfd-8eed-2cfd7a5195c6
2020-06-25 14:11:30.434 [26731] snapshot/101/main I> saving snapshot `/home/avtikhon/Workspaces/tarantool/test/var/001_box/box/00000000000000000000.snap.inprogress'
2020-06-25 14:11:30.443 [26731] snapshot/101/main I> done
2020-06-25 14:11:30.444 [26731] main/103/box I> ready to accept requests
2020-06-25 14:11:30.444 [26731] main/103/box I> set 'log_level' configuration option to 5
2020-06-25 14:11:30.444 [26731] main/106/checkpoint_daemon I> scheduled next checkpoint for Thu Jun 25 16:06:04 2020
2020-06-25 14:11:30.444 [26731] main/103/box I> set 'memtx_memory' configuration option to 107374182
2020-06-25 14:11:30.444 [26731] main/103/box I> set 'listen' configuration option to "\/home\/avtikhon\/Workspaces\/tarantool\/test\/var\/001_box\/box.socket-iproto"
2020-06-25 14:11:30.444 [26731] main/103/box I> set 'log_format' configuration option to "plain"
2020-06-25 14:11:30.445 [26731] main/117/console/unix/:/home/avtikhon/Workspaces/tarantool/test/var/001_box/box.socket-admin I> started
2020-06-25 14:11:30.445 [26731] main C> entering the event loop
2020-06-25 14:11:30.479 [26731] main/119/console/unix/: I> set 'readahead' configuration option to 102400
2020-06-25 14:11:30.569 [26731] main/119/console/unix/: I> set 'readahead' configuration option to 16320
2020-06-25 14:11:30.582 [26731] main/119/console/unix/: I> set 'readahead' configuration option to 128
2020-06-25 14:11:30.587 [26731] main/119/console/unix/: I> set 'readahead' configuration option to 102400
2020-06-25 14:11:30.589 [26731] main/420/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.594 [26731] main/422/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.599 [26731] main/423/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.605 [26731] main/424/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.615 [26731] main/425/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.625 [26731] main/426/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.635 [26731] main/427/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.641 [26731] main/428/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.649 [26731] main/429/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.662 [26731] main/430/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.666 [26731] main/431/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.674 [26731] main/433/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.681 [26731] main/434/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.688 [26731] main/435/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.693 [26731] main/432/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.694 [26731] main/119/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.697 [26731] main/436/console/unix/: I> set 'readahead' configuration option to 16320

Found that the root cause of the issue, that both tests run on the same
worker, in this case function on_disconnected must be cleaned. Also clean
up of the test at its end improved.

Part of #5082
avtikhon added a commit that referenced this issue Jun 25, 2020
@avtikhon
test: fix flaky box/net.box_readahead_gh-3958 test
340e884 
Issue:

[014] --- box/net.box_readahead_gh-3958.result Mon Jun 15 15:33:23 2020
[014] +++ box/net.box_readahead_gh-3958.reject Tue Jun 16 02:24:04 2020
[014] @@ -46,6 +46,7 @@
[014]  ...
[014]  test_run:wait_log('default', 'readahead limit is reached', 1024, 0.1)
[014]  ---
[014] +- readahead limit is reached
[014]  ...
[014]  s:drop()
[014]  ---
[014]
[014] Last 15 lines of Tarantool Log file [Instance "box"][/tarantool/test/var/014_box/box.log]:
[014] 2020-06-16 02:24:03.792 [5585] main/121/console/unix/: I> set 'read_only' configuration option to false
[014] 2020-06-16 02:24:03.834 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.835 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.835 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.837 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.837 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.837 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.951 [5585] main/121/console/unix/: space.h:336 E> ER_NO_SUCH_INDEX_ID: No index #1 is defined in space '_space'
[014] 2020-06-16 02:24:04.180 [5585] main/121/console/unix/: I> set 'readahead' configuration option to 128
[014] 2020-06-16 02:24:04.183 [5585] main/121/console/unix/: I> set 'readahead' configuration option to 102400
[014] 2020-06-16 02:24:04.189 [5585] main/453/console/unix/: I> set 'readahead' configuration option to 16320

Found that the root cause of the issue, was the previously run test
'box/net.box_call_blocks_gh-946.test.lua' on the same worker, in this
case the log output mistakenly checked by wait_log/grep_log test_run
function, which finds the grepping string in the log of the previous
test. To avoid of it the tests can be swapped in worker running queue
and in this case both tests pass, check swapped log output:

2020-06-17 10:57:39.881 [69372] main C> entering the event loop
2020-06-17 10:57:39.896 [69372] main/119/console/unix/: I> set 'readahead' configuration option to 128
2020-06-17 10:57:39.898 [69372] main/119/console/unix/: I> set 'readahead' configuration option to 102400
2020-06-17 10:57:40.003 [69372] main/156/console/unix/: I> set 'readahead' configuration option to 16320
2020-06-17 10:57:40.053 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.056 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.056 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.058 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.058 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.061 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.061 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.062 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.062 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.063 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.067 [69372] main C> got signal 15 - Terminated

Also found that 'readahead' issue from the first test blocks its
printing to log file due to suppressed. To fix this issue the
default server must be restarted at the very start of the test.

Closes #5082
@avtikhon avtikhon moved this from DOING to ON REVIEW in Quality Assurance Jun 26, 2020
avtikhon added a commit that referenced this issue Jul 2, 2020
@avtikhon
test-run: bump version
badfa8c 
Bumped test-run with ability to restart server on each test run
from the queue at the same worker.

Closes test-run#215
Closes #5082
avtikhon added a commit that referenced this issue Jul 2, 2020
@avtikhon
test-run: bump version
34c225c 
Bumped test-run with ability to restart server on each test run
from the queue at the same worker.

Closes test-run#215
Closes #5082
avtikhon added a commit that referenced this issue Jul 3, 2020
@avtikhon
test: fix flaky box/net.box_readahead_gh-3958 test
572f915 
Issue:

[014] --- box/net.box_readahead_gh-3958.result Mon Jun 15 15:33:23 2020
[014] +++ box/net.box_readahead_gh-3958.reject Tue Jun 16 02:24:04 2020
[014] @@ -46,6 +46,7 @@
[014]  ...
[014]  test_run:wait_log('default', 'readahead limit is reached', 1024, 0.1)
[014]  ---
[014] +- readahead limit is reached
[014]  ...
[014]  s:drop()
[014]  ---
[014]

Found that the root cause of the issue, was the previously run test
'box/net.box_call_blocks_gh-946.test.lua' on the same worker, in this
case the log output mistakenly checked by wait_log/grep_log test_run
function, which finds the grepping string in the log of the previous
test. When tests are run on different workers or in another order,
everything works.

Also found that another issue with failed 'readahead' at the test
'box/net.box_call_blocks_gh-946.test.lua' blocked printing of the
'readahead limit is reached' message at the current test due to was
suppressed with the messages from the first failed test. Suppression
was enabled by commit:

  e6ebd5e 'Rate limit certain warning messages'

Temporary rolling back of the this commit shows that messages from
both tests exists in the log file.

In another way it was checked the possible fix:

diff --git a/test/box/net.box_readahead_gh-3958.test.lua b/test/box/net.box_readahead_gh-3958.test.lua
index 1e33a84cb..f6969d7f0 100644
--- a/test/box/net.box_readahead_gh-3958.test.lua
+++ b/test/box/net.box_readahead_gh-3958.test.lua
@@ -17,6 +17,7 @@ box.schema.user.grant("guest", "read,write", "space", "test")
 c = net.connect(box.cfg.listen)

 box.cfg{readahead = 100 * 1024}
+require('log').info(string.rep(' ', 1024))

 box.error.injection.set("ERRINJ_WAL_DELAY", true)
 pad = string.rep('x', 8192)

which adds some empty space before the checking message in the log
file to avoid of suppresion. But in this case if the readahead
increamentation will be blocked, like:

diff --git a/test/box/net.box_readahead_gh-3958.test.lua b/test/box/net.box_readahead_gh-3958.test.lua
index 1e33a84cb..4948a18d2 100644
--- a/test/box/net.box_readahead_gh-3958.test.lua
+++ b/test/box/net.box_readahead_gh-3958.test.lua
@@ -16,7 +16,8 @@ box.schema.user.grant("guest", "read,write", "space", "test")
 -- make sure it is updated if box.cfg.readahead is changed.
 c = net.connect(box.cfg.listen)

-box.cfg{readahead = 100 * 1024}
+--box.cfg{readahead = 100 * 1024}
+require('log').info(string.rep(' ', 1024))

 box.error.injection.set("ERRINJ_WAL_DELAY", true)
 pad = string.rep('x', 8192)

and the tests will be run together with reproducer 'box.list.yaml':
- [box/net.box_call_blocks_gh-946.test.lua, null]
- [box/net.box_readahead_gh-3958.test.lua, null]

  ./test-run.py --reproduce box.list.yaml

then the test will not produce the checking issue for which the test
was created and will always false pass.

To avoid of all the issues mentioned above the default server must be
restarted at the very start of the current test.

Closes #5082
@avtikhon avtikhon moved this from ON REVIEW to DONE in Quality Assurance Jul 3, 2020
@kyukhin kyukhin closed this as completed in 4c7d828 Jul 3, 2020
kyukhin pushed a commit that referenced this issue Jul 3, 2020
@avtikhon @kyukhin
test: fix flaky box/net.box_readahead_gh-3958 test
43bcd0b 
Issue:

[014] --- box/net.box_readahead_gh-3958.result Mon Jun 15 15:33:23 2020
[014] +++ box/net.box_readahead_gh-3958.reject Tue Jun 16 02:24:04 2020
[014] @@ -46,6 +46,7 @@
[014]  ...
[014]  test_run:wait_log('default', 'readahead limit is reached', 1024, 0.1)
[014]  ---
[014] +- readahead limit is reached
[014]  ...
[014]  s:drop()
[014]  ---
[014]
[014] Last 15 lines of Tarantool Log file [Instance "box"][/tarantool/test/var/014_box/box.log]:
[014] 2020-06-16 02:24:03.792 [5585] main/121/console/unix/: I> set 'read_only' configuration option to false
[014] 2020-06-16 02:24:03.834 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.835 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.835 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.837 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.837 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.837 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.951 [5585] main/121/console/unix/: space.h:336 E> ER_NO_SUCH_INDEX_ID: No index #1 is defined in space '_space'
[014] 2020-06-16 02:24:04.180 [5585] main/121/console/unix/: I> set 'readahead' configuration option to 128
[014] 2020-06-16 02:24:04.183 [5585] main/121/console/unix/: I> set 'readahead' configuration option to 102400
[014] 2020-06-16 02:24:04.189 [5585] main/453/console/unix/: I> set 'readahead' configuration option to 16320

Found that the root cause of the issue, was the previously run test
'box/net.box_call_blocks_gh-946.test.lua' on the same worker, in this
case the log output mistakenly checked by wait_log/grep_log test_run
function, which finds the grepping string in the log of the previous
test. To avoid of it the tests can be swapped in worker running queue
and in this case both tests pass, check swapped log output:

2020-06-17 10:57:39.881 [69372] main C> entering the event loop
2020-06-17 10:57:39.896 [69372] main/119/console/unix/: I> set 'readahead' configuration option to 128
2020-06-17 10:57:39.898 [69372] main/119/console/unix/: I> set 'readahead' configuration option to 102400
2020-06-17 10:57:40.003 [69372] main/156/console/unix/: I> set 'readahead' configuration option to 16320
2020-06-17 10:57:40.053 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.056 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.056 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.058 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.058 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.061 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.061 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.062 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.062 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.063 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.067 [69372] main C> got signal 15 - Terminated

Also found that 'readahead' issue from the first test blocks its
printing to log file due to suppressed. To fix this issue the
default server must be restarted at the very start of the test.

Closes #5082

(cherry picked from commit 4c7d828)
kyukhin pushed a commit that referenced this issue Jul 3, 2020
@avtikhon @kyukhin
test: fix flaky box/net.box_readahead_gh-3958 test
41a59f8 
Issue:

[014] --- box/net.box_readahead_gh-3958.result Mon Jun 15 15:33:23 2020
[014] +++ box/net.box_readahead_gh-3958.reject Tue Jun 16 02:24:04 2020
[014] @@ -46,6 +46,7 @@
[014]  ...
[014]  test_run:wait_log('default', 'readahead limit is reached', 1024, 0.1)
[014]  ---
[014] +- readahead limit is reached
[014]  ...
[014]  s:drop()
[014]  ---
[014]
[014] Last 15 lines of Tarantool Log file [Instance "box"][/tarantool/test/var/014_box/box.log]:
[014] 2020-06-16 02:24:03.792 [5585] main/121/console/unix/: I> set 'read_only' configuration option to false
[014] 2020-06-16 02:24:03.834 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.835 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.835 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.837 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.837 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.837 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.951 [5585] main/121/console/unix/: space.h:336 E> ER_NO_SUCH_INDEX_ID: No index #1 is defined in space '_space'
[014] 2020-06-16 02:24:04.180 [5585] main/121/console/unix/: I> set 'readahead' configuration option to 128
[014] 2020-06-16 02:24:04.183 [5585] main/121/console/unix/: I> set 'readahead' configuration option to 102400
[014] 2020-06-16 02:24:04.189 [5585] main/453/console/unix/: I> set 'readahead' configuration option to 16320

Found that the root cause of the issue, was the previously run test
'box/net.box_call_blocks_gh-946.test.lua' on the same worker, in this
case the log output mistakenly checked by wait_log/grep_log test_run
function, which finds the grepping string in the log of the previous
test. To avoid of it the tests can be swapped in worker running queue
and in this case both tests pass, check swapped log output:

2020-06-17 10:57:39.881 [69372] main C> entering the event loop
2020-06-17 10:57:39.896 [69372] main/119/console/unix/: I> set 'readahead' configuration option to 128
2020-06-17 10:57:39.898 [69372] main/119/console/unix/: I> set 'readahead' configuration option to 102400
2020-06-17 10:57:40.003 [69372] main/156/console/unix/: I> set 'readahead' configuration option to 16320
2020-06-17 10:57:40.053 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.056 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.056 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.058 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.058 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.061 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.061 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.062 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.062 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.063 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.067 [69372] main C> got signal 15 - Terminated

Also found that 'readahead' issue from the first test blocks its
printing to log file due to suppressed. To fix this issue the
default server must be restarted at the very start of the test.

Closes #5082

(cherry picked from commit 4c7d828)
kyukhin pushed a commit that referenced this issue Jul 3, 2020
@avtikhon @kyukhin
test: fix flaky box/net.box_readahead_gh-3958 test
19ece64 
Issue:

[014] --- box/net.box_readahead_gh-3958.result Mon Jun 15 15:33:23 2020
[014] +++ box/net.box_readahead_gh-3958.reject Tue Jun 16 02:24:04 2020
[014] @@ -46,6 +46,7 @@
[014]  ...
[014]  test_run:wait_log('default', 'readahead limit is reached', 1024, 0.1)
[014]  ---
[014] +- readahead limit is reached
[014]  ...
[014]  s:drop()
[014]  ---
[014]
[014] Last 15 lines of Tarantool Log file [Instance "box"][/tarantool/test/var/014_box/box.log]:
[014] 2020-06-16 02:24:03.792 [5585] main/121/console/unix/: I> set 'read_only' configuration option to false
[014] 2020-06-16 02:24:03.834 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.835 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.835 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.836 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.837 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.837 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.837 [5585] iproto iproto.cc:606 W> stopping input on connection fd 26, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
[014] 2020-06-16 02:24:03.951 [5585] main/121/console/unix/: space.h:336 E> ER_NO_SUCH_INDEX_ID: No index #1 is defined in space '_space'
[014] 2020-06-16 02:24:04.180 [5585] main/121/console/unix/: I> set 'readahead' configuration option to 128
[014] 2020-06-16 02:24:04.183 [5585] main/121/console/unix/: I> set 'readahead' configuration option to 102400
[014] 2020-06-16 02:24:04.189 [5585] main/453/console/unix/: I> set 'readahead' configuration option to 16320

Found that the root cause of the issue, was the previously run test
'box/net.box_call_blocks_gh-946.test.lua' on the same worker, in this
case the log output mistakenly checked by wait_log/grep_log test_run
function, which finds the grepping string in the log of the previous
test. To avoid of it the tests can be swapped in worker running queue
and in this case both tests pass, check swapped log output:

2020-06-17 10:57:39.881 [69372] main C> entering the event loop
2020-06-17 10:57:39.896 [69372] main/119/console/unix/: I> set 'readahead' configuration option to 128
2020-06-17 10:57:39.898 [69372] main/119/console/unix/: I> set 'readahead' configuration option to 102400
2020-06-17 10:57:40.003 [69372] main/156/console/unix/: I> set 'readahead' configuration option to 16320
2020-06-17 10:57:40.053 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.056 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.056 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.058 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.058 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.061 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.061 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.062 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.062 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.063 [69372] iproto iproto.cc:606 W> stopping input on connection fd 33, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-17 10:57:40.067 [69372] main C> got signal 15 - Terminated

Also found that 'readahead' issue from the first test blocks its
printing to log file due to suppressed. To fix this issue the
default server must be restarted at the very start of the test.

Closes #5082

(cherry picked from commit 4c7d828)
@avtikhon avtikhon removed this from DONE in Quality Assurance Jul 28, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@avtikhon avtikhon

Labels
flaky test qa Issues related to tests or testing subsystem
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@avtikhon