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

Tarantool development patches archive
 help / color / mirror / Atom feed

* [Tarantool-patches] [PATCH v1] test: fix flaky box/net.box_readahead_gh-3958 test
@ 2020-06-17 12:00 Alexander V. Tikhonov
  2020-06-18 18:39 ` Alexander Turenko
  0 siblings, 1 reply; 2+ messages in thread
From: Alexander V. Tikhonov @ 2020-06-17 12:00 UTC (permalink / raw)
  To: Kirill Yukhin, Sergey Bronnikov; +Cc: tarantool-patches, Alexander Turenko

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

^ permalink raw reply	[flat|nested] 2+ messages in thread

* Re: [Tarantool-patches] [PATCH v1] test: fix flaky box/net.box_readahead_gh-3958 test
  2020-06-17 12:00 [Tarantool-patches] [PATCH v1] test: fix flaky box/net.box_readahead_gh-3958 test Alexander V. Tikhonov
@ 2020-06-18 18:39 ` Alexander Turenko
  0 siblings, 0 replies; 2+ messages in thread
From: Alexander Turenko @ 2020-06-18 18:39 UTC (permalink / raw)
  To: Alexander V. Tikhonov; +Cc: tarantool-patches

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

^ permalink raw reply	[flat|nested] 2+ messages in thread

end of thread, other threads:[~2020-06-18 18:40 UTC | newest]

Thread overview: 2+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2020-06-17 12:00 [Tarantool-patches] [PATCH v1] test: fix flaky box/net.box_readahead_gh-3958 test Alexander V. Tikhonov
2020-06-18 18:39 ` Alexander Turenko

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox