[Tarantool-patches] [PATCH v2 1/2] test: fix flaky box/net.box_call_blocks_gh-946

[Tarantool-patches] [PATCH v2 1/2] test: fix flaky box/net.box_call_blocks_gh-946

[Alexander V. Tikhonov]

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

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

[Tarantool-patches] [PATCH v2 2/2] 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

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

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_readahead_gh-3958.result   | 1 +
 test/box/net.box_readahead_gh-3958.test.lua | 1 +
 2 files changed, 2 insertions(+)

diff --git a/test/box/net.box_readahead_gh-3958.result b/test/box/net.box_readahead_gh-3958.result
index fc2093531..def624cc9 100644
--- a/test/box/net.box_readahead_gh-3958.result
+++ b/test/box/net.box_readahead_gh-3958.result
@@ -1,6 +1,7 @@
 test_run = require('test_run').new()
 ---
 ...
+test_run:cmd('restart server default')
 net = require('net.box')
 ---
 ...
diff --git a/test/box/net.box_readahead_gh-3958.test.lua b/test/box/net.box_readahead_gh-3958.test.lua
index 1e33a84cb..f34240b65 100644
--- a/test/box/net.box_readahead_gh-3958.test.lua
+++ b/test/box/net.box_readahead_gh-3958.test.lua
@@ -1,4 +1,5 @@
 test_run = require('test_run').new()
+test_run:cmd('restart server default')
 net = require('net.box')
 
 --
-- 
2.17.1

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

[Alexander Turenko]

Please, polish the commit message. The fix itself is okay.

It would be counter-productive to play ping-pong around the problem
description, so let's do your best and ask Kirill to push. No need to
review the messages with me again.

I'm okay after clarification of details pointed below.

WBR, Alexaner Turenko.

On Thu, Jun 25, 2020 at 02:25:11PM +0300, Alexander V. Tikhonov wrote:
> 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]

Okay.

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

I think this block is redundant: you already show above that wait_log()
found the warning re readahead, while it should not. And provided
interpretation below.

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

It is okay.

> To avoid of it the tests can be swapped in worker running queue
> and in this case both tests pass, check swapped log output:

I guess you want to say that when tests are run on different workers or
in another order, everything works. Initially I don't get what is
'swapping in worker running queue' and how I can do it. Too much
specific terms to express different ordering, IMHO.

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

I don't think that this big log is useful. Proper description what is
going on is enough.

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

I know the context, but I would not understand it from the message if I
would not know already.

You describe another possible fix with printing a 1 KiB log entry before
a test case and then check a last 1 KiB of the log for the 'readahead
limit reached' message.

You should describe it (maybe even provide a diff) and describe the
reason why it does not work: ratelimiting of such messages may lead to
disappearing some amount of messages when its pressure is descreased
below the limit (nothing triggers printing of suspended messages if such
messages are not triggered anymore). Let's experiment with this and
describe your observations.

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

> index 1e33a84cb..f34240b65 100644
> --- a/test/box/net.box_readahead_gh-3958.test.lua
> +++ b/test/box/net.box_readahead_gh-3958.test.lua
> @@ -1,4 +1,5 @@
>  test_run = require('test_run').new()
> +test_run:cmd('restart server default')
>  net = require('net.box')

Okay. But I would leave a short comment here, like 'discard all logs
from previous tests and clear log ratelimiting statistics'.

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

[Alexander V. Tikhonov]

Hi Alexander, thanks a lot for your help and review. I've made all
corrections in the commit message as you suggested.

Kirill please proceed with pushing the fix to all release branches.

On Mon, Jun 29, 2020 at 03:18:08PM +0300, Alexander Turenko wrote:
> Please, polish the commit message. The fix itself is okay.
> 
> It would be counter-productive to play ping-pong around the problem
> description, so let's do your best and ask Kirill to push. No need to
> review the messages with me again.
> 
> I'm okay after clarification of details pointed below.
> 
> WBR, Alexaner Turenko.
> 
> On Thu, Jun 25, 2020 at 02:25:11PM +0300, Alexander V. Tikhonov wrote:
> > 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]
> 
> Okay.
> 
> > [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
> 
> I think this block is redundant: you already show above that wait_log()
> found the warning re readahead, while it should not. And provided
> interpretation below.
> 
> > 
> > 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.
> 
> It is okay.
> 
> > To avoid of it the tests can be swapped in worker running queue
> > and in this case both tests pass, check swapped log output:
> 
> I guess you want to say that when tests are run on different workers or
> in another order, everything works. Initially I don't get what is
> 'swapping in worker running queue' and how I can do it. Too much
> specific terms to express different ordering, IMHO.
> 
> > 
> > 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
> 
> I don't think that this big log is useful. Proper description what is
> going on is enough.
> 
> > 
> > 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.
> 
> I know the context, but I would not understand it from the message if I
> would not know already.
> 
> You describe another possible fix with printing a 1 KiB log entry before
> a test case and then check a last 1 KiB of the log for the 'readahead
> limit reached' message.
> 
> You should describe it (maybe even provide a diff) and describe the
> reason why it does not work: ratelimiting of such messages may lead to
> disappearing some amount of messages when its pressure is descreased
> below the limit (nothing triggers printing of suspended messages if such
> messages are not triggered anymore). Let's experiment with this and
> describe your observations.
> 
> > 
> > Closes #5082
> > ---
> > 
> > Github: https://github.com/tarantool/tarantool/tree/avtikhon/gh-5082-net-box-readahead
> > Issue: https://github.com/tarantool/tarantool/issues/5082
> 
> > index 1e33a84cb..f34240b65 100644
> > --- a/test/box/net.box_readahead_gh-3958.test.lua
> > +++ b/test/box/net.box_readahead_gh-3958.test.lua
> > @@ -1,4 +1,5 @@
> >  test_run = require('test_run').new()
> > +test_run:cmd('restart server default')
> >  net = require('net.box')
> 
> Okay. But I would leave a short comment here, like 'discard all logs
> from previous tests and clear log ratelimiting statistics'.

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

[Kirill Yukhin]

Hello,

On 25 июн 14:25, Alexander V. Tikhonov wrote:
> 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
> ---
> 
> Github: https://github.com/tarantool/tarantool/tree/avtikhon/gh-5082-net-box-readahead
> Issue: https://github.com/tarantool/tarantool/issues/5082

I've checked the patch into 1.10, 2.3, 2.4 and master.

--
Regards, Kirill Yukhin

Re: [Tarantool-patches] [PATCH v2 1/2] test: fix flaky box/net.box_call_blocks_gh-946

[Alexander Turenko]

It is not clear what is the issue. Is the test fails? How exactly? And
it does not look related to #5082, which is about another test.

Warnings re readahead limit are not a problem per se.

Please, clarify what is the problem and send it separately from #5082 if
it is not related.

WBR, Alexander Turenko.

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