[Tarantool-patches] [PATCH v1] test: fix flaky box/net.box_readahead_gh-3958 test

[Tarantool-patches] [PATCH v1] test: fix flaky box/net.box_readahead_gh-3958 test

[Alexander V. Tikhonov]

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
---

Github: https://github.com/tarantool/tarantool/tree/avtikhon/gh-5082-net-box-readahead
Issue: https://github.com/tarantool/tarantool/issues/5082

 test/box/net.box_call_blocks_gh-946.result   | 30 ++++++++++++++++++++
 test/box/net.box_call_blocks_gh-946.test.lua | 12 ++++++++
 2 files changed, 42 insertions(+)

diff --git a/test/box/net.box_call_blocks_gh-946.result b/test/box/net.box_call_blocks_gh-946.result
index 2f6d5fcf2..d9d868ce1 100644
--- a/test/box/net.box_call_blocks_gh-946.result
+++ b/test/box/net.box_call_blocks_gh-946.result
@@ -11,6 +11,12 @@ test_run:cmd('create server connecter with script = "box/proxy.lua"')
 ---
 - true
 ...
+readahead = box.cfg.readahead
+---
+...
+box.cfg{readahead = 100 * 1024}
+---
+...
 --
 -- gh-946: long polling CALL blocks input
 --
@@ -117,3 +123,27 @@ box.session.on_disconnect(on_disconnect) == on_disconnect
 ---
 - true
 ...
+c:close()
+---
+...
+box.schema.user.revoke('guest', 'execute', 'function', 'fast_call')
+---
+...
+box.schema.user.revoke('guest', 'execute', 'function', 'long_call')
+---
+...
+box.schema.user.revoke('guest', 'execute', 'function', 'wait_signal')
+---
+...
+box.schema.func.drop('fast_call')
+---
+...
+box.schema.func.drop('long_call')
+---
+...
+box.schema.func.drop('wait_signal')
+---
+...
+box.cfg{readahead = readahead}
+---
+...
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
 --
@@ -61,3 +64,12 @@ collectgarbage('collect')
 fiber.sleep(0)
 
 box.session.on_disconnect(on_disconnect) == on_disconnect
+
+c:close()
+box.schema.user.revoke('guest', 'execute', 'function', 'fast_call')
+box.schema.user.revoke('guest', 'execute', 'function', 'long_call')
+box.schema.user.revoke('guest', 'execute', 'function', 'wait_signal')
+box.schema.func.drop('fast_call')
+box.schema.func.drop('long_call')
+box.schema.func.drop('wait_signal')
+box.cfg{readahead = readahead}
-- 
2.17.1

Re: [Tarantool-patches] [PATCH v1] test: fix flaky box/net.box_readahead_gh-3958 test

[Alexander Turenko]

Filed https://github.com/tarantool/test-run/issues/214 , where I
proposed to add a mechanism to elide all past logs for grep_log() and
wait_log().

Let's consider vinyl/compact.test.lua way for a while:

 | -- <prepare>
 | require('log').info(string.rep(" ", 1024))
 | -- <commands that either produce some logs or don't>
 | test_run:wait_log(<...>, <...>, 400) == nil

(Don't miss [1]. Don't sure whether it is still actual after [2].
Please, either check it strongly or keep being on the safe side with
1000/400 magic numbers.)

This way is less intruisive than modifying another test.

CCed Sergey as author of the test case.

[1]: https://github.com/tarantool/tarantool/commit/43965c89fe560fdaa7d916a447a74b9bb3453171
[2]: https://github.com/tarantool/tarantool/commit/437e82ed6bbed98e1fa54cbf8bec178fab50a80d